profiler_beispiel.html

Ein Optimierungsbeispiel mit Hilfe eines Profilers

Einleitung

Als Beispiel soll der Qt Designer von Trolltech, der gemeinsam mit Qt-2.2.3 ausgeliefert wurde, mit Hilfe eines Profilers auf langsame Funktionen untersucht werden. Eine der langsamsten Funktionen wird angeschaut und verbessert. Der neue Code wird ebenfalls mit dem Profiler getestet, um zu sehen, ob tatsächlich eine Verbesserung bemerkbar ist.

Das Testsystem:

• Pentium I, 133MHz, 32MB RAM, Matrox Millenium I, UW-SCSI Platten
• Debian GNU/Linux 2.2
• Linux Kernel 2.4.0
• XFree86 4.02
• Qt-2.2.3 (aus den Quellen kompiliert)

Vorbereitung

Als erstes muss das Programm mit den richtigen Optionen kompiliert werden. Dazu habe ich in den Konfigurationsdateien ganz einfach jeweils gcc und g++ durch gcc -pg und g++ -pg ersetzt. (Qt erzeugt die Makefiles mit einstellungen aus den Dateien im Verzeichnis configs. In diesem Fall war es configs/linux-g++-shared. In anderen Fällen müsste diese Einstellung direkt im Makefile geschehen.)

Jetzt wird Qt ganz normal mittels "make" kompiliert. Dabei wird auch das Programm "designer" erzeugt.

Jetzt wird ins Verzeichnis $QTDIR/bin gewechselt und dann da das Programm designer gestartet und ein wenig damit gearbeitet. Ich habe ein neues Formular (File->new->Widget) geöffnet und ein paar mal dessen Grösse verändert. Dabei musste jedes mal das Raster neu gezeichnet werden.

Anwendung von gprof

"designer" hat ohne unser zutun eine datei namens gmon.out erzeugt. Darin liegen profiling-Informationen, die mit gprof wie folgt ausgewertet werden können:

gprof ./designer 2>&1 > prof-original.txt

prof-original.txt enthält jetzt in Textform Informationen darüber, welche Funktionen wie oft aufgerufen wurden und wieviel CPU-Zeit sie benötigten. Die Ausgabe kann z.B. so aussehen:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
 67.96      1.23     1.23      414  2971.01  4130.43  FormWindow::paintGrid(QWidget *, QPaintEvent *)
 26.52      1.71     0.48  3721392     0.13     0.13  FormWindow::mainWindow(void) const
  1.10      1.73     0.02     8980     2.23     2.23  WidgetFactory::isPassiveInteractor(QObject *)
  1.10      1.75     0.02     3783     5.29     5.29  MainWindow::isAFormWindowChild(QObject *) const
  1.10      1.77     0.02                             QArray::detach(void)
  0.55      1.78     0.01      130    76.92    76.92  PixmapChooser::loadPixmap(QString const &, PixmapChooser::Size)
  0.55      1.79     0.01        5  2000.00  2000.00  saveDefaultProperties(QWidget *, int)

... (gekürzt)

Die erste Spalte gibt den prozentualen Zeitanteil an, der in der Funktion verstreicht. Die 2. Spalte die gesamte Zeit, die wärend dem Programmablauf in der Funktion verbracht wird. Die dritte Spalte ist ähnlich wie die zweite Spalte, zählt aber nur Operationen, die direkt in der Funktion ausgeführt werden, ohne weitere Funktionsaufrufe in der Funktion. "calls" zählt die Anzahl Aufrufe der Funktion. "self" gibt die Zeit an, die für Operationen einer Funktion bei einem Aufruf verstreicht, "total" zählt zusätzlich zu "self" noch die Zeit für Unterfunktionsaufrufe innerhalb der betrachteten Funktion dazu.

Auffinden der langsamsten Funktion

