Profiling your application with Valgrind Callgrind: Icinga2

We are using a variety of tools to ensure that our applications do not leak memory, suffer from performance issues or actually trigger unwanted behavior. This tool stack changes over time, and it is also different for web, script and binary applications. Next to the Icinga bits I am responsible for the LConf Backend and other Perl foo here at NETWAYS – I’ve already written about profiling Perl. During Icinga 1.x and 2.x development we’ve come around a couple of tools for profiling memory consumption with Massif or using the Google perftools.
One of our specialties at NETWAYS Development is further that we’re capable of identifying and resolving issues directly – be it performance, memory, locking, race conditions, etc. aside from the code we’re developing and running at customers.

The perfect code vs performance

While the perfect code does not exist, it’s always interesting and also required to refactor your own code parts based on current conditions and requirements. The code in 2.2.4 had one function interface being called, namely AddObject(). This function is merely doing the following for ‘repository add’ and ‘node update-config’:

  • Get all the object names from `repository.d` and checking if the added object already exists
  • Create a new object by attributes and run it against the Icinga 2’s config validation
  • Check if the change already exists by reading the `changes` directory
  • Add the change to the changelog (for calling ‘commit’ later on)

This is perfectly fine for keeping the same functionality shared among several occasions where this code is used. But we’ve run into severe performance issues with like 20000 calls to AddObject() inside one ‘node update-config’ run.

How to tackle the problem

Valgrind provides a tool named callgrind which tracks the function calls and time of a specific binary being run. While this is a bit slower than the Google perftools, it provides more detailed data. The ‘callgring.out.PID’ file can then be visualized in KCacheGrind.
Install Valgrind alongside with KcacheGrind. I’m using Fedora 21, other distributions use similar package names.

# yum install valgrind kcachegrind graphviz

In order to profile Icinga 2 with all debug symbols included, I’m compiling Icinga 2 with debug symbols enabled: -DCMAKE_BUILD_TYPE=Debug (Note: Using Icinga 2 packages you’ll get a separate package).
Valgrind requires a bunch of parameters which are easier being modified in a small script. I’m also running the direct debug build binaries instead of the installed binary here. Generating some sort of huge debug config inside the Icinga 2 cluster and node inventory is left to the reader’s imagination 😉 (I’ll write a different blog post for that sooner or later).

# vim callgrind_icinga2
#!/bin/bash
valgrind \
-v \
--trace-children=yes \
--tool=callgrind \
--simulate-cache=yes \
--collect-jumps=yes \
--dump-instr=yes \
--dump-line=yes \
/home/michi/coding/icinga/icinga2/debug/Bin/Debug/icinga2 node update-config
# sudo ./callgrind_icinga2

If you want to enforce a manual dump before the program ends, you can invoke the following command:

# callgrind_control -d

 

Visualize and analyze the bottlenecks

Opening the callgrind.out file(s)

$ sudo kcachegrind callgrind.out.16903

unveiled that there were certain unnecessary calls to generic functions.

  • Getting objects/changes on each AddObject() call is useless
  • ‘node update-config’ would cause AddObject() to validate each object. But we know already we’re right not parsing user’s input from the cli arguments.

Solve the problem

Refactoring the code and allowing to pass one-time collected objects/changes as well as suppressing configuration validation solved the problem in the end. Still it unveiled that you should sometimes stop feature development and profile your own application 🙂

Michael Friedrich
Michael Friedrich
Senior Developer

Michael ist seit vielen Jahren Icinga-Entwickler und hat sich Ende 2012 in das Abenteuer NETWAYS gewagt. Ein Umzug von Wien nach Nürnberg mit der Vorliebe, österreichische Köstlichkeiten zu importieren - so mancher Kollege verzweifelt an den süchtig machenden Dragee-Keksi und der Linzer Torte. Oder schlicht am österreichischen Dialekt der gerne mit Thomas im Büro intensiviert wird ("Jo eh."). Wenn sich Michael mal nicht in der Community helfend meldet, arbeitet er am nächsten LEGO-Projekt oder geniesst...

