Login timings and systemtap

[grundym us ibm com]

Hi Folks -

I've been working on getting some useful data about the gnome login
process from systemtap. For these tests I've been using a stock openSUSE
10.2, but can work with / help folks work with other rigs if needed.

I've got the start indicator, just wait for the second enter (first for
user, second for password), but need to figure out a good place for the
stop indicator. I've been eyeballing when the desktop paint is done.
That's fine for the measurements I'm going to talk about in a minute,
but doesn't help with that total time span measurement to give us
comparisons. If someone could point out a file, function and approx line
that is regarded as the completion line, I'd greatly appreciate it.

So, what I've done so far is some basic syscall and exec analysis. For
syscalls, I started by doing a general profile of the top syscalls on
the system during the login process. Here's the top 20:

syscall			count		average time	total time
----------------	-----------	-------------	------------
sys_poll		7866		18015430	141709373064
sys_futex		1222		60080969	73418945172
sys_select		3504		8113277		28428924036
sys_nanosleep		32		462817611	14810163552
sys_read		34880		286725		10000998864
sys_epoll_wait		85		101588761	8635044744
sys_wait4		244		10936167	2668424820
sys_fsync		1		949032732	949032732
sys_gettimeofday	11918		62396		743638812
sys_mmap2		6872		91118		626165760
sys_accept		395		1388100		548299680
sys_recvmsg		89		3223544		286895424
sys_open		11789		22167		261336348
sys_rt_sigsuspend	81		2092186		169467132
sys_semtimedop		1039		142505		148063680
sys_ioctl		2165		60374		130709844
sys_close		57760		1968		113720844
sys_stat64		8422		9711		81787620
sys_writev		7175		7553		54194424
sys_write		3886		13405		52093764


The timings here aren't perfect, or probably even that close, but it
gives a good idea relatively where we sit. From these I chose a subset
of the most active no having to do with io. Put those in a script that
profiles syscalls per process, for results like this:


process		pid	syscall			count	time (us)
------------	------	------------------	------	---------
gnome-panel	8633	sys_poll		560	2748739
gnome-panel	8633	sys_mmap2		299	2330
gnome-panel	8633	sys_gettimeofday	304	959
gnome-panel	8633	sys_accept		5	36
gnome-panel	8633	sys_futex		3	11
gnome-panel	8633	sys_wait4		1	6
gnome-panel	8633	sys_recvmsg		1	3
gdm		3834	sys_poll		14	185348
gdm		3834	sys_accept		2	15
gdm		3834	sys_mmap2		1	3
gdm		3994	sys_select		18	2268479
gdm		3994	sys_recvmsg		1	150497
gdm		3994	sys_poll		9	16902
gdm		3994	sys_wait4		4	753
gdm		3994	sys_mmap2		10	88
gdm		3994	sys_gettimeofday	7	32
gdm		8551	sys_poll		281	2596939
gdm		8551	sys_wait4		59	64786
gdm		8551	sys_mmap2		495	2252
gdm		8551	sys_select		2	964
gdm		8551	sys_gettimeofday	304	873
gdm		8551	sys_recvmsg		27	120
gdm		8551	sys_accept		9	81
gdm		8551	sys_futex		3	11
 

(There's a bit more to that, I think what I'll do is put a page in the
wiki with my scripts and results.)

The next thing I did was take those same system calls and set a script
to take a user backtrace if it spent more than 0.1 seconds in the call.
I haven't post-processed this one yet, so I don't have line numbers for
each step of the backtrace, but it looks something like this:

gdm:sys_select 1085368 (us)
[user] <0xb7f90410>  b7f90000:00000410 [vdso]
[user] <0x08064308>  08048000:0001c308 /opt/gnome/sbin/gdm
[user] <0x08065aa6>  08048000:0001daa6 /opt/gnome/sbin/gdm
[user] <0x08066d19>  08048000:0001ed19 /opt/gnome/sbin/gdm
[user] <0x08059ff3>  08048000:00011ff3 /opt/gnome/sbin/gdm
[user] <0x0804f560>  08048000:00007560 /opt/gnome/sbin/gdm
[user] <0x0805008a>  08048000:0000808a /opt/gnome/sbin/gdm
[user] <0xb75edf9c>  b75d8000:00015f9c /lib/libc-2.5.so
[user] <0x0804e451>  08048000:00006451 /opt/gnome/sbin/gdm

