Monday Jan 10, 2005

LASIK Surgery

Two years ago, after a great deal of introspection and research, I decided to undergo LASIK surgery. I was 34 at the time and I had worn glasses for the vast majority of my life. My vision was 20/600, which means I could see at 20 feet what most people could see at 600 feet. I was very nearsighted. Without glasses I was unable to read anything further than about 5 inches from my face. Today, my vision is 20/20 in both eyes and the wonder of living life without glasses has not worn off.

Deciding On LASIK

My optometrist and I had spoken about LASIK and other vision correction surgeries for close to five years. At first his knowledge of the surgeries was superficial and his advice was to wait for a few years. Later he advised me to wait until my eyes settled down since most reputable surgeons require a candidate's prescription to be stable for two years. That was four years ago. I started to read up on the procedures available and talking to people who had the surgeries.

Most of the people I talked to had either PRK or LASIK surgeries. Most reported similar experiences, with LASIK seeming to have shorter recovery times. My optometrist started performing patient screening for a local franchise of The Laser Center and began learning a great deal about LASIK. I spent a great deal of time researching on the web; reading about the various positive and negative outcomes.

Two and half years ago, during a routine exam, my optometrist announced that my eyes had been stable for two years and he thought that I might be a good candidate for LASIK. He recommended The Laser Center in Austin, mostly due to the fact that only one surgeron was performing operations there and his success rate was extremely impressive. I contacted The Laser Center and scheduled a battery of test to determine if I was indeed a good candidate.

Elective Refractive Surgery

I arrived at The Laser Center armed with a checklist of questions and a paper entitled "Ten Reasons Why You Should Not Have Eye Surgery" ( or something very close ). I would be making a majority of my decision to trust my eyes to these people based on their reaction to my questions. They were delighted that I had brought so many questions with me and we proceeded to spend over an hour going through each question. The people at The Laser Center were very forth coming and provided as much historical data on previous surgeries' results as were available ( three years ). Before the first test to determine my suitability for surgery, I was ready to trust these people.

Next came a battery of tests, the purpose of most I forget. The one that stands out in my memory produced a topographic map of my eyes. It measured the thickness of my corneas and the amount of variation seemed alarming until I noticed the key. The apparant hills and valleys were absurdly small features on my corneas and completely normal. The final verdict, my corneas were thick enough to make me a good candidate for surgery. Thin corneas might tear during the procedure which increases the amount of time required to heal dramatically and increases the possibility of infection. Thick is definitely better.

LASIK or Maybe I Shouldn't Have Asked

Excerpted from

LASIK stands for Laser-Assisted In Situ Keratomileusis and is a procedure that permanently changes the shape of the cornea, the clear covering of the front of the eye, using an excimer laser. A knife, called a microkeratome, is used to cut a flap in the cornea. A hinge is left at one end of this flap. The flap is folded back revealing the stroma, the middlesection of the cornea. Pulses from a computer-controlled laser vaporize a portion of the stroma and the flap is replaced.

You can imagine that reading about it and experiencing it might be two very different things. And you'd be right.

My surgery was scheduled for 11:15 am on January 9th. My wife and my optometrist accompanyed me to the clinic. My wife was going to drive me home afterwards and my optometrist just plain kicked ass (he's semi-retired now, otherwise I'd be shouting his name to the rooftops). We got there early and spent about 20 minutes in the (posh) waiting room before I was taken to prep. Preperation involved taking a sedative, a final check by the staff eye doctor and a brief visit from the surgeon. The surgeon was brief but positive and then I was lead into a darkened room to wait my turn. There was quiet classical music playing and three other people in the room mellowing out with their sedatives. One by one we lead away to the operating suite. My optometrist came and got me and it was my turn.

Blurred Impressions of Something Scary

The sedative administered before the procedure is important because three very unnatural things are about to happen. I entered the surgical suite and was situated on a padded table with a cluster of vaguely industrial equipment around the head. Vaguely because I wasn't wearing my glasses at the time. They don't waste alot of time, and in very short order they began prepping my eyes by placing numbing drops in them and cleaning around my eyes. Because blinking can be disruptive during the procedure, they then insert a lid speculum into your eye ( this is addition to taping your eyelids open ). That is the first unnatural thing. Next a suction cup is attached to your eye to hold the eye still while the microkeratome is used to cut a flap in the cornea. That is very unnatural, but didn't hurt. The flap is then lifted and folded over in preperation for the laser. At this point, my vision was very blurry and I was directed to look directly into a small red light directly above me ( the aperature for laser ). The laser used in my procedure incorporated an eye tracker which provides feedback to the laser and will also shut the laser off if your eye moves too far out of axis.

