diff mbox series

perf/core: Fix perf_sample_data not properly initialized for different swevents in perf_tp_event()

Message ID 20230412095240.181516-1-yangjihong1@huawei.com
State New
Headers
Series perf/core: Fix perf_sample_data not properly initialized for different swevents in perf_tp_event() |

Commit Message

Yang Jihong April 12, 2023, 9:52 a.m. UTC 
  data->sample_flags may be modified in perf_prepare_sample(),
in perf_tp_event(), different swevents use the same on-stack
perf_sample_data, the previous swevent may change sample_flags in
perf_prepare_sample(), as a result, some members of perf_sample_data are
not correctly initialized when next swevent_event preparing sample
(for example data->id, the value varies according to swevent).

A simple scenario triggers this problem is as follows:

  # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209014396 ]
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209014662 ]
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209014910 ]
  [ perf record: Woken up 0 times to write data ]
  [ perf record: Dump perf.data.2023041209015164 ]
  [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
  # ls -l
  total 860
  -rw------- 1 root root  95694 Apr 12 09:01 perf.data.2023041209014396
  -rw------- 1 root root 606430 Apr 12 09:01 perf.data.2023041209014662
  -rw------- 1 root root  82246 Apr 12 09:01 perf.data.2023041209014910
  -rw------- 1 root root  82342 Apr 12 09:01 perf.data.2023041209015164
  # perf script -i perf.data.2023041209014396
  0x11d58 [0x80]: failed to process type: 9 [Bad address]

Solution: Add perf_sample_data_flags_{save, restore} helpers to save and
restore sample_flags when processing different swevents

After fix:

  # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209442259 ]
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209442514 ]
  [ perf record: dump data: Woken up 0 times ]
  [ perf record: Dump perf.data.2023041209442760 ]
  [ perf record: Woken up 0 times to write data ]
  [ perf record: Dump perf.data.2023041209443003 ]
  [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
  # ls -l
  total 864
  -rw------- 1 root root 100166 Apr 12 09:44 perf.data.2023041209442259
  -rw------- 1 root root 606438 Apr 12 09:44 perf.data.2023041209442514
  -rw------- 1 root root  82246 Apr 12 09:44 perf.data.2023041209442760
  -rw------- 1 root root  82342 Apr 12 09:44 perf.data.2023041209443003
  # perf script -i perf.data.2023041209442259 | head -n 5
              perf   232 [000]    66.846217: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=D ==> next_comm=perf next_pid=234 next_prio=120
              perf   234 [000]    66.846449: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
              perf   232 [000]    66.846546: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120
              perf   234 [000]    66.846606: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
              perf   232 [000]    66.846646: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120

Fixes: bb447c27a467 ("perf/core: Set data->sample_flags in perf_prepare_sample()")
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
 include/linux/perf_event.h | 11 +++++++++++
 kernel/events/core.c       | 13 ++++++++++++-
 2 files changed, 23 insertions(+), 1 deletion(-)

Comments

Peter Zijlstra April 17, 2023, 11:45 a.m. UTC | #1 
On Wed, Apr 12, 2023 at 09:52:40AM +0000, Yang Jihong wrote:
> data->sample_flags may be modified in perf_prepare_sample(),
> in perf_tp_event(), different swevents use the same on-stack
> perf_sample_data, the previous swevent may change sample_flags in
> perf_prepare_sample(), as a result, some members of perf_sample_data are
> not correctly initialized when next swevent_event preparing sample
> (for example data->id, the value varies according to swevent).
> 
> A simple scenario triggers this problem is as follows:
> 
>   # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209014396 ]
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209014662 ]
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209014910 ]
>   [ perf record: Woken up 0 times to write data ]
>   [ perf record: Dump perf.data.2023041209015164 ]
>   [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
>   # ls -l
>   total 860
>   -rw------- 1 root root  95694 Apr 12 09:01 perf.data.2023041209014396
>   -rw------- 1 root root 606430 Apr 12 09:01 perf.data.2023041209014662
>   -rw------- 1 root root  82246 Apr 12 09:01 perf.data.2023041209014910
>   -rw------- 1 root root  82342 Apr 12 09:01 perf.data.2023041209015164
>   # perf script -i perf.data.2023041209014396
>   0x11d58 [0x80]: failed to process type: 9 [Bad address]
> 
> Solution: Add perf_sample_data_flags_{save, restore} helpers to save and
> restore sample_flags when processing different swevents
> 
> After fix:
> 
>   # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209442259 ]
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209442514 ]
>   [ perf record: dump data: Woken up 0 times ]
>   [ perf record: Dump perf.data.2023041209442760 ]
>   [ perf record: Woken up 0 times to write data ]
>   [ perf record: Dump perf.data.2023041209443003 ]
>   [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
>   # ls -l
>   total 864
>   -rw------- 1 root root 100166 Apr 12 09:44 perf.data.2023041209442259
>   -rw------- 1 root root 606438 Apr 12 09:44 perf.data.2023041209442514
>   -rw------- 1 root root  82246 Apr 12 09:44 perf.data.2023041209442760
>   -rw------- 1 root root  82342 Apr 12 09:44 perf.data.2023041209443003
>   # perf script -i perf.data.2023041209442259 | head -n 5
>               perf   232 [000]    66.846217: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=D ==> next_comm=perf next_pid=234 next_prio=120
>               perf   234 [000]    66.846449: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
>               perf   232 [000]    66.846546: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120
>               perf   234 [000]    66.846606: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
>               perf   232 [000]    66.846646: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120

This seems a little bit short on analysis; what actual flags are the
problem? Much of the data will in fact be identical between these
invocations and endlessly re-computing that is wasteful.

I'm thinking perhaps those flags that update ->dyn_size are the problem?
At the same time, Should you not also then clear dyn_size?
Yang Jihong April 18, 2023, 1:35 a.m. UTC | #2 
Hello,

On 2023/4/17 19:45, Peter Zijlstra wrote:
> On Wed, Apr 12, 2023 at 09:52:40AM +0000, Yang Jihong wrote:
>> data->sample_flags may be modified in perf_prepare_sample(),
>> in perf_tp_event(), different swevents use the same on-stack
>> perf_sample_data, the previous swevent may change sample_flags in
>> perf_prepare_sample(), as a result, some members of perf_sample_data are
>> not correctly initialized when next swevent_event preparing sample
>> (for example data->id, the value varies according to swevent).
>>
>> A simple scenario triggers this problem is as follows:
>>
>>    # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209014396 ]
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209014662 ]
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209014910 ]
>>    [ perf record: Woken up 0 times to write data ]
>>    [ perf record: Dump perf.data.2023041209015164 ]
>>    [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
>>    # ls -l
>>    total 860
>>    -rw------- 1 root root  95694 Apr 12 09:01 perf.data.2023041209014396
>>    -rw------- 1 root root 606430 Apr 12 09:01 perf.data.2023041209014662
>>    -rw------- 1 root root  82246 Apr 12 09:01 perf.data.2023041209014910
>>    -rw------- 1 root root  82342 Apr 12 09:01 perf.data.2023041209015164
>>    # perf script -i perf.data.2023041209014396
>>    0x11d58 [0x80]: failed to process type: 9 [Bad address]
>>
>> Solution: Add perf_sample_data_flags_{save, restore} helpers to save and
>> restore sample_flags when processing different swevents
>>
>> After fix:
>>
>>    # perf record -e sched:sched_switch --switch-output-event sched:sched_switch -a sleep 1
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209442259 ]
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209442514 ]
>>    [ perf record: dump data: Woken up 0 times ]
>>    [ perf record: Dump perf.data.2023041209442760 ]
>>    [ perf record: Woken up 0 times to write data ]
>>    [ perf record: Dump perf.data.2023041209443003 ]
>>    [ perf record: Captured and wrote 0.069 MB perf.data.<timestamp> ]
>>    # ls -l
>>    total 864
>>    -rw------- 1 root root 100166 Apr 12 09:44 perf.data.2023041209442259
>>    -rw------- 1 root root 606438 Apr 12 09:44 perf.data.2023041209442514
>>    -rw------- 1 root root  82246 Apr 12 09:44 perf.data.2023041209442760
>>    -rw------- 1 root root  82342 Apr 12 09:44 perf.data.2023041209443003
>>    # perf script -i perf.data.2023041209442259 | head -n 5
>>                perf   232 [000]    66.846217: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=D ==> next_comm=perf next_pid=234 next_prio=120
>>                perf   234 [000]    66.846449: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
>>                perf   232 [000]    66.846546: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120
>>                perf   234 [000]    66.846606: sched:sched_switch: prev_comm=perf prev_pid=234 prev_prio=120 prev_state=S ==> next_comm=perf next_pid=232 next_prio=120
>>                perf   232 [000]    66.846646: sched:sched_switch: prev_comm=perf prev_pid=232 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=234 next_prio=120
> 
> This seems a little bit short on analysis; what actual flags are the
> problem? Much of the data will in fact be identical between these
> invocations and endlessly re-computing that is wasteful.
> 
In the preceding example, data->id is incorrectly initialized,
that is, PERF_SAMPLE_ID | PERF_SAMPLE_IDENTIFIER
The detailed process is as follows:
1. In the example of perf record, create two swevents evt1 and evt2,
and attach to sched:sched_switch, assume that the IDs are 10 and 11
2. In perf_tp_event():
struct perf_sample_data data // on-stack value
hlist_for_each_entry_rcu
  -> perf_swevent_event(evt1, &data)
   -> perf_swevent_overflow(evt1, &data)
    -> ...
     -> perf_prepare_sample(evt1, &data)
      -> __perf_event_header__init_id(evt1, &data)
       -> data->sample_flags |= data->type & PERF_SAMPLE_ID_ALL
          // data->sample_flags set PERF_SAMPLE_ID | PERF_SAMPLE_IDENTIFIER
       -> if (sample_type & (PERF_SAMPLE_ID | PERF_SAMPLE_IDENTIFIER))
                   data->id = primary_event_id(event);
          // for evt1, the if condition is met,
          // and data->id can be correctly initialized.
