Bug 212213 - Why are there log from 'perf' process when I enabled '--exclude-perf'?
Summary: Why are there log from 'perf' process when I enabled '--exclude-perf'?
Status: RESOLVED PATCH_ALREADY_AVAILABLE
Alias: None
Product: Tools
Classification: Unclassified
Component: Other (show other bugs)
Hardware: ARM Linux
: P1 normal
Assignee: Tools.Other
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-03-10 04:13 UTC by zhanweiw
Modified: 2021-03-24 05:58 UTC (History)
2 users (show)

See Also:
Kernel Version: 4.19
Subsystem:
Regression: No
Bisected commit-id:

Attachments
change name of workload start process to reflect its not the main perf process (802 bytes, patch)
2021-03-15 12:57 UTC, Arnaldo Carvalho de Melo 		Details | Diff
Add an attachment (proposed patch, testcase, etc.)

Description zhanweiw 2021-03-10 04:13:39 UTC 
I run it with the command below:
perf record -e kmem:kmalloc --filter 'bytes_alloc<650 && bytes_alloc>620' -e kmem:kfree --exclude-perf -aR -g sleep 30

Since it has include '--exclude-perf', why I still find log about 'perf' process?
Thanks in advance.

```
perf 11055 [007] 48766.539315: kmem:kmalloc: call_site=ffffff8dc29c86f4 ptr=0xffffffcb9065eb00 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL|__GFP_ZERO
	ffffff8dc2862ec8 __kmalloc+0x2d4 ([kernel.kallsyms])
	ffffff8dc2862ec8 __kmalloc+0x2d4 ([kernel.kallsyms])
	ffffff8dc29c86f4 ovl_alloc_entry+0x2c ([kernel.kallsyms])
	ffffff8dc29c7cbc ovl_lookup+0x440 ([kernel.kallsyms])
	ffffff8dc2891000 path_openat+0x98c ([kernel.kallsyms])
	ffffff8dc28905f8 do_filp_open+0x80 ([kernel.kallsyms])
	ffffff8dc288a56c do_open_execat+0x8c ([kernel.kallsyms])
	ffffff8dc288becc do_execveat_common+0x1b0 ([kernel.kallsyms])
	ffffff8dc288c448 sys_execve+0x4c ([kernel.kallsyms])
	ffffff8dc2684480 el0_svc_naked+0x34 ([kernel.kallsyms])
	      76fc630228 execve+0x8 (/data/local/usr/lib/libc.so)
	      59cfe75bb8 evlist__prepare_workload+0x250 (/data/local/usr/bin/perf)
	      59cfde9e68 cmd_record+0xf3c (/data/local/usr/bin/perf)
	      59cfe70174 perf_env__set_cmdline+0x38 (/data/local/usr/bin/perf)

perf 11055 [007] 48766.539315:   kmem:kfree: call_site=ffffff8dc29c7e08 ptr=0xffffffcbab80c800
	ffffff8dc2863250 kfree+0xa0 ([kernel.kallsyms])
	ffffff8dc2863250 kfree+0xa0 ([kernel.kallsyms])
	ffffff8dc29c7e08 ovl_lookup+0x58c ([kernel.kallsyms])
	ffffff8dc2891000 path_openat+0x98c ([kernel.kallsyms])
	ffffff8dc28905f8 do_filp_open+0x80 ([kernel.kallsyms])
	ffffff8dc288a56c do_open_execat+0x8c ([kernel.kallsyms])
	ffffff8dc288becc do_execveat_common+0x1b0 ([kernel.kallsyms])
	ffffff8dc288c448 sys_execve+0x4c ([kernel.kallsyms])
	ffffff8dc2684480 el0_svc_naked+0x34 ([kernel.kallsyms])
	      76fc630228 execve+0x8 (/data/local/usr/lib/libc.so)
	      59cfe75bb8 evlist__prepare_workload+0x250 (/data/local/usr/bin/perf)
	      59cfde9e68 cmd_record+0xf3c (/data/local/usr/bin/perf)
	      59cfe70174 perf_env__set_cmdline+0x38 (/data/local/usr/bin/perf)
```
Comment 1 Arnaldo Carvalho de Melo 2021-03-10 12:58:24 UTC 
So, --exclude-perf applies to the last preceding tracepoint, which is suprising, agreed, I'll look at the man page to see if it states that it applies to all, no, it says it appplies only to the last -e, so it is working as advertised, to have what you want use:

