amigadave: devtools template

amigadave — Thu, 11 Mar 2010 15:21:27 GMT

devtools template

← Older revision		Revision as of 15:21, 11 March 2010
Line 1:		Line 1:
		+	{{Devtools}}
		+
		+
	== Description ==		== Description ==

Line 296:		Line 299:
	[[Documentation/devtools/maemo5/syslog\|syslog]]		[[Documentation/devtools/maemo5/syslog\|syslog]]

-	~~[[Category:Devtools]]~~
	[[Category:Fremantle]]		[[Category:Fremantle]]

amigadave: Category:Devtools and Category:Fremantle

amigadave — Fri, 12 Feb 2010 11:40:09 GMT

Category:Devtools and Category:Fremantle

← Older revision		Revision as of 11:40, 12 February 2010
Line 295:		Line 295:

	[[Documentation/devtools/maemo5/syslog\|syslog]]		[[Documentation/devtools/maemo5/syslog\|syslog]]
		+
		+	[[Category:Devtools]]
		+	[[Category:Fremantle]]

kaltsi: New page: == 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 bo...

kaltsi — Tue, 06 Oct 2009 08:50:21 GMT

New page: == Description == ''sp-startup-time'' provides a library that can be preloaded with <code>LD_PRELOAD</code> to measure the startup time of Gtk applications. You can use it to identify bo...

New page

== Description ==

''sp-startup-time'' provides a library that can be preloaded with <code>LD_PRELOAD</code> 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

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

<code>LD_PRELOAD</code> 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 <code>LD_PRELOAD</code>. This means that prelinked applications spend time in resolving library symbols when this is used.

Note!
In scratchbox <code>LD_PRELOAD</code> 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 <code>ld.so</code> configuration.

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

<pre>
# LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so app-to-run
</pre>

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:

<pre>
#!/bin/sh
export LD_PRELOAD=/usr/lib/sp-startup-time/libstartup.so
app-to-run
</pre>

Apart from the environment you can use the global <code>ld.so</code> configuration to force preloading libstartup for all applications by editing the <code>/etc/ld.so.preload</code> 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:

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

See also "How to interpret the results" below.

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

<code>
STARTUP_LOG_DIR
</code>

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.

<code>
STARTUP_LOG_FILE
</code>

Explicitly set path used for writing logs.

If not set
<code><$STARTUP_LOG_DIR>/<appname>--<pid>.startup</code>
will be used.

<code>
STARTUP_WRITE_LOG
</code>

If set to '<code>yes</code>', and the process reaches Gtk idle state, the full startup log will be written.

If set to '<code>force</code>' the startup log will be written always, not just for Gtk apps.

<code>
STARTUP_IDLE_QUIT
</code>

If set (to anything) <code>gtk_main_quit()</code> 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 <code>/tmp/startup.env</code>. This allows changing configuration for applications for which the environment values would be hard to modify. You could for example use <code>/etc/ld.so.preload</code> to globally enable libstartup use for all applications and then set the configuration options via <code>/tmp/startup.env</code>.

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

<pre>
+------- 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 -------------------------------------------
</pre>

It compiles as usual:

<pre>
# gcc -o hello hello.c
</pre>

It executes as normal without ''libstartup'':

<pre>
# ./hello
hello, world
</pre>

And you get the custom timestamps with:

<pre>
# 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 -------------------------------
</pre>

The rationale behind hijacking <code>__cyg_profile_func_enter()</code>:

* we can't override functions defined in the main application binary using <code>LD_PRELOAD</code> -> 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.

=== How to interpret the results ===

==== syslog ====

<pre>
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
</pre>

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

==== startup log ====

Entry time stamp:

- <code>t_tod</code> time since epoch.
- <code>t_real</code> elapsed time since process create
- <code>t_user</code> CPU time spent in user land before call
- <code>t_sys</code> CPU time spent in kernel space before call

Time within:

- <code>f_real</code> elapsed time within entry
- <code>t_user</code> CPU time spent in user land during the call
- <code>t_sys</code> CPU time spent in kernel space during the call

Entry identification:

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

<pre>
+------- 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 ------------------------
</pre>

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.

<code>
+ 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
</code>

The timestamps are obtained with <code>times()</code> syscall which allows us to trace:

- <code>real time</code> (elapsed wall clock time)
- <code>user time</code> (time spent executing code)
- <code>sys time</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:

<code>lib_init -> gtk_init</code>

Usually libstartup initialization is executed just before control is yielded to <code>main()</code> entry of the application. So this transition can be considered as "non-gui-init".

<code>gtk_init -> gtk_main</code>

Setting up application main GUI.

<code>gtk_main -> gui_idle</code>

Realizing application main GUI.

<code>gui_idle -> gtk_main_quit</code>

Normal application operation.

<code>gtk_main_quit -> lib_exit</code>

Application shutdown

<code>lib_exit -> lib_fini</code>

As the <code>lib_exit</code> is most likely the last <code>atexit</code> handler called and <code>lib_fini</code> 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 <code>main()</code> 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 <code>/proc/pid/status</code>) 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 <code>gtk_main</code>. 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)

== See Also ==

[[Documentation/devtools/maemo5/syslog|syslog]]

Documentation/devtools/maemo5/sp-startup-time - Revision history

amigadave: devtools template

amigadave: Category:Devtools and Category:Fremantle

kaltsi: New page: == 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 bo...

kaltsi: New page: == 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 bo...