Example: tprof command

You can view the complete details of the tprof command in Files Reference.

The following example demonstrates how to collect a CPU tick profile of a program using the tprof command. The example was executed on a 4-way SMP system and since it is a fast-running system, the command completed in less than a second. To make this program run longer, the array size, or Asize, was changed to 4096 instead of 1024.

Upon running the following command, the version1.prof file is created in the current directory:

# tprof -z -u -p version1 -x version1

The version1.prof file reports how many CPU ticks for each of the programs that were running on the system while the version1 program was running.

The following is an example of what the version1.prof file contains:

          Process            Freq    Total   Kernel     User   Shared    Other
          =======            ====    =====   ======     ====   ======    =====
             wait               4     5810     5810        0        0        0
       ./version1               1     1672       35     1637        0        0
   /usr/bin/tprof               2       15       13        0        2        0
       /etc/syncd               1        2        2        0        0        0
      /usr/bin/sh               2        2        2        0        0        0
          swapper               1        1        1        0        0        0
 /usr/bin/trcstop               1        1        1        0        0        0
             rmcd               1        1        1        0        0        0
          =======             ===    =====   ======     ====   ======    =====
            Total              13     7504     5865     1637        2        0

           Process      PID      TID    Total   Kernel     User   Shared    Other
          =======      ===      ===    =====   ======     ====   ======    =====
             wait    16392    16393     1874     1874        0        0        0
             wait    12294    12295     1873     1873        0        0        0
             wait    20490    20491     1860     1860        0        0        0
       ./version1   245974   606263     1672       35     1637        0        0
             wait     8196     8197      203      203        0        0        0
   /usr/bin/tprof   291002   643291       13       13        0        0        0
   /usr/bin/tprof   274580   610467        2        0        0        2        0
       /etc/syncd    73824   110691        2        2        0        0        0
      /usr/bin/sh   245974   606263        1        1        0        0        0
      /usr/bin/sh   245976   606265        1        1        0        0        0
 /usr/bin/trcstop   245976   606263        1        1        0        0        0
          swapper        0        3        1        1        0        0        0
             rmcd   155876   348337        1        1        0        0        0
          =======      ===      ===    =====   ======     ====   ======    =====
            Total                       7504     5865     1637        2        0


      Total Samples = 7504       Total Elapsed Time = 18.76s

   Profile: ./version1
   Total Ticks For All Processes (./version1) = 1637

           Subroutine   Ticks     %        Source   Address  Bytes
        =============  ======  ======     =======   =======  =====
                .main    1637   21.82  version1.c       350    536


   Profile: ./version1
   Total Ticks For ./version1[245974] (./version1) = 1637

           Subroutine   Ticks     %        Source   Address  Bytes
        =============  ======  ======     =======   =======  =====
                .main    1637   21.82  version1.c       350    536

The first section of the report summarizes the results by program, regardless of the process ID, or PID. It shows the number of different processes, or Freq, that ran each program at some point.

The second section of the report displays the number of ticks consumed by, or on behalf of, each process. In the example, the version1 program used 1637 ticks itself and 35 ticks occurred in the kernel on behalf of the version1 process.

The third section breaks down the user ticks associated with the executable program being profiled. It reports the number of ticks used by each function in the executable program and the percentage of the total run's CPU ticks (7504) that each function's ticks represent. Since the system's CPUs were mostly idle, most of the 7504 ticks are idle ticks.

To see what percentage of the busy time this program took, subtract the wait thread's CPU ticks, which are the idle CPU ticks, from the total and then divide the difference from the total number of ticks.

Total number of ticks / (Total - Idle CPU ticks) = % busy time of program
                1637 /  (7504 - 5810) =
                1637 /  1694 = 0.97

So, the percentage of system busy ticks is 97%.