Tuesday, January 20, 2009

Getting maximum info at booting

As I already written above, it's very useful to know all the current processes in boot time. You can get more interesting information. If we look at the contents of "live-devices-local" script in OpenSolaris LiveCD we'll see possibility to use iosnoop with output in logfile (iosnoop uses DTrace to monitor disk events in real time):

...
# Turn on I/O tracing if requested and possible
trace=`prtconf -v /devices|sed -n '/trace/{;n;p;}'|cut -f 2 -d\'`
if [ "$trace" = "on" ]; then
if [ -n "$mntpt" ]; then
outputfile="${mntpt}/traceout"
echo "Enabling I/O Tracing ..." > /dev/console
/opt/DTT/Bin/iosnoop -Deg > "$outputfile" 2> /dev/console &
# Wait for iosnoop to actually initialize
sleep 10
else
echo "Unable to enable I/O Tracing" > /dev/console
echo "Must have a mountable Solaris root slice on harddisk" > /dev/console
echo "to hold trace output" > /dev/console
fi
fi
...

Here's another fast way without using "live-devices-local" script: boot with "-m milestone=none" and next (I'm using opensnoop):

mount -F tmpfs -o size=32m swap /var/log
/opt/DTT/Bin/opensnoop -eg > /var/log/opensnoop.log &
svcadm milestone all

Except iosnoop a lot of helpful information can be gathered using other DTrace scripts (opensnoop,errinfo) with various arguments. For example, the opensnoop script considerably simplifies search of all files necessary for booting without errors.

Monday, January 12, 2009

Boot chart with help of DTrace and Python

Anonymous tracing allows to receive more interesting information about Solaris booting process. I use a simple D-script (boot.d):

#!/usr/sbin/dtrace -Cs
#pragma D option quiet
/* I need process pid, his forks and life time */
proc:::create
{
printf("<fork ppid=%d cpid=%d execname=%s time=%d />\n",
pid,args[0]->pr_pid,execname,`lbolt*10/ `hz);
}

proc:::exec-success
{
printf("<process pid=%d execname=%s time=%d />\n",
pid,execname,`lbolt*10/ `hz);
}

proc:::exit
{

printf("<end pid=%d execname=%s time=%d />\n",
pid, execname,`lbolt*10/ `hz);
}

Then I enable anonymous tracing:

dtrace -AFs /boot/boot.d
reboot

After reboot I write a logfile and disable anonymous tracing:

dtrace -ae -o bootlog
dtrace -A

Logfile looks like this:

CPU FUNCTION
0 | exec_common:exec-success <process pid=1 execname=init time=63 />
0 | cfork:create <fork ppid=1 cpid=4 execname=init time=66 />
0 | exec_common:exec-success <process pid=4 execname=ksh93 time=67 />
0 | exec_common:exec-success <process pid=4 execname=autopush time=87 />
0 | proc_exit:exit <end pid=4 execname=autopush time=92 />
0 | cfork:create <fork ppid=1 cpid=5 execname=init time=92 />
0 | exec_common:exec-success <process pid=5 execname=ksh93 time=92 />
0 | exec_common:exec-success <process pid=5 execname=soconfig time=94 />
...

Now by help of a python it's possible to parse logfile. I've written a small script bootchart.py for parsing and chart construction. It would be great to trace and draw the cpu part but this is not implemented yet.
To create boot chart you need run bootchart.py with logfile as an argument:

bootchart.py bootlog

This is a boot chart example for OpenSolaris 2008.11: