Systemtap scripts for Gnome performance
I've thrown together some scripts for measuring login time activity. Mostly based on existing generic tools with some mods for this purpose. All the scripts have a enter key based starting and stopping mechanism right now. After the second enter (think username enter, password enter) the scripts begin recording data. Since I don't have a programatic end point (yet), for now I'm making due with hitting enter again when it looks like the desktop is completely rendered.
Getting Started
The first step will be getting systemtap set up on your machine. The systemtap wiki has information on getting set up in the For Developers section. Most things we'll do here shouldn't require compiling systemtap from a CVS snapshot. I don't want to discourage you from trying that, it's just not required. If something does wind up requiring a new feature I'll be sure to point that out.
Simple but useful oneliners
This one tracks execve calls, really handy to see what all is being started up.
stap -e 'probe syscall.execve {if (uid() != 0) printf("process(%d:%s) execs process(%d) uid(%d:%d): %s %s\n", ppid(), pexecname(), pid(), uid(), euid(),execname(), argstr)}'Here's what the output looks like:
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 process(9554:bash) execs process(9555) uid(1000:1000): bash /usr/bin/tty
Here's another one that watches file opens, and tells if the call was successful or not
probe syscall.open {printf("%s:open %s ", execname(), argstr)} probe syscall.open.return {printf("%s\n", retstr)}
Login Performance script particulars
For login performance measurements, I've been using the enter key as a trigger. The kbd_event function gets key down and key up events. If we're marking on the enter after the password, that will be the third occurence of that key code. In the code here I also catch the 5th occurence to stop processing. Just hit enter when you want to stop recording. It will be better when we get a file / function / line combo to watch. More on that in a sec.
probe begin {
kbcount = 0
active = 0
warn("Profile specific syscalls by pid, active")
}
probe kernel.function("kbd_event") {
# Changes 'm' to 'b' .
if ($event_code == 28) {
kbcount++
printf("ec %d kbcount %d\n", $event_code, kbcount)
if (kbcount == 3){
warn("Starting Run\n")
# if there are globals that may have data
# and shouldn't, delete them here
active = 1
}
if (kbcount == 5){
warn("End Signalled\n")
active = 0
exit()
}
}
}With that code in place, you just put a if(!active) check in the beginning of probes, or a common function called by probes. Here's an example in a probe:
probe syscall.close {
if(!active) next
printf("%s: close %d\n", execname(), fd);
}and an example in a common function called by the probes:
function decumulate () {
if (!active) return -1
pid = pid()
if (execname() != "staprun") {
...
Scripts and Output
At this point, I've been doing some pretty basic work with three scripts and the execve one-liner (above). I expect this section to grow over time as different needs are accomodated. The scripts in one way or another are all based on the examples that come with systemtap. Mostly because I just don't write very many things from scratch anymore. Who does? 
sys-prof.stp
sys-prof.stp is the broad brush I started my analysis with. Based right off an example script, it measures the amount of times a sys_ kernel function (a syscall) is called, and the time spent between function entry and exit (in microseconds). To run it and save the output use:
./sys-prof.stp -o sys-profile.txt
The output is in unordered "report" format (full file download and yes, I know ms isn't microseconds):
sys_poll calls: 7731 avg time (ms): 8752 total(ms):67669335 sys_utime calls: 16 avg time (ms): 15 total(ms): 247 sys_unlink calls: 22 avg time (ms): 16 total(ms): 360 sys_umask calls: 20 avg time (ms): 1 total(ms): 24 sys_rt_sigreturn calls: 4 avg time (ms): 2 total(ms): 8 sys_gettid calls: 4 avg time (ms): 1 total(ms): 4 sys_getpriority calls: 1 avg time (ms): 6 total(ms): 6 sys_lremovexattr calls: 1 avg time (ms): 112 total(ms): 112 sys_lgetxattr calls: 3 avg time (ms): 6 total(ms): 19 sys_lsetxattr calls: 1 avg time (ms): 177 total(ms): 177
Since it is not ordered in any useful fashion, I use the following sed to turn the output into a .csv so I can play around with it in OpenOffice.org calc (using our previous output filename):
sed -e 's/calls:/,/' -e 's/avg time .ms.:/,/' -e 's/total.ms.:/,/' -e's/[ \t]*//g' < sys-profile.txt > sys-profile.csv
profile.stp
profile.stp is based on the output from sys-prof.stp, I came up with a list of syscalls, not involved with i/o, that took the longest to complete. I put probes for these in profile.stp. Could I have just used the same grab every syscall method like sys-prof.stp? Yes, but I felt that limiting the the amount of calls would make it easier to analyze without having to preprocess the files or wade through a bunch of extra data points.
./profile.stp -o profilerun.csv
The output is a csv file. The format is Process, PID, System Call Name, Count, Time. I recommend bringing it into calc or gnumeric and use the data sort to sort by Process, then PID, then Time (decending). Here is the output from my recent tests. In calc and sorted it looks like this:
Process PID System Call Name Count Time --------------- ---- ---------------- ------ ------ application-bro 9096 sys_poll 34 425098 application-bro 9096 sys_mmap2 254 1988 application-bro 9096 sys_gettimeofday 591 1751 application-bro 9096 sys_futex 4 18 application-bro 9096 sys_accept 2 14 application-bro 9096 sys_recvmsg 1 4 auditd 3512 sys_select 1 0 awk 9128 sys_mmap2 11 47
gno-profile-wustk2.stp
gno-profile-wustk2.stp adds a user stack backtrace to the mix. It's hard coded to take a stacktrace if the call takes over .1 seconds to complete. If we stack trace everything, the output file is 20 meg, just way to much information. Yes, I know the name sucks, the next version will have a new name. The user stack trace functionality uses a feature of systemtap called guru mode. In guru mode you can embed c code into your tap scripts. It offers tremendous power to the mix, remember though "With great power comes great responsibility". Not that anyone is doing Gnome performance testing on production sensitive machines, just remember the user stack tracing is under development right now. It may try to eat small pets and children. I caught it hitting on my wife and raiding the liquor cabinet. Embedded c carries risks, but the rewards can be cool. The version of user stack tracing in this script is not what is going to wind up in the systemtap runtime. I'm currently working on a newer better safer version for that. I've received some great input from the systemtap community and I'm working on it. In the mean time this will do. To run it, since it has embedded c code in it, we need to specify the guru mode flag: -g
./gno-profile-wustk2.stp -g -o gnome-test4-profile-with-user-stack.txt
The output is large even when we just take the real slow calls. I have a full output from a test run available. Here's a sample:
gdmgreeter:sys_poll 140374 (us) [user] <0xb7f8a410> b7f8a000:00000410 [vdso] [user] <0xb7544e53> b7514000:00030e53 /opt/gnome/lib/libglib-2.0.so.0.1200.4 [user] <0xb75451c9> b7514000:000311c9 /opt/gnome/lib/libglib-2.0.so.0.1200.4 [user] <0xb7d25cd4> b7bf9000:0012ccd4 /opt/gnome/lib/libgtk-x11-2.0.so.0.1000.6 [user] <0x08052117> 08048000:0000a117 /opt/gnome/lib/gdm/gdmgreeter [user] <0xb7107f9c> b70f2000:00015f9c /lib/libc-2.5.so [user] <0x080510a1> 08048000:000090a1 /opt/gnome/lib/gdm/gdmgreeter
The backtraces need to be further analyzed for useful information, namely where in the code are they. For each library and program you see listed in a backtrace you'll need to install Debuginfo rpms, or have built them with debugging information. You can then use addr to line and specify the address or offset (the number to the right of the colon) and figure out where in the code this happened.
To Do
- Find "marker" spot to indicate the login process is over
- Create method to turn off probes from marker spot (I'm thinking a little program that uses ptrace to set the marker, when the interrupt hits systemtap might be able to trap the appropriate ptrace function (I have to look into this a little more, I forget if ptrace is in the kprobes no-no zone)
- Create script to parse the backtrace data and come up with a list of Debuginfo rpms to install
- Create script to add line number information to the stack traces with addr2line
- Get more input on what data will help folks
- Make a script out of the exec oneliner to use the enter key start marker
- Go fly a kite. It's windy out and my kid got a pirate ship shaped kite for his birthday, time to go...