...
  -> perf_swevent_event(evt2, &data)
   -> perf_swevent_overflow(evt2, &data)
    -> ...
     -> perf_prepare_sample(evt2, &data)
      -> __perf_event_header__init_id(evt2, &data)
       -> if (sample_type & (PERF_SAMPLE_ID | PERF_SAMPLE_IDENTIFIER))
                   data->id = primary_event_id(event);
          // data->sample_flags set PERF_SAMPLE_ID | 
PERF_SAMPLE_IDENTIFIER in evt1,
          // therefore, the condition is not met for evt2.
          // As a result, the ID of evt2 is not assigned to data-id.

> I'm thinking perhaps those flags that update ->dyn_size are the problem?
> At the same time, Should you not also then clear dyn_size?
Yes, according to the code, dyn_size should also be cleared.
Maybe we need to change it to the following, which would be more 
appropriate?

--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -10144,14 +10144,14 @@ void perf_tp_event(u16 event_type, u64 count, 
void *record, int entry_size,
                 },
         };

-       perf_sample_data_init(&data, 0, 0);
-       perf_sample_save_raw_data(&data, &raw);
-
         perf_trace_buf_update(record, event_type);

         hlist_for_each_entry_rcu(event, head, hlist_entry) {
-               if (perf_tp_event_match(event, &data, regs))
+               if (perf_tp_event_match(event, &data, regs)) {
+                       perf_sample_data_init(&data, 0, 0);
+                       perf_sample_save_raw_data(&data, &raw);
                         perf_swevent_event(event, count, &data, regs);
+               }
         }