perf record -vv -e kmem:kmalloc --filter 'bytes_alloc<650 && bytes_alloc>620' --exclude-perf -e kmem:kfree --exclude-perf -aR -g sleep 30

Using strace we can see what happens, first with your command line:

# strace -s 10000 -e ioctl perf record -vv -e kmem:kmalloc --filter 'bytes_alloc<650 && bytes_alloc>620' -e kmem:kfree --exclude-perf -aR -g sleep 30 |& grep PERF_EVENT_IOC_SET_FILTER
ioctl(4, PERF_EVENT_IOC_SET_FILTER, "bytes_alloc<650 && bytes_alloc>620") = 0
ioctl(5, PERF_EVENT_IOC_SET_FILTER, "bytes_alloc<650 && bytes_alloc>620") = 0
<SNIP per cpu filter setting>
ioctl(29, PERF_EVENT_IOC_SET_FILTER, "common_pid != 3577837") = 0
<SNIP per cpu filter setting>

See? the first -e that is not followed by --exclude-perf doesn't excludes it, the second, the kmem:kfree, is followed by --exclude-perf and thus jas the filter expression for perf's pid, and its the only filter expression, since you didn't followed kmem:kfree with a --filter.

Now with the command line where both -e are followed by --exclude-perf:

# strace -s 10000 -e ioctl perf record -vv -e kmem:kmalloc --filter 'bytes_alloc<650 && bytes_alloc>620' -exclude-perf -e kmem:kfree --exclude-perf -aR -g sleep 30 |& grep common_pidR
ioctl(4, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 3578023)") = 0
ioctl(5, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 3578023)") = 0
<SNIP per cpu filter setting>
ioctl(29, PERF_EVENT_IOC_SET_FILTER, "common_pid != 3578023") = 0
ioctl(30, PERF_EVENT_IOC_SET_FILTER, "common_pid != 3578023") = 0
<SNIP per cpu filter setting>

See? the common_pid filter is added to both tracepoints.

The source code uses:

foreach_evsel_in_last_glob(evlist, add_exclude_perf_filter,
                                          NULL);

This means that something like:  '-e kmem:* --exclude-perf' should have that common_pid expression applied to all kmem tracepoints.
Comment 2 zhanweiw 2021-03-11 02:49:17 UTC 
Thanks Arnaldo so much for this info, you're so nice. -:)
Comment 3 zhanweiw 2021-03-15 06:55:30 UTC 
Hi Arnaldo,