Staring at the red dot, the surgeon announced that the eye tracker had locked on and the laser would be firing it's preprogrammed sequence for some number of seconds. I don't recall the exact number, but it was less than 60 seconds. During that time, the laser buzzed but I didn't notice any visual artifacts. I was struggling to look at the red light, terrified that I'd wreck my eyes by moving at the wrong time. I also had a vague impression of a burnt smell, which of course was the ablated tissue from my eye. The third unnatural thing.

The surgeon counted down the last few seconds and the laser shut off. He then inspected the work done by the laser and spent a great deal of time folding over and smoothing out the flap in my corena.

The first eye ( the right ) was done.

I was shaking like I was caught in a blizzard without a jacket. I had no idea how I would endure the left eye. The discomfort of the ligature and the fear of loosing my sight due to moving during the procedure were overpowering.

And then the coolest thing happened. My optometrist, who had accompanied me into the suite and observed everything so far, reached out and patted my foot and murmured a few words of encouragement. That's all. I felt a sense of relief that just flooded me. I can't explain it since I was defintely under the influence of the sedative, but I stopped shaking as much and the team went to work on my left eye. While uncomfortable, the left eye was no where near the ordeal that the right eye was.

Less than ten minutes in the suite and I was being led out. My doctor and the staff doctor examined my cornea flaps and gave care directions to my wife since I was still pretty shook up. I had antibiotic eye drops and steroid drops and lubricant drops and a pair of clear eye shields that I would need to wear for weeks ( to prevent me from touching or rubbing my eyes and disrupting the healing of the flaps in my corneas ).

On the car ride home, I was blurrily reading the roadside signs.

Without glasses.


The first two weeks I was certain that I'd had a bad outcome and my anxiety during the procedure was the cause. But in reality my eyes were healing and my expectations hadn't been realistic. My vision was blurry but already far better than it had been without glasses. After two weeks, my vision was 20/20 in the right eye and 20/15 in the left. I would have good seeing days and bad seeing days, but I think those might have been related to the muscles around my eyes re-learning a lifetime of movement to accomodate my new accuity. My doctor was unable to explain the descrepency between my right and left eyes. We think the difference might have been induced by my anxiety during the right eye, but it's only a theory. We recommended back to the clinic that they review the amount and type of sedative given since I might not have received enough.

The two biggest post-procedure complaints most people have are dry eyes and haloing at night. The dry eyes stems from the nerves in the cornea which are severed when the flap is cut. Those nerves provide feedback when the eye became dry and take time to grow back. For the first six months afterwards I used eye lubrication three or more times a day. Two years later I don't have any need for supplimental lubrication.

Haloing ( or flaring ) at night happens when viewing a bright light ( such as oncoming headlights in traffic ). For me, the haloing is no worse than what I had experienced with contacts. There is an interesting retouched photos on Surgical Eyes which attempt to show what it's like to experience haloing. The photos are not representative of how I see at night; the halos I see are much less pronounced.

Two Years Later

It's been just over two years and I could not be happier. I can wear cheap $5 sunglasses and not worry if I loose them. I can SCUBA dive without worring about loosing contacts during a dive. My pistol and rifle shooting improved. I can read the clock across the room when I wake up in the morning. Practically every aspect of my life improved, including my self-esteem.

As I grow older I'm told I will become farsighted and will require reading glasses. Until then I should enjoy 30 or more years of good vision. I think I can live with that.


Friday Aug 13, 2004

Perl+DTrace=Instruction Tracing

As promised, an ugly perl script that can be used to generate a custom DTrace script which will generate an instruction trace.

For instance:

trogdor:utrace -> ls
hello\*      hello.c\*  utrace.txt\* 
trogdor:utrace -> -i hello
trogdor:utrace -> sudo dtrace -Cs hello.t -c hello

For the interested, here is the text of the traced program, the DTrace script, and the output generated.

The perl script is no where near "feature complete", nor is it an example of good perl programming practice ( parts of it are legible ). But, say it with me, it scratched an itch :).


Thursday Jul 29, 2004

