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)
Comments:

With the addition of -E to truss, my recommended set of truss flags can now be expressed as "-DeadElf". Cool.

Posted by Brian Utterback on April 08, 2005 at 08:04 AM BST #

Post a Comment:
  • HTML Syntax: NOT allowed
About

gjl

Search

Archives
« April 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
    
       
Today