The Good, the Blog & the Ugly - Tim Cook's Weblog
- All
- MySQL
- Performance
- Personal
- Sun
Friday March 16, 2007
Simplifying "lockstat -I" Output (or Ruby Is Better Than Perl)
There, I said it. I have been a Perl scripter for nearly 20 years (since early version 3). I think Ruby has pretty much everything Perl has, and more, like:
- It is really object-oriented (rather than Perl's bolt-on objects). I am much more likely to end up using this functionality.
- It has operator overloading
- It has a "case" statement
- There is no Obfuscated Ruby Contest (though IMHO there could be one)
Anyway, enough religous argument. I want to thank my colleague Neel for putting me onto it, and now I will provide a simple example.
Post-Processing "lockstat -I"
The Ruby script below post-processes the output of "lockstat -I". Why you ask? - well, because the output of "lockstat -I" can be tens of thousands of lines, and it does not coalesce by CPU.
The script below will coalesce by CPU, and PC within a function (useful if you forgot the "-k" flag to lockstat). A very simple change will also make it coalesce by PIL, but I will leave that as an exercise for the reader.
Ruby Post-Processor Script
One thing about this is that I would write this script almost exactly the same way if I used Perl. That is another plus of Ruby - it is easy to pick-up for a Perl programmer.
#!/bin/env ruby -w
# lockstatI.rb - Simplify "lockstat -I" output
#
# http://blogs.sun.com/timc, 16 Mar 2007
#
# SYNOPSIS
# lockstat -I [-i 971 -n <nnnnnn> ] sleep <nnn> | lockstatI.rb
PROG = "lockstatI"
#-- Once we have printed values that cover this proportion, then quit
CUTOFF = 95.0
DASHES = ('-' * 79) + "\n"
#========================================================================
# MAIN
#========================================================================
print "#{PROG} - will display top #{CUTOFF}% of events\n"
events = 0
period = 0
state = 0
counts = {}
#-- The classic state machine
ARGF.each_line do |line|
next if line == "\n"
case state
when 0
if line =~ /^Profiling interrupt: (\d+) events in (\d.*\d) seconds/
then
puts line
state = 1
events = $1
period = $2
next
end
when 1
if line == DASHES then
state = 2
end
when 2
if line == DASHES then
break
end
f = line.split
count = f[0]
cpu, pil = f[5].split('+')
#-- Coalesce PCs within functions; i.e. do not differentiate by
#-- offset within a function. Useful if "-k" was not specified
#-- on the lockstat command.
caller = f[6].split('+')[0]
if pil then
caller = caller + "[" + pil + "]"
end
counts[caller] = counts[caller].to_i + count.to_i
end
end
#-- Give me an array of keys sorted by descending value
caller_keys = counts.keys.sort { |a, b| counts[b] <=> counts[a] }
#-- Dump it out
printf "%12s %5s %5s %s\n", "Count", "%", "cuml%", "Caller[PIL]"
cuml = 0.0
caller_keys.each do |key|
percent = counts[key].to_f * 100.0 / events.to_f
cuml += percent
printf "%12d %5.2f %5.2f %s\n", counts[key], percent, cuml, key
if cuml >= CUTOFF then
break
end
end
|
Example Output
Free beer to the first person to tell me what this is showing. It was not easy to comprehend the 90,000 line "lockstat -I" output prior to post-processing it though. You get this problem when you have 72 CPUs...
lockstatI - will display top 95.0% of events
Profiling interrupt: 4217985 events in 60.639 seconds (69559 events/sec)
Count % cuml% Caller[PIL]
1766747 41.89 41.89 disp_getwork[11]
1015005 24.06 65.95 (usermode)
502560 11.91 77.86 lock_set_spl_spin
83066 1.97 79.83 lock_spin_try[11]
62670 1.49 81.32 mutex_enter
53883 1.28 82.60 mutex_vector_enter
40847 0.97 83.57 idle
40024 0.95 84.51 lock_set_spl[11]
27004 0.64 85.15 splx
17432 0.41 85.57 send_mondo_set[13]
15876 0.38 85.94 atomic_add_int
14841 0.35 86.30 disp_getwork
|
Posted at 01:00PM Mar 16, 2007 by timc in Performance | Comments[1]
This is a personal weblog, I do not speak for my employer.
Posted by Bugster on March 16, 2007 at 01:45 PM PDT #