DTrace Instruction Tracing Continues..

Wow, this has me bugged. Using this script ( called itrc.d ):

        printf("%d %016llx",vtimestamp,uregs[R_PC]);

# dtrace -s itrc.d -c hello3 > rtrc.hello3

a custom SPARC disassembler, and a really awful perl script, I produced:

Delta NS Address          Instruction   (disassembled)
       0 0000000100000740 bc102000      or      %g0, 0x0, %fp
   12960 0000000100000744 e05ba87f      ldx     [%sp+0x87f], %l0
    7120 0000000100000748 1b000000      sethi   0x0, %o5
    5040 000000010000074c 9a136001      or      %o5, 0x1, %o5
    4960 0000000100000750 9b2b7020      sllx    %o5, 0x1020, %o5
    4640 0000000100000754 13000403      sethi   0x100c00, %o1
    3920 0000000100000758 9212400d      or      %o1, %o5, %o1
    4240 000000010000075c e0226208      stw     %l0, [%o1+ 0x208]
    4240 0000000100000760 a203a887      add     %sp, 0x887, %l1

I think I'm almost done.


DTrace Instruction Tracing

Adam Leventhal pointed out that the DTrace pid provider can instrument user-land instructions, so my interest was piqued enough to give it a whirl last night. The script I ended up with is just stupidly short, I feel like I'm cheating.

        printf("pc %p: %x",uregs[R_PC],\*(uint )copyin(uregs[R_PC],4));

Using a new DTrace feature, I start the trace and get some output:

# dtrace -c ./hello2 -s itrc.d 
CPU     ID                    FUNCTION:NAME
  0  38695                     _start:entry pc 1000006a0: 91d02038
  0  38696                         _start:0 pc 1000006a0: 91d02038
  0  38697                         _start:4 pc 1000006a4: 91d02038
  0  38698                         _start:8 pc 1000006a8: 91d02038

That doesn't look right. The PC's look good, but those aren't the instructions at those addresses. Or are they? I was a bit foggy last night when I started messing with this, so I assumed that I wasn't using copyin() right. Somehow I was getting the address of the DTrace buffer that copyin returns or something. In the cold light of morning things look different. It occurs to me that 91d02038 looks familiar. Yes I know, it's numbers. The crawling itch in my lizard hacker brain was trying to tell me something:

91d02038 <=> ta      %icc, 0x38

What? Your lizard hacker brain doesn't tell you stuff like that? Lucky you. So I was using copyin correctly. I am fetching the instruction at the PC, just not the original instruction. As everybody knows, 0x38 is the DTRACE pid provider trap, so this instruction is the DTrace instrumentation that makes it all work.

I'm feeling moderately clever for having figured that out on only two cups of coffee. :)


Wednesday Jul 28, 2004

Adventures in Instruction Tracing: Part Duex!

Yesterday I began talking about cobbling together a user-land instruction trace tool using a variety of UltraSPARC and Solaris features. Today I'm going to cop out alittle and present the comments for the user trap handler I wrote which is the heart of the tool. For the truly bored, I've provided a hello.c and associated (post-processeed) trace.


#if 0

illtrap_hndlr - Btrace3 ILLTRAP utrap handler

Btrace3 instruments the code of a program by substituting control
transfer instructions (CTIs) with specially prepared ILLTRAP
instructions.  When the code executes, the ILLTRAP instructions cause
the utrap handler to execute.  This allows us to observe the actual
path of execution by noting which ILLTRAP instructions are executed.

It probably is worth mentioning that the ILLTRAP instruction is a
sneaky way of hiding 22 bit constant data in your code.  According to
_The SPARC Architecture Manual_ Version 9, David Weaver and Tom
Germond, page 168:

"The ILLTRAP instruction causes a illegal_instruction exception. The
 const22 value is ignored by the hardware; specifically, this field is
 NOT reserved by the architecure for any future use."

I have taken advantage of this by crafting the ILLTRAP instructions so
that they serve as indices into the array of saved original
instructions. Used in a flat array, a const22 value gives us 2\^22-1 or
roughly 4 million points where code can be instrumented.  For the
current generation of software this number of probe points appears to
suffice, but it is not difficult to conceive of future applications
where the number of probe points exceeds this flat space.