Heap-Fragmentation analysieren

Bei Dateisystemen ist der Fragmentations-Effekt ziemlich bekannt:

  1. Zunächst werden viele Dateien erstellt.
  2. Einige dieser Dateien werden anschließend gelöscht.
  3. Wenn nun eine große Datei angelegt wird und anderweitig kein Platz mehr frei ist, wird diese in mehrere Teile aufgesplittet, um die entstandenen Lücken zu füllen. – Es entsteht Fragmentation.

Während das Problem bei Dateisystemen durch Neuanordnung der Dateiteile (Defragmentation) vergleichsweise einfach gelöst werden kann, gibt es beim Arbeitsspeicher ein ähnliches Problem, das sich nicht ganz so einfach in den Griff bekommen lässt.
Für malloc() muss die libc immer mehr Speicher vom Kernel anfordern, wenn kein Speicherbereich mehr frei ist, der groß genug ist. Dabei kann die libc bestehende Allocations nicht im Speicher verschieben, da sie nicht weiss, wo die Anwendung Pointer auf diese Allocations besitzt. Eine nachträgliche Defragmentierung ist somit nicht möglich.
Um dieses Problem zu veranschaulichen, habe ich einen Profiler geschrieben (fprofile.cpp), der malloc(), realloc() und free() instrumentiert, um beobachten zu können, wie sich die Speicherbenutzung bei meinem Testprogramm (Icinga 2) mit der Zeit verändert.
Der Profiler ist eine Library, die prinzipiell aus zwei Teilen besteht:

  • Einem eigenen Allocator: Der Profiler benötigt für die Profil-Daten selbst Speicher. Wenn ich hier malloc() verwenden würde, würde der Profiler eventuell selbst zur Heap-Fragmentation beitragen. Deswegen habe ich einen vergleichsweise naiven Allocator geschrieben, der intern mmap() verwendet.
  • Dem eigentlichen Profiler: Um malloc(), realloc() und free() durch meine eigenen Funktionen ersetzen zu können, muss die Library per LD_PRELOAD geladen werden. Der Profiler merkt sich, welche Speicherbereiche von malloc() “belegt” wurden und schreibt diese Informationen sekündlich als Bild in eine Datei. Die Wahl ist dabei auf das PNM-Format gefallen, da es trivial zu schreiben ist und keine externen Libraries benötigt (http://en.wikipedia.org/wiki/Portable_anymap).

Der Profiler kann mit folgendem Befehl kompiliert werden:

g++ -fPIC -shared -g -o libfprofiler.so fprofiler.cpp -pthread

Anschließend können wir unsere eigene Anwendung wie folgt profilen:

LD_PRELOAD=./libfprofiler.so ./sbin/icinga2 -c ...

Der Profiler erstellt nun im aktuellen Verzeichnis seine Reports:

$ ls *.pnm
frame100.pnm  frame105.pnm  frame110.pnm  frame115.pnm  frame120.pnm
frame101.pnm  frame106.pnm  frame111.pnm  frame116.pnm  frame121.pnm
frame102.pnm  frame107.pnm  frame112.pnm  frame117.pnm  frame122.pnm
frame103.pnm  frame108.pnm  frame113.pnm  frame118.pnm  frame123.pnm
frame104.pnm  frame109.pnm  frame114.pnm  frame119.pnm  frame124.pnm

Die Dateien können wir nun mit einem beliebigen Bildbearbeitungsprogramm öffnen (GIMP, EOG, usw.).
Jeder Pixel steht dabei für eine Speicherseite (4kB). Weiß bedeutet, dass zumindest ein Teil der Seite belegt ist. Schwarze Pixel stehen für komplett freie Seiten. Wenn zwischen den Adressen von zwei Allocations mehr als 100MB Unterschied ist, zeichnet der Profiler eine blaue Linie.
In den folgenden beiden Beispielreports ist der Speicherverbrauch von Icinga 2 zu sehen. Im ersten Bild ist Icinga 2 dabei gerade mit dem Parsen der Config fertig geworden – während das zweite Bild den Stand zeigt, nachdem Icinga 2 alle Speicherbereiche freigegeben hat, die der Config-Parser intern benötigt hat:
frame120
frame130
Sehr schön sieht man im zweiten Bild, wie der Heap nun ziemlich viele Lücken aufweist. Auch wenn rein rechnerisch nur ein Bruchteil des Speichers tatsächlich verwendet wird, kann die libc diese Speicherbereiche nicht an den Kernel zurückgeben.
Im Allgemeinen gibt es folgende Lösungsansätze, um Heap-Fragmentation zu vermeiden:

  • Unterschiedliche Heaps für Objekte mit unterschiedlicher Lebensdauer verwenden (z.B. eigener Heap für den Config-Parser)
  • Anzahl der gleichzeitig vorhandenen Allocations verringern
  • Speicherverbrauch allgemein verringern

Abschließend noch ein Tipp: Mit ffmpeg kann man aus den *.pnm-Dateien einen Film generieren:

ffmpeg -f image2 -r 1 -pattern_type glob -i 'frame*.pnm' -r 24 output.mp4

Profiling von PHP mit Xdebug

Oftmals fällt es gar nicht auf. Man entwickelt sein Programm und greift auf Funktionen zurück, die schon seit Dekaden bestens funktionieren. Allerdings stellt man irgendwann fest, daß alles immer langsamer wird. Auf den ersten Blick ist nicht ersichtlich warum es zu diesen Einbußen kommt. Der zweite Blick auf den Profiler zeigt das die vermeintlich robuste Funktion eigentlich langsam ist. Durch mehrmalige Verwendung zwingt es die ganze Applikation in die Knie.
Auch beim tunen hilft’s: PHP ist an vielen Stellen inkonsistent und reagiert entsprechend anders, wie schaut es mit der Geschwindigkeit von Iteratoren zu Schleifen aus – oder array_key_exists zu isset? Hier gibt der Profiler Aufschluss was man am besten vermeidet und was man lieber vermeidet.
Einen guten guten Profiler für PHP kommt von Xdebug (wahrscheinlich auch der einzige). Installiert kriegt man ihn am besten aus dem Distro Repository (z.B. von Ubuntu) oder einfach aus den Sourcen mit phpize && sh configure && make && make install. Nach dem er nicht dauerhaft benötigt kann man ihn mit einem Trigger über die URL aktivieren. Über die Kommandozeile setzt man einfach das entsprechende ini-flag und der Profiler schreibt Valgrind kompatible Ausgabe nach /tmp. Eine Standardkonfiguration für Xdebug schaut demnach folgendermaßen aus:

[xdebug]
xdebug.profiler_enable=0
xdebug.profiler_enable_trigger=1

Trigger Möglichkeiten:

wget http://localhost/myscript.php?XDEBUG_PROFILE=1
php -d xdebug.profiler_enable=On myscript.php

Die Datei (z.B. /tmp/cachegrind.out.24869) kann man mit WinCacheGrind oder KCachegrind einsehen und optimiert entweder anhand der Zeitabläufe oder anhand der Aufrufe. Je nach Menge spart das ordentlich Zeit.
Hier ein Beispiel anhand verschiedener Iterationsmöglichkeiten in PHP:

Der Test ist natürlich nicht objektiv, zeigt aber, daß die vermeintlich gleiche Aufgabe nicht gleich optimal abläuft. Häufig findet man mit dem Profiler dann Funktionen im Code welche gnadenlos vergewaltigt werden (oder für einen anderen Zweck entworfen wurden) – Und das verbrennt dann richtig Zeit!

Marius Hein
Marius Hein
Head of Development

Marius Hein ist schon seit 2003 bei NETWAYS. Er hat hier seine Ausbildung zum Fachinformatiker absolviert, dann als Application Developer gearbeitet und ist nun Leiter der Softwareentwicklung. Ausserdem ist er Mitglied im Icinga Team und verantwortet dort das Icinga Web.