gnome-power-man:sys_poll 124761 (us)
[user] <0xb7f3e410>  b7f3e000:00000410 [vdso]
[user] <0xb704421b>  b701b000:0002921b /usr/lib/libdbus-1.so.3.2.0
[user] <0xb703cb99>  b701b000:00021b99 /usr/lib/libdbus-1.so.3.2.0
[user] <0xb703b2ec>  b701b000:000202ec /usr/lib/libdbus-1.so.3.2.0
[user] <0xb702751d>  b701b000:0000c51d /usr/lib/libdbus-1.so.3.2.0
[user] <0xb70294a4>  b701b000:0000e4a4 /usr/lib/libdbus-1.so.3.2.0
[user] <0xb7035691>  b701b000:0001a691 /usr/lib/libdbus-1.so.3.2.0
[user] <0xb7028901>  b701b000:0000d901 /usr/lib/libdbus-1.so.3.2.0
[user] <0xb74c4040>  b74b7000:0000d040 /usr/lib/libdbus-glib-1.so.2.0.0
[user] <0x0804fdd7>  08048000:00007dd7 /opt/gnome/bin/gnome-power-manager
[user] <0xb73055ea>  b72dc000:000295ea /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72ece22>  b72dc000:00010e22 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eaa7b>  b72dc000:0000ea7b /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb5de>  b72dc000:0000f5de /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb790>  b72dc000:0000f790 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0x0804fbd5>  08048000:00007bd5 /opt/gnome/bin/gnome-power-manager
[user] <0x0806071d>  08048000:0001871d /opt/gnome/bin/gnome-power-manager
[user] <0xb73055ea>  b72dc000:000295ea /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72ece22>  b72dc000:00010e22 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eaa7b>  b72dc000:0000ea7b /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb5de>  b72dc000:0000f5de /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb790>  b72dc000:0000f790 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0x0805df05>  08048000:00015f05 /opt/gnome/bin/gnome-power-manager
[user] <0x0805909e>  08048000:0001109e /opt/gnome/bin/gnome-power-manager
[user] <0xb73055ea>  b72dc000:000295ea /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72ece22>  b72dc000:00010e22 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eaa7b>  b72dc000:0000ea7b /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb5de>  b72dc000:0000f5de /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb790>  b72dc000:0000f790 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0x080585f5>  08048000:000105f5 /opt/gnome/bin/gnome-power-manager
[user] <0x08054831>  08048000:0000c831 /opt/gnome/bin/gnome-power-manager
[user] <0xb73055ea>  b72dc000:000295ea /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72ece22>  b72dc000:00010e22 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eaa7b>  b72dc000:0000ea7b /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb5de>  b72dc000:0000f5de /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0xb72eb790>  b72dc000:0000f790 /opt/gnome/lib/libgobject-2.0.so.0.1200.4
[user] <0x080539ec>  08048000:0000b9ec /opt/gnome/bin/gnome-power-manager
[user] <0x08051bb5>  08048000:00009bb5 /opt/gnome/bin/gnome-power-manager
[user] <0xb6e63f9c>  b6e4e000:00015f9c /lib/libc-2.5.so
[user] <0x0804dc31>  08048000:00005c31 /opt/gnome/bin/gnome-power-manager

The first address is the return address in the program's address space,
the second set is the begining of the vma the address is in, the second
is the offset (so you can easily find the line with addr2line and
libraries).

I also did a quick exec trace, which looks like this:
process(3050:resmgrd) execs process(9537) uid(0:0): resmgrd /usr/bin/polkit-resmgr-grant 
process(3050:resmgrd) execs process(9537) uid(0:0): polkit-resmgr-g /usr/bin/polkit-grant-privilege -u grundym -p desktop-console
process(3050:resmgrd) execs process(9538) uid(0:0): resmgrd /bin/sh -c "/usr/sbin/hal-resmgr --grant=$RES_USER"
process(3050:resmgrd) execs process(9538) uid(0:0): sh /usr/sbin/hal-resmgr --grant=grundym
process(3994:gdm) execs process(9539) uid(0:0): gdm /etc/opt/gnome/gdm/PostLogin/Default 
process(9540:gdm) execs process(9541) uid(0:0): gdm /etc/opt/gnome/gdm/PreSession/Default 
process(9541:Default) execs process(9543) uid(0:0): Default /opt/gnome/bin/gdmflexiserver "--command=GET_CONFIG greeter/GraphicalThemedColor :0"
process(9544:Default) execs process(9546) uid(0:0): Default /usr/bin/sed "s/^\([^ ]*\) .*$/\1/"
process(9547:Default) execs process(9549) uid(0:0): Default /usr/bin/sed "s/^.* \(.*\)$/\1/"
process(9541:Default) execs process(9550) uid(0:0): Default /usr/bin/xsetroot -cursor_name left_ptr -solid #76848F
process(9540:gdm) execs process(9541) uid(0:0): Default /usr/bin/sessreg -a -w /var/log/wtmp -u /var/run/utmp -x /var/lib/gdm/:0.Xservers -h
process(3994:gdm) execs process(9540) uid(1000:1000): gdm /bin/bash --login /etc/opt/gnome/gdm/Xsession gnome no-fake-login
process(9552:bash) execs process(9553) uid(1000:1000): bash /bin/ls -l /proc/9540/exe

I'll take any suggestions on data to collect that would make analysis
easier. There are many variations we can do to the scripts I have. Would
knowing the arguments to syscalls help? If I can get a stop marker and
make that work, we should be able to get some acurate end to end
timings. 

Thanks
Mike