Thursday March 23, 2006

A few days ago, I took Dtrace for a test drive and reported initial results here. This entry finishes the story--or at least takes it as far as I'm willing to go for the sake of a slow-loading spreadsheet. In any case, the spreadsheet was never the issue: I'm using this get a feel for Dtrace and its capabilities and have a few more features to illustrate.

As Dan Price point out in a Navel comment, the long times spent in lwp_park() are likely a symptom of the problem rather than the problem itself. A thread is likely being parked over and over again, waiting for something to complete. I took a quick look at the return codes from all invocations of lwp_park using this little dtrace script:

syscall::lwp_park:return
/pid==6152/
{
   @foo[errno] = count();
}

And, sure enough, found that the vast majority of the calls to lwp_park were returning after timing out. It did seem the thread was waiting for some as yet unknown event to complete.

In addition to his observation, Dan also suggested using Dtrace's profile provider to shed more light on what StarOffice is doing as it loads the problematic spreadsheet. Off to the Dtrace manual again. Nice. Dtrace provides the ability to periodically interrupt a running process and sample what it's doing. A bit like what gprof offers.

The profiling command I used was essentially exactly what Dan had suggested:

dtrace -n profile:::profile-997'/execname=="soffice.bin"/{@a[ustack()]=count();}' \
       -n END'{trunc(@a,10); printa(@a);}'

The use of execname was more convenient than specifying a PID and I learned about the END action from this example as well. The command periodically collects the state of the user stack and then aggregates that information and prints the ten most popular stack traces, which should give a statistical indication of where StarOffice is spending its time while loading the spreadsheet.

Rather than include the raw output here, I've looked at the stacks and see that most of the time is being spent in routines with names like XMLStylesContext, XMLNumFormatContext, NumberFormatter, etc. From this I deduce that StarOffice is for some reason taking a very long time to parse the XML representation of this particular spreadsheet. Somewhat anti-climactic, I guess, but it always was about the journey, not the destination.