On Fri, 2004-05-28 at 16:39, Will Cohen wrote:

start profiling note time command-line invocation of application

<bunch of application initialization> <call library function that indicates application is running> <key function notes time, shutdown profiling>

You could just profile this program:

int main (int argc, char **argv) { gtk_init (&argc, &argv); exit (0); }

The equivalent for GNOME is a bit more complex (and probably wastes a fair bit more time).

It's probably a better measure if you create a window, rather than just the init, since some things are done lazily:

int main (int argc, char **argv) { GtkWidget *window; GtkWidget *button;

gtk_init (&argc, &argv);

window = gtk_window_new (GTK_WINDOW_TOPLEVEL); button = gtk_button_new_with_label ("Hello"); gtk_container_add (GTK_CONTAINER (window), button); gtk_widget_show (button); gtk_widget_show_now (window); /* blocks in mainloop until window has been mapped by X server */

exit (0); }

That should be a good measure of how long it takes GTK + X server to get a minimal window on the screen.

One thing we know takes time is loading stock icons, so you could make the button have an icon to add profiling of that issue: gtk_button_new_from_stock (GTK_STOCK_OPEN);

Havoc

On Sun, 2004-05-30 at 05:21, Mark McLoughlin wrote:

I'm not sure there is a reliable way to detect when an application has finished startup. Perhaps the first time the main loop goes idle would be a good indicator but I think you have difficulty distinguishing between that case and the case of the app blocking on the result of a CORBA call.

For nmany applications, a pretty good good (intrusive) way to figure out when the app is up on the screen and painted is to put a g_idle_add() into an expose handler; applications will typically handle all exposes before going idle again.

To give you an idea of where a GNOME application starting up spends its time see this:

http://mail.gnome.org/archives/desktop-devel-list/2004-April/msg00360.html

The only things really specific to the panel in this is the loading of main menu and applets/launchers.

I believe this is 'strace -tt' measurement? My experience is that that can be quite distorting because it greatly magnifies the per-syscall overhead.

Regards, Owen

Owen Taylor wrote:

On Sun, 2004-05-30 at 05:21, Mark McLoughlin wrote:

...

I'm not sure there is a reliable way to detect when an application has finished startup. Perhaps the first time the main loop goes idle would be a good indicator but I think you have difficulty distinguishing between that case and the case of the app blocking on the result of a CORBA call.

For nmany applications, a pretty good good (intrusive) way to figure out when the app is up on the screen and painted is to put a g_idle_add() into an expose handler; applications will typically handle all exposes before going idle again.

...

To give you an idea of where a GNOME application starting up spends its time see this:

http://mail.gnome.org/archives/desktop-devel-list/2004-April/msg00360.html

The only things really specific to the panel in this is the loading of main menu and applets/launchers.

I believe this is 'strace -tt' measurement? My experience is that that can be quite distorting because it greatly magnifies the per-syscall overhead.

I took the examples that Havoc posted earlier and ran them to see what kind of difference the strace made on the runtimes. Run code on 2.4GHz pentium 4 machine with FC2 displaying on Pentium III RHEL3 machine. init1 is the really short example, init2 is the longer example. The volume of output from the strace does seem to affect the timing, particularly on the second example.

/usr/bin/time ./init1 >& notrace1

0.00user 0.00system 0:00.08elapsed 14%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (0major+738minor)pagefaults 0swaps

/usr/bin/time strace -tt ./init1 >& trace

0.02user 0.03system 0:00.10elapsed 55%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (0major+909minor)pagefaults 0swaps

/usr/bin/time ./init2 >& notrace2

0.04user 0.01system 0:00.17elapsed 33%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (0major+1265minor)pagefaults 0swaps

/usr/bin/time strace -tt ./init2 >& trace2

0.08user 0.08system 0:00.46elapsed 36%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (0major+1437minor)pagefaults 0swaps

The amount of data generated by the strace is significant (>200Kb/s for the second example):

$ wc trace1 543 3777 42811 trace1 $ wc trace2 1282 8312 103580 trace2

I have seen some performance tools that allow insertion of instrumentation into a program by the developer after the program is compiled. One could place points to measure events without overwhelming the system with a huge amount of data. However, this requires a programmer to have some knowledge of the workings of the program or else they won't get useful measurement.

For compile time instrumentation we could use the -finstrument-functions option in gcc with support functions that record when each function is entered and left. Probably only want to compile a portion of the code with this option to get an overview of where time is spent otherwise the amount of output would exceed the strace.

-Will