Debugging
From Buzztard
Finding errors in complex applications needs help. here we gather tips, tricks and examples.
Contents |
Debug Messages
To see whats going on inside your buzztard application you need some debugging support. Here we describe how you can use debugging support in buzztard and how to integrate in into your own code.
Writing debug messages
As buzztard uses gstreamer, we use their debugging methods. There are several general debug methods you can use:
- GST_LOG (level 5)
- GST_INFO (level 4)
- GST_DEBUG (level 3)
- GST_WARNING (level 2)
- GST_ERROR (level 1)
To generate a debug info use the GST_INFO method. For example to generate a debug info you can write following code:
GST_INFO("buzztard starts with %d arguments\n",argc);
To generate a debug message use the GST_DEBUG method. For example to generate a debug message you can write following code:
GST_DEBUG("failed to link the machines\n");
GST_WARNING and GST_ERROR are there to notify about problematic situations or definite errors.
Seeing the debug messages
Ok. You would like to see the debug messages? It is quite simple. To see all debug messages from gstreamer in Level 2 and from buzztard in Level 3 you can start your buzztard with following arguments:
./buzztard-edit --gst-debug="*:2,bt-*:3" song.bt
Attention! Following commandline will not produce the expected messages:
./buzztard-edit --gst-debug="*:3,bt-*:2" song.bt
You must use the levels in rising order 1 -> 2 -> 3 -> ...
To debug only buzztard in Level 3 you can start buzztard with following commandline option:
./buzztard-edit --gst-debug="bt-*:3" song.btz
Capturing the debug messages
Debug output can be a lot. And it sometimes wraps lines and so on. In such cases it would be nice to capture it and view it in a editor. Here is how to do it:
./buzztard-edit 2>debug.log --gst-debug-no-color --gst-debug="bt-*:4" --command=load --input-file=../share/buzztard/songs/buzz4.xml
I usually filter the output then by
cat debug.log | sed -e 's/ \+/ /g' | sed -e 's/([ 0-9]*) / /g' | sed -e 's/^\([A-Z]\)[A-Z]*/\1/g' | cut -d' ' -f 1,5-
This removes timestamps, thread number and squeezes log-level.
Compile-time problems
Macro issues
This email teaches a smart trick to track down issues with the preprocessor. It recommends to set CC when running make:
make CC='gcc -g -save-temps -Wp,-dD ...'
This will produce all macro definitions, expanded in .i files (those files can be made more reaable using GNU indent).
Run-time problems
Problems indicated by warnings/errors
During testing you might receive warnings in the console that you would like to trace. The plan is to trap the location with an error log statement and then make that statement fatal. This can be done with the following command:
gdb --args ./buzztard-edit --gst-debug="*:2,bt-*:3" --g-fatal-warnings
Short gdb introduction
In gdb start the app with the run command (or the shortcut r). When the app stops due to the error, use the backtrace (bt) command to see from where it comes.
Crashers
If the app terminates or hangs - try to remember what you did and rerun under gdb. Then tell us about the backtrace you got. In case the app hangs press Ctrl-C. That gets you back to gdb and lets you print the backtrace.
Better backtraces
Please have debug symbol packages installed.
One idea that helps in gtk/gstreamer apps is to get object names into the backtrace would be to log the (objectname,address) pairs from the library and use something like that to improve the backtrace (needs more work):
grep "gstobject.c" debug.log | cut -c101- | sed "s#<\(.*\)> \(0x.*\)#s/=\2/=\\<\1\\>/g#" | uniq -u >debug1.log sed -fdebug1.log gdb.txt >gdb_fmt.txt
gnome bug buddy
Normally gnome bug buddy would intercept the crasher and allow you to create a report. If this is not what you want, you can disable gnome bug-buddy with this env-var:
export GNOME_DISABLE_CRASH_DIALOG=1
Problems revealed by unit tests
If the application to test is uninstalled (e.g. a unit-test), this is the trick to get it to work:
libtool --mode=execute gdb ./bt_edit
If the binary is a unit test you should call it like this:
CK_FORK="no" libtool --mode=execute gdb ./bt_edit
Otherwise you wouldn't be able to get a stacktrace from gdb. Finnaly if you want gdb to stop on GLib warnings/criticals this may help:
CK_FORK="no" G_DEBUG="fatal_criticals" libtool --mode=execute gdb ./bt_edit
You can even run a single test under gdb:
CK_FORK=no BT_CHECKS="test_btsong_io_native_refcounts" /usr/bin/make bt_core.gdb
or
CK_FORK=no BT_CHECKS="test_btsong_io_native_refcounts" libtool --mode=execute gdb ./bt_edit
(Note that I used full path to make above as I use pretty_make and this would not start gdb interactively.)
G_DEBUG stoppers
If you want to find out whats the problem on a warning or a fatal error you can use the following G_DEBUG stopper:
G_DEBUG="fatal_criticals" G_DEBUG="fatal_warnings"
We have tests that only fail in fork mode. To find out about this we try:
1.) enable core dumps and load those (seems to do work)
ulimit -c 10000 make check cd tests libtool --mode=execute gdb ./bt_edit -c core.xxxxx
2.) try to follow new processes in gdb (we still don't get stack traces)
set follow-fork-mode child
Ressource usage
Debug GObject reference counting
Some wisdom about when to unref or not (buzztard specific):
- when getting a list (e.g. "machine" from setup), do not unref the machines in the list
- when getting a filtered-list from setup, do unref :(
Which actions ref an object?:
- g_object_get()
- g_value_dup_object()
- gtk_tree_model_get(store,&iter,col_id,&obj,-1);
... and which do not?:
- g_signal_connect()
- g_value_get_object()
Logging
One can sprinkle this all over the sources:
GST_DEBUG("object: %p refs: %d)",object,G_OBJECT_REF_COUNT(object);
RefDbg
Get the refdbg tool (for the time being consider the latest version) and install it. To find out about the ref-ct of e.g. BtMachine instances, start the binary as below:
LD_LIBRARY_PATH=$HOME/debug/lib:$LD_LIBRARY_PATH \ refdbg -c "btnum=8 ; logobjs=0 ; r0=<BtMachine> D:All L:All" ./buzztard-edit
Then look into refdbg.log.
Hint1: This will only work if you have the glib configured with the --disable-visibility flag which is for example not the default in most linux distributions.--waffel 15:18, 10 Jun 2005 (CEST)
Hint2: Since at least glib2-2.25 one also should configure --disable-Bsymbolic. --[[ensonic 22:28, 11 December 2010 (CET)]]
Another way is to use it in conjunction with gdb:
LD_LIBRARY_PATH=$HOME/debug/lib:$LD_LIBRARY_PATH \ refdbg -c "btnum=8 ; logobjs=0 ; r0=B:Error" gdb ./buzztard-edit
In this example it interrupts program execution whenever an ref-counting error has been detected.
One issue is a program that segfaults. This would not call the refdbg destructor and thus no refdbg.log would be written. But also here is a way out:
refdbg -c "btnum=20 ; logobjs=0 ; r0=<BtSourceMachine> D:None L:All" gdb ./buzztard-edit # now in gdb run # crash happend call refdbg_save_log () quit
To get a list of remaining object refs (and filter that somewhat):
LD_LIBRARY_PATH=$HOME/debug/lib:$LD_LIBRARY_PATH \ refdbg -c "btnum=0 ; r0=D:None L:None" ./buzztard-edit cat refdbg.log | egrep -v "(Atk|Gdk|Pango|GtkIMModule|GFile|GLocal|GDummy|Style)" | grep -v "Gtk.*Style" | grep -v "GstPlugin" | grep -v "Gst.*Factory" | grep -v "GstPadTemplate" >refdbg.flt.log
A complete session with the latest refdbg development version might look like this:
rm refdbg.log* refdbg -c "btnum=20 ; logobjs=0 ; r0=<BtPattern> D:Error L:All" gdb ./buzztard-edit refdbg-splitlog.pl refdbg-filterlog.pl refdbg.log.FAIL.xxxxxxx
Gdb
The GNU debugger is scriptable. We have one gdb script in the repo that gathers backtraces for particular ref/unref operations. The output is written to a log file. This log file is filtered by a perl script. The perl script reformats the backtraces, truncates them to strip common trailing stack frames and removes certain known ref/unref pairs to ease going through the remaining ones. For example one get from 156 frames for one testcase down to 20.
More resources:
SystemTap
glib/gobject contains a (yet) uninstalled file named gobject.stp inside the gobject folder. In theory a script like below should work. In does not on OpenSuse 11.3 because of bug 656091 and on Ubuntu 10.10 (Maverick).
#!/bin/sh dbglibdir=$HOME/debug/lib stap -v gobject.stp \ -d ../src/lib/core/.libs/libbuzztard-core.so \ -d ../src/lib/ic/.libs/libbuzztard-ic.so \ -d ${dbglibdir}/libglib-2.0.so \ -d ${dbglibdir}/libgobject-2.0.so \ -d ${dbglibdir}/libgtk-x11-2.0.so \ -d ./bt_edit \ -c ./bt_edit
Debug memory usage
One can use some envvar to make GLib and LibC more friendly to mem-leak checkers:
G_SLICE=always-malloc G_DEBUG=gc-friendly GLIBCPP_FORCE_NEW=1 GLIBCXX_FORCE_NEW=1
Use them with both valgrind and MALLOC_CHECK_*!
Valgrind
On the x86/ppc platforms one can use valgrind to check for memleaks. To do so run an app as below:
valgrind --tool=memcheck --leak-check=full --leak-resolution=high \ --trace-children=yes --num-callers=20 -v ./buzztard-edit
This works for uninstalled tests as well:
valgrind --tool=memcheck --leak-check=full --leak-resolution=high \ --trace-children=yes --num-callers=20 -v ./.libs/buzztard_cmd
If you have the GStreamer sources available, it might make sense to use the suppression file from there:
ln -s ~/projects/gstreamer-0.10/gstreamer/common/gst.supp ./ valgrind --tool=memcheck --leak-check=full --leak-resolution=high \ --trace-children=yes --num-callers=20 --suppressions=gst.supp -v ./buzztard-edit
There is also a supression file for gtk.
Finally if you have valgrind >= 3.4.x use --track-origins=yes in addition, when trying to find the reasons for uninitialized memory access.
We can also profile memory usage:
valgrind --tool=massif -v ./buzztard-edit
This generates files named massif.<pid>.ps and massif.<pid>.txt.
And remember - be patient - valgrind takes a while to run ;-).
LibC
The glibc on linux system provides some help as well. If one sees messages like
*** glibc detected *** free(): invalid pointer: 0x082587f4 ***
the one can rerun the program with an additional environment variable beeing set
MALLOC_CHECK_=3 gdb --args ./buzztard-cmd
A value of '2' causes glib to call abort after the error, which allows you top get a stacktrace from gdb. A value of '1' just shows the error and a value of 3 does both - showing the info plus aborting. A value of '0' ignores the error.
If this still not helps one can use MALLOC_TRACE: First add a call to mtrace() to start of main(), then recompile and link. Afterwards execute:
MALLOC_TRACE=heap.log ./myprog
This creates the log. Analyze it using
mtrace myprog heap.log
When using this for unittests add CK_FORK=no to make the failing test abort.
AddressSanitizer (ASan)
http://code.google.com/p/address-sanitizer/wiki/HowToBuild
Debug memory usage
For details see Profiling Memory Use in GNOME Software
valgrind --tool=massif --trace-children=yes --depth=5 \ --alloc-fn=g_malloc --alloc-fn=g_realloc --alloc-fn=g_try_malloc --alloc-fn=g_malloc0 --alloc-fn=g_mem_chunk_alloc \ ./buzztard-edit
Debug multi-threading issues
On the x86/ppc platforms one can use valgrind to check for threading issues. To do so run an app as below:
valgrind --tool=helgrind -v ./buzztard-edit
valgrind --tool=drd -v ./buzztard-edit
Library call stats
Valgrind comes with a tool called lackey that can be used to count call invocations:
valgrind --tool=lackey --fnname=malloc ./buzztard-cmd ...
The advantage of lackey over ltrace is that it works across libraries. The disadvantage is its slowness :/
Gtk+
Build yourself a gtk with --enable-debug=yes to e.g. $HOME/debug
Then call the application with:
LD_LIBRARY_PATH=$HOME/debug/lib:$LD_LIBARY_PATH GDK_PIXBUF_MODULE_FILE=/etc/gtk-2.0/gdk-pixbuf.loaders GTK_PATH=/usr/lib/gtk-2.0 ./buzztard-edit
If you have no /etc/gtk-2.0/gdk-pixbuf.loaders (like I had under ubuntu), run this command:
sudo gdk-pixbuf-query-loaders > /etc/gtk-2.0/gdk-pixbuf.loaders
There is a nice tool to peek into gtk uis at runtime called Parasite.
GDB Tips
To get the type-name of a gobject:
print g_type_name(((GTypeClass*)((GTypeInstance*)widget)->g_class)->g_type)
Makefiles
Debug command execution
Makefiles are not easy to debug. Read this article to learn some tricks. In essence add this to the top of the Makefile.am
OLD_SHELL := @SHELL@ SHELL = $(warning Building $@$(if $<, (from $<))$(if $?, ($? newer)))$(OLD_SHELL) -vx
Get a list of targets
grep '^[^#[:space:]][^=]*:' Makefile | sort
# in the directory containing your Makefile: make -rpn | sed -n -e '/^$/ { n ; /^[^ ]*:/p }' # ... or add a touch of color by highlighting the targets in the rules: make -rpn | sed -n -e '/^$/ { n ; /^[^ ]*:/p }' | egrep --color '^[^ ]*:'
An interesting patch to spit out a dot graph of the dependencies was proposed in august 2010 on gnu make list. Seems to not yet be included :/.