The first implementation of Btrace played a dangerous shell game,
storing the original instruction back into the executing stream of
instructions and re-inserting the ILLTRAP when handling the next
probed CTI.  Despite the odd corner case, this technique worked
surprisingly well in a single- threaded application.  It falls apart
when attempting to trace multi- threaded applications since the
complexity of managing multiple stores into the instruction stream and
guranteeing correctness of the instrumented program proved simply

Btrace3 sidesteps the self-modifying code aspects of Btrace1 and 2 by
emulating the CTI instruction instead of storing the probed
instruction back into the instruction stream.  This is possible since
the utrap handler can choose where the trapping context begins
executing after the utrap handler returns.  Typical utrap handlers
either skip the trapping instruction or restart the trapping
instruction after modifying the state of the trapping context.  A CTI
instruction can be emulated by calculating the target address if the
branch is taken and then determining if the CTI is taken.  After
evaluating any conditions predicated by the type of instruction being
emulated, it is a simple matter to return with arbitrary PC and nPC

Since the instruction stream remains instrumented during the lifetime
of of the process, the synchronization complexity of the tracing code
is greatly reduced.  The only remaining synchronization point is trace
buffer management, which is a relatively well understood problem.

The first Btrace implementation also uncovered the importance of
preserving the state of the trapping context before proceeding with
tracing activities.  The two macros UTRAP_PROLOG and UTRAP_EPILOG
preserve and restore the following registers: %ccr, %g1 - %g7.
Additionally, UTRAP_PROLOG writes ASI_PNF to %asi as required by the
__sparc_utrap_install(2) man page before calls are made to ABI
conforming functions.  Values are preserved on the stack, making the
utrap handler reasonably re-entrant.  The stack also has room for
sundry other values; %tick, %fsr, %l6 and %l7 (PC and nPC) from
trapping context, and the ILLTRAP instruction at [%l6].  The macro
UTRAP_EPILOG restores the state of %ccr, %g1 - %g7 which have may have
been corrupted by the utrap handler activites.

The following is a pseudo pseudocode description of how illtrap_hndlr works:


   sampled_tick_register = gethrtime()

   save trapping context

   original instruction = ProbeTable[ trapping ILLTRAP instruction ]

   tid = thr_self();     /\* re-implemented to avoid linking libthread \*/

   cpuid = getcpuid()    /\* new in Solaris 9 \*/

   switch( original instruction )
     case CALL:
        emulate CALL instruction

     case BPr:
        emulate BPr instruction	
     case FBfcc:
        emulate FBfcc instruction	
     case FBPfcc:
        emulate FBPfcc instruction	
     case Bicc:
        emulate Bicc instruction	

     case BPcc:
        emulate BPcc instruction	

     case JMPL:
        emulate JMPL instruction	
     default:   /\* getting to default is an error condition \*/
        unregister illtrap_hndlr
        restore trapping context
        restart trapping instruction, this time without the handler to
          catch it when it falls.  the program should die.
   /\* end of switch \*/

   pick PC and nPC values based on contents of FLG register which
   indicates if the branch was taken and if the delay slot instruction was

   if( !TraceOn )
     restore trapping context
     start executing at PC and nPC computed during instruction emulation
   if( cTrcSlot > TRCMAX )
     cTrcSlot = 0;

   store btfrec_t built in emulate_\* to TraceBuffer[cTrcSlot]



   restore trapping conext

   start executing at PC and nPC computed during instruction emulation


Of course there's alittle bit of hand waving, but that should give the
reader a basic idea of what's being done and in what order. 


Tuesday Jul 27, 2004

Anything You Can Do, D Can Do Better!

Not sour grapes honest! Jon Haslam saw my fsflush post and couldn't just bask in the glory that was old school hacking. He had to throw the new hotness at the problem. I, for one, welcome our new DTrace overlords!


Adventures in Instruction Tracing

One thing that performance people like to do is actually know what instructions are executed by a CPU. Crazy, I know. You can disassemble the program to know what specific machine instructions compose the program, but you still don't know what instructions specifically are executed at run-time due to branching in the code induced by the input to the program.

