Please read first Frederic's blog, for a detailed introduction and how the solution of this tricky problem was identified with dtrace.
In summary, a telephone application of the service and hosting provider, Portrix, had a problem: after a couple of days of running the application, the system time went up, and eventually, became so high that the voice quality suffered. Restarting the application was not a solution and the machine had to be rebooted.
Our first
suggestion and traditional approach, is to use the SUN profiler. We
wanted to get three profiles : A first in the beginning, a second after
some normal load, and a last one when the system time is high. All
three profiles can then be loaded into the SUN analyser, for an easy
comparison.
This would have given us two things : first a time line which could allow us
to see where unexpected high system timings are spent, and second a performance
profile which can be used to tune the application.
The latest version of the SUN profiler has option to attach to a running process, and record a profile
%collect -P <pid> -t 180
should use dbx to attach, collect data for 180 seconds, and then detach and finish the experiment.
If you are using an older version of the profiler, you can do this through the debugger directly
dbx attach PID collector enable cont
leave it running the time you want and stop it with Control C ^C
Any of these commands uses the debugger to attach a running process. The debugger has to stop the process for doing this (this is why you see the continue after the attach command). Furthermore, there is another risk: the debugger and profiler may catch or delay application important signals. For a mission critical application, running real users, this is completely unacceptable. At best, the application can handle the interrupts, and users will experience a small delay, at worst, the telephone conversation is cut.
How can you possible debug or profile an application without even having the possibility to use a debugger ? Well, Solaris has a solution: Over 30-thousand probes are coming with the kernel and are waiting for you to be listened. The D scripting language is used to enable these probes, and to get a formatted and readable output.
The
most general way to query a running system are these dtrace command
lines. The first will grab all functions that are called, while the
second while dive into the call stacks.
#dtrace -n 'profile-10ms{@a[func(arg0)]=count()} END{trunc(@a,100)}'
#dtrace -n 'profile-10ms{@a[stack()]=count()} END{trunc(@a,100)}'
Start
any of these probes, let them run during one minute and stop them with
ControlC. Firing up the first one, we see the following output:
unix`mutex_vector_enter 629 unix`default_lock_delay 770 SUNW,UltraSPARC-T1`cpu_mutex_delay 889 unix`cas_delay 1214 zaptel`process_timers 6242 unix`cpu_halt 40277
while the second one looks into the stacks of the functions and we are seeing at the end of this list
zaptel`__zt_process_getaudio_chunk+0xfbc zaptel`__zt_transmit_chunk+0x70 zaptel`zt_receive+0xd7c ztdummy`ztdummy_timer+0x30 genunix`cyclic_softint+0xa4 unix`cbe_level1+0x8 unix`intr_thread+0x168 60
SUNW,UltraSPARC-T1`bcopy+0x68c zaptel`__zt_getbuf_chunk+0x20c zaptel`__zt_transmit_chunk+0x28 zaptel`zt_receive+0xd7c ztdummy`ztdummy_timer+0x30 genunix`cyclic_softint+0xa4 unix`cbe_level1+0x8 unix`intr_thread+0x168 96From this listing you are already see that the ztdummy driver is doing strange things, and that it is the culprit of the high system time usage. This explains why the restart of the application did not help. The driver was not restarted.
The problem with the dtrace command line above may be that they are taken across the entire system, in both user and kernel space, with no restriction to a PID, program, user or CPU. The profile event fires with either arg0 or arg1 set. arg0 means your in the kernel, arg1 means your in user. Typically you want to narrow it down to a PID or at least exexname (pid == $1, execname == "myprog", etc). You can do this by adding /cpu==6/ before the command, and putting either arg0 or arg1 into the func calls.
dtrace -n 'profile-10ms/cpu==6/{@a[func(arg0)]=count()} END{trunc(@a,100)}'
dtrace -n 'profile-10ms/pid==1234/{@a[func(arg0)]=count()} END{trunc(@a,100)}'
Or you can directly use this script (kindly provided by Jim Fiori) which directly attaches to a PID only.
# cat uprof.d
#!/usr/sbin/dtrace -qs BEGIN { interval = $2 - 1; } profile-997 /arg1 && pid == $1/ { @s1[ustack(5)] = count(); @s2[ufunc(arg1)] = count(); s1total++; } tick-1sec /--interval <= 0/ { printf("\nHottest stacks...\n"); trunc (@s1,30); printa(@s1); printf("\nHottest functions...\n"); trunc (@s2,30); printa(@s2); printf("\nTOTAL samples %d\n",s1total); exit(0); } #chmod 755 uprof.d #./uprof.d <pid> <#seconds>
There
is another tool in the
Sun Studio warchest, project D-Light, that will allow you to attach to
a running process and observe whatever attributes you want. Under the
covers, it uses Dtrace, so anything you can collect with Dtrace is
possible to show in
D-Light. Since D-Light is graphical (think the timeline view that Analyzer has) the best Dtrace data to display is time on the
X-axis and the data you want to observe on the Y-axis. Here is a whitepaper that describes an overview of this.
[Read More]
![[This is a Roller site]](http://blogs.sun.com/performance/resource/images/roller-logo.gif){kind=logo}