Die Ausgabe von gprof zeigt deutlich, dass die meiste Zeit während dem Programmablauf in der Funktion FormWindow::paintGrid verstreicht. Mit Hilfe von grep im Quellverzeichnis vom designer wird die betroffene Quelldatei schnell gefunden:

heimers:/usr/local# cd qt-2.2.3/tools/designer/designer
heimers:/usr/local/qt-2.2.3/tools/designer/designer# grep  FormWindow::paintGrid *.cpp
formwindow.cpp:void FormWindow::paintGrid( QWidget *w, QPaintEvent *e )

Mit einem Editor findet man jetzt folgenden Code:

void FormWindow::paintGrid( QWidget *w, QPaintEvent *e )
{
    if ( !mainWindow()->showGrid() )
        return;
    QPainter p( w );
    p.setClipRegion( e->rect() );
    p.setPen( colorGroup().foreground() );
    for ( int i = 0; i < w->width() / mainWindow()->grid().x() + 20; ++i ) {
        for ( int j = 0; j < w->height() / mainWindow()->grid().y() + 20; ++j )
            p.drawPoint( i * mainWindow()->grid().x(), j * mainWindow()->grid().y() );
    }
}

Es handelt sich offensichtlich um die Funktion, die Das Punktraster im Qt-Formular zeichnet. Mit ein wenig Programmiererfahrung findet man folgende Probleme:

• Es werden Berechnungen in jedem Schleifendurchgang gemacht, die nur einmal nötig wären.
• Es werden Multiplikationen durchgeführt, die in diesem Fall durch eine Reihe von Additionen ersetzt werden könnten.

Ich habe die Funktion wie folgt umgeschrieben. Die Punkte werden bei exakt den gleichen Koordinaten gezeichnet, aber es wird wesentlich weniger gerechnet, obwohl die Funktion ein wenig komplizierter aussieht:

void FormWindow::paintGrid( QWidget *w, QPaintEvent *e )
{
  int x=0,y=0,jmax;
    if ( !mainWindow()->showGrid() )
	return;
    QPainter p( w );
    p.setClipRegion( e->rect() );
    p.setPen( colorGroup().foreground() );
	jmax = w->height() / mainWindow()->grid().y() + 20;
    for ( int i = 0; i < w->width() / mainWindow()->grid().x() + 20; ++i ) 
      {
		y=0;	
		for ( int j = 0; j < jmax; ++j )
		  {
		  p.drawPoint(x,y);
		  y+=mainWindow()->grid().y();
		  }
		x+=mainWindow()->grid().x();

	  }
}

Der designer wird jetzt wieder kompiliert und ausgeführt. Der gprof-output sieht nun wie folgt aus:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
 41.18      0.14     0.14   942024     0.15     0.15  FormWindow::mainWindow(void) const
 29.41      0.24     0.10      287   348.43   836.24  FormWindow::paintGrid(QWidget *, QPaintEvent *)
  8.82      0.27     0.03     3057     9.81     9.81  MainWindow::isAFormWindowChild(QObject *) const
  8.82      0.30     0.03                             QArray::detach(void)
  2.94      0.31     0.01      115    86.96    86.96  WidgetDatabase::className(int)
  2.94      0.32     0.01        5  2000.00  2000.00  saveDefaultProperties(QWidget *, int)
... (gekürzt)

Offensichtlich ist FormWindow::paintGrid deutlich schneller geworden und verbraucht nicht mehr die meiste CPU-Zeit des Programmes.

Bemerkungen

Es ist offensichtlich nicht nötig, ein Programm zu verstehen um es zu verbessern. Ich kenne den Code vom Qt-designer sonst nicht. ich habe ausschliesslich die oben angegebenen paar Zeilen angeschaut, die ich mit Hilfe des Profilers gefunden habe und konnte trotzdem das Programm verbessern.

P.S. Trolltech hat den Hinweis dankend angenommen und selbst eine nochmals verbesserte Version dieser Funktion geschrieben, welche in neueren QT-Versionen zu finden ist.