lkml.org 
[lkml]   [2020]   [Jan]   [3]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [RFC PATCH] perf tools: cs-etm: fix endless record after being terminated
Hi Wei,

On Thu, Jan 02, 2020 at 03:41:44PM +0800, Wei Li wrote:
> In __cmd_record(), when receiving SIGINT(ctrl + c), a done flag will
> be set and the event list will be disabled by evlist__disable() once.
>
> While in auxtrace_record.read_finish(), the related events will be
> enabled again, if they are continuous, the recording seems to be endless.
>
> If the cs_etm event is disabled, we don't enable it again here.
>
> Note: This patch is NOT tested since i don't have such a machine with
> coresight feature, but the code seems buggy same as arm-spe and intel-pt.
>
> Signed-off-by: Wei Li <liwei391@huawei.com>
> ---
> tools/perf/arch/arm/util/cs-etm.c | 10 +++++++---
> 1 file changed, 7 insertions(+), 3 deletions(-)
>
> diff --git a/tools/perf/arch/arm/util/cs-etm.c b/tools/perf/arch/arm/util/cs-etm.c
> index ede040cf82ad..1893a0e3b1e1 100644
> --- a/tools/perf/arch/arm/util/cs-etm.c
> +++ b/tools/perf/arch/arm/util/cs-etm.c
> @@ -865,9 +865,13 @@ static int cs_etm_read_finish(struct auxtrace_record *itr, int idx)
> struct evsel *evsel;
>
> evlist__for_each_entry(ptr->evlist, evsel) {
> - if (evsel->core.attr.type == ptr->cs_etm_pmu->type)
> - return perf_evlist__enable_event_idx(ptr->evlist,
> - evsel, idx);
> + if (evsel->core.attr.type == ptr->cs_etm_pmu->type) {
> + if (evsel->disabled)
> + return 0;
> + else
> + return perf_evlist__enable_event_idx(
> + ptr->evlist, evsel, idx);
> + }
> }

I took some time to test on Arm CoreSight, the perf program can be
terminated by Ctrl+c with SIGINT signal on the mainline kernel.

And after capturing ftrace data with below log:

5242 migration/2-19 [002] d..3 4648.383155: sched_migrate_task: comm=perf pid=1692 prio=120 orig_cpu=2 dest_cpu=0
5243 migration/2-19 [002] d..2 4648.383167: sched_switch: prev_comm=migration/2 prev_pid=19 prev_prio=0 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
5244 <idle>-0 [000] d..2 4648.383167: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=1692 next_prio=120
5245 perf-1692 [000] d..2 4648.383193: sched_stat_runtime: comm=perf pid=1692 runtime=35420 [ns] vruntime=1636633943 [ns]
5246 perf-1692 [000] d..3 4648.383200: sched_waking: comm=migration/0 pid=11 prio=0 target_cpu=000
5247 perf-1692 [000] dN.4 4648.383203: sched_wakeup: comm=migration/0 pid=11 prio=0 target_cpu=000
5248 perf-1692 [000] dN.2 4648.383205: sched_stat_runtime: comm=perf pid=1692 runtime=9340 [ns] vruntime=1636643283 [ns]
5249 perf-1692 [000] d..2 4648.383208: sched_switch: prev_comm=perf prev_pid=1692 prev_prio=120 prev_state=R+ ==> next_comm=migration/0 next_pid=11 next_prio=0
5250 migration/0-11 [000] d..3 4648.383215: sched_migrate_task: comm=perf pid=1692 prio=120 orig_cpu=0 dest_cpu=1
5251 algorithm1-721 [001] dN.2 4648.383225: sched_stat_runtime: comm=algorithm1 pid=721 runtime=2906000 [ns] vruntime=3501282256244 [ns]
5252 algorithm1-721 [001] d..2 4648.383229: sched_switch: prev_comm=algorithm1 prev_pid=721 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=1692 next_prio=120
5253 migration/0-11 [000] d..2 4648.383235: sched_switch: prev_comm=migration/0 prev_pid=11 prev_prio=0 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
5254 algorithm1-721 [001] d..4 4648.383241: <stack trace>
5255 => kprobe_breakpoint_handler
5256 => call_break_hook
5257 => brk_handler
5258 => do_debug_exception
5259 => el1_sync_handler
5260 => el1_sync
5261 => etm_event_stop
5262 => event_sched_out.isra.106
5263 => group_sched_out.part.108
5264 => ctx_sched_out
5265 => task_ctx_sched_out
5266 => __perf_event_task_sched_out
5267 => __schedule
5268 => schedule
5269 => do_notify_resume
5270 => work_pending

We can see after send SIGINT signal, the process 'perf' will be
migrated from CPU2 to CPU0 (line 5242) and it will preempt process
'algorithm1' (line 5252); after the process 'algorithm1' is scheduled
out, the function etm_event_stop() will be invoked to stop tracing.

If we connect with the code in cs_etm_read_finish(), it tries to call
ioctl PERF_EVENT_IOC_ENABLE, but because the process 'algorithm1' is
scheduled out, so the perf event should not be enabled afterwards.

I may miss something at here ... Could you confirm what's the type of
attached process? normal process or RT process?

Thanks,
Leo

P.s. I tested IntelPT with 5.2-rc3 kernel, it also can be terminated
properly.

> return -EINVAL;
> --
> 2.17.1
>

\
 
 \ /
  Last update: 2020-01-03 09:25    [W:0.054 / U:3.204 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site