Monday, January 12, 2015

Find the Fun in "How difficult can debugging mem leaks on mobile be?"; Or : an afternoon spent with Valgrind!

So!

QuickBar on SailfishOS has come a decent way, I would say. We've got :
  * full apps support (both android and native);
  * device-lock screen support;
  * Swipe-launch
  * on-lockscreen presence
  * favourites.

And we have more to come:
  * autostart
  * integration with event screen
  * ...

All in all, a nice (still little) stash of features!
Recently I have been wondering; given SailfishOS's problem with memory management, how does Quickbar's memory footprint affect the overall performance of the system? The application is omnipresent  once launced, and farily easily interacted with. Consequently, a memory leak might threaten stability of the system quite severly if left to run on it's own unnoticed.
Given this thought, I decided to focus on memory consumption next. So, I went off into this investigation by first figuring out the overall size of the memory footprint of QuickBar. There is this utility, pmap, which perfectly fits this purpose. So, devel-su/pkcon install pmap, pmap -x .Upon the first result, I jumped on my chair : Quickbar used a whole whopping 130 MB!! 

Subsequent measures re-confirmed this number. So somewhere memory is either leaking very badly, or ressource usage is not optimized at all. This needed to be investigated more in detail, which led to the hunt for more to this purpouse suitable tools.
The search lead me to Valgrind, open-source tool with excellent run-time analysis toolkit. I fired up a putty term, devel-su / pkcon install valgrind, crossed my fingers, and to my surprise the tool is present in Mer, so it got installed and I was ready to go. First thing to do, was to gain more knowledge on the command line. For my specific purpouses (memory leakage), I came up with the following minimalistic command line:

   --workaround-gcc296-bugs=yes       Ignore a Known compiler issue
   --show-leak-kinds=all                       Display all kinds of leaks
   --log-file=/tmp/output-valgrind.txt   Logfile location
   --leak-check=full                               Check for all possible memory leaks
   --tool=memcheck                              Toolkit for memory check

As a test round, I built a standard Sailfish app in default configuration (meaning debug mode, no optimizations, QML debugging on), deployed it (and the relative debug symbols) to the device. pmap for this empty app gives a default memory footprint of 127MB (which relaxed my nerves a bit). So then next was the run it in Valgrid (BTW, All the type of analysis provided in the trace log are explained down to the detail in the Valgrind manual - brace for long read).

Running the commandline above against my emptyapp test application, gave me a typical recap for the result of the analysis in question (given the due time spent waiting due to the performance impact):
==8455== Memcheck, a memory error detector
==8455== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.
==8455== Using Valgrind-3.9.0 and LibVEX; rerun with -h for copyright info
==8455== Command: emptyapp
==8455== Parent PID: 8454
......
==8455== LEAK SUMMARY:
==8455==    definitely lost: 409 bytes in 31 blocks
==8455==    indirectly lost: 46,302 bytes in 500 blocks
==8455==      possibly lost: 173,058 bytes in 1,344 blocks
==8455==    still reachable: 1,384,442 bytes in 16,850 blocks
==8455==         suppressed: 0 bytes in 0 blocks
==8455==
==8455== For counts of detected and suppressed errors, rerun with: -v
==8455== Use --track-origins=yes to see where uninitialised values come from
==8455== ERROR SUMMARY: 3717 errors from 35 contexts (suppressed: 0 from 0)
Notice how Valgrind gives you the option to (tentatively) track origins of memory leaks (not used in this case). Entries in the tracelog file are for example:

==8455== Invalid read of size 4
==8455==    at 0x401A8BC: ??? (in /lib/ld-2.15.so)
==8455==  Address 0x78c52dc is 52 bytes inside a block of size 54 alloc'd
==8455==    at 0x4838CBC: malloc (vg_replace_malloc.c:291)
==8455==    by 0x4008B0F: ??? (in /lib/ld-2.15.so)
==8455==
==8455== Syscall param sendmsg(msg.msg_iov[0]) points to uninitialised byte(s)
==8455==    at 0x554D544: sendmsg (in /lib/libpthread-2.15.so)
==8455==  Address 0x78c9dde is 4,158 bytes inside a block of size 16,424 alloc'd
==8455==    at 0x4838CBC: malloc (vg_replace_malloc.c:291)
==8455==    by 0x7F29E53: ??? (in /usr/lib/libwayland-client.so.0.1.0)
==8455==
==8455== Conditional jump or move depends on uninitialised value(s)
==8455==    at 0x7CA7988: mmap (in /system/lib/libc.so)
==8455==
==8455== Syscall param mmap2(length) contains uninitialised byte(s)
==8455==    at 0x7C9AAD8: __mmap2 (in /system/lib/libc.so)
==8455==
==8455== Syscall param mmap2(offset) contains uninitialised byte(s)
==8455==    at 0x7C9AAD8: __mmap2 (in /system/lib/libc.so)
==8455==
==8455== 20 bytes in 1 blocks are still reachable in loss record 138 of 538
==8455==    at 0x4837D5C: operator new[](unsigned int) (vg_replace_malloc.c:378)
==8455==    by 0x7E2F131: std::_Locale_impl::make_classic_locale() (in /system/lib/libstlport.so)
==8455==
....
==8455== 20 bytes in 1 blocks are still reachable in loss record 139 of 538
==8455==    at 0x4837D5C: operator new[](unsigned int) (vg_replace_malloc.c:378)
==8455==    by 0x7E2F141: std::_Locale_impl::make_classic_locale() (in /system/lib/libstlport.so)
==8455==

.....
==8455== 2,560 bytes in 2 blocks are possibly lost in loss record 468 of 538
==8455==    at 0x4837D5C: operator new[](unsigned int) (vg_replace_malloc.c:378)
==8455==    by 0x7E3B4A5: std::__node_alloc_impl::_S_chunk_alloc(unsigned int, int&) (in /system/lib/libstlport.so)

......
==8455== 46,430 (128 direct, 46,302 indirect) bytes in 1 blocks are definitely lost in loss record 533 of 538
==8455==    at 0x48365A8: calloc (vg_replace_malloc.c:618)
==8455==    by 0x7F01437: xkb_state_new (in /usr/lib/libxkbcommon.so.0.0.0)
==8455==
==8455== 59,204 bytes in 1,092 blocks are possibly lost in loss record 534 of 538
==8455==    at 0x4838CBC: malloc (vg_replace_malloc.c:291)
==8455==    by 0x51E69D7: QArrayData::allocate(unsigned int, unsigned int, unsigned int, QFlags) (in /usr/lib/libQt5Core.so.5.2.2)
==8455== 

We have uninitialized values on conditional jumps and syscalls(not much we can do about these) ;
the "still reachable" data's are - in a very simplified view - mostly pointers not nullified (i.e. pointing to void) or pointing to non-standard locations (cookies before the memory array, some compilers use them to store information like the length of the memory array etc).
The ones you want to keep an eye upon are the "possibly lost" and "definitely lost" ones, which pin-point possible and almost certain memory leaks respectively.

The memory foot print of the same empty app in Release mode (obtained via pmap ) returned a memory footprint of also 127 MBytes.

So, the question arised - if the footprint of a bare-bone Qt app is about 127 MBytes, how much is one without Qt? I headed back to my QtCreator, and built a non-qt c project (containing the default "Hello world" plus a sleep for 10 minutes); then deployed it to the phone, and ran a pmap check on it. The result on the first run (with no modifications to the project) was staggering : 87 MBytes!
Looking at the output of pmap, I discovered the one to blame, namely libQtCore, which was loaded as well. I decided to google around, and stumbled on this post, which seemed to hind to the fact that QtCreator automatically linked QtCore and QtGui even in non-qt projects unless told not to do so (in my case via a QT -= core gui in the .pro file).
So I went back, and added the line above to the project file, recompiled and copied over to the device, and re-run. The result was a significantly reduced memory foot print, which was between 2 and 3 megabytes.