From gcc 6.2 and onward, the compiler complains about
‘cs_etm_global_header_fmts’ not being used (and rightly so).
One solution is to remove the declaration but it is a matter of time before we need to modify the header. Another solution is to simply print the information conveyed by the header.
There is a few advantages that comes with the latter:
1) We know how many CPUs are part of the session, without having to count the number of magic numbers.
2) We get to see if the snapshot option was specified.
3) When we change the header we know exactly what kind of header we are dealing with.
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org --- tools/perf/util/cs-etm.c | 3 +++ 1 file changed, 3 insertions(+)
diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c index 0adb8e4aff2f..82702039ab2e 100644 --- a/tools/perf/util/cs-etm.c +++ b/tools/perf/util/cs-etm.c @@ -1494,6 +1494,9 @@ static void cs_etm__print_auxtrace_info(u64 *val, size_t num) { unsigned i,j,cpu;
+ for (i = 0; i < CS_HEADER_VERSION_0_MAX; i++) + fprintf(stdout, cs_etm_global_header_fmts[i], val[i]); + for (i = CS_HEADER_VERSION_0_MAX, cpu = 0; cpu < num; ++cpu) {
if (val[i] == __perf_cs_etmv3_magic) {
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC | head -1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm// uname failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017 aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc version 4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at ../kernel/workqueue.c:1442 __queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted 4.11.0-rc1-g8e9e2e2 #4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>] pstate: a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0: ffff80097feac100 0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4 ffff80097612f930 ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000 ffff80097612fa20 ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780 0000000000000001 0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020 0000000000000000 00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00 ffff80097152ad88 0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000 ffff80097152ab80 0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000 0000000000000000 626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b ffff0000080894e0 0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
--- The Coresight PMUs can be configured to work in "full trace" or "snapshot" mode. In full trace mode trace acquisition is enabled from beginning to end with trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000 ---
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4 /home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/coresight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether that means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {
So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ] <hang>
Thanks,
Kim
I can confirm this applies and runs OK on my juno-r1 system - linaro gcc6.2 built perf and kernel. (with no hard hang) I am also seeing the additional printout when I do perf report --dump on the collected data. I can also confirm the issue Kim sees when using the 'sudo ./perf record -e cs_etm// uname ' command line.
Mike
On 16 March 2017 at 22:33, Kim Phillips kim.phillips@arm.com wrote:
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC | head -1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm// uname failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017 aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc version 4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at ../kernel/workqueue.c:1442 __queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted 4.11.0-rc1-g8e9e2e2 #4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>] pstate: a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0: ffff80097feac100 0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4 ffff80097612f930 ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000 ffff80097612fa20 ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780 0000000000000001 0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020 0000000000000000 00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00 ffff80097152ad88 0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000 ffff80097152ab80 0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000 0000000000000000 626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b ffff0000080894e0 0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
The Coresight PMUs can be configured to work in "full trace" or "snapshot" mode. In full trace mode trace acquisition is enabled from beginning to end with trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4 /home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/ coresight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether that means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ]
<hang>
Thanks,
Kim _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
On 17 March 2017 at 05:57, Mike Leach mike.leach@linaro.org wrote:
I can confirm this applies and runs OK on my juno-r1 system - linaro gcc6.2 built perf and kernel. (with no hard hang) I am also seeing the additional printout when I do perf report --dump on the collected data.
Perfect - thanks for the confirmation. I'll push to gitHub.
I can also confirm the issue Kim sees when using the 'sudo ./perf record -e cs_etm// uname ' command line.
A sink needs to be specified within the //. Otherwise perf doesn't know what sink to use.
Mike
On 16 March 2017 at 22:33, Kim Phillips kim.phillips@arm.com wrote:
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC | head -1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm// uname failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017 aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc version 4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at ../kernel/workqueue.c:1442 __queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted 4.11.0-rc1-g8e9e2e2 #4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>] pstate: a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0: ffff80097feac100 0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4 ffff80097612f930 ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000 ffff80097612fa20 ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780 0000000000000001 0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020 0000000000000000 00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00 ffff80097152ad88 0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000 ffff80097152ab80 0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000 0000000000000000 626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b ffff0000080894e0 0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
The Coresight PMUs can be configured to work in "full trace" or "snapshot" mode. In full trace mode trace acquisition is enabled from beginning to end with trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4
/home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/coresight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether that means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ]
<hang>
Thanks,
Kim _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
On 17 March 2017 at 14:28, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 17 March 2017 at 05:57, Mike Leach mike.leach@linaro.org wrote:
I can confirm this applies and runs OK on my juno-r1 system - linaro
gcc6.2
built perf and kernel. (with no hard hang) I am also seeing the additional printout when I do perf report --dump on
the
collected data.
Perfect - thanks for the confirmation. I'll push to gitHub.
I can also confirm the issue Kim sees when using the 'sudo ./perf record
-e
cs_etm// uname ' command line.
A sink needs to be specified within the //. Otherwise perf doesn't know what sink to use.
Agreed. A re-test shows that if a sink is enabled using sysfs before 'sudo ./perf record -e cs_etm// uname' , then data is captured and no crash occurs. This matches what the coresight.txt documentation states, though re-enabling this way is required before each run - a patch to the docs has been submitted to make this clear - along with the option of defining the sink in the perf command line.
Without pre-enabling, missing the sink between cs_etm// causes the crash. Ideally, bad input should result in an error message. Something worth looking at in future?
Mike
Mike
On 16 March 2017 at 22:33, Kim Phillips kim.phillips@arm.com wrote:
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC |
head
-1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm//
uname
failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT
2017
aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc
version
4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT
Thu
Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at ../kernel/workqueue.c:1442 __queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted
4.11.0-rc1-g8e9e2e2
#4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>]
pstate:
a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0: ffff80097feac100 0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4 ffff80097612f930 ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000 ffff80097612fa20 ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780 0000000000000001 0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020 0000000000000000 00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00 ffff80097152ad88 0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000 ffff80097152ab80 0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000 0000000000000000 626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b ffff0000080894e0 0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
The Coresight PMUs can be configured to work in "full trace" or
"snapshot"
mode. In full trace mode trace acquisition is enabled from beginning to end
with
trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4
/home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/co
resight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether that means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ]
<hang>
Thanks,
Kim _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
On 21 March 2017 at 05:00, Mike Leach mike.leach@linaro.org wrote:
On 17 March 2017 at 14:28, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 17 March 2017 at 05:57, Mike Leach mike.leach@linaro.org wrote:
I can confirm this applies and runs OK on my juno-r1 system - linaro gcc6.2 built perf and kernel. (with no hard hang) I am also seeing the additional printout when I do perf report --dump on the collected data.
Perfect - thanks for the confirmation. I'll push to gitHub.
I can also confirm the issue Kim sees when using the 'sudo ./perf record -e cs_etm// uname ' command line.
A sink needs to be specified within the //. Otherwise perf doesn't know what sink to use.
Agreed. A re-test shows that if a sink is enabled using sysfs before 'sudo ./perf record -e cs_etm// uname' , then data is captured and no crash occurs. This matches what the coresight.txt documentation states, though re-enabling this way is required before each run
- a patch to the docs has been submitted to make this clear - along with
the option of defining the sink in the perf command line.
Without pre-enabling, missing the sink between cs_etm// causes the crash. Ideally, bad input should result in an error message. Something worth looking at in future?
When writing the driver I (mistakenly) thought the error message you get from perf was enough. To fix this we need to enhance the flex/bison infrastructure. If you guys think it's absolutely needed I can have a look but I'm pretty sure we can live with it.
On the flip side that part will need a huge overhaul when we add support for the multiple sink - I suggest we tackle it then.
Mathieu
Mike
Mike
On 16 March 2017 at 22:33, Kim Phillips kim.phillips@arm.com wrote:
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC | head -1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm// uname failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017 aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc version 4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at ../kernel/workqueue.c:1442 __queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted 4.11.0-rc1-g8e9e2e2 #4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>] pstate: a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0: ffff80097feac100 0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4 ffff80097612f930 ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000 ffff80097612fa20 ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780 0000000000000001 0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020 0000000000000000 00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00 ffff80097152ad88 0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000 ffff80097152ab80 0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000 0000000000000000 626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b ffff0000080894e0 0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
The Coresight PMUs can be configured to work in "full trace" or "snapshot" mode. In full trace mode trace acquisition is enabled from beginning to end with trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4
/home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/coresight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether that means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ]
<hang>
Thanks,
Kim _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
[reply all this time...]
On 21 March 2017 at 17:21, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 21 March 2017 at 05:00, Mike Leach mike.leach@linaro.org wrote:
On 17 March 2017 at 14:28, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 17 March 2017 at 05:57, Mike Leach mike.leach@linaro.org wrote:
I can confirm this applies and runs OK on my juno-r1 system - linaro gcc6.2 built perf and kernel. (with no hard hang) I am also seeing the additional printout when I do perf report --dump
on
the collected data.
Perfect - thanks for the confirmation. I'll push to gitHub.
I can also confirm the issue Kim sees when using the 'sudo ./perf
record
-e cs_etm// uname ' command line.
A sink needs to be specified within the //. Otherwise perf doesn't know what sink to use.
Agreed. A re-test shows that if a sink is enabled using sysfs before
'sudo
./perf record -e cs_etm// uname' , then data is captured and no crash occurs. This
matches
what the coresight.txt documentation states, though re-enabling this way
is
required before each run
- a patch to the docs has been submitted to make this clear - along with
the option of defining the sink in the perf command line.
Without pre-enabling, missing the sink between cs_etm// causes the crash. Ideally, bad input should result in an error message. Something worth looking at in future?
When writing the driver I (mistakenly) thought the error message you get from perf was enough. To fix this we need to enhance the flex/bison infrastructure. If you guys think it's absolutely needed I can have a look but I'm pretty sure we can live with it.
On the flip side that part will need a huge overhaul when we add support for the multiple sink - I suggest we tackle it then.
Mathieu
Agreed, No rush to fix this immediately as not preventing people from
using it. Mike
Mike
Mike
On 16 March 2017 at 22:33, Kim Phillips kim.phillips@arm.com wrote:
On Thu, 16 Mar 2017 12:04:33 -0600 Mathieu Poirier mathieu.poirier@linaro.org wrote:
Reported-by: Kim Phillips kim.phillips@arm.com Signed-off-by: Mathieu Poirier mathieu.poirier@linaro.org
I wish I'd be able to add my Tested-by:, but unfortunately, I can't:
When I build perf natively with gcc 6.3, with this patch:
kim@juno perf perf-opencsd-4.11-rc1$ strings -a ./perf | grep GCC | head -1 GCC: (Debian 6.3.0-6) 6.3.0 20170205
and invoke perf slightly differently than in the other thread (no tasksets, no etr spec), I get the memory allocation failure:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm// uname failed to mmap with 12 (Cannot allocate memory) kim@juno perf perf-opencsd-4.11-rc1$ uname -a Linux juno 4.11.0-rc1-g8e9e2e2 #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017 aarch64 GNU/Linux kim@juno perf perf-opencsd-4.11-rc1$ dmesg |grep gcc [ 0.000000] Linux version 4.11.0-rc1-g8e9e2e2 (kim@dupont) (gcc version 4.9.4 20151028 (prerelease) (Linaro GCC 4.9-2016.02) ) #4 SMP PREEMPT Thu Mar 16 15:55:24 CDT 2017
but this time, there is a stacktrace on the serial console:
[ 119.044143] ------------[ cut here ]------------ [ 119.048729] WARNING: CPU: 0 PID: 2819 at
../kernel/workqueue.c:1442
__queue_work+0x3c8/0x478 [ 119.057080] Modules linked in: [ 119.060100] [ 119.061574] CPU: 0 PID: 2819 Comm: perf Not tainted 4.11.0-rc1-g8e9e2e2 #4 [ 119.068376] Hardware name: ARM Juno development board (r2) (DT) [ 119.074232] task: ffff8009732f0c80 task.stack: ffff80097612c000 [ 119.080090] PC is at __queue_work+0x3c8/0x478 [ 119.084400] LR is at __queue_work+0x29c/0x478 [ 119.088709] pc : [<ffff0000080e60c4>] lr : [<ffff0000080e5f98>] pstate: a00001c5 [ 119.096026] sp : ffff80097612fac0 [ 119.099302] x29: ffff80097612fac0 x28: 0000000000000000 [ 119.104560] x27: 0000000000000400 x26: ffff000009157740 [ 119.109818] x25: 0000000000000000 x24: ffff800976804400 [ 119.115075] x23: 0000000000000040 x22: ffff80097fea8280 [ 119.120333] x21: ffff000008fb4000 x20: ffff80097152ad80 [ 119.125591] x19: ffff80097feac100 x18: 0000000000000000 [ 119.130849] x17: 0000ffff7994a7a8 x16: ffff0000080894e0 [ 119.136106] x15: 000000000000013b x14: 0000000000000000 [ 119.141364] x13: 626b5f6b636f6c6d x12: 0000000000000000 [ 119.146621] x11: 0000000000000000 x10: 0000000000000000 [ 119.151879] x9 : 0000000000000000 x8 : ffff80097152ab80 [ 119.157136] x7 : 0000000000000000 x6 : 0000000000000001 [ 119.162393] x5 : 0000000000000000 x4 : 0000000000000000 [ 119.167650] x3 : 0000000000000000 x2 : 0000000000000000 [ 119.172907] x1 : 0000000000000000 x0 : ffff80097152ad88 [ 119.178164] [ 119.179634] ---[ end trace c565de4a9bd0da95 ]--- [ 119.184199] Call trace: [ 119.186618] Exception stack(0xffff80097612f8f0 to 0xffff80097612fa20) [ 119.192991] f8e0:
ffff80097feac100
0001000000000000 [ 119.200742] f900: ffff80097612fac0 ffff0000080e60c4
ffff80097612f930
ffff0000081c19e8 [ 119.208492] f920: ffff000009134a80 0000000000000000
ffff80097612fa20
ffff0000081c2370 [ 119.216242] f940: 0000000000000000 ffff000009135780
0000000000000001
0000000000000000 [ 119.223992] f960: ffff800972500000 0000000000000020
0000000000000000
00000000014092c0 [ 119.231742] f980: ffff800972506000 ffff7e0025c5de00
ffff80097152ad88
0000000000000000 [ 119.239491] f9a0: 0000000000000000 0000000000000000
0000000000000000
0000000000000000 [ 119.247241] f9c0: 0000000000000001 0000000000000000
ffff80097152ab80
0000000000000000 [ 119.254991] f9e0: 0000000000000000 0000000000000000
0000000000000000
626b5f6b636f6c6d [ 119.262741] fa00: 0000000000000000 000000000000013b
ffff0000080894e0
0000ffff7994a7a8 [ 119.270490] [<ffff0000080e60c4>] __queue_work+0x3c8/0x478 [ 119.275833] [<ffff0000080e61c4>] queue_work_on+0x50/0x6c [ 119.281092] [<ffff0000088d76b4>] etm_setup_aux+0x168/0x208 [ 119.286523] [<ffff0000081b30b0>] rb_alloc_aux+0x230/0x2b4 [ 119.291866] [<ffff0000081ae418>] perf_mmap+0x408/0x558 [ 119.296952] [<ffff0000081fc5f8>] mmap_region+0x340/0x55c [ 119.302209] [<ffff0000081fcb00>] do_mmap+0x2ec/0x394 [ 119.307122] [<ffff0000081dcce4>] vm_mmap_pgoff+0xcc/0xf0 [ 119.312379] [<ffff0000081fa53c>] SyS_mmap_pgoff+0xb0/0x23c [ 119.317809] [<ffff000008089538>] sys_mmap+0x58/0x74 [ 119.322636] [<ffff000008083730>] el0_svc_naked+0x24/0x28
It's 100% consistent. I don't expect this to be expected behaviour, esp. given the same way of invocation is in Documentation/trace/coresight.txt:
The Coresight PMUs can be configured to work in "full trace" or "snapshot" mode. In full trace mode trace acquisition is enabled from beginning to end with trace data being recorded continuously:
linaro@linaro-nano:~$ perf record -e cs_etm// dd if=/dev/random of=./test.txt bs=1k count=1000
Resolving the stack address from the etm_setup_aux entry in the stack trace:
kim@dupont juno perf-opencsd-4.11-rc1$ addr2line -e vmlinux ffff0000088d76b4
/home/kim/git/OpenCSD/juno/../drivers/hwtracing/coresight/
coresight-etm-perf.c:260
Line 260 is the closing '}' to the function. I'm not sure whether
that
means it's the INIT_WORK in the function that's not happy with something it was passed?
Looking at kernel/workqueue.c line 1442, it has:
if (WARN_ON(!list_empty(&work->entry))) {So perhaps one of INIT_WORK's params was NULL? Can you take a look?
btw, thanks for applying Sebastian's 'perf tools: fix printing of auxtrace_info': now, when using the invocation style mentioned in the other thread with Mike Leach (tasksets & etr spec), it makes perf 'finish its sentence' prior to locking up the system:
kim@juno perf perf-opencsd-4.11-rc1$ sudo ./perf record -e cs_etm/@20070000.etr/u --per-thread taskset -c 0 uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.021 MB perf.data ]
<hang>
Thanks,
Kim _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
-- Mike Leach Principal Engineer, ARM Ltd. Blackburn Design Centre. UK
On Tue, 21 Mar 2017 21:44:14 +0000 Mike Leach mike.leach@linaro.org wrote:
On 21 March 2017 at 17:21, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 21 March 2017 at 05:00, Mike Leach mike.leach@linaro.org wrote:
Without pre-enabling, missing the sink between cs_etm// causes the crash. Ideally, bad input should result in an error message. Something worth looking at in future?
When writing the driver I (mistakenly) thought the error message you get from perf was enough. To fix this we need to enhance the flex/bison infrastructure. If you guys think it's absolutely needed I can have a look but I'm pretty sure we can live with it.
On the flip side that part will need a huge overhaul when we add support for the multiple sink - I suggest we tackle it then.
Agreed, No rush to fix this immediately as not preventing people from using it.
depends on how one defines "using it": I tried to use it, and couldn't. I can now because I wrote this mailing list, and that's because I became impatient trying to debug the driver.
Just in preparing output for that last email I just sent, fully knowing that the step to enable the sink is necessary, I *still* hit up-arrow, enter, and got my terminal rudely splattered over:
root@juno:~# taskset -c 2 /home/kim/git/OpenCSD/tools/perf/perf record -o perf-etm.data -e cs_etm//u --per-thread taskset -c 2 ./sort-O3 [ 1132.149525] ------------[ cut here ]------------ [ 1132.154109] WARNING: CPU: 2 PID: 2592 at ../kernel/workqueue.c:1442 __queue_work+0x450/0x520 [ 1132.162457] Modules linked in: ip_tables x_tables ipv6 [ 1132.167547] [ 1132.169018] CPU: 2 PID: 2592 Comm: perf Not tainted 4.11.0-rc3-00035-g093b995 #25 [ 1132.176421] Hardware name: ARM Juno development board (r2) (DT) [ 1132.182276] task: ffff800974e23400 task.stack: ffff800975528000 [ 1132.188132] PC is at __queue_work+0x450/0x520 [ 1132.192439] LR is at __queue_work+0x10c/0x520 [ 1132.196745] pc : [<ffff0000080e8958>] lr : [<ffff0000080e8614>] pstate: a00001c5 [ 1132.204062] sp : ffff80097552ba80 [ 1132.207335] x29: ffff80097552ba80 x28: ffff80097fea8300 [ 1132.212591] x27: ffff800970569400 x26: ffff000009059000 [ 1132.217847] x25: ffff0000091e0840 x24: 0000000000000002 [ 1132.223103] x23: 0000000000000040 x22: ffff800977404400 [ 1132.228358] x21: 0000000000000029 x20: ffff000009007000 [ 1132.233612] x19: ffff80097fedc100 x18: 0000000000000000 [ 1132.238868] x17: 0000ffffb66457a8 x16: ffff000008089668 [ 1132.244123] x15: 000000000000013b x14: 0000000000000000 [ 1132.249377] x13: 626b5f6b636f6c6d x12: 0000000000000040 [ 1132.254632] x11: 0000000000000005 x10: 0000000000000000 [ 1132.259888] x9 : ffff800977000028 x8 : 0000000000000000 [ 1132.265142] x7 : ffff80097fea8300 x6 : ffff80097fea8300 [ 1132.270398] x5 : ffff800977000000 x4 : ffff80097fea8300 [ 1132.275652] x3 : 0000000000000000 x2 : 0000000000000000 [ 1132.280907] x1 : 0000000000000000 x0 : ffff800970569408 [ 1132.286162] [ 1132.287630] ---[ end trace 52e5d735196c6a0d ]--- [ 1132.292194] Call trace: [ 1132.294609] Exception stack(0xffff80097552b8b0 to 0xffff80097552b9e0) [ 1132.300980] b8a0: ffff80097fedc100 0001000000000000 [ 1132.308727] b8c0: ffff80097552ba80 ffff0000080e8958 ffff80097fedcaf0 0000000000000000 [ 1132.316474] b8e0: ffff80097fedcaf0 0000000000000000 ffff80097552b920 ffff0000081d6e64 [ 1132.324221] b900: ffff80097552b920 ffff0000081d6afc ffff80097fff1c80 0000000000000011 [ 1132.331968] b920: ffff80097552ba10 ffff0000081d7594 0000000000000000 ffff80097fff2b80 [ 1132.339715] b940: 0000000000000001 0000000000000400 ffff800970569408 0000000000000000 [ 1132.347461] b960: 0000000000000000 0000000000000000 ffff80097fea8300 ffff800977000000 [ 1132.355208] b980: ffff80097fea8300 ffff80097fea8300 0000000000000000 ffff800977000028 [ 1132.362955] b9a0: 0000000000000000 0000000000000005 0000000000000040 626b5f6b636f6c6d [ 1132.370702] b9c0: 0000000000000000 000000000000013b ffff000008089668 0000ffffb66457a8 [ 1132.378449] [<ffff0000080e8958>] __queue_work+0x450/0x520 [ 1132.383789] [<ffff0000080e8a90>] queue_work_on+0x68/0x80 [ 1132.389045] [<ffff0000088f9044>] etm_setup_aux+0x164/0x228 [ 1132.394472] [<ffff0000081c63a8>] rb_alloc_aux+0x230/0x310 [ 1132.399811] [<ffff0000081c1520>] perf_mmap+0x3f8/0x560 [ 1132.404893] [<ffff000008213acc>] mmap_region+0x39c/0x5c8 [ 1132.410146] [<ffff000008213f4c>] do_mmap+0x254/0x380 [ 1132.415056] [<ffff0000081f2ab4>] vm_mmap_pgoff+0xcc/0xf0 [ 1132.420310] [<ffff000008211870>] SyS_mmap_pgoff+0xb0/0x230 [ 1132.425737] [<ffff0000080896c0>] sys_mmap+0x58/0x78 [ 1132.430561] [<ffff000008083730>] el0_svc_naked+0x24/0x28 failed to mmap with 12 (Cannot allocate memory) root@juno:~#
It seems to me a quick fix in the driver (not the flex/bison infrastructure) to emit a simple "I don't see a sink I can use" to dmesg and return an -EINVAL or somesuch would be much more user friendly than the above.
Just my 2c.
Kim
On 24 March 2017 at 00:44, Kim Phillips kim.phillips@arm.com wrote:
On Tue, 21 Mar 2017 21:44:14 +0000 Mike Leach mike.leach@linaro.org wrote:
On 21 March 2017 at 17:21, Mathieu Poirier mathieu.poirier@linaro.org wrote:
On 21 March 2017 at 05:00, Mike Leach mike.leach@linaro.org wrote:
Without pre-enabling, missing the sink between cs_etm// causes the crash. Ideally, bad input should result in an error message. Something worth looking at in future?
When writing the driver I (mistakenly) thought the error message you get from perf was enough. To fix this we need to enhance the flex/bison infrastructure. If you guys think it's absolutely needed I can have a look but I'm pretty sure we can live with it.
On the flip side that part will need a huge overhaul when we add support for the multiple sink - I suggest we tackle it then.
Agreed, No rush to fix this immediately as not preventing people from using it.
depends on how one defines "using it": I tried to use it, and couldn't. I can now because I wrote this mailing list, and that's because I became impatient trying to debug the driver.
Just in preparing output for that last email I just sent, fully knowing that the step to enable the sink is necessary, I *still* hit up-arrow, enter, and got my terminal rudely splattered over:
Don't enable the sink using sysfs, specify the sink on the perf command line and use the up arrow as much as you like.
Mike
root@juno:~# taskset -c 2 /home/kim/git/OpenCSD/tools/perf/perf record -o perf-etm.data -e cs_etm//u --per-thread taskset -c 2 ./sort-O3 [ 1132.149525] ------------[ cut here ]------------ [ 1132.154109] WARNING: CPU: 2 PID: 2592 at ../kernel/workqueue.c:1442 __queue_work+0x450/0x520 [ 1132.162457] Modules linked in: ip_tables x_tables ipv6 [ 1132.167547] [ 1132.169018] CPU: 2 PID: 2592 Comm: perf Not tainted 4.11.0-rc3-00035-g093b995 #25 [ 1132.176421] Hardware name: ARM Juno development board (r2) (DT) [ 1132.182276] task: ffff800974e23400 task.stack: ffff800975528000 [ 1132.188132] PC is at __queue_work+0x450/0x520 [ 1132.192439] LR is at __queue_work+0x10c/0x520 [ 1132.196745] pc : [<ffff0000080e8958>] lr : [<ffff0000080e8614>] pstate: a00001c5 [ 1132.204062] sp : ffff80097552ba80 [ 1132.207335] x29: ffff80097552ba80 x28: ffff80097fea8300 [ 1132.212591] x27: ffff800970569400 x26: ffff000009059000 [ 1132.217847] x25: ffff0000091e0840 x24: 0000000000000002 [ 1132.223103] x23: 0000000000000040 x22: ffff800977404400 [ 1132.228358] x21: 0000000000000029 x20: ffff000009007000 [ 1132.233612] x19: ffff80097fedc100 x18: 0000000000000000 [ 1132.238868] x17: 0000ffffb66457a8 x16: ffff000008089668 [ 1132.244123] x15: 000000000000013b x14: 0000000000000000 [ 1132.249377] x13: 626b5f6b636f6c6d x12: 0000000000000040 [ 1132.254632] x11: 0000000000000005 x10: 0000000000000000 [ 1132.259888] x9 : ffff800977000028 x8 : 0000000000000000 [ 1132.265142] x7 : ffff80097fea8300 x6 : ffff80097fea8300 [ 1132.270398] x5 : ffff800977000000 x4 : ffff80097fea8300 [ 1132.275652] x3 : 0000000000000000 x2 : 0000000000000000 [ 1132.280907] x1 : 0000000000000000 x0 : ffff800970569408 [ 1132.286162] [ 1132.287630] ---[ end trace 52e5d735196c6a0d ]--- [ 1132.292194] Call trace: [ 1132.294609] Exception stack(0xffff80097552b8b0 to 0xffff80097552b9e0) [ 1132.300980] b8a0: ffff80097fedc100 0001000000000000 [ 1132.308727] b8c0: ffff80097552ba80 ffff0000080e8958 ffff80097fedcaf0 0000000000000000 [ 1132.316474] b8e0: ffff80097fedcaf0 0000000000000000 ffff80097552b920 ffff0000081d6e64 [ 1132.324221] b900: ffff80097552b920 ffff0000081d6afc ffff80097fff1c80 0000000000000011 [ 1132.331968] b920: ffff80097552ba10 ffff0000081d7594 0000000000000000 ffff80097fff2b80 [ 1132.339715] b940: 0000000000000001 0000000000000400 ffff800970569408 0000000000000000 [ 1132.347461] b960: 0000000000000000 0000000000000000 ffff80097fea8300 ffff800977000000 [ 1132.355208] b980: ffff80097fea8300 ffff80097fea8300 0000000000000000 ffff800977000028 [ 1132.362955] b9a0: 0000000000000000 0000000000000005 0000000000000040 626b5f6b636f6c6d [ 1132.370702] b9c0: 0000000000000000 000000000000013b ffff000008089668 0000ffffb66457a8 [ 1132.378449] [<ffff0000080e8958>] __queue_work+0x450/0x520 [ 1132.383789] [<ffff0000080e8a90>] queue_work_on+0x68/0x80 [ 1132.389045] [<ffff0000088f9044>] etm_setup_aux+0x164/0x228 [ 1132.394472] [<ffff0000081c63a8>] rb_alloc_aux+0x230/0x310 [ 1132.399811] [<ffff0000081c1520>] perf_mmap+0x3f8/0x560 [ 1132.404893] [<ffff000008213acc>] mmap_region+0x39c/0x5c8 [ 1132.410146] [<ffff000008213f4c>] do_mmap+0x254/0x380 [ 1132.415056] [<ffff0000081f2ab4>] vm_mmap_pgoff+0xcc/0xf0 [ 1132.420310] [<ffff000008211870>] SyS_mmap_pgoff+0xb0/0x230 [ 1132.425737] [<ffff0000080896c0>] sys_mmap+0x58/0x78 [ 1132.430561] [<ffff000008083730>] el0_svc_naked+0x24/0x28 failed to mmap with 12 (Cannot allocate memory) root@juno:~#
It seems to me a quick fix in the driver (not the flex/bison infrastructure) to emit a simple "I don't see a sink I can use" to dmesg and return an -EINVAL or somesuch would be much more user friendly than the above.
Just my 2c.
Kim
-
Kim Phillips -
Mathieu Poirier -
Mike Leach