Documentation/devtools/maemo5/sp-startup-time

Description
sp-startup-time provides a library that can be preloaded with  to measure the startup time of Gtk applications.

You can use it to identify bottlenecks in your application's startup and possibly to improve the user experience by providing you information to optimize the startup time.

Packages
source: sp-startup-time

binary: sp-startup-time, sp-startup-time-dbg, sp-startup-time-dev

How it works
There are a few functions that are typically called during a Gtk application's startup and libstartup intercepts these function calls and collects the time each of them was called. The startup is considered finished once the installed Gtk idle callback is called.

has some shortcomings:


 * It can be used only if the applications can be run directly, i.e. it does not work with maemo-launched Gtk applications.


 * Prelink information cannot be used with . This means that prelinked applications spend time in resolving library symbols when this is used.

Note! In scratchbox  does not work directly because scratchbox uses that by itself, use the run-with-startup-time script instead.

If instructed, libstartup will also write a full log of the intercepted calls. This is done at the time the application is unloaded.

Preloading
You can use two methods for preloading the libstartup binary during application execution; environment or global  configuration.

Setting the  environment variable like below is preferred as that way it doesn't affect any other programs:


 * 1) LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so app-to-run

However if the "app-to-run" happens to be a launcher script, not a real binary you might need to edit the script itself to contain the preload setting like this:

export LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so app-to-run
 * 1) !/bin/sh

Apart from the environment you can use the global  configuration to force preloading libstartup for all applications by editing the   file. This is not however encouraged as any mistake might make the system unbootable.

Configuration
Normally libstartup writes the time application used to reach Gtk idle into syslog, but you can get more detailed information and direct it also to elsewhere with something like this:

export STARTUP_IDLE_QUIT=yes export STARTUP_WRITE_LOG=yes export STARTUP_LOG_FILE=/home/user/startup-log.csv

See also "How to interpret the results" below.

The environment variables and how they control the runtime behavior of libstartup are:

Explicitly set the directory where libstartup will write the logs. If not set the logs will be written to the current working directory of the process at the time when libstartup init is called - that is just before the main function is entered.

Explicitly set path used for writing logs. If not set will be used.

If set to ' ', and the process reaches Gtk idle state, the full startup log will be written. If set to ' ' the startup log will be written always, not just for Gtk apps.

If set (to anything)  will be called when idle state is reached. This is useful for batch testing several runs/applications.

The values can also be set by writing them to. This allows changing configuration for applications for which the environment values would be hard to modify. You could for example use  to globally enable libstartup use for all applications and then set the configuration options via.

Custom timestamps
Sometimes you might want to add application specific measurement points to the libstartup log. This can be accomplished by inserting code similar to the example below to the application source file(s):

+--- hello.c ---
 * 1) include &lt;stdio.h&gt;

void __cyg_profile_func_enter(const void *, const void *);

__cyg_profile_func_enter((void *)(-1),text)
 * 1) define libstartup_custom_timestamp(text) \

int main(void) { sleep(1);

libstartup_custom_timestamp("main1"); printf("hello, "); fflush(stdout); sleep(1);

libstartup_custom_timestamp("main2"); printf("world\n"); fflush(stdout); sleep(1);

libstartup_custom_timestamp("main3");

sleep(1); return 0; } +--- hello.c ---

It compiles as usual:

It executes as normal without libstartup:
 * 1) gcc -o hello hello.c

hello, world
 * 1) ./hello

And you get the custom timestamps with:

$ STARTUP_WRITE_LOG=f LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so ./hello
 * 1) on device:

$ STARTUP_WRITE_LOG=f run-with-startup ./hello
 * 1) in scratchbox:

hello, world

+--- hello--5092.startup --- generator=sp-startup-time 0.0.7 create_tod=1195657960.406658
 * 1) a file will be created:

t_tod,t_real,t_user,t_sys,f_real,f_user,f_sys,name 1195657960.406658,0.000,0.000,0.000,0.000,0.000,0.000,create 1195657960.406660,0.000,0.000,0.000,0.000,0.000,0.000,lib_init 1195657961.412616,1.000,0.000,0.000,0.000,0.000,0.000,main1 1195657962.422009,2.010,0.000,0.000,0.000,0.000,0.000,main2 1195657963.427050,3.020,0.000,0.000,0.000,0.000,0.000,main3 1195657964.432335,4.020,0.000,0.000,0.000,0.000,0.000,lib_exit 1195657964.432337,4.020,0.000,0.000,0.000,0.000,0.000,lib_fini +--- hello--5092.startup ---

