profile: Migrate to new symbol API and remove addresses
authorSasha Goldshtein <goldshtn@gmail.com>
Thu, 9 Feb 2017 04:23:20 +0000 (23:23 -0500)
committerSasha Goldshtein <goldshtn@gmail.com>
Tue, 21 Feb 2017 09:30:43 +0000 (09:30 +0000)
The default profile output used to include stack addresses,
which are not used in 99+% of the cases.

tools/old/profile.py
tools/profile.py
tools/profile_example.txt

index 6f28eed..7dbc246 100755 (executable)
@@ -347,11 +347,11 @@ for k, v in sorted(counts.items(), key=lambda counts: counts[1].value):
     else:
         # print default multi-line stack output.
         for addr in kernel_stack:
-            print("    %016x %s" % (addr, aksym(addr)))
+            print("    %s" % aksym(addr))
         if do_delimiter:
             print("    --")
         for addr in user_stack:
-            print("    %016x %s" % (addr, b.sym(addr, k.pid)))
+            print("    %s" % b.sym(addr, k.pid))
         print("    %-16s %s (%d)" % ("-", k.name, k.pid))
         print("        %d\n" % v.value)
 
index 1b99f43..0658306 100755 (executable)
@@ -287,11 +287,11 @@ for k, v in sorted(counts.items(), key=lambda counts: counts[1].value):
     else:
         # print default multi-line stack output.
         for addr in kernel_stack:
-            print("    %016x %s" % (addr, aksym(addr)))
+            print("    %s" % aksym(addr))
         if do_delimiter:
             print("    --")
         for addr in user_stack:
-            print("    %016x %s" % (addr, b.sym(addr, k.pid)))
+            print("    %s" % b.sym(addr, k.pid))
         print("    %-16s %s (%d)" % ("-", k.name, k.pid))
         print("        %d\n" % v.value)
 
index ab1c4eb..25f9854 100644 (file)
@@ -9,67 +9,66 @@ Example output:
 # ./profile
 Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
 ^C
-    ffffffff81189249 filemap_map_pages
-    ffffffff811bd3f5 handle_mm_fault
-    ffffffff81065990 __do_page_fault
-    ffffffff81065caf do_page_fault
-    ffffffff817ce228 page_fault
-    00007fed989afcc0 [unknown]
+    filemap_map_pages
+    handle_mm_fault
+    __do_page_fault
+    do_page_fault
+    page_fault
+    [unknown]
     -                cp (9036)
         1
 
-    00007f31d76c3251 [unknown]
-    47a2c1e752bf47f7 [unknown]
+    [unknown]
+    [unknown]
     -                sign-file (8877)
         1
 
-    ffffffff813d0af8 __clear_user
-    ffffffff813d5277 iov_iter_zero
-    ffffffff814ec5f2 read_iter_zero
-    ffffffff8120be9d __vfs_read
-    ffffffff8120c385 vfs_read
-    ffffffff8120d786 sys_read
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
-    00007fc5652ad9b0 read
+    __clear_user
+    iov_iter_zero
+    read_iter_zero
+    __vfs_read
+    vfs_read
+    sys_read
+    entry_SYSCALL_64_fastpath
+    read
     -                dd (25036)
         4
 
-    0000000000400542 func_a
-    0000000000400598 main
-    00007f12a133e830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (13549)
         5
 
 [...]
 
-    ffffffff8105eb66 native_safe_halt
-    ffffffff8103659e default_idle
-    ffffffff81036d1f arch_cpu_idle
-    ffffffff810bba5a default_idle_call
-    ffffffff810bbd07 cpu_startup_entry
-    ffffffff817bf4a7 rest_init
-    ffffffff81d65f58 start_kernel
-    ffffffff81d652db x86_64_start_reservations
-    ffffffff81d65418 x86_64_start_kernel
+    native_safe_halt
+    default_idle
+    arch_cpu_idle
+    default_idle_call
+    cpu_startup_entry
+    rest_init
+    start_kernel
+    x86_64_start_reservations
+    x86_64_start_kernel
     -                swapper/0 (0)
         72
 