Thanks,
Yang.


> 
> .
>
Peter Zijlstra April 18, 2023, 10:25 a.m. UTC | #3 
On Tue, Apr 18, 2023 at 09:35:23AM +0800, Yang Jihong wrote:

> > I'm thinking perhaps those flags that update ->dyn_size are the problem?
> > At the same time, Should you not also then clear dyn_size?

> Yes, according to the code, dyn_size should also be cleared.
> Maybe we need to change it to the following, which would be more
> appropriate?
> 
> --- a/kernel/events/core.c
> +++ b/kernel/events/core.c
> @@ -10144,14 +10144,14 @@ void perf_tp_event(u16 event_type, u64 count, void
> *record, int entry_size,
>                 },
>         };
> 
> -       perf_sample_data_init(&data, 0, 0);
> -       perf_sample_save_raw_data(&data, &raw);
> -
>         perf_trace_buf_update(record, event_type);
> 
>         hlist_for_each_entry_rcu(event, head, hlist_entry) {
> -               if (perf_tp_event_match(event, &data, regs))
> +               if (perf_tp_event_match(event, &data, regs)) {
> +                       perf_sample_data_init(&data, 0, 0);
> +                       perf_sample_save_raw_data(&data, &raw);
>                         perf_swevent_event(event, count, &data, regs);
> +               }
>         }

