Profiling under SunOS
John E. Davis
I am looking for a profiling tool that is similar to `pixie' under Ultrix
for SunOS 4.x (NOT solaris). I have tried `prof', `gprof', and `tcov' but
the statistics provided by these programs do not seem to be anywhere near as
useful as the `pixie' statistics (See below for an example). Briefly, the
statistics provided by `pixie' show the number of MACHINE cycles per line.
It seems that `tcov' only shows the number of times a line is executed.
There is a big difference between these numbers.
Do DEC machines have special hardware that SunOS machines do not have that
support such analysis?
Here is an explicit example of the output provided by pixie. First, the
program (silly.c) is presented followed by the pixie output. I am sure you
will agree that gprof, etc... is a poor performace tool compared to pixie.
------------ silly.c -------------------
#include <stdio.h>
#include <string.h>
int main (int argc, char **argv)
{
char buf[256], *b, *a;
int argc_save, n_times;
char **argv_save;
b = buf;
argv_save = argv;
argc_save = argc;
n_times = 1000;
while (n_times--)
{
argc = argc_save;
argv = argv_save;
while (argc--)
{
a = *argv++;
while (*a)
{
if (b < buf + (sizeof (buf) - 1))
{
*b++ = *a;
}
a++;
}
}
*b = 0;
}
fprintf (stdout, "The length of %s is %d\n", buf, strlen (buf));
return 0;
}
------------- pixie output -----------------------------
Profile listing generated Mon Jul 3 16:31:03 1995 with:
prof -pixie ./a.out ./a.out.Addrs ./a.out.Counts
----------------------------------------------------------------------------------
* -p[rocedures] using basic-block counts; *
* sorted in descending order by the number of cycles executed in each *
* procedure; unexecuted procedures are excluded *
----------------------------------------------------------------------------------
383939 cycles
cycles %cycles cum % cycles bytes procedure (file)
/call /line
361533 94.16 94.16 361533 11 main (silly.c)
14997 3.91 98.07 55 14 _flsbuf (../flsbuf.c)
4743 1.24 99.31 4743 17 _doprnt (../doprnt.c)
2054 0.53 99.84 1027 7 strlen (../strlen.c)
133 0.03 99.88 45 12 fclose (../fclose.c)
117 0.03 99.91 117 10 malloc (../malloc.c)
75 0.02 99.93 38 17 fflush (../fclose.c)
52 0.01 99.94 52 19 _fwalk (../data.c)
33 0.01 99.95 33 13 morecore (../malloc.c)
31 0.01 99.96 31 13 _getstdiobuf (../getstdiobuf.c)
29 0.01 99.96 29 15 fprintf (../fprintf.c)
27 0.01 99.97 9 5 sbrk (../sbrk.s)
18 0.00 99.97 18 12 free (../malloc.c)
18 0.00 99.98 6 16 close (../close.s)
16 0.00 99.98 16 5 __start (./crt0.s)
16 0.00 99.99 16 14 exit (../exit.c)
12 0.00 99.99 12 15 isatty (../isatty.c)
9 0.00 99.99 9 12 _cleanup (../data.c)
6 0.00 99.99 6 16 write (../write.s)
6 0.00 100.00 6 16 ioctl (../ioctl.s)
6 0.00 100.00 6 16 fstat (../fstat.s)
6 0.00 100.00 6 16 getpagesize (../getpagesize.s)
2 0.00 100.00 2 6 _exit (../_exit.s)
----------------------------------------------------------------------------------
* -p[rocedures] using invocation counts; *
* sorted in descending order by number of calls per procedure; *
* unexecuted procedures are excluded *
----------------------------------------------------------------------------------
307 invocations total
calls %calls cum% bytes procedure (file)
277 90.23 90.23 584 _flsbuf (../flsbuf.c)
3 0.98 91.21 32 close (../close.s)
3 0.98 92.18 212 fclose (../fclose.c)
3 0.98 93.16 44 sbrk (../sbrk.s)
2 0.65 93.81 28 strlen (../strlen.c)
2 0.65 94.46 476 fflush (../fclose.c)
1 0.33 94.79 5100 _doprnt (../doprnt.c)
1 0.33 95.11 208 _fwalk (../data.c)
1 0.33 95.44 212 morecore (../malloc.c)
1 0.33 95.77 188 main (silly.c)
1 0.33 96.09 204 fprintf (../fprintf.c)
1 0.33 96.42 388 malloc (../malloc.c)
1 0.33 96.74 72 free (../malloc.c)
1 0.33 97.07 176 _getstdiobuf (../getstdiobuf.c)
1 0.33 97.39 68 __start (./crt0.s)
1 0.33 97.72 192 exit (../exit.c)
1 0.33 98.05 60 isatty (../isatty.c)
1 0.33 98.37 36 _cleanup (../data.c)
1 0.33 98.70 32 write (../write.s)
1 0.33 99.02 32 ioctl (../ioctl.s)
1 0.33 99.35 32 fstat (../fstat.s)
1 0.33 99.67 32 getpagesize (../getpagesize.s)
1 0.33 100.00 16 _exit (../_exit.s)
----------------------------------------------------------------------------------
* -h[eavy] using basic-block counts; *
* sorted in descending order by the number of cycles executed in each *
* line; unexecuted lines are excluded *
----------------------------------------------------------------------------------
procedure (file) line bytes cycles % cum %
main (silly.c) 32 12 106000 27.61 27.61
main (silly.c) 26 12 100255 26.11 53.72
main (silly.c) 28 8 50255 13.09 66.81
main (silly.c) 31 4 50000 13.02 79.83
main (silly.c) 24 16 24000 6.25 86.08
main (silly.c) 33 12 13000 3.39 89.47
main (silly.c) 23 8 12000 3.13 92.60
_doprnt (../doprnt.c) 994 120 2844 0.74 93.34
_flsbuf (../flsbuf.c) 135 52 2221 0.58 93.91
main (silly.c) 35 12 2001 0.52 94.44
main (silly.c) 21 8 2000 0.52 94.96
_flsbuf (../flsbuf.c) 166 32 1939 0.51 95.46
_flsbuf (../flsbuf.c) 58 28 1939 0.51 95.97
_flsbuf (../flsbuf.c) 131 28 1939 0.51 96.47
_flsbuf (../flsbuf.c) 63 20 1385 0.36 96.83
strlen (../strlen.c) 37 8 1024 0.27 97.10
strlen (../strlen.c) 36 8 1024 0.27 97.37
main (silly.c) 34 4 1000 0.26 97.63
main (silly.c) 19 4 1000 0.26 97.89
_flsbuf (../flsbuf.c) 92 12 834 0.22 98.10
_flsbuf (../flsbuf.c) 132 12 831 0.22 98.32
_flsbuf (../flsbuf.c) 82 16 831 0.22 98.54
_flsbuf (../flsbuf.c) 85 20 831 0.22 98.75
_doprnt (../doprnt.c) 990 124 788 0.21 98.96
_flsbuf (../flsbuf.c) 162 8 554 0.14 99.10
_doprnt (../doprnt.c) 993 20 516 0.13 99.24
_flsbuf (../flsbuf.c) 119 8 277 0.07 99.31
_flsbuf (../flsbuf.c) 142 4 277 0.07 99.38
_flsbuf (../flsbuf.c) 140 4 277 0.07 99.45
_flsbuf (../flsbuf.c) 117 4 277 0.07 99.53
_flsbuf (../flsbuf.c) 91 4 277 0.07 99.60
_flsbuf (../flsbuf.c) 139 4 276 0.07 99.67
_doprnt (../doprnt.c) 327 84 190 0.05 99.72
_doprnt (../doprnt.c) 330 28 99 0.03 99.75
_doprnt (../doprnt.c) 329 12 57 0.01 99.76
_doprnt (../doprnt.c) 326 28 37 0.01 99.77
fclose (../fclose.c) 212 32 24 0.01 99.78
_doprnt (../doprnt.c) 371 52 22 0.01 99.78
_doprnt (../doprnt.c) 328 4 19 0.00 99.79
fclose (../fclose.c) 225 24 18 0.00 99.79
malloc (../malloc.c) 595 8 18 0.00 99.80
_fwalk (../data.c) 79 20 15 0.00 99.80
fclose (../fclose.c) 237 20 15 0.00 99.80
fclose (../fclose.c) 227 20 15 0.00 99.81
_fwalk (../data.c) 81 24 14 0.00 99.81
_doprnt (../doprnt.c) 238 56 14 0.00 99.82
fflush (../fclose.c) 134 44 14 0.00 99.82
_doprnt (../doprnt.c) 563 28 13 0.00 99.82
close (../close.s) 18 24 12 0.00 99.83
fclose (../fclose.c) 208 16 12 0.00 99.83
fflush (../fclose.c) 126 20 10 0.00 99.83
_doprnt (../doprnt.c) 1007 116 10 0.00 99.83
_doprnt (../doprnt.c) 355 44 10 0.00 99.84
fflush (../fclose.c) 173 20 10 0.00 99.84
fflush (../fclose.c) 203 20 10 0.00 99.84
fflush (../fclose.c) 92 20 10 0.00 99.84
malloc (../malloc.c) 593 4 9 0.00 99.85
fclose (../fclose.c) 218 12 9 0.00 99.85
main (silly.c) 36 36 9 0.00 99.85
_doprnt (../doprnt.c) 912 36 9 0.00 99.85
fprintf (../fprintf.c) 132 48 9 0.00 99.86
malloc (../malloc.c) 594 4 9 0.00 99.86
_doprnt (../doprnt.c) 520 36 9 0.00 99.86
fclose (../fclose.c) 220 16 8 0.00 99.86
morecore (../malloc.c) 679 32 8 0.00 99.86
exit (../exit.c) 53 32 8 0.00 99.87
_flsbuf (../flsbuf.c) 107 32 8 0.00 99.87
malloc (../malloc.c) 626 32 8 0.00 99.87
_doprnt (../doprnt.c) 981 124 8 0.00 99.87
fflush (../fclose.c) 172 28 8 0.00 99.87
_doprnt (../doprnt.c) 366 16 8 0.00 99.88
_getstdiobuf (../getstdiobuf.c) 63 32 8 0.00 99.88
free (../malloc.c) 715 28 7 0.00 99.88
fprintf (../fprintf.c) 110 28 7 0.00 99.88
fprintf (../fprintf.c) 73 28 7 0.00 99.88
malloc (../malloc.c) 587 28 7 0.00 99.89
_fwalk (../data.c) 71 28 7 0.00 99.89
_doprnt (../doprnt.c) 562 12 6 0.00 99.89
isatty (../isatty.c) 12 24 6 0.00 99.89
fclose (../fclose.c) 236 8 6 0.00 99.89
_doprnt (../doprnt.c) 944 12 6 0.00 99.89
_fwalk (../data.c) 80 8 6 0.00 99.90
sbrk (../sbrk.s) 34 8 6 0.00 99.90
_doprnt (../doprnt.c) 960 24 6 0.00 99.90
_flsbuf (../flsbuf.c) 136 24 6 0.00 99.90
malloc (../malloc.c) 582 24 6 0.00 99.90
close (../close.s) 20 8 6 0.00 99.90
_getstdiobuf (../getstdiobuf.c) 68 20 5 0.00 99.91
fclose (../fclose.c) 228 20 5 0.00 99.91
malloc (../malloc.c) 581 20 5 0.00 99.91
_doprnt (../doprnt.c) 943 28 5 0.00 99.91
_doprnt (../doprnt.c) 918 28 5 0.00 99.91
malloc (../malloc.c) 627 20 5 0.00 99.91
malloc (../malloc.c) 647 20 5 0.00 99.91
_fwalk (../data.c) 89 24 5 0.00 99.91
free (../malloc.c) 706 16 4 0.00 99.92
_doprnt (../doprnt.c) 367 8 4 0.00 99.92
ioctl (../ioctl.s) 18 24 4 0.00 99.92
write (../write.s) 18 24 4 0.00 99.92
fstat (../fstat.s) 18 24 4 0.00 99.92
_getstdiobuf (../getstdiobuf.c) 82 16 4 0.00 99.92
malloc (../malloc.c) 571 16 4 0.00 99.92
_flsbuf (../flsbuf.c) 108 16 4 0.00 99.92
_fwalk (../data.c) 78 16 4 0.00 99.92
morecore (../malloc.c) 692 16 4 0.00 99.92
morecore (../malloc.c) 687 16 4 0.00 99.93
morecore (../malloc.c) 672 16 4 0.00 99.93
morecore (../malloc.c) 669 16 4 0.00 99.93
_flsbuf (../flsbuf.c) 109 16 4 0.00 99.93
_doprnt (../doprnt.c) 558 12 4 0.00 99.93
malloc (../malloc.c) 583 16 4 0.00 99.93
_cleanup (../data.c) 96 16 4 0.00 99.93
strlen (../strlen.c) 38 8 4 0.00 99.93
isatty (../isatty.c) 14 20 4 0.00 99.93
main (silly.c) 16 16 4 0.00 99.94
malloc (../malloc.c) 603 20 4 0.00 99.94
_doprnt (../doprnt.c) 986 124 4 0.00 99.94
malloc (../malloc.c) 616 16 4 0.00 99.94
_doprnt (../doprnt.c) 945 8 4 0.00 99.94
getpagesize (../getpagesize.s) 18 24 4 0.00 99.94
malloc (../malloc.c) 628 16 4 0.00 99.94
sbrk (../sbrk.s) 32 4 3 0.00 99.94
_getstdiobuf (../getstdiobuf.c) 65 12 3 0.00 99.94
sbrk (../sbrk.s) 33 4 3 0.00 99.94
sbrk (../sbrk.s) 31 4 3 0.00 99.94
sbrk (../sbrk.s) 30 4 3 0.00 99.95
fflush (../fclose.c) 135 12 3 0.00 99.95
sbrk (../sbrk.s) 35 4 3 0.00 99.95
_getstdiobuf (../getstdiobuf.c) 80 12 3 0.00 99.95
_flsbuf (../flsbuf.c) 99 12 3 0.00 99.95
sbrk (../sbrk.s) 36 4 3 0.00 99.95
sbrk (../sbrk.s) 37 4 3 0.00 99.95
fclose (../fclose.c) 232 4 3 0.00 99.95
fclose (../fclose.c) 231 4 3 0.00 99.95
fclose (../fclose.c) 233 4 3 0.00 99.95
exit (../exit.c) 66 20 3 0.00 99.95
_getstdiobuf (../getstdiobuf.c) 57 12 3 0.00 99.95
_flsbuf (../flsbuf.c) 115 12 3 0.00 99.95
_doprnt (../doprnt.c) 517 20 3 0.00 99.96
fclose (../fclose.c) 210 4 3 0.00 99.96
main (silly.c) 5 12 3 0.00 99.96
exit (../exit.c) 79 12 3 0.00 99.96
fclose (../fclose.c) 211 12 3 0.00 99.96
_doprnt (../doprnt.c) 552 16 3 0.00 99.96
_cleanup (../data.c) 95 12 3 0.00 99.96
main (silly.c) 37 12 3 0.00 99.96
morecore (../malloc.c) 655 12 3 0.00 99.96
fclose (../fclose.c) 234 4 3 0.00 99.96
fclose (../fclose.c) 235 4 3 0.00 99.96
malloc (../malloc.c) 633 8 2 0.00 99.96
malloc (../malloc.c) 632 8 2 0.00 99.96
fprintf (../fprintf.c) 96 8 2 0.00 99.96
malloc (../malloc.c) 621 12 2 0.00 99.97
isatty (../isatty.c) 9 8 2 0.00 99.97
fprintf (../fprintf.c) 97 12 2 0.00 99.97
_doprnt (../doprnt.c) 919 12 2 0.00 99.97
_doprnt (../doprnt.c) 955 4 2 0.00 99.97
fflush (../fclose.c) 183 8 2 0.00 99.97
malloc (../malloc.c) 592 8 2 0.00 99.97
_doprnt (../doprnt.c) 954 4 2 0.00 99.97
malloc (../malloc.c) 589 8 2 0.00 99.97
fflush (../fclose.c) 174 12 2 0.00 99.97
_doprnt (../doprnt.c) 949 4 2 0.00 99.97
morecore (../malloc.c) 681 8 2 0.00 99.97
fflush (../fclose.c) 170 4 2 0.00 99.97
morecore (../malloc.c) 688 8 2 0.00 99.97
_doprnt (../doprnt.c) 1009 8 2 0.00 99.97
exit (../exit.c) 78 8 2 0.00 99.97
fflush (../fclose.c) 137 8 2 0.00 99.97
_cleanup (../data.c) 93 8 2 0.00 99.97
fflush (../fclose.c) 103 8 2 0.00 99.97
malloc (../malloc.c) 586 8 2 0.00 99.98
_getstdiobuf (../getstdiobuf.c) 78 8 2 0.00 99.98
_flsbuf (../flsbuf.c) 114 8 2 0.00 99.98
_doprnt (../doprnt.c) 317 8 2 0.00 99.98
malloc (../malloc.c) 618 8 2 0.00 99.98
strlen (../strlen.c) 31 4 2 0.00 99.98
free (../malloc.c) 720 8 2 0.00 99.98
write (../write.s) 20 8 2 0.00 99.98
_getstdiobuf (../getstdiobuf.c) 79 8 2 0.00 99.98
_doprnt (../doprnt.c) 342 8 2 0.00 99.98
ioctl (../ioctl.s) 20 8 2 0.00 99.98
free (../malloc.c) 713 8 2 0.00 99.98
free (../malloc.c) 700 8 2 0.00 99.98
fstat (../fstat.s) 20 8 2 0.00 99.98
fprintf (../fprintf.c) 117 8 2 0.00 99.98
_doprnt (../doprnt.c) 518 36 2 0.00 99.98
__start (./crt0.s) 87 8 2 0.00 99.98
_doprnt (../doprnt.c) 526 16 2 0.00 99.98
_doprnt (../doprnt.c) 559 4 2 0.00 99.98
_doprnt (../doprnt.c) 553 8 2 0.00 99.99
_doprnt (../doprnt.c) 561 4 2 0.00 99.99
_doprnt (../doprnt.c) 565 12 2 0.00 99.99
_doprnt (../doprnt.c) 564 8 2 0.00 99.99
getpagesize (../getpagesize.s) 20 8 2 0.00 99.99
_flsbuf (../flsbuf.c) 137 4 1 0.00 99.99
_flsbuf (../flsbuf.c) 138 4 1 0.00 99.99
_doprnt (../doprnt.c) 915 4 1 0.00 99.99
_exit (../_exit.s) 19 4 1 0.00 99.99
__start (./crt0.s) 90 4 1 0.00 99.99
__start (./crt0.s) 91 4 1 0.00 99.99
__start (./crt0.s) 92 4 1 0.00 99.99
__start (./crt0.s) 93 4 1 0.00 99.99
__start (./crt0.s) 94 4 1 0.00 99.99
__start (./crt0.s) 95 4 1 0.00 99.99
__start (./crt0.s) 96 4 1 0.00 99.99
__start (./crt0.s) 97 4 1 0.00 99.99
__start (./crt0.s) 120 4 1 0.00 99.99
__start (./crt0.s) 121 4 1 0.00 99.99
__start (./crt0.s) 122 4 1 0.00 99.99
__start (./crt0.s) 123 4 1 0.00 99.99
malloc (../malloc.c) 591 4 1 0.00 99.99
malloc (../malloc.c) 615 4 1 0.00 99.99
_doprnt (../doprnt.c) 446 8 1 0.00 99.99
malloc (../malloc.c) 596 4 1 0.00 99.99
malloc (../malloc.c) 620 4 1 0.00 99.99
_doprnt (../doprnt.c) 538 16 1 0.00 99.99
_doprnt (../doprnt.c) 539 16 1 0.00 99.99
malloc (../malloc.c) 634 4 1 0.00 99.99
_doprnt (../doprnt.c) 541 8 1 0.00 99.99
_doprnt (../doprnt.c) 542 16 1 0.00 99.99
main (silly.c) 10 4 1 0.00 99.99
_doprnt (../doprnt.c) 544 8 1 0.00 99.99
main (silly.c) 13 4 1 0.00 99.99
morecore (../malloc.c) 670 4 1 0.00 100.00
_doprnt (../doprnt.c) 445 4 1 0.00 100.00
malloc (../malloc.c) 613 4 1 0.00 100.00
malloc (../malloc.c) 614 4 1 0.00 100.00
malloc (../malloc.c) 617 4 1 0.00 100.00
_doprnt (../doprnt.c) 555 8 1 0.00 100.00
_doprnt (../doprnt.c) 556 12 1 0.00 100.00
main (silly.c) 12 4 1 0.00 100.00
morecore (../malloc.c) 677 4 1 0.00 100.00
malloc (../malloc.c) 584 4 1 0.00 100.00
malloc (../malloc.c) 590 4 1 0.00 100.00
_fwalk (../data.c) 72 4 1 0.00 100.00
_doprnt (../doprnt.c) 250 4 1 0.00 100.00
_doprnt (../doprnt.c) 312 4 1 0.00 100.00
_exit (../_exit.s) 18 4 1 0.00 100.00
__start (./crt0.s) 88 4 1 0.00 100.00
__start (./crt0.s) 89 4 1 0.00 100.00
_getstdiobuf (../getstdiobuf.c) 69 4 1 0.00 100.00
free (../malloc.c) 716 4 1 0.00 100.00
malloc (../malloc.c) 580 4 1 0.00 100.00
Markus Armbruster
[...]
> I am looking for a profiling tool that is similar to `pixie' under Ultrix
> for SunOS 4.x (NOT solaris).
> Do DEC machines have special hardware that SunOS machines do not have that
> support such analysis?
No, it's done in software. From pixie(1):
The pixie command reads an executable program, partitions it into basic
blocks, and writes an equivalent program containing additional code that
counts the execution of each basic block. A basic block is a region of
the program that can be entered only at the beginning and exited only at
the end. The pixie command also generates a file containing the address
of each of the basic blocks.
The instrumented program writes file containing a basic block
execution histogram on exit. With this information the pixtstats
utility can easily determine the execution count of every machine
instruction in the program and uses this to estimate the cycles.
In principle, this can be done for any machine, but I don't know
actual implementations except pixie.
NB: Instead of reorganizing executable programs, the compiler could
insert execution counters into every basic block. However, you will
want to compile execution counters into all the libraries, too.
[...]
> I am sure you
> will agree that gprof, etc... is a poor performace tool compared to pixie.
Amen.
Markus
Heiner Steven
> In article <3t9kb2$s...@senator-bedfellow.MIT.EDU> da...@space.mit.edu (John E. Davis) writes:
> [...]
> > for SunOS 4.x (NOT solaris).
> > Do DEC machines have special hardware that SunOS machines do not have that
> > support such analysis?
> No, it's done in software. From pixie(1):
> The pixie command reads an executable program, partitions it into basic
> blocks, and writes an equivalent program containing additional code that
> counts the execution of each basic block. A basic block is a region of
> the program that can be entered only at the beginning and exited only at
> the end. The pixie command also generates a file containing the address
> of each of the basic blocks.
[...]
This sounds like the description for tcov(1):
tcov (1) - construct test coverage analysis and
statement-by-statement profile
If you compile the program with the option -d, the program is
prepared for usage with tcov. See the manual pages for details.
[...]
> > will agree that gprof, etc... is a poor performace tool compared to pixie.
Well, gprof measures the execution times of the functions, and
tcov(1) shows the lines in the functions where the time is spent.
I use both of them.
Heiner
--
-------------------------------------------------------------
/ Heiner Steven h...@bintec.de / The expressed opinions are /
/ BinTec Computersysteme GmbH / mine, not BinTec's -- /
/ Willstaetter Str. 30 ------- ...even if they should be ;-)/
/ D-90449 Nuernberg / priv.: hei...@hsysnbg.nbg.sub.org /
------------------------------------------------------------