From: "Steven Rostedt (Google)" <[email protected]>
Make sure all the events in each of the sub-buffers that were mapped in a
memory region are valid. This moves the code that walks the buffers for
time-stamp validation out of the CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS
ifdef block and is used to validate the content. Only the ring buffer
event meta data is checked and not the data load.
This also has a second purpose. The buffer_page structure that points to
the data sub-buffers has accounting that keeps track of the number of
events that are on the sub-buffer. This updates that counter as well. That
counter is used in reading the buffer and knowing if the ring buffer is
empty or not.
Signed-off-by: Steven Rostedt (Google) <[email protected]>
---
kernel/trace/ring_buffer.c | 222 +++++++++++++++++++++++++++----------
1 file changed, 165 insertions(+), 57 deletions(-)
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",
--
2.43.0
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/[email protected]/config)
compiler: microblaze-linux-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240308/[email protected]/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 <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
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
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki