Bug 86991
| Summary: | Perf tool performance issues | ||
|---|---|---|---|
| Product: | Tracing/Profiling | Reporter: | Pavel Odintsov (pavel.odintsov) |
| Component: | Perf tool | Assignee: | Arnaldo Carvalho de Melo (acme) |
| Status: | NEW --- | ||
| Severity: | normal | ||
| Priority: | P1 | ||
| Hardware: | x86-64 | ||
| OS: | Linux | ||
| Kernel Version: | 3.17.1 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
Hello! I'm using perf tool from upstream kernel tree linux-3.17.1 and tried to profile my server with CentOS 2.6.32 kernel. But my server run ~29222 processes and I need wait about 20 minutes for initial perf top -U. I do some strace and found perf tool reading my /proc for every one process from 30000: strace -f -p 711584 Process 711584 attached - interrupt to quit read(6, "000000 00:00 0 \n7fa8654a6000-7fa"..., 1024) = 518 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69906/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69906/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tkthreadd/5605\nState:\tS (sl"..., 1024) = 763 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69906/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69907/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69907/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tkhelper/5605\nState:\tS (sle"..., 1024) = 766 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69907/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69954/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69954/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tapache2\nState:\tS (sleeping"..., 1024) = 1011 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69954/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "7f078f2e6000-7f078f40c000 rw-s 0"..., 1024) = 1024 read(6, "3c1 532588 /vz/"..., 1024) = 1024 read(6, " /vz/root/3823/usr"..., 1024) = 1024 brk(0x2377000) = 0x2377000 read(6, " /vz/root/3823/usr/lib"..., 1024) = 1024 read(6, "vz/root/3823/usr/lib/apache2/mod"..., 1024) = 1024 read(6, "_dir.so\n7f079085d000-7f0790a5c00"..., 1024) = 1024 read(6, " /vz/root/3823/usr/lib/ap"..., 1024) = 1024 read(6, "b/apache2/modules/mod_autoindex."..., 1024) = 1024 read(6, "usr/lib/apache2/modules/mod_auth"..., 1024) = 1024 read(6, "16 /vz/root/382"..., 1024) = 1024 read(6, " b6:333c1 532619 "..., 1024) = 1024 read(6, "/3823/lib/libnss_files-2.11.3.so"..., 1024) = 1024 read(6, "so\n7f5639337000-7f5639339000 rw-"..., 1024) = 1024 read(6, " /vz/root/3823/lib/libdl-2"..., 1024) = 1024 read(6, " /vz/root/3823/lib/librt-2"..., 1024) = 1024 read(6, "ot/3823/lib/libpthread-2.11.3.so"..., 1024) = 1024 read(6, "00 b6:333c1 532469 "..., 1024) = 1024 read(6, "ib/ld-2.11.3.so\n7f563da6d000-7f5"..., 1024) = 930 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69962/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69962/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tsystemd-udevd\nState:\tS (sl"..., 1024) = 1008 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69962/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "00400000-00432000 r-xp 00000000 "..., 1024) = 1024 read(6, "lib/x86_64-linux-gnu/libnss_nis-"..., 1024) = 1024 read(6, " /vz/root/1383/lib/x86"..., 1024) = 1024 read(6, "t/1383/lib/x86_64-linux-gnu/libp"..., 1024) = 1024 read(6, "783 /vz/root/138"..., 1024) = 1024 read(6, "/lib/x86_64-linux-gnu/libpcre.so"..., 1024) = 1024 read(6, "3/lib/x86_64-linux-gnu/librt-2.1"..., 1024) = 1024 read(6, "86_64-linux-gnu/libnih-dbus.so.1"..., 1024) = 1024 read(6, "ux-gnu/libcgmanager.so.0.0.0\n7fc"..., 1024) = 1024 read(6, "\n7fc569568000-7fc56958a000 r-xp "..., 1024) = 1024 read(6, "00 rw-p 00000000 00:00 0 \n7fc569"..., 1024) = 873 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69966/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69966/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tgetty\nState:\tS (sleeping)\n"..., 1024) = 998 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69966/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "00400000-00407000 r-xp 00000000 "..., 1024) = 1024 read(6, "6_64-linux-gnu/libnss_nis-2.19.s"..., 1024) = 1024 read(6, " /vz/root/1383/lib/x86_64-li"..., 1024) = 1024 read(6, " b6:39bc1 1177842 "..., 1024) = 710 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69967/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69967/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tgetty\nState:\tS (sleeping)\n"..., 1024) = 998 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69967/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "00400000-00407000 r-xp 00000000 "..., 1024) = 1024 read(6, "6_64-linux-gnu/libnss_nis-2.19.s"..., 1024) = 1024 read(6, " /vz/root/1383/lib/x86_64-li"..., 1024) = 1024 read(6, " b6:39bc1 1177842 "..., 1024) = 710 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69968/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69968/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tnginx\nState:\tS (sleeping)\n"..., 1024) = 998 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 open("/proc/69968/maps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "00400000-004c1000 r-xp 00000000 "..., 1024) = 1024 read(6, "/1383/lib/x86_64-linux-gnu/libns"..., 1024) = 1024 read(6, " /vz/root/1383/l"..., 1024) = 1024 read(6, "b6:39bc1 1211054 "..., 1024) = 1024 read(6, "b6:39bc1 1211268 "..., 1024) = 1024 read(6, "7813 /vz/root/13"..., 1024) = 1024 read(6, " 1211269 /vz/roo"..., 1024) = 1024 read(6, ".11.0\n7fb6c2efa000-7fb6c30f9000 "..., 1024) = 1024 read(6, "lib/x86_64-linux-gnu/libfreetype"..., 1024) = 1024 read(6, " /vz/root/1383/usr/lib/x86_64-l"..., 1024) = 1024 read(6, "3dd9000 r-xp 00000000 b6:39bc1 1"..., 1024) = 1024 read(6, " /vz/root/1383/lib"..., 1024) = 1024 read(6, " /vz/root/1383/usr/li"..., 1024) = 1024 read(6, "0000-7fb6c4c74000 r-xp 00000000 "..., 1024) = 1024 read(6, "t.so.1.1.28\n7fb6c50b2000-7fb6c52"..., 1024) = 1024 read(6, "/1383/lib/x86_64-linux-gnu/libz."..., 1024) = 1024 read(6, "53 /vz/root/1383"..., 1024) = 1024 read(6, "rw-p 0000a000 b6:39bc1 1177700 "..., 1024) = 1024 read(6, "000-7fb6c6521000 r--p 00022000 b"..., 1024) = 523 read(6, "", 1024) = 0 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 getdents(5, /* 0 entries */, 32768) = 0 close(5) = 0 open("/proc/69969/task", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5 getdents(5, /* 3 entries */, 32768) = 80 open("/proc/69969/status", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f018b72e000 read(6, "Name:\tnginx\nState:\tS (sleeping)\n"..., 1024) = 1017 close(6) = 0 munmap(0x7f018b72e000, 4096) = 0 And after ~20 minutes of loading it started. Could you optimize perf top tool startup because with so long start it's really hard to debug kernel performance issues? While reading /proc filesystem perf top eat whole my cpu: root 711584 114 0.0 165452 14572 pts/8 R+ 14:42 0:06 /opt/perf top -U I tried to collect data with perf record and can't got success to because it hangs: /opt/perf record -a -g ^C[ perf record: Woken up 828 times to write data ] [ perf record: Captured and wrote 335.307 MB perf.data (~14649805 samples) ] ^C And strace shown very interesting lines: root 223995 96.4 0.0 486100 166220 pts/7 R+ 14:33 11:00 /opt/perf record -a -g strace -f -p 223995 Process 223995 attached - interrupt to quit brk(0x61bd000) = 0x61bd000 brk(0x61de000) = 0x61de000 brk(0x61ff000) = 0x61ff000 brk(0x6220000) = 0x6220000 brk(0x6241000) = 0x6241000 brk(0x6262000) = 0x6262000 brk(0x6283000) = 0x6283000 brk(0x62a4000) = 0x62a4000 brk(0x62c5000) = 0x62c5000 brk(0x62e6000) = 0x62e6000 brk(0x6307000) = 0x6307000 brk(0x6328000) = 0x6328000 brk(0x6349000) = 0x6349000 brk(0x636a000) = 0x636a000 brk(0x638b000) = 0x638b000 brk(0x63ac000) = 0x63ac000 brk(0x63cd000) = 0x63cd000 brk(0x63ee000) = 0x63ee000 brk(0x640f000) = 0x640f000 brk(0x6430000) = 0x6430000 brk(0x6451000) = 0x6451000 brk(0x6472000) = 0x6472000 brk(0x6493000) = 0x6493000 brk(0x64b4000) = 0x64b4000 brk(0x64d5000) = 0x64d5000 brk(0x64f6000) = 0x64f6000 brk(0x6517000) = 0x6517000 brk(0x6538000) = 0x6538000 brk(0x6559000) = 0x6559000 brk(0x657a000) = 0x657a000 brk(0x659b000) = 0x659b000 brk(0x65bc000) = 0x65bc000 brk(0x65dd000) = 0x65dd000 brk(0x65fe000) = 0x65fe000 brk(0x661f000) = 0x661f000 brk(0x6640000) = 0x6640000 brk(0x6661000) = 0x6661000 brk(0x6682000) = 0x6682000 brk(0x66a3000) = 0x66a3000 brk(0x66c4000) = 0x66c4000 brk(0x66e5000) = 0x66e5000 brk(0x6706000) = 0x6706000 brk(0x6727000) = 0x6727000 brk(0x6748000) = 0x6748000 brk(0x6769000) = 0x6769000 brk(0x678a000) = 0x678a000 brk(0x67ab000) = 0x67ab000 brk(0x67cc000) = 0x67cc000 brk(0x67ed000) = 0x67ed000 brk(0x680e000) = 0x680e000 root 223995 96.4 0.0 486100 166220 pts/7 R+ 14:33 11:00 /opt/perf record -a -g brk(0x682f000) = 0x682f000 brk(0x6850000) = 0x6850000 brk(0x6871000) = 0x6871000 brk(0x6892000) = 0x6892000 brk(0x68b3000) = 0x68b3000 brk(0x68d4000) = 0x68d4000 brk(0x68f5000) = 0x68f5000 brk(0x6916000) = 0x6916000 brk(0x6937000) = 0x6937000 brk(0x6958000) = 0x6958000 brk(0x6979000) = 0x6979000 brk(0x699a000) = 0x699a000 brk(0x69bb000) = 0x69bb000 brk(0x69dc000) = 0x69dc000 brk(0x69fd000) = 0x69fd000 brk(0x6a1e000) = 0x6a1e000 brk(0x6a3f000) = 0x6a3f000 brk(0x6a60000) = 0x6a60000 brk(0x6a81000) = 0x6a81000 brk(0x6aa2000) = 0x6aa2000 brk(0x6ac3000) = 0x6ac3000 brk(0x6ae4000) = 0x6ae4000 brk(0x6b05000) = 0x6b05000 brk(0x6b26000) = 0x6b26000 brk(0x6b47000) = 0x6b47000 brk(0x6b68000) = 0x6b68000 brk(0x6b89000) = 0x6b89000 brk(0x6baa000) = 0x6baa000 brk(0x6bcb000) = 0x6bcb000 brk(0x6bec000) = 0x6bec000 brk(0x6c0d000) = 0x6c0d000 brk(0x6c2e000) = 0x6c2e000 brk(0x6c4f000) = 0x6c4f000 brk(0x6c70000) = 0x6c70000 brk(0x6c91000) = 0x6c91000 brk(0x6cb2000) = 0x6cb2000 brk(0x6cd3000) = 0x6cd3000 brk(0x6cf4000) = 0x6cf4000 brk(0x6d15000) = 0x6d15000 brk(0x6d36000) = 0x6d36000 brk(0x6d57000) = 0x6d57000 brk(0x6d78000) = 0x6d78000 brk(0x6d99000) = 0x6d99000 brk(0x6dba000) = 0x6dba000 brk(0x6ddb000) = 0x6ddb000 brk(0x6dfc000) = 0x6dfc000 brk(0x6e1d000) = 0x6e1d000 brk(0x6e3e000) = 0x6e3e000 brk(0x6e5f000) = 0x6e5f000 brk(0x6e80000) = 0x6e80000 brk(0x6ea1000) = 0x6ea1000 brk(0x6ec2000) = 0x6ec2000 brk(0x6ee3000) = 0x6ee3000 But perf.data looks like collected correctly: ls -la perf.data -rw------- 1 root root 336M Окт 27 14:33 perf.data