The rationale behind hijacking :

=> we use a dummy function provided by gnu libc
 * we can't override functions defined in the main application binary using  -> it must be in some library
 * we could provide dummy library with some kind of hook, but that would require modifying the application linking, not just the source code

Note: The amount of measurement points is currently limited to 32. For Gtk applications this should leave 20 or so custom entries.

Note: If the same custom tag is used several times, only the last occurence is placed to the log file.

syslog
Jan 27 14:33:51 localhost libstartup[12706]: firefox-bin=1.19 seconds Jan 27 14:34:32 localhost libstartup[12727]: firefox-bin=1.13 seconds

The elapsed wall-clock time from process creation to Gtk idle time is written as seconds.

startup log
Entry time stamp:

-  time since epoch. -  elapsed time since process create -  CPU time spent in user land before call -   CPU time spent in kernel space before call Time within:

-  elapsed time within entry -  CPU time spent in user land during the call -   CPU time spent in kernel space during the call Entry identification:

-    name of called function, or function1.leave->function2.entry transition

+--- firefox-bin--12727.startup generator=sp-startup-time 0.0.7 create_tod=1195658611.448291

t_tod,t_real,t_user,t_sys,f_real,f_user,f_sys,name 1195658611.448291,0.000,0.000,0.000,0.280,0.000,0.010,create 1195658611.728293,0.280,0.000,0.010,0.000,0.000,0.000,lib_init 1195658611.729729,0.280,0.000,0.010,0.000,0.000,0.000,gtk_init 1195658611.735175,0.280,0.000,0.010,3.010,0.110,0.040,gtk_init->gtk_main 1195658614.744454,3.290,0.110,0.050,0.000,0.000,0.000,gtk_main 1195658614.744454,3.290,0.110,0.050,2.290,0.290,0.030,gtk_main->gui_idle 1195658617.032341,5.580,0.400,0.080,0.000,0.000,0.000,gui_idle 1195658617.032341,5.580,0.400,0.080,18.740,0.120,0.020,gui_idle->gtk_main_quit 1195658635.775691,24.320,0.520,0.100,0.010,0.000,0.000,gtk_main_quit 1195658635.775702,24.330,0.520,0.100,0.080,0.050,0.000,gtk_main_quit->lib_exit 1195658635.855718,24.410,0.570,0.100,0.000,0.000,0.000,lib_exit 1195658635.855720,24.410,0.570,0.100,0.000,0.000,0.000,lib_fini +--- firefox-bin--12727.startup

The following calls are intercepted and logged. The entries with preceding '+' will have time stamps for both entry to and leave from function. The ones marked with '-' will have only entry time stamps.

The timestamps are obtained with  syscall which allows us to trace:

-  (elapsed wall clock time) -  (time spent executing code) -   (time spent in kernel servicing the process)

If there time difference between leaving the previous traced function and entering the next, a transition entry will be written. The interpretation of these transition entries depends on the situation, but generally:

Usually libstartup initialization is executed just before control is yielded to  entry of the application. So this transition can be considered as "non-gui-init".

Setting up application main GUI.

Realizing application main GUI.

Normal application operation.

Application shutdown

As the  is most likely the last   handler called and   the first library unload code executed, this is very unlikely to have nonzero time. The "create" entry needs a bit of explanation too. The idea is that this contains time taken by the dynamic linker to bind the various binaries to the process. As the init code from libstartup is if not the last at least one of the last things done before entering application  function, we can guess that the CPU time spent before this is from the dynamic loader. Perhaps surprisingly determining the real time is quite difficult. The reason is that the syscalls that can be used to query time values return corrected real time and the process create time (as available via ) contains uncorrected jiffies value. To overcome this the libstartup forks a child process and uses the create time difference between parent and child as elapsed real time estimate. The child process is terminated right after the time difference evaluation.

The idle detection is also not without problems. It is common that there is a brief idle period right after entering. For this reason the idle status is is noted only when the idle handler is called enough times without using CPU for other purposes (in the context of the application process).

Links
[run-with-startup-time man page](/development/documentation/man_pages/run-with-startup-time.html)