X

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

Join the discussion

Comments ( 1 )
  • Bugster Friday, March 16, 2007
    Can you file an RFE for lockstat to have this output mode directly?
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.