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@entry=PIXMAN_OP_SRC, src=src@entry=0x1861920, mask=mask@entry=0x0, dest=dest@entry=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@entry=0x7f74f5838040 <spans>, extents=extents@entry=0x7ffd9ac6c7e0, boxes=boxes@entry=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@entry=0x1985b30, return_value=return_value@entry=0x7ffd9ac6ce80, n_param_values=n_param_values@entry=2, param_values=param_values@entry=0x7ffd9ac6cee0, invocation_hint=invocation_hint@entry=0x7ffd9ac6ce60, marshal_data=marshal_data@entry=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@entry=0x18be400, signal_id=<optimized out>, detail=detail@entry=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@entry=0x7ffd9ac6ce80, n_param_values=2, param_values=param_values@entry=0x7ffd9ac6cee0, invocation_hint=invocation_hint@entry=0x7ffd9ac6ce60) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gclosure.c:804 #16 0x00007f74f5b6cfc1 in signal_emit_unlocked_R (node=node@entry=0x1889430, detail=detail@entry=0, instance=instance@entry=0x18be400, emission_return=emission_return@entry=0x7ffd9ac6cff0, instance_and_params=instance_and_params@entry=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@entry=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@entry=0x18be400 [GtkWindow], event=event@entry=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@entry=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@entry=0x19c2fb0, return_value=return_value@entry=0x0, instance=instance@entry=0x188e230, args=args@entry=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@entry=0x7ffd9ac6d5e0) at /build/glib2.0-wnDt2X/glib2.0-2.48.1/./gobject/gsignal.c:3294 #28 0x00007f74f5b7608f in g_signal_emit (instance=instance@entry=0x188e230, signal_id=<optimized out>, detail=detail@entry=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@entry=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@entry=<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@entry=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@entry=1, dispatch=dispatch@entry=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