-    ffffffff8105eb66 native_safe_halt
-    ffffffff8103659e default_idle
-    ffffffff81036d1f arch_cpu_idle
-    ffffffff810bba5a default_idle_call
-    ffffffff810bbd07 cpu_startup_entry
-    ffffffff8104df55 start_secondary
+    native_safe_halt
+    default_idle
+    arch_cpu_idle
+    default_idle_call
+    cpu_startup_entry
+    start_secondary
     -                swapper/1 (0)
         75
 
 The output was long; I truncated some lines ("[...]").
 
-This default output prints stack traces as two columns (raw addresses, and
-then translated symbol names), followed by a line to describe the process (a
-dash, the process name, and a PID in parenthesis), and then an integer count
-of how many times this stack trace was sampled.
+This default output prints stack traces, followed by a line to describe the
+process (a dash, the process name, and a PID in parenthesis), and then an
+integer count of how many times this stack trace was sampled.
 
 The output above shows the most frequent stack was from the "swapper/1"
 process (PID 0), running the native_safe_halt() function, which was called
@@ -95,57 +94,57 @@ Profiling just that process:
 # ./profile -p 25036
 Sampling at 49 Hertz of PID 25036 by user + kernel stack... Hit Ctrl-C to end.
 ^C
-    0000000000402748 [unknown]
-    00007fc56561422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (25036)
         1
 
-    00007fc5652ada0e __write
+    __write
     -                dd (25036)
         1
 
-    00007fc5652ad9b0 read
+    read
     -                dd (25036)
         1
 
 [...]
 
-    00000000004047b2 [unknown]
-    00007fc56561422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (25036)
         2
 
-    ffffffff817cc060 entry_SYSCALL_64_fastpath
-    00007fc5652ada10 __write
-    00007fc56561422c [unknown]
+    entry_SYSCALL_64_fastpath
+    __write
+    [unknown]
     -                dd (25036)
         3
 
-    ffffffff817cc060 entry_SYSCALL_64_fastpath
-    00007fc5652ad9b0 read
+    entry_SYSCALL_64_fastpath
+    read
     -                dd (25036)
         3
 
-    ffffffff813d0af8 __clear_user
-    ffffffff813d5277 iov_iter_zero
-    ffffffff814ec5f2 read_iter_zero
-    ffffffff8120be9d __vfs_read
-    ffffffff8120c385 vfs_read
-    ffffffff8120d786 sys_read
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
-    00007fc5652ad9b0 read
-    00007fc56561422c [unknown]
+    __clear_user
+    iov_iter_zero
+    read_iter_zero
+    __vfs_read
+    vfs_read
+    sys_read
+    entry_SYSCALL_64_fastpath
+    read
+    [unknown]
     -                dd (25036)
         3
 
-    ffffffff813d0af8 __clear_user
-    ffffffff813d5277 iov_iter_zero
-    ffffffff814ec5f2 read_iter_zero
-    ffffffff8120be9d __vfs_read
-    ffffffff8120c385 vfs_read
-    ffffffff8120d786 sys_read
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
-    00007fc5652ad9b0 read
+    __clear_user
+    iov_iter_zero
+    read_iter_zero
+    __vfs_read
+    vfs_read
+    sys_read
+    entry_SYSCALL_64_fastpath
+    read
     -                dd (25036)
         7
 
@@ -162,41 +161,41 @@ Lets add delimiters between the user and kernel stacks, using -d:
 
 # ./profile -p 25036 -d
 ^C
-    ffffffff8120b385 __vfs_write
-    ffffffff8120d826 sys_write
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
+    __vfs_write
+    sys_write
+    entry_SYSCALL_64_fastpath
     --
-    00007fc5652ada10 __write
+    __write
     -                dd (25036)
         1
 
     --
-    00007fc565255ef3 [unknown]
-    00007fc56561422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (25036)
         1
 
-    ffffffff813d4569 iov_iter_init
-    ffffffff8120be8e __vfs_read
-    ffffffff8120c385 vfs_read
-    ffffffff8120d786 sys_read
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
+    iov_iter_init
+    __vfs_read
+    vfs_read
+    sys_read
+    entry_SYSCALL_64_fastpath
     --
-    00007fc5652ad9b0 read
+    read
     -                dd (25036)
         1
 
 [...]
 