That is certainly the safe option. I just went through the list and
while there's certainly a number of options we'll recompute for naught,
most of them are indeed either dyn_size or event specific :/

So yeah, please send the above as v2.
Yang Jihong April 19, 2023, 1:47 a.m. UTC | #4 
Hello,

On 2023/4/18 18:25, Peter Zijlstra wrote:
> On Tue, Apr 18, 2023 at 09:35:23AM +0800, Yang Jihong wrote:
> 
>>> I'm thinking perhaps those flags that update ->dyn_size are the problem?
>>> At the same time, Should you not also then clear dyn_size?
> 
>> Yes, according to the code, dyn_size should also be cleared.
>> Maybe we need to change it to the following, which would be more
>> appropriate?
>>
>> --- a/kernel/events/core.c
>> +++ b/kernel/events/core.c
>> @@ -10144,14 +10144,14 @@ void perf_tp_event(u16 event_type, u64 count, void
>> *record, int entry_size,
>>                  },
>>          };
>>
>> -       perf_sample_data_init(&data, 0, 0);
>> -       perf_sample_save_raw_data(&data, &raw);
>> -
>>          perf_trace_buf_update(record, event_type);
>>
>>          hlist_for_each_entry_rcu(event, head, hlist_entry) {
>> -               if (perf_tp_event_match(event, &data, regs))
>> +               if (perf_tp_event_match(event, &data, regs)) {
>> +                       perf_sample_data_init(&data, 0, 0);
>> +                       perf_sample_save_raw_data(&data, &raw);
>>                          perf_swevent_event(event, count, &data, regs);
>> +               }
>>          }
> 
> That is certainly the safe option. I just went through the list and
> while there's certainly a number of options we'll recompute for naught,
> most of them are indeed either dyn_size or event specific :/
> 
> So yeah, please send the above as v2.
> 
OK, will send v2 according to above fix solution.

Thanks,
Yang.
diff mbox series

Patch

diff --git a/include/linux/perf_event.h b/include/linux/perf_event.h
index d5628a7b5eaa..7499bd3a2ed5 100644
--- a/include/linux/perf_event.h
+++ b/include/linux/perf_event.h
@@ -1185,6 +1185,17 @@  struct perf_sample_data {
 		    PERF_MEM_S(LOCK, NA)  |\
 		    PERF_MEM_S(TLB, NA))
 
+/* Note: caller must ensure flags is not NULL */
+static inline void perf_sample_data_flags_save(struct perf_sample_data *data, u64 *flags)
+{
+	*flags = data->sample_flags;
+}
+
+static inline void perf_sample_data_flags_restore(struct perf_sample_data *data, u64 flags)
+{
+	data->sample_flags = flags;
+}
+
 static inline void perf_sample_data_init(struct perf_sample_data *data,
 					 u64 addr, u64 period)
 {
diff --git a/kernel/events/core.c b/kernel/events/core.c
index 435815d3be3f..ea1fb63a6037 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -10136,6 +10136,7 @@  void perf_tp_event(u16 event_type, u64 count, void *record, int entry_size,
 {
 	struct perf_sample_data data;
 	struct perf_event *event;
+	u64 sample_flags;
 
 	struct perf_raw_record raw = {
 		.frag = {
@@ -10150,8 +10151,18 @@  void perf_tp_event(u16 event_type, u64 count, void *record, int entry_size,
 	perf_trace_buf_update(record, event_type);
 
 	hlist_for_each_entry_rcu(event, head, hlist_entry) {
-		if (perf_tp_event_match(event, &data, regs))
+		if (perf_tp_event_match(event, &data, regs)) {
+			/*
+			 * sample_flags may be modified in perf_event_output_*
+			 * (see perf_prepare_sample). For different swevents,
+			 * use the same on-stack perf_sample_data, therefore,
+			 * need to save samle_flags, and restore it
+			 * after perf_swevent_event.
+			 */
+			perf_sample_data_flags_save(&data, &sample_flags);
 			perf_swevent_event(event, count, &data, regs);
+			perf_sample_data_flags_restore(&data, sample_flags);
+		}
 	}
 
 	/*