I've just tried again with the command you suggested, but it seems 'pref' still can be found in the result, and it can be found in both 'kmalloc' & 'kfree':
```
# perf record -e kmem:kmalloc --filter 'bytes_alloc<650 && bytes_alloc>620' --exclude-perf -e kmem:kfree --exclude-perf -aR sleep 30
Couldn't synthesize cgroup events.
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 3.374 MB perf.data (2720 samples) ]

# perf script -k "/data/local/kernel/vmlinux" | head -100
            perf 16759 [006] 133243.532458: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06fe9480 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [006] 133243.532548:   kmem:kfree: call_site=ffffff95c58c8384 ptr=0xffffffdfe9adc680
            perf 16759 [006] 133243.532554:   kmem:kfree: call_site=ffffff95c58c7940 ptr=0x0
            perf 16759 [006] 133243.532631: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06fe9980 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [006] 133243.532667:   kmem:kfree: call_site=ffffff95c58c8384 ptr=0xffffffdfe9adc680
            perf 16759 [006] 133243.532674:   kmem:kfree: call_site=ffffff95c58c7940 ptr=0x0
            perf 16759 [006] 133243.532745: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06fea600 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [006] 133243.532788:   kmem:kfree: call_site=ffffff95c58c8384 ptr=0xffffffdfe9adc680
            perf 16759 [006] 133243.532794:   kmem:kfree: call_site=ffffff95c58c7940 ptr=0x0
            perf 16759 [006] 133243.532862: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06fe8d00 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [006] 133243.532895:   kmem:kfree: call_site=ffffff95c58c8384 ptr=0xffffffdfe9adc680
            perf 16759 [006] 133243.532901:   kmem:kfree: call_site=ffffff95c58c7940 ptr=0x0
            perf 16759 [006] 133243.532967: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06feba00 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [006] 133243.533003:   kmem:kfree: call_site=ffffff95c58c8384 ptr=0xffffffdfe9adc680
            perf 16759 [006] 133243.533009:   kmem:kfree: call_site=ffffff95c58c7940 ptr=0x0
            perf 16759 [006] 133243.533074: kmem:kmalloc: call_site=ffffff95c5a91040 ptr=0xffffffdf06fe8580 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_KERNEL_ACCOUNT
            perf 16759 [003] 133243.535183: kmem:kmalloc: call_site=ffffff95c5aa3718 ptr=0xffffffdf06fe9c00 bytes_req=10 bytes_alloc=640 gfp_flags=GFP_ATOMIC
            perf 16759 [003] 133243.535207:   kmem:kfree: call_site=ffffff95c5aa4b18 ptr=0xffffffdf06fe9c00
            perf 16759 [003] 133243.535238:   kmem:kfree: call_site=ffffff95c5aa5438 ptr=0x0
 kworker/u16:13- 13886 [000] 133243.535461: kmem:kmalloc: call_site=ffffff95c653cdcc ptr=0xffffffdf06fe9c00 bytes_req=40 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:13- 13886 [000] 133243.535512: kmem:kmalloc: call_site=ffffff95c653cdf4 ptr=0xffffffdf06fea100 bytes_req=28 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:13- 13886 [000] 133243.535557: kmem:kmalloc: call_site=ffffff95c653ce4c ptr=0xffffffdf06feab00 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:13- 13886 [000] 133243.535650: kmem:kmalloc: call_site=ffffff95c653d01c ptr=0xffffffdf06feb780 bytes_req=4 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:13- 13886 [000] 133243.535700: kmem:kmalloc: call_site=ffffff95c653d538 ptr=0xffffffdf06fe8300 bytes_req=88 bytes_alloc=640 gfp_flags=GFP_ATOMIC|__GFP_ZERO
         swapper     0 [001] 133243.536779: kmem:kmalloc: call_site=ffffff95c65398bc ptr=0xffffffdf06febc80 bytes_req=48 bytes_alloc=640 gfp_flags=GFP_ATOMIC|__GFP_ZERO
         swapper     0 [001] 133243.536806: kmem:kmalloc: call_site=ffffff95c65398d4 ptr=0xffffffdf06fe8a80 bytes_req=20 bytes_alloc=640 gfp_flags=GFP_ATOMIC
         swapper     0 [001] 133243.536891:   kmem:kfree: call_site=ffffff95c6539b5c ptr=0xffffffdf06fe8a80
         swapper     0 [001] 133243.536908:   kmem:kfree: call_site=ffffff95c6539b64 ptr=0xffffffdf06febc80
 kworker/u16:13- 13886 [000] 133243.537219:   kmem:kfree: call_site=ffffff95c653e1a8 ptr=0xffffffdf06fe8300
 kworker/u16:13- 13886 [000] 133243.537260:   kmem:kfree: call_site=ffffff95c653ccd0 ptr=0xffffffdf06feb780
 kworker/u16:13- 13886 [000] 133243.537294:   kmem:kfree: call_site=ffffff95c653cce8 ptr=0xffffffdf06feab00
 kworker/u16:13- 13886 [000] 133243.537327:   kmem:kfree: call_site=ffffff95c653ccf0 ptr=0xffffffdf06fea100
 kworker/u16:13- 13886 [000] 133243.537358:   kmem:kfree: call_site=ffffff95c653ccf8 ptr=0xffffffdfe9aded80
 kworker/u16:13- 13886 [000] 133243.537392:   kmem:kfree: call_site=ffffff95c653cd00 ptr=0xffffffdf06fe9c00
 kworker/u16:3-m 15687 [002] 133243.537939: kmem:kmalloc: call_site=ffffff95c653cdcc ptr=0xffffffdf06fe9c00 bytes_req=40 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:3-m 15687 [002] 133243.537997: kmem:kmalloc: call_site=ffffff95c653cdf4 ptr=0xffffffdf06fe9200 bytes_req=28 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:3-m 15687 [002] 133243.538041: kmem:kmalloc: call_site=ffffff95c653ce4c ptr=0xffffffdf06fea100 bytes_req=24 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:3-m 15687 [002] 133243.538133: kmem:kmalloc: call_site=ffffff95c653d01c ptr=0xffffffdf06fea880 bytes_req=8 bytes_alloc=640 gfp_flags=GFP_NOIO|__GFP_ZERO
 kworker/u16:3-m 15687 [002] 133243.538181: kmem:kmalloc: call_site=ffffff95c653d538 ptr=0xffffffdf06feab00 bytes_req=88 bytes_alloc=640 gfp_flags=GFP_ATOMIC|__GFP_ZERO
         swapper     0 [001] 133243.538692: kmem:kmalloc: call_site=ffffff95c65398bc ptr=0xffffffdf06fead80 bytes_req=48 bytes_alloc=640 gfp_flags=GFP_ATOMIC|__GFP_ZERO
         swapper     0 [001] 133243.538707: kmem:kmalloc: call_site=ffffff95c65398d4 ptr=0xffffffdf06feb780 bytes_req=20 bytes_alloc=640 gfp_flags=GFP_ATOMIC
```

