| Message ID | 20240306020006.586558735@goodmis.org (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | tracing: Persistent traces across a reboot or crash | expand |
Hi Steven, kernel test robot noticed the following build errors: [auto build test ERROR on next-20240305] [cannot apply to tip/x86/core akpm-mm/mm-everything linus/master v6.8-rc7 v6.8-rc6 v6.8-rc5 v6.8-rc7] [If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch#_base_tree_information] url: https://github.com/intel-lab-lkp/linux/commits/Steven-Rostedt/ring-buffer-Allow-mapped-field-to-be-set-without-mapping/20240306-100047 base: next-20240305 patch link: https://lore.kernel.org/r/20240306020006.586558735%40goodmis.org patch subject: [PATCH 8/8] ring-buffer: Validate boot range memory events config: microblaze-allmodconfig (https://download.01.org/0day-ci/archive/20240308/202403082327.SiOUrqxy-lkp@intel.com/config) compiler: microblaze-linux-gcc (GCC) 13.2.0 reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240308/202403082327.SiOUrqxy-lkp@intel.com/reproduce) If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags | Reported-by: kernel test robot <lkp@intel.com> | Closes: https://lore.kernel.org/oe-kbuild-all/202403082327.SiOUrqxy-lkp@intel.com/ All error/warnings (new ones prefixed by >>): kernel/trace/ring_buffer.c: In function 'rb_read_data_buffer': >> kernel/trace/ring_buffer.c:1629:29: error: 'cpu_buffer' undeclared (first use in this function) 1629 | atomic_inc(&cpu_buffer->record_disabled); \ | ^~~~~~~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c:1629:29: note: each undeclared identifier is reported only once for each function it appears in 1629 | atomic_inc(&cpu_buffer->record_disabled); \ | ^~~~~~~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:1631:17: error: implicit declaration of function 'dump_buffer_page'; did you mean 'free_buffer_page'? [-Werror=implicit-function-declaration] 1631 | dump_buffer_page(bpage, info, tail); \ | ^~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:1631:34: error: 'bpage' undeclared (first use in this function); did you mean 'dpage'? 1631 | dump_buffer_page(bpage, info, tail); \ | ^~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:1631:41: error: 'info' undeclared (first use in this function) 1631 | dump_buffer_page(bpage, info, tail); \ | ^~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:1636:25: warning: 'return' with no value, in function returning non-void [-Wreturn-type] 1636 | return; \ | ^~~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c:1642:12: note: declared here 1642 | static int rb_read_data_buffer(struct buffer_data_page *dpage, int tail, int cpu, | ^~~~~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:1667:33: error: label 'out' used but not defined 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c: In function 'rb_set_commit_to_write': kernel/trace/ring_buffer.c:3588:45: warning: assignment to 'long unsigned int' from 'struct buffer_data_page *' makes integer from pointer without a cast [-Wint-conversion] 3588 | meta->commit_buffer = cpu_buffer->commit_page->page; | ^ kernel/trace/ring_buffer.c: At top level: >> kernel/trace/ring_buffer.c:3957:13: warning: conflicting types for 'dump_buffer_page'; have 'void(struct buffer_data_page *, struct rb_event_info *, long unsigned int)' 3957 | static void dump_buffer_page(struct buffer_data_page *bpage, | ^~~~~~~~~~~~~~~~ >> kernel/trace/ring_buffer.c:3957:13: error: static declaration of 'dump_buffer_page' follows non-static declaration kernel/trace/ring_buffer.c:1631:17: note: previous implicit declaration of 'dump_buffer_page' with type 'void(struct buffer_data_page *, struct rb_event_info *, long unsigned int)' 1631 | dump_buffer_page(bpage, info, tail); \ | ^~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c:1667:33: note: in expansion of macro 'buffer_warn_return' 1667 | buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", | ^~~~~~~~~~~~~~~~~~ kernel/trace/ring_buffer.c: In function 'check_buffer': >> kernel/trace/ring_buffer.c:4046:9: error: 'ret' undeclared (first use in this function); did you mean 'net'? 4046 | ret = rb_read_data_buffer(bpage, tail, &ts, cpu_buffer->cpu, true); | ^~~ | net >> kernel/trace/ring_buffer.c:4046:48: warning: passing argument 3 of 'rb_read_data_buffer' makes integer from pointer without a cast [-Wint-conversion] 4046 | ret = rb_read_data_buffer(bpage, tail, &ts, cpu_buffer->cpu, true); | ^~~ | | | u64 * {aka long long unsigned int *} kernel/trace/ring_buffer.c:1642:78: note: expected 'int' but argument is of type 'u64 *' {aka 'long long unsigned int *'} 1642 | static int rb_read_data_buffer(struct buffer_data_page *dpage, int tail, int cpu, | ~~~~^~~ >> kernel/trace/ring_buffer.c:4046:63: warning: passing argument 4 of 'rb_read_data_buffer' makes pointer from integer without a cast [-Wint-conversion] 4046 | ret = rb_read_data_buffer(bpage, tail, &ts, cpu_buffer->cpu, true); | ~~~~~~~~~~^~~~~ | | | int kernel/trace/ring_buffer.c:1643:52: note: expected 'long long unsigned int *' but argument is of type 'int' 1643 | unsigned long long *timestamp, bool warn) | ~~~~~~~~~~~~~~~~~~~~^~~~~~~~~ >> kernel/trace/ring_buffer.c:4020:13: warning: unused variable 'e' [-Wunused-variable] 4020 | int e; | ^ >> kernel/trace/ring_buffer.c:4018:17: warning: unused variable 'delta' [-Wunused-variable] 4018 | u64 ts, delta; | ^~~~~ >> kernel/trace/ring_buffer.c:4016:35: warning: unused variable 'event' [-Wunused-variable] 4016 | struct ring_buffer_event *event; | ^~~~~ cc1: some warnings being treated as errors vim +/cpu_buffer +1629 kernel/trace/ring_buffer.c 1621 1622 #define buffer_warn_return(fmt, ...) \ 1623 do { \ 1624 /* If another report is happening, ignore this one */ \ 1625 if (atomic_inc_return(&ts_dump) != 1) { \ 1626 atomic_dec(&ts_dump); \ 1627 goto out; \ 1628 } \ > 1629 atomic_inc(&cpu_buffer->record_disabled); \ 1630 pr_warn(fmt, ##__VA_ARGS__); \ > 1631 dump_buffer_page(bpage, info, tail); \ 1632 atomic_dec(&ts_dump); \ 1633 /* There's some cases in boot up that this can happen */ \ 1634 if (WARN_ON_ONCE(system_state != SYSTEM_BOOTING)) \ 1635 /* Do not re-enable checking */ \ > 1636 return; \ 1637 } while (0) 1638 #else 1639 #define buffer_warn_return(fmt, ...) do { } while (0) 1640 #endif 1641 1642 static int rb_read_data_buffer(struct buffer_data_page *dpage, int tail, int cpu, > 1643 unsigned long long *timestamp, bool warn) 1644 { 1645 struct ring_buffer_event *event; 1646 u64 ts, delta; 1647 int events = 0; 1648 int e; 1649 1650 ts = dpage->time_stamp; 1651 1652 for (e = 0; e < tail; e += rb_event_length(event)) { 1653 1654 event = (struct ring_buffer_event *)(dpage->data + e); 1655 1656 switch (event->type_len) { 1657 1658 case RINGBUF_TYPE_TIME_EXTEND: 1659 delta = rb_event_time_stamp(event); 1660 ts += delta; 1661 break; 1662 1663 case RINGBUF_TYPE_TIME_STAMP: 1664 delta = rb_event_time_stamp(event); 1665 delta = rb_fix_abs_ts(delta, ts); 1666 if (warn && delta < ts) { > 1667 buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", 1668 cpu, ts, delta); 1669 } 1670 ts = delta; 1671 break; 1672 1673 case RINGBUF_TYPE_PADDING: 1674 if (event->time_delta == 1) 1675 break; 1676 fallthrough; 1677 case RINGBUF_TYPE_DATA: 1678 events++; 1679 ts += event->time_delta; 1680 break; 1681 1682 default: 1683 return -1; 1684 } 1685 } 1686 *timestamp = ts; 1687 return events; 1688 } 1689
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index e74185a4d864..f7b511935fcf 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -1610,10 +1610,171 @@ static bool rb_meta_valid(struct ring_buffer_meta *meta, int cpu, subbuf = (void *)subbuf + subbuf_size; } - pr_info("Ring buffer meta is from previous boot!\n"); return true; } +static int rb_meta_subbuf_idx(struct ring_buffer_meta *meta, void *subbuf); + +#ifdef CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS +static DEFINE_PER_CPU(atomic_t, checking); +static atomic_t ts_dump; + +#define buffer_warn_return(fmt, ...) \ + do { \ + /* If another report is happening, ignore this one */ \ + if (atomic_inc_return(&ts_dump) != 1) { \ + atomic_dec(&ts_dump); \ + goto out; \ + } \ + atomic_inc(&cpu_buffer->record_disabled); \ + pr_warn(fmt, ##__VA_ARGS__); \ + dump_buffer_page(bpage, info, tail); \ + atomic_dec(&ts_dump); \ + /* There's some cases in boot up that this can happen */ \ + if (WARN_ON_ONCE(system_state != SYSTEM_BOOTING)) \ + /* Do not re-enable checking */ \ + return; \ + } while (0) +#else +#define buffer_warn_return(fmt, ...) do { } while (0) +#endif + +static int rb_read_data_buffer(struct buffer_data_page *dpage, int tail, int cpu, + unsigned long long *timestamp, bool warn) +{ + struct ring_buffer_event *event; + u64 ts, delta; + int events = 0; + int e; + + ts = dpage->time_stamp; + + for (e = 0; e < tail; e += rb_event_length(event)) { + + event = (struct ring_buffer_event *)(dpage->data + e); + + switch (event->type_len) { + + case RINGBUF_TYPE_TIME_EXTEND: + delta = rb_event_time_stamp(event); + ts += delta; + break; + + case RINGBUF_TYPE_TIME_STAMP: + delta = rb_event_time_stamp(event); + delta = rb_fix_abs_ts(delta, ts); + if (warn && delta < ts) { + buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", + cpu, ts, delta); + } + ts = delta; + break; + + case RINGBUF_TYPE_PADDING: + if (event->time_delta == 1) + break; + fallthrough; + case RINGBUF_TYPE_DATA: + events++; + ts += event->time_delta; + break; + + default: + return -1; + } + } + *timestamp = ts; + return events; +} + +static int rb_validate_buffer(struct buffer_data_page *dpage, int cpu) +{ + unsigned long long ts; + int tail; + + tail = local_read(&dpage->commit); + return rb_read_data_buffer(dpage, tail, cpu, &ts, false); +} + +/* If the meta data has been validated, now validate the events */ +static void rb_meta_validate_events(struct ring_buffer_per_cpu *cpu_buffer) +{ + struct ring_buffer_meta *meta = cpu_buffer->ring_meta; + struct buffer_page *head_page; + unsigned long entry_bytes = 0; + unsigned long entries = 0; + int ret; + int i; + + if (!meta || !meta->head_buffer) + return; + + /* Do the reader page first */ + ret = rb_validate_buffer(cpu_buffer->reader_page->page, cpu_buffer->cpu); + if (ret < 0) { + printk("INVALID READER PAGE\n"); + goto invalid; + } + entries += ret; + entry_bytes += local_read(&cpu_buffer->reader_page->page->commit); + local_set(&cpu_buffer->reader_page->entries, ret); + + head_page = cpu_buffer->head_page; + + /* If both the head and commit are on the reader_page then we are done. */ + if (head_page == cpu_buffer->reader_page && + head_page == cpu_buffer->commit_page) + goto done; + + /* Iterate until finding the commit page */ + for (i = 0; i < meta->nr_subbufs + 1; i++, rb_inc_page(&head_page)) { + + /* Reader page has already been done */ + if (head_page == cpu_buffer->reader_page) + continue; + + ret = rb_validate_buffer(head_page->page, cpu_buffer->cpu); + if (ret < 0) { + pr_info("Ring buffer meta [%d] invalid buffer page\n", + cpu_buffer->cpu); + goto invalid; + } + entries += ret; + entry_bytes += local_read(&head_page->page->commit); + local_set(&cpu_buffer->head_page->entries, ret); + + if (head_page == cpu_buffer->commit_page) + break; + } + + if (head_page != cpu_buffer->commit_page) { + pr_info("Ring buffer meta [%d] commit page not found\n", + cpu_buffer->cpu); + goto invalid; + } + done: + local_set(&cpu_buffer->entries, entries); + local_set(&cpu_buffer->entries_bytes, entry_bytes); + + pr_info("Ring buffer meta [%d] is from previous boot!\n", cpu_buffer->cpu); + return; + + invalid: + /* The content of the buffers are invalid, reset the meta data */ + meta->head_buffer = 0; + meta->commit_buffer = 0; + + /* Reset the reader page */ + local_set(&cpu_buffer->reader_page->entries, 0); + local_set(&cpu_buffer->reader_page->page->commit, 0); + + /* Reset all the subbuffers */ + for (i = 0; i < meta->nr_subbufs - 1; i++, rb_inc_page(&head_page)) { + local_set(&head_page->entries, 0); + local_set(&head_page->page->commit, 0); + } +} + static void rb_range_meta_init(struct trace_buffer *buffer, int nr_pages) { struct ring_buffer_meta *meta; @@ -1691,8 +1852,6 @@ static void *rbm_next(struct seq_file *m, void *v, loff_t *pos) return rbm_start(m, pos); } -static int rb_meta_subbuf_idx(struct ring_buffer_meta *meta, void *subbuf); - static int rbm_show(struct seq_file *m, void *v) { struct ring_buffer_per_cpu *cpu_buffer = m->private; @@ -1940,6 +2099,8 @@ rb_allocate_cpu_buffer(struct trace_buffer *buffer, long nr_pages, int cpu) if (ret < 0) goto fail_free_reader; + rb_meta_validate_events(cpu_buffer); + /* If the boot meta was valid then this has already been updated */ meta = cpu_buffer->ring_meta; if (!meta || !meta->head_buffer || @@ -3844,26 +4005,6 @@ static void dump_buffer_page(struct buffer_data_page *bpage, pr_warn("expected end:0x%lx last event actually ended at:0x%x\n", tail, e); } -static DEFINE_PER_CPU(atomic_t, checking); -static atomic_t ts_dump; - -#define buffer_warn_return(fmt, ...) \ - do { \ - /* If another report is happening, ignore this one */ \ - if (atomic_inc_return(&ts_dump) != 1) { \ - atomic_dec(&ts_dump); \ - goto out; \ - } \ - atomic_inc(&cpu_buffer->record_disabled); \ - pr_warn(fmt, ##__VA_ARGS__); \ - dump_buffer_page(bpage, info, tail); \ - atomic_dec(&ts_dump); \ - /* There's some cases in boot up that this can happen */ \ - if (WARN_ON_ONCE(system_state != SYSTEM_BOOTING)) \ - /* Do not re-enable checking */ \ - return; \ - } while (0) - /* * Check if the current event time stamp matches the deltas on * the buffer page. @@ -3902,41 +4043,8 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer, if (atomic_inc_return(this_cpu_ptr(&checking)) != 1) goto out; - ts = bpage->time_stamp; - - for (e = 0; e < tail; e += rb_event_length(event)) { - - event = (struct ring_buffer_event *)(bpage->data + e); - - switch (event->type_len) { - - case RINGBUF_TYPE_TIME_EXTEND: - delta = rb_event_time_stamp(event); - ts += delta; - break; - - case RINGBUF_TYPE_TIME_STAMP: - delta = rb_event_time_stamp(event); - delta = rb_fix_abs_ts(delta, ts); - if (delta < ts) { - buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", - cpu_buffer->cpu, ts, delta); - } - ts = delta; - break; + ret = rb_read_data_buffer(bpage, tail, &ts, cpu_buffer->cpu, true); - case RINGBUF_TYPE_PADDING: - if (event->time_delta == 1) - break; - fallthrough; - case RINGBUF_TYPE_DATA: - ts += event->time_delta; - break; - - default: - RB_WARN_ON(cpu_buffer, 1); - } - } if ((full && ts > info->ts) || (!full && ts + info->delta != info->ts)) { buffer_warn_return("[CPU: %d]TIME DOES NOT MATCH expected:%lld actual:%lld delta:%lld before:%lld after:%lld%s context:%s\n",