Re: perf trace report with time consumed

[Milian Wolff <milian.wolff@kdab.com>]

[-- Attachment #1: Type: text/plain, Size: 5993 bytes --]

On Montag, 4. April 2016 08:14:08 CEST Jiri Olsa wrote:
> On Sun, Apr 03, 2016 at 08:46:19PM +0200, Milian Wolff wrote:
> > Jiri, see my mail below for the WIP patch below that triggers the crash
> > when DWARF callchains are enabled for `perf trace`.
> > 
> > Would be great if you could tell me what I'm missing.
> 
> would you please resend, I can't apply the one you posted
> 
> [jolsa@krava linux-perf]$ patch -p1 < /tmp/w
> patching file tools/perf/builtin-trace.c
> Hunk #1 FAILED at 34.
> patch: **** malformed patch at line 126: PRINT_IP_OPT_DSO | PRINT_IP_OPT_SYM
> /* TODO print_opts*/,

I send Jiri the patch off-list to which he replied:

> > so by enabling call graph you enabled code in unwind__prepare_access
> > which will set thread->priv which perf trace is already using for
> > some other stuff..
> > 
> > the thread__trace will think the thread->priv is already allocated
> > and rest of the code will access thread->priv as struct thread_trace
> > while it's allocated as unw_addr_space_t
> > 
> > I guess either perf trace or the unwind code need to change
> > another location for its private data in the thread..
> > we could move that dwarf private stuff to separate location
> > 
> > I'll prepare patch this week if I dont see anyone else doing that ;-)

This is indeed the reason, my naive approach of adding a `priv2` to `thread` 
and adding a "2" suffix to all uses of `thread__{set,}priv` in `builtin-
trace.c` makes it work:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
     0.174 ( 0.002 ms): ex_sleep/4390 close(fd: 3                                                           
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7e07 close (/usr/lib/ld-2.23.so)
            7f688a8bf20b _dl_sysdep_read_whole_file (/usr/lib/ld-2.23.so)
            7f688a8c5446 _dl_load_cache_lookup (/usr/lib/ld-2.23.so)
            7f688a8b79ba _dl_map_object (/usr/lib/ld-2.23.so)
            7f688a8bbcb2 openaux (/usr/lib/ld-2.23.so)
            7f688a8be264 _dl_catch_error (/usr/lib/ld-2.23.so)
            7f688a8bbf23 _dl_map_object_deps (/usr/lib/ld-2.23.so)
            7f688a8b2033 dl_main (/usr/lib/ld-2.23.so)
            7f688a8c629c _dl_sysdep_start (/usr/lib/ld-2.23.so)
            7f688a8b3d4a _dl_start (/usr/lib/ld-2.23.so)
            7f688a8afd98 _dl_start_user (/usr/lib/ld-2.23.so)
     0.200 ( 0.004 ms): ex_sleep/4390 open(filename: 0x8aad10b0, flags: 
CLOEXEC                             ) = 3
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7d07 open64 (/usr/lib/ld-2.23.so)
            7f688a8b58d8 open_verify.constprop.7 (/usr/lib/ld-2.23.so)
     0.204 ( 0.003 ms): ex_sleep/4390 read(fd: 3, buf: 0x7ffe4d16e7a8, count: 
832                           ) = 832
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7d27 read (/usr/lib/ld-2.23.so)
            7f688a8b591c open_verify.constprop.7 (/usr/lib/ld-2.23.so)
     0.210 ( 0.002 ms): ex_sleep/4390 fstat(fd: 3, statbuf: 0x7ffe4d16e640                                  
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7c94 _fxstat (/usr/lib/ld-2.23.so)
            7f688a8b44f2 _dl_map_object_from_fd (/usr/lib/ld-2.23.so)
LOST 1 events!
LOST 2 events!
LOST 2 events!
LOST 2 events!
LOST 4 events!
LOST 2 events!
LOST 4 events!
LOST 2 events!
LOST 2 events!
LOST 4 events!
  1000.525 (1000.317 ms): ex_sleep/4390  ... [continued]: nanosleep()) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
  1001.637 ( 1.091 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
            7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
            5582244227cd main (/tmp/ex_sleep)
  1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
            7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
            5582244227d7 main (/tmp/ex_sleep)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Is there a way to increase the event buffer or something like that to not lose 
events when the costly dwarf unwinding happens for the first time? Consecutive 
unwinding is cached by libunwind and much faster.

Alternatively, I could try to unwind in the `sys_enter`, but then I'd need to 
buffer the output to print the trace after the duration line...

How would you guys handle this situation?

Also, Jiri, Arnaldo - what would be your suggestion on how to handle the 
`thread::priv` situation - I doubt my naive `priv2` approach is acceptable.

Thanks

-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]