linux-kernel - Re: [RFC PATCH] perf tools: cs-etm: fix endless record after being terminated

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <acc0afd9-5d0e-dcb8-d56a-ac5680049c8c@huawei.com>
Date:   Mon, 6 Jan 2020 11:00:19 +0800
From:   "liwei (GF)" <liwei391@...wei.com>
To:     Leo Yan <leo.yan@...aro.org>
CC:     <acme@...nel.org>, <mark.rutland@....com>,
        <alexander.shishkin@...ux.intel.com>, <jolsa@...hat.com>,
        <namhyung@...nel.org>, <suzuki.poulose@....com>,
        <mathieu.poirier@...aro.org>, <ilubashe@...mai.com>,
        <peterz@...radead.org>, <mingo@...hat.com>,
        <linux-arm-kernel@...ts.infradead.org>,
        <linux-kernel@...r.kernel.org>, <huawei.libin@...wei.com>
Subject: Re: [RFC PATCH] perf tools: cs-etm: fix endless record after being
 terminated

Hi Leo,

Thanks for your test and sorry for missing the reproducing info.
The attachment is my test procedure, i can reproduce this issue
with it on kernel 5.5-rc4 definitely.

I have tested these patches on kernel 5.5-rc4, with intel-pt on Xeon
Gold 6140 (72 cores) and arm-spe on HiSilicon Hi1620 (128 cores).
But i can not test CoreSight temporarily, could you please test it
with the test procedure again?

P.s. Running the test procedure as a normal process is enough.

Thanks，
Wei

On 2020/1/3 16:24, Leo Yan wrote:

> 
> 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
>>
> 
> .
> 


View attachment "perf_endless_record.c" of type "text/plain" (1216 bytes)