Documentation/devtools/maemo5/sp-startup-time
 |
This article documents a developer tool. A list of available devtools is available, together with installation instructions. |
Contents |
[edit] Description
sp-startup-time provides a library that can be preloaded with LD_PRELOAD 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.
[edit] Packages
source: sp-startup-time
binary: sp-startup-time, sp-startup-time-dbg, sp-startup-time-dev
[edit] Usage Examples
[edit] 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.
LD_PRELOAD 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
LD_PRELOAD. This means that prelinked applications spend time in resolving library symbols when this is used.
Note!
In scratchbox LD_PRELOAD 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.
[edit] Preloading
You can use two methods for preloading the libstartup binary during application execution; environment or global ld.so configuration.
Setting the LD_PRELOAD environment variable like below is preferred as that way it doesn't affect any other programs:
# 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:
#!/bin/sh export LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so app-to-run
Apart from the environment you can use the global ld.so configuration to force preloading libstartup for all applications by editing the /etc/ld.so.preload file. This is not however encouraged as any mistake might make the system unbootable.
[edit] 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:
STARTUP_LOG_DIR
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.
STARTUP_LOG_FILE
Explicitly set path used for writing logs.
If not set
<$STARTUP_LOG_DIR>/<appname>--<pid>.startup
will be used.
STARTUP_WRITE_LOG
If set to 'yes', and the process reaches Gtk idle state, the full startup log will be written.
If set to 'force' the startup log will be written always, not just for Gtk apps.
STARTUP_IDLE_QUIT
If set (to anything) gtk_main_quit() 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 /tmp/startup.env. This allows changing configuration for applications for which the environment values would be hard to modify. You could for example use /etc/ld.so.preload to globally enable libstartup use for all applications and then set the configuration options via /tmp/startup.env.
[edit] 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 -------------------------------------------
#include <stdio.h>
void __cyg_profile_func_enter(const void *, const void *);
#define libstartup_custom_timestamp(text) \
__cyg_profile_func_enter((void *)(-1),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:
# gcc -o hello hello.c
It executes as normal without libstartup:
# ./hello hello, world
And you get the custom timestamps with:
# on device: $ STARTUP_WRITE_LOG=f LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so ./hello # in scratchbox: $ STARTUP_WRITE_LOG=f run-with-startup ./hello hello, world # a file will be created: +------- hello--5092.startup ------------------------------- generator=sp-startup-time 0.0.7 create_tod=1195657960.406658 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 __cyg_profile_func_enter():
- we can't override functions defined in the main application binary using
LD_PRELOAD-> 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
=> we use a dummy function provided by gnu libc
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.
[edit] How to interpret the results
[edit] 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.
[edit] startup log
Entry time stamp:
- t_tod time since epoch.
- t_real elapsed time since process create
- t_user CPU time spent in user land before call
- t_sys CPU time spent in kernel space before call
Time within:
- f_real elapsed time within entry
- t_user CPU time spent in user land during the call
- t_sys CPU time spent in kernel space during the call
Entry identification:
- name 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.
+ create
+ lib_init (installs lib_exit as atexit handler)
+ gtk_init (installs gui_idle as gtk idle handler)
- gtk_main
- gui_idle
+ gtk_main_quit
- lib_exit
- lib_fini
The timestamps are obtained with times() syscall which allows us to trace:
- real time (elapsed wall clock time)
- user time (time spent executing code)
- sys time (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:
lib_init -> gtk_init
Usually libstartup initialization is executed just before control is yielded to main() entry of the application. So this transition can be considered as "non-gui-init".
gtk_init -> gtk_main
Setting up application main GUI.
gtk_main -> gui_idle
Realizing application main GUI.
gui_idle -> gtk_main_quit
Normal application operation.
gtk_main_quit -> lib_exit
Application shutdown
lib_exit -> lib_fini
As the lib_exit is most likely the last atexit handler called and lib_fini 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 main() 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 /proc/pid/status) 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 gtk_main. 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).
[edit] Links
[run-with-startup-time man page](/development/documentation/man_pages/run-with-startup-time.html)
[edit] See Also
- This page was last modified on 11 March 2010, at 15:21.
- This page has been accessed 6,970 times.