vi-curious Gary J Little's Weblog

Truss is easily fooled.

Was talking to Tim U about an Oracle TNSlistener problem that we had a timestamped truss for. It turns out that that I'd misunderstood the timestamps, and I suspect I'm not the only one. Tim has a concise explanation in his blog, but since I like to see this stuff in action (Ruth tells me this makes me a Kinesthetic learner) here is a simple example. We have a short program that does an open/close, then a big loop doing arithmetic in userland and then another open/close.

#include 
#include 
#include 
#include 
#include 

int  main()
{
 int c,d,i,x;

 c=open(".",O_RDONLY);
 close(c);
 x=0;d=0;
 int *ptr;
 ptr=&d;
 for (i=0;i<9999999;i++)
 {
  for (i=0;i<99999999;i++)
   {
    x=i+1;
    *ptr=x;
   }
 }

 c=open(".",O_RDONLY);
 close(c);
 return(0);

}

The resulting truss shows that the second 'open()' took over one second, to open the same file which previously took <10 msec truss -Dd

 0.0183  0.0002 setustack(0xFF3A2088)
 0.0193  0.0010 open(".", O_RDONLY)                             = 3
 0.0198  0.0005 close(3)                                        = 0
 1.5498  1.5300 open(".", O_RDONLY)                             = 3
 1.5503  0.0005 close(3)                                        = 0
 1.5511  0.0008 _exit(0)

In reality the time was spent in userland doing the large loop, but all we see in truss -Dd is the time between the last close and the next open. By changing the loops to be smaller we change the output thus:

 0.0168  0.0002 setustack(0xFF3A2088)
 0.0177  0.0009 open(".", O_RDONLY)                             = 3
 0.0182  0.0005 close(3)                                        = 0
 0.0194  0.0012 open(".", O_RDONLY)                             = 3
 0.0199  0.0005 close(3)                                        = 0
 0.0203  0.0004 _exit(0)

Prior to Solaris 10, there's not much that can be done about that, but being aware of how truss calculates the values is at least a start. With Solaris 10, and -E option we get a much better representation of what's going on. truss -Ed

 0.0243  0.0001 setustack(0xFF3A2088)
 0.0254  0.0004 open(".", O_RDONLY)                             = 3
 0.0266  0.0000 close(3)                                        = 0
 1.6171  0.0004 open(".", O_RDONLY)                             = 3
 1.6178  0.0000 close(3)                                        = 0
 1.6184  0.0000 _exit(0)

( Apr 07 2005, 11:59:52 AM BST ) Permalink Comments [1]