Here is the 'strace' log:
```
sys_perf_event_open: pid -1  cpu 0  group_fd -1  flags 0x8 = 21
sys_perf_event_open: pid -1  cpu 1  group_fd -1  flags 0x8 = 22
sys_perf_event_open: pid -1  cpu 2  group_fd -1  flags 0x8 = 23
sys_perf_event_open: pid -1  cpu 3  group_fd -1  flags 0x8 = 24
sys_perf_event_open: pid -1  cpu 4  group_fd -1  flags 0x8 = 25
sys_perf_event_open: pid -1  cpu 5  group_fd -1  flags 0x8 = 26
sys_perf_event_open: pid -1  cpu 6  group_fd -1  flags 0x8 = 27
sys_perf_event_open: pid -1  cpu 7  group_fd -1  flags 0x8 = 28
ioctl(4, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(5, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(6, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(8, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(9, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(10, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(11, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(12, PERF_EVENT_IOC_SET_FILTER, "(bytes_alloc<650 && bytes_alloc>620) && (common_pid != 16971)") = 0
ioctl(13, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(14, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(15, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(16, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(17, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(18, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(19, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
ioctl(20, PERF_EVENT_IOC_SET_FILTER, "common_pid != 16971") = 0
mmap size 528384B
0xb4000074d2eb10c8: mmap mask[0]:
ioctl(4, PERF_EVENT_IOC_ID, [257934])   = 0
ioctl(13, PERF_EVENT_IOC_SET_OUTPUT, 4) = 0
ioctl(13, PERF_EVENT_IOC_ID, [257942])  = 0
ioctl(21, PERF_EVENT_IOC_SET_OUTPUT, 4) = 0
ioctl(21, PERF_EVENT_IOC_ID, [257950])  = 0
0xb4000074d2ec1170: mmap mask[0]:
ioctl(5, PERF_EVENT_IOC_ID, [257935])   = 0
ioctl(14, PERF_EVENT_IOC_SET_OUTPUT, 5) = 0
ioctl(14, PERF_EVENT_IOC_ID, [257943])  = 0
```
Comment 4 Arnaldo Carvalho de Melo 2021-03-15 12:42:26 UTC 
so, 16759 must be the 'sleep' process, that perf first forks, then execs, so after the fork and before the exec it'll still appear as 'perf', see here in my attempt:

