Message-ID: <1466526448.2944.18.camel@collabora.com>
Date:	Tue, 21 Jun 2016 18:27:28 +0200
From:	Emanuele Aina <emanuele.aina@...labora.com>
To:	linux-kernel@...r.kernel.org
Cc:	Peter Zijlstra <peterz@...radead.org>,
	Ingo Molnar <mingo@...hat.com>,
	Arnaldo Carvalho de Melo <acme@...nel.org>,
	Alexander Shishkin <alexander.shishkin@...ux.intel.com>
Subject: Incomplete backtraces/call stacks with `perf record --call-graph
 dwarf`

Hello,
 I'm trying to trace applications with the intention of creating a
flame chart of their execution and I'm (ab)using `perf` to do so.

Unfortunately I keep getting incomplete call stacks, ie. stacks that
don't end up in main(). Using `--call-graph dwarf` improves the
situation a bit by storing some complete chains but some events still
don't go up to main().

$ perf record --call-graph dwarf -p $PID
$ perf script
[...]
cairo-checker-p 16494 48335.846306:     397338 cycles:ppp: 
            7f0a24bbddd7 sse2_fill (/usr/lib/x86_64-linux-gnu/libpixman-1.so.0.33.6)
            7f0a24ba21fb _pixman_implementation_fill (/usr/lib/x86_64-linux-gnu/libpixman-1.so.0.33.6)
            7f0a24b5c8b9 pixman_fill (/usr/lib/x86_64-linux-gnu/libpixman-1.so.0.33.6)
            7f0a2940e0c6 fill_boxes (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a29447af0 clip_and_composite_boxes.part.11 (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a29447fce clip_and_composite_boxes (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a294482e9 _cairo_spans_compositor_mask (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a294027f9 _cairo_compositor_paint (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a2944b191 _cairo_surface_paint (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a2940b12f _cairo_gstate_fill (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a294042f9 _cairo_default_context_fill (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a293fd335 cairo_fill (/usr/lib/x86_64-linux-gnu/libcairo.so.2.11400.6)
            7f0a2aad1b8a gdk_window_begin_paint_region (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2af81487 gtk_main_do_event (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2000.6)
            7f0a2aab77b5 _gdk_event_emit (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2aac64f8 _gdk_window_process_updates_recurse_helper (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2aac761c gdk_window_process_updates_internal (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2aac77d3 gdk_window_process_updates_with_mode (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a29a121d4 _g_closure_invoke_va (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.4800.1)
            7f0a29a2c9a6 g_signal_emit_valist (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.4800.1)
            7f0a29a2d08f g_signal_emit (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.4800.1)
            7f0a2aabf76e gdk_frame_clock_paint_idle (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2aaadb38 gdk_threads_dispatch (/usr/lib/x86_64-linux-gnu/libgdk-3.so.0.2000.6)
            7f0a2973bac3 g_timeout_dispatch (/lib/x86_64-linux-gnu/libglib-2.0.so.0.4800.1)
            7f0a2973b05a g_main_context_dispatch (/lib/x86_64-linux-gnu/libglib-2.0.so.0.4800.1)
            7f0a2973b400 g_main_context_iterate.isra.29 (/lib/x86_64-linux-gnu/libglib-2.0.so.0.4800.1)
            7f0a2973b722 g_main_loop_run (/lib/x86_64-linux-gnu/libglib-2.0.so.0.4800.1)
            7f0a2af807d5 gtk_main (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2000.6)
                  40190c main (/home/em/zzz/cairo-checker-pattern)
            7f0a28e3c5f0 __libc_start_main (/lib/x86_64-linux-gnu/libc-2.22.so)
                  4011b9 _start (/home/em/zzz/cairo-checker-pattern)

cairo-checker-p 16494 48335.846485:     445044 cycles:ppp: 
            7f0a24b9352e bits_image_fetch_nearest_affine_normal_r5g6b5 (/usr/lib/x86_64-linux-gnu/libpixman-1.so.0.33.6)
            7f0a24ba063c general_composite_rect (/usr/lib/x86_64-linux-gnu/libpixman-1.so.0.33.6)

[...]

The first event is ok, I wonder why the second one does not chain up
like the first one (it's not something specific to libpixman, it
happens sometimes in libgtk-3 too).

Debug symbols are installed, gdb can get a full backtrace for
bits_image_fetch_nearest_affine_normal_r5g6b5() too:

gdb bits_image_fetch_nearest_affine_normal_r5g6b5()
> bt
#0  0x00007f74f0cdc450 in bits_image_fetch_nearest_affine_normal_r5g6b5 (iter=0x7ffd9ac65d10, mask=0x0) at ../../pixman/pixman-fast-path.c:3165
#1  0x00007f74f0ce963c in general_composite_rect (imp=0x1832e00, info=<optimized out>) at ../../pixman/pixman-general.c:220
#2  0x00007f74f0ca5761 in pixman_image_composite32 (op=op@...ry=PIXMAN_OP_SRC, src=src@...ry=0x1861920, mask=mask@...ry=0x0, dest=dest@...ry=0x19fc620, src_x=0, src_y=0, mask_x=0, mask_y=0, dest_x=0, dest_y=0, width=252, height=341) at ../../pixman/pixman.c:700
#3  0x00007f74f5556ac4 in composite_boxes (_dst=<optimized out>, op=<optimized out>, abstract_src=<optimized out>, abstract_mask=<optimized out>, src_x=0, src_y=0, mask_x=0, mask_y=0, dst_x=0, dst_y=0, boxes=0x7ffd9ac6c550, extents=0x7ffd9ac6c81c) at ../../../../src/cairo-image-compositor.c:538
#4  0x00007f74f5590a1a in clip_and_composite_boxes (boxes=0x7ffd9ac6c550, extents=0x7ffd9ac6c7e0, compositor=0x7f74f5838040 <spans>) at ../../../../src/cairo-spans-compositor.c:683
#5  0x00007f74f5590a1a in clip_and_composite_boxes (compositor=compositor@...ry=0x7f74f5838040 <spans>, extents=extents@...ry=0x7ffd9ac6c7e0, boxes=boxes@...ry=0x7ffd9ac6c550) at ../../../../src/cairo-spans-compositor.c:882
#6  0x00007f74f5590fce in clip_and_composite_boxes (compositor=0x7f74f5838040 <spans>, extents=0x7ffd9ac6c7e0, boxes=0x7ffd9ac6c550) at ../../../../src/cairo-spans-compositor.c:901
#7  0x00007f74f55912e9 in _cairo_spans_compositor_mask (_compositor=0x7f74f5838040 <spans>, extents=0x7ffd9ac6c7e0) at ../../../../src/cairo-spans-compositor.c:999
#8  0x00007f74f554b7f9 in _cairo_compositor_paint (compositor=0x7f74f5838040 <spans>, surface=0x1936c20, op=<optimized out>, source=<optimized out>, clip=<optimized out>) at ../../../../src/cairo-compositor.c:65
#9  0x00007f74f5594191 in _cairo_surface_paint (surface=0x1936c20, op=CAIRO_OPERATOR_SOURCE, source=0x7ffd9ac6cb20, clip=0x1936ec0) at ../../../../src/cairo-surface.c:2117
#10 0x00007f74f5553895 in _cairo_gstate_paint (gstate=0x1ab9bd8) at ../../../../src/cairo-gstate.c:1067
#11 0x00007f74f5546175 in INT_cairo_paint (cr=0x1ab9a10) at ../../../../src/cairo.c:2003
#12 0x000000000040177a in drawCallback (widget=0x18be400 [GtkWindow], cr=0x1ab9a10, userData=0x7ffd9ac6f401) at cairo-checker-pattern.c:121
#13 0x00007f74f70cb48c in _gtk_marshal_BOOLEAN__BOXED (closure=closure@...ry=0x1985b30, return_value=return_value@...ry=0x7ffd9ac6ce80, n_param_values=n_param_values@...ry=2, param_values=param_values@...ry=0x7ffd9ac6cee0, invocation_hint=invocation_hint@...ry=0x7ffd9ac6ce60, marshal_data=marshal_data@...ry=0x0) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkmarshalers.c:86
#14 0x00007f74f720bfaf in gtk_widget_draw_marshaller (closure=0x1985b30, return_value=0x7ffd9ac6ce80, n_param_values=2, param_values=0x7ffd9ac6cee0, invocation_hint=0x7ffd9ac6ce60, marshal_data=0x0) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkwidget.c:955
#18 0x00007f74f5b7608f in <emit signal ??? on instance 0x18be400 [GtkWindow]> (instance=instance@...ry=0x18be400, signal_id=<optimized out>, detail=detail@...ry=0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3441
    #15 0x00007f74f5b5afa5 in g_closure_invoke (closure=0x1985b30, return_value=return_value@...ry=0x7ffd9ac6ce80, n_param_values=2, param_values=param_values@...ry=0x7ffd9ac6cee0, invocation_hint=invocation_hint@...ry=0x7ffd9ac6ce60) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gclosure.c:804
    #16 0x00007f74f5b6cfc1 in signal_emit_unlocked_R (node=node@...ry=0x1889430, detail=detail@...ry=0, instance=instance@...ry=0x18be400, emission_return=emission_return@...ry=0x7ffd9ac6cff0, instance_and_params=instance_and_params@...ry=0x7ffd9ac6cee0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3629
    #17 0x00007f74f5b757f9 in g_signal_emit_valist (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>, var_args=var_args@...ry=0x7ffd9ac6d0a0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3395
#19 0x00007f74f7218ada in gtk_widget_draw_internal (widget=0x18be400 [GtkWindow], cr=0x1ab9a10, clip_to_size=<optimized out>) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkwidget.c:6983
#20 0x00007f74f7218dd9 in gtk_widget_send_expose (widget=widget@...ry=0x18be400 [GtkWindow], event=event@...ry=0x7ffd9ac6d2c0) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkwidget.c:7528
#21 0x00007f74f70ca492 in gtk_main_do_event (event=0x7ffd9ac6d2c0) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkmain.c:1798
#22 0x00007f74f6c007b5 in _gdk_event_emit (event=event@...ry=0x7ffd9ac6d2c0) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkevents.c:73
#23 0x00007f74f6c0f4f8 in _gdk_window_process_updates_recurse_helper (window=0x184a5c0 [GdkWaylandWindow], expose_region=<optimized out>) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkwindow.c:3587
#24 0x00007f74f6c1061c in gdk_window_process_updates_internal (window=0x184a5c0 [GdkWaylandWindow]) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkwindow.c:3733
#25 0x00007f74f6c107d3 in gdk_window_process_updates_with_mode (window=<optimized out>, recurse_mode=<optimized out>) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkwindow.c:3934
#26 0x00007f74f5b5b1d4 in _g_closure_invoke_va (closure=closure@...ry=0x19c2fb0, return_value=return_value@...ry=0x0, instance=instance@...ry=0x188e230, args=args@...ry=0x7ffd9ac6d5e0, n_params=<optimized out>, param_types=0x0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gclosure.c:867
#27 0x00007f74f5b759a6 in g_signal_emit_valist (instance=0x188e230, signal_id=<optimized out>, detail=0, var_args=var_args@...ry=0x7ffd9ac6d5e0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3294
#28 0x00007f74f5b7608f in g_signal_emit (instance=instance@...ry=0x188e230, signal_id=<optimized out>, detail=detail@...ry=0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3441
#29 0x00007f74f6c080bf in _gdk_frame_clock_emit_paint (frame_clock=frame_clock@...ry=0x188e230 [GdkFrameClockIdle]) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkframeclock.c:640
#30 0x00007f74f6c0876e in gdk_frame_clock_paint_idle (data=0x188e230) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdkframeclockidle.c:430
#31 0x00007f74f6bf6b38 in gdk_threads_dispatch (data=0x19acc40, data@...ry=<error reading variable: value has been optimized out>) at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gdk/gdk.c:720
#32 0x00007f74f5884ac3 in g_timeout_dispatch (source=0x1afab00, callback=<optimized out>, user_data=<optimized out>) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./glib/gmain.c:4577
#33 0x00007f74f588405a in g_main_context_dispatch (context=0x183c200) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./glib/gmain.c:3154
#34 0x00007f74f588405a in g_main_context_dispatch (context=context@...ry=0x183c200) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./glib/gmain.c:3769
#35 0x00007f74f5884400 in g_main_context_iterate (context=0x183c200, block=block@...ry=1, dispatch=dispatch@...ry=1, self=<optimized out>) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./glib/gmain.c:3840
#36 0x00007f74f5884722 in g_main_loop_run (loop=0x19773a0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./glib/gmain.c:4034
#37 0x00007f74f70c97d5 in gtk_main () at /build/gtk+3.0-UYMeaD/gtk+3.0-3.20.6/./gtk/gtkmain.c:1269
#38 0x000000000040190c in main (argc=2, argv=0x7ffd9ac6d998) at cairo-checker-pattern.c:152

I'm on Debian unstable, kernel 4.6.2-1 x86_64.

Any idea of what I'm doing wrong?

Thanks!

-- 

Emanuele Aina
www.collabora.com

Powered by blists - more mailing lists