-    ffffffff813d0af8 __clear_user
-    ffffffff813d5277 iov_iter_zero
-    ffffffff814ec5f2 read_iter_zero
-    ffffffff8120be9d __vfs_read
-    ffffffff8120c385 vfs_read
-    ffffffff8120d786 sys_read
-    ffffffff817cc076 entry_SYSCALL_64_fastpath
+    __clear_user
+    iov_iter_zero
+    read_iter_zero
+    __vfs_read
+    vfs_read
+    sys_read
+    entry_SYSCALL_64_fastpath
     --
-    00007fc5652ad9b0 read
+    read
     -                dd (25036)
         9
 
@@ -210,59 +209,59 @@ func_b(). Profiling it for 5 seconds:
 # ./profile -p `pgrep -n func_ab` 5
 Sampling at 49 Hertz of PID 2930 by user + kernel stack for 5 secs.
 
-    000000000040053e func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         2
 
-    0000000000400566 func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         3
 
-    000000000040053a func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         5
 
-    0000000000400562 func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         12
 
-    000000000040056a func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         19
 
-    0000000000400542 func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         22
 
-    0000000000400571 func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         64
 
-    0000000000400549 func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         72
 
@@ -540,33 +539,33 @@ You can increase or decrease the sample frequency. Eg, sampling at 9 Hertz:
 # ./profile -F 9
 Sampling at 9 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
 ^C
-    000000000040056a func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         1
 
 [...]
 
-    ffffffff8105eb66 native_safe_halt
-    ffffffff8103659e default_idle
-    ffffffff81036d1f arch_cpu_idle
-    ffffffff810bba5a default_idle_call
-    ffffffff810bbd07 cpu_startup_entry
-    ffffffff8104df55 start_secondary
+    native_safe_halt
+    default_idle
+    arch_cpu_idle
+    default_idle_call
+    cpu_startup_entry
+    start_secondary
     -                swapper/3 (0)
         8
 
-    ffffffff8105eb66 native_safe_halt
-    ffffffff8103659e default_idle
-    ffffffff81036d1f arch_cpu_idle
-    ffffffff810bba5a default_idle_call
-    ffffffff810bbd07 cpu_startup_entry
-    ffffffff817bf497 rest_init
-    ffffffff81d65f58 start_kernel
-    ffffffff81d652db x86_64_start_reservations
-    ffffffff81d65418 x86_64_start_kernel
+    native_safe_halt
+    default_idle
+    arch_cpu_idle
+    default_idle_call
+    cpu_startup_entry
+    rest_init
+    start_kernel
+    x86_64_start_reservations
+    x86_64_start_kernel
     -                swapper/0 (0)
         8
 
@@ -577,99 +576,99 @@ For example, just user stacks:
 # ./profile -U
 Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
 ^C
-    0000000000402ccc [unknown]
-    00007f45a624422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    0000000000404b80 [unknown]
-    00007f45a624422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    0000000000404d77 [unknown]
-    00007f45a624422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    00007f45a5e85e5e [unknown]
-    00007f45a624422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    0000000000402d12 [unknown]
-    00007f45a624422c [unknown]
+    [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    0000000000400562 func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         1
 
-    0000000000404805 [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    00000000004047de [unknown]
+    [unknown]
     -                dd (2931)
         1
 
-    0000000000400542 func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         3
 
-    00007f45a5edda10 __write
-    00007f45a624422c [unknown]
+    __write
+    [unknown]
     -                dd (2931)
         3
 
-    000000000040053a func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         4
 
-    000000000040056a func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         7
 
     -                swapper/6 (0)
         10
 
-    0000000000400571 func_b
-    00000000004005ac main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_b
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         10
 
-    00007f45a5edda10 __write
+    __write
     -                dd (2931)
         10
 
-    0000000000400549 func_a
-    0000000000400598 main
-    00007f0458819830 __libc_start_main
-    083e258d4c544155 [unknown]
+    func_a
+    main
+    __libc_start_main
+    [unknown]
     -                func_ab (2930)
         11
 
-    00007f45a5edd9b0 read
+    read
     -                dd (2931)
         12
 
-    00007f45a5edd9b0 read
-    00007f45a624422c [unknown]
+    read
+    [unknown]
     -                dd (2931)
         14