lkml.org 
[lkml]   [2020]   [Jan]   [5]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [RFC PATCH] perf tools: cs-etm: fix endless record after being terminated
Date
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
>>
>
> .
>

#define _GNU_SOURCE

#include <stdlib.h>
#include <stdio.h>
#include <sys/types.h>
#include <sys/sysinfo.h>
#include <unistd.h>
#include <sched.h>
#include <ctype.h>
#include <string.h>
#include <pthread.h>

int num = 0;
int test[65535];

int mess_rw(int data)
{
int i;

while (1) {
for (i = 0; i < (sizeof(test) / sizeof(test[0])); i++) {
if (test[i] != data)
test[i] = data;
}
}
}

void *test_thread(void *arg)
{
int cpu = *(int *)arg;
cpu_set_t mask;

CPU_ZERO(&mask);
CPU_SET(cpu, &mask);
if (!sched_setaffinity(0, sizeof(mask), &mask))
printf("thread %d: running on cpu %d\n", cpu, cpu);
else
printf("thread %d: fail to set CPU affinity\n", cpu);

mess_rw(cpu);

return NULL;
}

int main(int argc, char *argv[])
{
num = sysconf(_SC_NPROCESSORS_CONF);
pthread_t thread[num];
int id[num];
int i;

printf("PID %d on system with %d processor(s)\n", getpid(), num);

for (i = 0; i < num; i++) {
id[i] = i;
pthread_create(&thread[i], NULL, test_thread, (void *)&id[i]);
}

for (i = 0; i < num; i++) {
pthread_join(thread[i], NULL);
}

return 0;
}

\
 
 \ /
  Last update: 2020-01-06 04:00    [W:0.051 / U:3.164 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site