So way back when, clever programmers found ways to instrument their code ( or more often, somebody else's code ) in order to determine what instructions a CPU was executing. There are lots of techniques for doing this, but I'd like to talk about the one I implemented and was disclosed in a short paper that was published in the May 2004 issue of Research Disclosure Journal. I'm happy to have been published, but the two page limit did sort of cramp my style.

Branch Tracing

Some computer architectures provide a spiffy feature, often referred to as "trap on branch". It is possible to build a pretty efficient instruction tracing tool using trap on branch since it interrupts the code under observation only at the end of a basic block, rather than on every instruction executed. On average a SPARCv9 basic block consists of 5 instrutions, so using trap on branch to trace would trap 80% less than trapping on every instruction. Wait for it. Unfortunately, SPARCv9 does not define a trap on branch. Oh if only.

Work With What You've Got

Despite the lack of branch on trap in SPARCv9, there are some other architectural goodies defined which the intrepid hacker could exploit. The first thing I looked at was the Instruction Breakpoint Register( Ok, technically not defined by SPARCv9, it's a USIII implementation defined extension ), which caused a breakpoint trap to fire when an instruction matched a user definable mask. Originally intended as a means of hot-patching broken instructions in the field, this feature never really worked as designed and was disabled in USIII+.

Another cool feature that doesn't get alot of love is the user trap handler facility, described in __sparc_utrap_install(2) and in the SPARC architecture manual (verson 9). It allows a user to define and install a custom trap handler for a specific (but diverse) set of exceptions. Now that is pretty cool!

You Got Your Debugger In My Instruction Tracer!

Skipping ahead alittle bit, I had the idea of combining an old debugger technique for breakpointing with SPARC user trap handlers to create a poor-man's trap on branch. Many debuggers implement breakpointing by inserting an illegal instruction at the specified address in the program and catching the illegal instruction trap generated when the client program executes it. The debugger then patches up the replaced instruction or emulates it, whichever seemed easier to do at the time. An instruction tracing tool could patch up the victim target application, replacing all it's control transfer instructions (CTIs) with ILLTRAP instructions ( SPARC instructions whose specific job is cause an illegal instruction trap ). Then when the target runs, every time it tries to branch it causes a trap which we can intercept with a user trap handler. The handler could write a record to a trace file and then fix up the broken branch and restart the target. Simplicity itself!

It's Never That Easy

Where to start. First, user trap handling for ILLTRAP was broken as detailed in bug 4650095. Second, there's the small matter of introducing ILLTRAPs into a program. Third, what to do with the CTIs that you've replaced with ILLTRAPs and all the trace output you will generate?

I discovered that an LD_AUDIT shared object would be an excellent way to introduce the trace instrumentation into a target application. The runtime linker audit interfaces are described adequately in rtld_audit(3ext) and in excellent detail in the Linker and Libraries Guide. The audit interfaces give the determined hacker a great deal of freedom to mess with an executable before control is passed to it from the runtime linker. Another advantage of this technique is the instrumenting code and the target code all share the same address space, so it's very easy to find and replace all the CTIs in the target code with ILLTRAPs.

A Commercial Plug And Then A Pause For Breath

As an engineer for Sun, I have found these three books to be invaluable:

  1. The SPARC Architecture Manual, version 9
  2. Solaris Interals
  3. Linker And Libraries Guide

The Linker and Library Guide in particular is an amazing piece of work, especially when you learn that it's written by the same guys who write the linker code. Those guys rock! All that's missing is a blog from Siezo!

Tomorrow, I'll post some condensed notes on the design of a user-land instruction tracing tool built on user traps called Btrace3, and why it ultimately was a flop.


Friday Jul 23, 2004

fsflush: what is it doing?

Yesterday I was reading performance related bug reports, trolling for work, when I stumbled upon 5024143. I don't know alot about fsflush, so I did some reading and found that on10's fsflush is keeping some internal statistics concerning it's operation that it isn't sharing ( a kstat would be a good place to start ). So being a curious sort, I whipped up a libkvm(3LIB) consumer to expose fsflush's stats to userland. fsfstat is born! Caveat: on10 required.

Some Example Output

Here is sample output from fsfstat run on a 12-way 4800 with 28G of real memory, mostly idle ( Burninator! ).

trogdor:fsfstat -> sudo ./fsfstat 1
15:08:44    119810   3.3      235        0        0        0        0     340320
15:08:45    119810   6.7      235        0        0        0        0     324880
15:08:46    119810  10.0      235        0        0        0        0     324800
15:08:47    119810  13.3      235        0        0        0        0     318000
15:08:48    119810  16.7      634        2        0        0        0     501840
15:08:49    119810  20.0    13802      773        6        7        0    4269440
15:08:50    119810  23.3      235        0        0        0        0     335520
15:08:51    119810  26.7      235        0        0        0        0     320800
15:08:52    119810  30.0      235        0        0        0        0     317840
15:08:53    119810  33.3      235        0        0        0        0     317360
15:08:54    119810  36.7      235        0        0        0        0     320640
15:08:55    119810  40.0      235        0        0        0        0     323680
15:08:56    119810  43.3      235        0        0        0        0     320400
15:08:57    119810  46.7      235        0        0        0        0     315440
15:08:58    119810  50.0      235        0        0        0        0     318800
15:08:59    119810  53.3      235        0        0        0        0     319440
15:09:00    119810  56.7     6367     3124        0        0        0    7615280
15:09:01    119810  60.0   110739    54692        0        6        0  118389680
15:09:03    119810  63.3    33125    14333      374       10        0   31190320
15:09:04    239620  70.0      470        0        0        0        0     663520
15:09:05    119810  73.3      235        0        0        0        0     324240
15:09:06    119810  76.7      235        0        0        0        0     320080
15:09:07    119810  80.0      235        0        0        0        0     317280
15:09:08    119810  83.3      235        0        0        0        0     319680
15:09:09    119810  86.7      235        0        0        0        0     318640
15:09:10    119810  90.0     6572      773       18        0        0    3049280
15:09:11    119810  93.3   113238      617        4        0        0   20368080
15:09:12    119810  96.7   103493        0        0       21        0   17344240
15:09:13    119810 100.0      235        0        0        0        0     346960
15:09:14    119810   3.3      235        0        0        0        0     321040
15:09:15    119810   6.7      235        0        0        0        0     324240
15:09:16    119810  10.0      235        0        0        0        0     322960
15:09:17    119810  13.3      235        0        0        0        0     318400
15:09:18    119810  16.7     2139       96        0        0        0    1095680
15:09:19    119810  20.0    12249      679        6        0        0    3521120
15:09:20    119810  23.3      235        0        0        0        0     334400
15:09:21    119810  26.7      235        0        0        0        0     326960
15:09:22    119810  30.0      235        0        0        0        0     325840
15:09:23    119810  33.3      235        0        0        0        0     320240
15:09:24    119810  36.7      235        0        0        0        0     316720
15:09:25    119810  40.0      235        0        0        0        0     317040
15:09:26    119810  43.3      235        0        0        0        0     316640
15:09:27    119810  46.7      235        0        0        0        0     317120
15:09:28    119810  50.0      235        0        0        0        0     317040
15:09:29    119810  53.3      235        0        0        0        0     317600
15:09:30    119810  56.7    13010     6448        0        0        0   15070240
15:09:31    119810  60.0   115114    56225      109        0        0  121045120
15:09:32    119810  63.3    21994     9476      265        0        0   20595040
15:09:33    119810  66.7      235        0        0        0        0     339840
15:09:34    119810  70.0      235        0        0        0        0     319760

The first column is a timestamp, the second column is number of 8k pages scanned. The fourth column is number of pages examined, which can be a smaller number due to larger pages being composed of sets of smaller pages. Locked, modified, coalesce and release I'm still foggy on ( I need to read and understand fsflush.c some more ). The final column is the time in nanoseconds that fsflush ran over the previous interval. I've saved the third column for last because I thought I was being rather clever. The third column tracks how far thru memory fsflush has scanned since fsfstat has been observing it. In this way, we can tell when fsflush has made a complete sweep thru physical memory and is starting over again.

Some Interesting Observations

Using the locality information gained by the percentage progress thru memory, we can see a pattern emerging in the sample data. Starting at the 20%, 56% and 90% range, we see three second bursts of activity that recurr. I don't have a definite explanation for this activity, and I wouldn't mind hearing thoughts about what's going on here.

Anyway, today is a double-two-fer :) I'm just happy with how this hack turned out.


Tuesday Jul 20, 2004

LD_PRELOAD, or how I added timestamps to the output of anything.

A pet peeve of mine forever has been the fact that the \*stat family of tools don't timestamp their output. Oh sure, iostat has been granted a timestamp but vmstat, mpstat and the rest were left out in the cold. Yes, you could write a wrapper script which time stamps the beginning and the end of a ream of vmstat output but you still have to work to figure out when an event occurred in the middle of a 11,111,111 line capture of performance data.

Given my need to explore the odd nooks and crannies for what is possible, I thought it might be fun to write an LD_PRELOAD shared object which interjected a timestamp at the beginning of a line of output. All I'd need to do is provide a new printf and I'd be done right? Wrong!

After some messing about, it turned out that write(2) and _write() were the culprits that needed to be overridden to accomplish the mission. It also turned out that I needed to do some line buffering since I wanted the timestamp to be nice and tidy in column 1 of the output. For those of you with access to the internal network, you can find the fruit of my labor here. Those of you who don't can contact me and if my manager approves I could make it more widely available.

An example using venerable vmstat:

schwa:stamp-1.1 -> vmstat 1
 kthr      memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr f0 s0 s1 s6   in   sy   cs us sy id
 0 0 0 1729512 1154760 0 116 1  0  0  0  0  0  0  1  0  634 1594  717  1  1 97
 0 0 0 1648560 1030352 0 21  0  0  0  0  0  0  0  0  0  633 1323  466  0  0 100
 0 0 0 1648560 1030352 0 12  0  0  0  0  0  0  0  0  0  585 1157  425  0  0 100
 0 0 0 1648560 1030352 0 15  0  0  0  0  0  0  0 52  0  756 1143  492  0 21 79
 0 0 0 1648560 1030352 0 15  0  0  0  0  0  0  0  0  0  722 1658  509  0  0 100
schwa:stamp-1.1 -> setenv LD_PRELOAD
schwa:stamp-1.1 -> vmstat 1
14:21:28  kthr      memory            page            disk          faults      cpu
14:21:28  r b w   swap  free  re  mf pi po fr de sr f0 s0 s1 s6   in   sy   cs us sy id
14:21:28  0 0 0 1729504 1154744 0 116 1  0  0  0  0  0  0  1  0  634 1594  717  1  1 97
14:21:29  0 0 0 1648480 1030272 0 23  0  0  0  0  0  0  0  0  0  591 1211  415  0  0 99
14:21:30  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  577 1179  413  0  1 99
14:21:31  0 0 0 1648480 1030272 0 12  0  0  0  0  0  0  0  0  0  582 1240  438  0  0 100
14:21:32  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  584 1150  404  0  0 100
14:21:33  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  644 1543  492  1  0 99
14:21:34  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  677 1353  477  0  0 100
14:21:35  0 0 0 1648480 1030272 0 18  0  0  0  0  0  0  0 27  0  843 1644  552  0  1 99
14:21:36  0 0 0 1647280 1030032 0 325 0  0  0  0  0  0  0  0  0  777 2056  687  8  0 92
14:21:37  0 0 0 1648480 1030272 0 16  0  0  0  0  0  0  0  0  0  705 1422  526  2  0 98
14:21:38  0 0 0 1648480 1030272 0 40  0  0  0  0  0  0  0  0  0  772 2260  723  3  0 97

Admittedly, not horribly clever but it scratched an itch.


Thursday Jul 15, 2004

First Post!!!

I'm so pumped!

I'm blogging like all the other cool kids!

I'm Erik, I live and work in Austin Texas. I am a serious UNIX nerd, and I geek out on observability issues. I worked for IBM for 8 or so years; first as a co-op student, then a contractor and finally a regular employee. I worked with AIX on multiple platforms during my time there ( PS/2, RS/6000 and the RT briefly ). I joined Sun in August of 1999 .

Things I Claim to Know Something About

  • Solaris Kernel and Virtual Memory
  • SPARCv9 User Trap Handling
  • Application Linking and Loading (
  • ELF File Format
  • UNIX C Development Environment
  • emacs and emacs lisp
  • SPARC Assembly
  • X11/Xlib/Xt and Motif Application Development
  • TCP/IP Application Development
  • Pthread and Thread Application Development
  • Kstat Observability Development
  • Audit Library Development
  • MDB Debugger Command (dcmd) Development
  • Solaris Device Driver and Loadable Module Development
  • Kernel and User-land Application Debugging
  • General UNIX Hackery

When I'm not pounding on a keyboard, I like:

  • Competitive Pistol Shooting
  • Playing SOCOM 2 online, my nickname is "Jöhnny".
  • Slowly re-modeling my house.
  • Assembling PCs from random parts.
  • Napping with my dogs ( Sam and Sid ).

Wow this is harder than I thought, writing all this stuff. Maybe I'm not cut out for blogging!





« April 2014