### 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)
```

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 #

• HTML Syntax: NOT allowed