lkml.org 
[lkml]   [2023]   [Apr]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
From
SubjectRe: [PATCH] perf/core: Fix perf_sample_data not properly initialized for different swevents in perf_tp_event()
Date
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.

>
> .
>

\
 
 \ /
  Last update: 2023-04-18 03:36    [W:0.058 / U:1.352 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site