[root@five ~]# perf script --pid 15905
            perf 15905 [009]  1498.356094:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356116:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356116:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356138:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356148:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356148:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356168:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356176:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356176:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356194:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356204:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356204:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356225:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356233:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356234:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356256:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356265:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356265:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356288:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356295:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356296:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356317:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [009]  1498.356325:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
            perf 15905 [009]  1498.356325:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf750421c00
            perf 15905 [009]  1498.356348:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
            perf 15905 [014]  1498.356386:   kmem:kfree: call_site=security_compute_sid.part.0+0x3b2 ptr=(nil)
            perf 15905 [014]  1498.356423:   kmem:kfree: call_site=load_elf_binary+0x207 ptr=0xffff9cf5b2a34220
            perf 15905 [014]  1498.356694:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf6d0b3b000
           sleep 15905 [014]  1498.356739:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
           sleep 15905 [014]  1498.356746:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
           sleep 15905 [014]  1498.356751:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356757:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356759:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356760:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356773:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356780:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356783:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356786:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf732f83000
           sleep 15905 [014]  1498.356791:   kmem:kfree: call_site=load_elf_binary+0xcfc ptr=0xffff9cf5a38a9480



So try again and do the 'perf script --pid PID-OF-PERF'

We can try to add some warning in the output to help with that, I'll see what I can do...
Comment 5 Arnaldo Carvalho de Melo 2021-03-15 12:44:04 UTC 
For some reason your call_site tracepoint fields are not being resolved, but if you look at the output for my attempt, you'll see that its the exevat code running, as I inferred and confirmed by using 'perf script --pid'.
Comment 6 Arnaldo Carvalho de Melo 2021-03-15 12:57:01 UTC 
Created attachment 295867 [details]
change name of workload start process to reflect its not the main perf process
Comment 7 Arnaldo Carvalho de Melo 2021-03-15 12:59:38 UTC 
With the attached patch in place we see that its just the execvp call to start that 'sleep' process:

[root@five ~]# perf script  --pid 19036
   perf-launcher 19036 [009]  2199.357582:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
   perf-launcher 19036 [009]  2199.357604:   kmem:kfree: call_site=free_bprm+0x8f ptr=(nil)
   perf-launcher 19036 [009]  2199.357604:   kmem:kfree: call_site=do_execveat_common+0x19d ptr=0xffff9cf786459800
   perf-launcher 19036 [009]  2199.357630:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
<SNIP>
   perf-launcher 19036 [000]  2199.358275:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf786fbac00
   perf-launcher 19036 [000]  2199.358276:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf786fb9200
   perf-launcher 19036 [000]  2199.358277:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf786fb9c00
   perf-launcher 19036 [000]  2199.358278:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf786458200
   perf-launcher 19036 [000]  2199.358279:   kmem:kfree: call_site=__free_slab+0xb5 ptr=0xffff9cf786458600
           sleep 19036 [000]  2199.358316:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
           sleep 19036 [000]  2199.358323:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=(nil)
           sleep 19036 [000]  2199.358330:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf58be2d000
           sleep 19036 [000]  2199.358337:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf58be2d000
           sleep 19036 [000]  2199.358339:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf58be2d000
           sleep 19036 [000]  2199.358341:   kmem:kfree: call_site=perf_event_mmap+0x279 ptr=0xffff9cf58be2d000
Comment 8 zhanweiw 2021-03-16 01:38:09 UTC 
Got it. Thanks Arnaldo so much!
Comment 9 Arnaldo Carvalho de Melo 2021-03-23 15:28:46 UTC 
Can you please close the tickets as they get resolved? Thanks.
Comment 10 zhanweiw 2021-03-24 05:58:56 UTC 
Thanks Arnaldo so much! I've set the status to 'RESOLVED'.
Note You need to log in before you can comment on or make changes to this bug.