GNOME Bugzilla – Bug 606044
Add support for dtrace/systemtap static markers
Last modified: 2010-11-26 12:35:26 UTC
Having some support for static markers for tracing is very useful when debugging apps or system behaviour. I have some initial probes that I will attach.
Created attachment 150787 [details] [review] Initial support for dtrace and systemtap This adds static markers for dtrace, which are also usable by systemtap. Additionally it adds a tapset for systemtap that makes it easier to use the static markers. --enable-dtrace will enable just the markers and --enable-systemtap will enable the markers and the systemtap tapsets. This initial set of probes is rather limited: * allocation and free using g_malloc & co * allocation and free using g_slice * gquark name tracking (useful for converting quarks to strings in probes) Notes on naming: Its traditional with dtrace to use probe names with dashes as delimiter (slice-alloc). Since dashes are not usable in identifiers the C code uses double underscores (slice__alloc) which is converted to dashes in the UI. We follow this for the shared lowlevel probe names. Additionally dtrace supports putting a "provider" part in the probe names which is essentially a namespacing thing. On systemtap this field is currently ignored (but may be implemented in the future), but this is not really a problem since in systemtap the probes are specified by combining the solib file and the marker name, so there can't really be name conflicts. For the systemtap tapset highlevel probes we instead use names that are systemtapish with single dashes as separators.
Created attachment 150788 [details] [review] Add dtrace and systemtap support for gobject This adds static markers and systemtap tapsets for: * type creation * object lifetimes (creation, ref, unref, dispose, finalize) * signal creation and emission Signal emissions and finalization marker have a corresponding *_end (or *-end in dtrace) version that is when the corresponding operation is finished.
See also: http://blogs.gnome.org/alexl/2010/01/04/tracing-glib/
Created attachment 157480 [details] [review] Initial support for dtrace and systemtap This adds static markers for dtrace, which are also usable by systemtap. Additionally it adds a tapset for systemtap that makes it easier to use the static markers. --enable-dtrace will enable just the markers and --enable-systemtap will enable the markers and the systemtap tapsets. This initial set of probes is rather limited: * allocation and free using g_malloc & co * allocation and free using g_slice * gquark name tracking (useful for converting quarks to strings in probes) Notes on naming: Its traditional with dtrace to use probe names with dashes as delimiter (slice-alloc). Since dashes are not usable in identifiers the C code uses double underscores (slice__alloc) which is converted to dashes in the UI. We follow this for the shared lowlevel probe names. Additionally dtrace supports putting a "provider" part in the probe names which is essentially a namespacing thing. On systemtap this field is currently ignored (but may be implemented in the future), but this is not really a problem since in systemtap the probes are specified by combining the solib file and the marker name, so there can't really be name conflicts. For the systemtap tapset highlevel probes we instead use names that are systemtapish with single dashes as separators.
Created attachment 157481 [details] [review] Add dtrace and systemtap support for gobject This adds static markers and systemtap tapsets for: * type creation * object lifetimes (creation, ref, unref, dispose, finalize) * signal creation and emission Signal emissions and finalization marker have a corresponding *_end (or *-end in dtrace) version that is when the corresponding operation is finished.
I rebased these two patches to git master, with some fixes: * Also generate the systemtap .o asm probe objects, since they appear to be required now; the generated headers reference a semaphore object per probe point. * Add a copyright header to gtrace.h
Also note that the bug Alex referenced ( http://sourceware.org/bugzilla/show_bug.cgi?id=11124 ) on the subject of systemtap inefficiency appears to have been fixed, so we should double check whether we can enable these probes on Fedora 14.
Review of attachment 157480 [details] [review]: One comment, but otherwise going to mark this ACN. ::: glib/glib_probes.d @@ +1,2 @@ + probe mem__alloc(void*, unsigned int, unsigned int, unsigned int); +provider glib { We should probably document these somehow; is the right place here or in the .stp.in file? I don't think it's obvious to someone looking at say "glib.mem_alloc" that "failable" means "this is a try_malloc".
Review of attachment 157481 [details] [review]: ::: gobject/gtrace.h @@ +1,2 @@ +#define __GLIBTRACE_H__ +#ifndef __GLIBTRACE_H__ Should probably rename this file to be clear it's for gobject; maybe call it gobject_trace.h? Also need a copyright.
Created attachment 157590 [details] [review] Initial support for dtrace and systemtap
Created attachment 157591 [details] [review] Add dtrace and systemtap support for gobject
I should mention this is still off by default, but it'd help if someone with x86 asm knowledge took a look at the updated SystemTap in Fedora 13 and checked whether the perf hit was acceptable.
I don't have principal objections to this. Here are some files that need to be changed: docs/reference/glib/building.sgml - include documentation about configure options docs/reference/glib/running.sgml - should probably add a section about profiling that should include a) a list of the current markers and b) some information on how to make use of this
(In reply to comment #13) > I don't have principal objections to this. > > Here are some files that need to be changed: > > docs/reference/glib/building.sgml - include documentation about configure > options Done. Though I realized, maybe we should wait on the performance analysis before putting this in, because I documented it as off-by-default, but that's not where we want to be ultimately. > docs/reference/glib/running.sgml - should probably add a section about > profiling that should include a) a list of the current markers and b) some > information on how to make use of this Documenting the tapset in running.sgml makes sense; but how about a live.gnome.org wiki page for example scripts? Or maybe we could have one or two in the docs, and then point to the wiki page for up-to-date user contributed examples?
I didn't do a thorough performance analysis, i just looked at the code and it added lots of unnecessary instructions (it should need very little). Verifying that the systemtap "fix" for this works is quite easy, just build with and without dtrace enabled and compare some of the affected functions in the gcc -S output.
Regarding the sdt.h-related extra instructions, actual measurements of the incremental cost of dormant (inactive) instrumentation would be very welcome. We expect these to be small because (a) most of it is to be bypassed under normal circumstances due to a semaphore variable that is normally 0, and (b) the bypassed part is labeled with gcc branch prediction directives that ought normally put it out of line of the hot instruction path.
Created attachment 159206 [details] [review] allow naming GSource, which could be used in a tapset A really useful tapset would replicate bug 588139 - namely, timing each GSource dispatch, and trying to show which source was dispatched and which took too long. Or similarly, doing a timeline of dispatches would be nice. I think part of such a tapset would be this attached patch to add g_source_set_name() or something. The tracing in gmain.c dispatch though should also give the name of the source's callback, as in bug 588139. This would be useful instead of or in addition to the manually-set source name. I don't know if systemtap can already find the name of a function pointer or if a bfd hack as in bug 588139 would be required. something like: TRACE (GLIB_BEFORE_SOURCE_DISPATCH(source, callback, source_name)); TRACE (GLIB_AFTER_SOURCE_DISPATCH(source, callback, source_name)); where callback is either the raw function pointer if systemtap etc. can use that, or a callback name somehow otherwise, I don't know. The point of this would be to find interactivity problems in apps.
Created attachment 160852 [details] [review] Initial support for dtrace and systemtap This is a simple rebase to the current git master.
Created attachment 160853 [details] [review] Add dtrace and systemtap support for gobject Rebased to git master.
Created attachment 160854 [details] disassembly and gobject-performance benchmark with dtrace disabled
Created attachment 160855 [details] disassembly and gobject-performance benchmark with dtrace enabled
As you can see from comparing the benchmark numbers, there's a ~3% slowdown in the gobject-performance benchmark. My instinct is that for real-world applications, this is going to end up being noise, basically, because creating and destroying GObjects isn't where most apps spend a lot of time.
But Alex - could you take a look at the attached disassembly? A little bit of system information. The benchmarks were run on a Fedora 13 virtual machine. walters@localhost glib]$ rpm -q gcc gcc-4.4.4-2.fc13.x86_64 [walters@localhost glib]$ uname -a Linux localhost.localdomain 2.6.33.3-85.fc13.x86_64 #1 SMP Thu May 6 18:09:49 UTC 2010 x86_64 x86_64 x86_64 GNU/Linux [walters@localhost glib]$ cat /etc/system-release Fedora release 13 (Goddard) [walters@localhost glib]$
Review of attachment 159206 [details] [review]: This patch looks fine to me.
Colin, would you mind running another build/benchmark, by adding #undef STAP_HAS_SEMAPHORES into the dtrace-generated .h file, replacing the #define STAP_HAS_SEMAPHORES one? It looks like the semaphore logic may be counter-productive in the simple case of the gobject allocate function.
Created attachment 160865 [details] disassembly and gobject-performance benchmark with dtrace enabled (but no semaphores) Ok, this one should be without semaphores.
The dissassembly in comment 26 without HAS_SEMAPTHORES is identical to the non-dtrace version, which is exactly what we want here (and it should be easily possible for such a trivial marker). However, the semaphores one does an extra semaphore check: db8c: 48 8b 05 7d 8d 23 00 mov 0x238d7d(%rip),%rax db93: 66 83 38 00 cmpw $0x0,(%rax) db97: 75 50 jne dbe9 <g_object_ref+0xc9> plus it spills stuff more on the stack and has some extra out of line code for the actual marker code. For the common case this amounts to larger code cache footprint, one memory read that may be uncached and/or frequently read on other cpus, and a few extra instructions executed. This is not horrible, but its kinda irritating when you know nothing of it is needed. So, I don't really agree with the decision to make every probe use semaphores, In fact I deliberately designed the marker points so that minimal or no extra data would need to be calculated for the marker (which is why e.g. the g_object_ref probe returns the old value and the gobject.object_ref probe has to manually add +1 to get the new one). Semaphores are interesting when the marker has to do a lot of work calculating otherwise unused values, but they are pure overhead when its not needed. I would prefer if you had to enable semaphore use on a per-marker level. Also, colin, if you want to look at assembly output, don't disassemble like that, instead look at the assembly produced by gcc when you build with -S (and optionally -fverbose-asm might be interesting)
Alexander, I agree. In stap land we'll improve sdt.h to parametrize and/or automate the semaphore logic. I am a bit suspicious of Colin's last version though, since there ought to be at least a nop inserted into the instruction stream. I wonder if the sdt.h stuff was entirely disabled by accident in that build. http://sourceware.org/bugzilla/show_bug.cgi?id=11592
Review of attachment 159206 [details] [review]: Shouldn't the name be freed in g_source_unref_internal when the source is destroyed?
(In reply to comment #29) > Review of attachment 159206 [details] [review]: > > Shouldn't the name be freed in g_source_unref_internal when the source is > destroyed? Good catch Nick! I've fixed this in my local commit, along with a few cleanups to the docs, and I've annotated some of the glib mainloop test just to get some coverage of the function.
Created attachment 162059 [details] gcc -S disassembly and gobject-performance benchmark with dtrace disabled This time with gcc -S
Created attachment 162060 [details] disassembly and gobject-performance benchmark with dtrace enabled (but no semaphores) this time with gcc -S
So, it looks to me like the difference between the two is pure noise, i.e. within 1%. But I need another analysis of the disassembly. I have a new patch prepped which enables this by default, in anticipation of a positive outcome.
Created attachment 162062 [details] [review] Initial support for dtrace and systemtap * Enabled by default * Add documentation to running.sgml * Document each probe point using the SystemTap doc style
Created attachment 162063 [details] [review] Add dtrace and systemtap support for gobject * Document each probe point
The attachement in comment #32 doesn't have the whole function in it, it only shows the first part of the marker (the probe section stuff). You need to go on until: .size IA__g_object_ref, .-IA__g_object_ref .p2align 4,,15 or something like that.
Created attachment 162111 [details] gcc -S disassembly and gobject-performance benchmark with dtrace disabled
Created attachment 162112 [details] gcc -S disassembly and gobject-performance benchmark with dtrace enabled (no semaphores)
Note the new code is generated with: [walters@lightbox gobject (systemtap)]$ rpm -q gcc gcc-4.4.4-5.el6.x86_64 [walters@lightbox gobject (systemtap)]$ cat /etc/redhat-release Red Hat Enterprise Linux Workstation release 6.0 Beta (Santiago) [walters@lightbox gobject (systemtap)]$ cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 15 model name : Intel(R) Core(TM)2 Duo CPU E6850 @ 3.00GHz stepping : 11 cpu MHz : 2000.000 cache size : 4096 KB
Yes, I like this one. It adds one extra register being saved and restored on the stack (%rbx), adding 2 instructions on entry and 2 on exit. The extra instructions it uses for the actual marker is: movl %eax, %ebp # Move old refcount to %ebp movq (%rbx), %rax # Store class pointer in %rax nop /* %rbx (%rax) %ebp */ # NOP Instruction that will be breakpoint So, a total of 7 instructions, including 1 memory read that may not be cached (wheras the 2 stack memory accesses are certainly cached). I very much doubt that anyone cares about this effect on performance. Some other probes are a bit more complex, but I doubt any slowdown will be measurable.
Attachment 162062 [details] pushed as bef9efd - Initial support for dtrace and systemtap Attachment 162063 [details] pushed as 8e41be1 - Add dtrace and systemtap support for gobject
Ok, let's go with this then. The pushed patch is on by default. Awesome work alex! It's already helped me a lot with GNOME Shell work.
colin: Please publicize this a bit to get more people to use systemtap, its kinda unknown atm, which is sad, given how very useful it is. Maybe we can start a wiki page with example stap scripts for various kind of debugging problems.
We'd welcome such scripts in the systemtap distribution proper, and/or http://sourceware.org/systemtap/wiki/WarStories
Should the files be actually installed somewhere as part of "make install"? Also having something more useful in http://library.gnome.org/devel/glib/stable/glib-running.html under "SystemTap" headline would help people to get started. What about a gnome-journal article about it?