sp-startup-time

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.

Packages

source: sp-startup-time

binary: sp-startup-time

Usage Examples

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.

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.

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.

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():

  1. we can't override functions defined in the main application binary using LD_PRELOAD -> it must be in some library

  2. 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.

How to interpret the results

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:

  • 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).

Links

run-with-startup-time man page

See Also

syslog