[ Bottom of Page | Previous Page | Next Page | Contents | Index | Library Home | Legal | Search ]

Performance Tools Guide and Reference

CPU Utilization Reporting Tool (curt)

The CPU Utilization Reporting Tool (curt) command converts an AIX trace file into a number of statistics related to CPU utilization and either process, thread or pthread activity. These statistics ease the tracking of specific application activity. The curt command works with both uniprocessor and multiprocessor AIX Version 4 and AIX Version 5 traces.

curt Command Syntax

The syntax for the curt command is as follows:

curt -i inputfile [-o outputfile] [-n gennamesfile] [-m trcnmfile] [-a pidnamefile] [-f timestamp] [-l timestamp] [-ehpstP]

Flags

-i inputfile Specifies the input AIX trace file to be analyzed.
-o outputfile Specifies an output file (default is stdout).
-n gennamesfile Specifies a names file produced by gennames.
-m trcnmfile Specifies a names file produced by trcnm.
-a pidnamefile Specifies a PID-to-process name mapping file.
-f timestamp Starts processing trace at timestamp seconds.
-l timestamp Stops processing trace at timestamp seconds.
-e Outputs elapsed time information for system calls.
-h Displays usage text (this information).
-p Outputs detailed process information.
-s Outputs information about errors returned by system calls.
-t Outputs detailed thread information.
-P Outputs detailed pthread information.

Parameters

gennamesfile The names file as produced by the gennames command.
inputfile The AIX trace file to be processed by the curt command.
outputfile The name of the output file created by the curt command.
pidnamefile If the trace process name table is not accurate, or if more descriptive names are desired, use the -a flag to specify a PID to process name mapping file. This is a file with lines consisting of a process ID (in decimal) followed by a space, then an ASCII string to use as the name for that process.
timestamp The time in seconds at which to start and stop the trace file processing.
trcnmfile The names file as produced by the trcnmcommand.

Measurement and Sampling

A raw, or unformatted, system trace from AIX Version 4 or AIX Version 5 is read by the curt command to produce summaries, as well as first and second level interrupt handlers. This summary information is useful for determining which application, system call, or interrupt handler is using most of the CPU time and is a candidate for optimization to improve system performance.

The following table lists the minimum trace hooks required for the curt command. Using only these trace hooks will limit the size of the trace file. However, other events on the system may not be captured in this case. This is significant if you intend to analyze the trace in more detail.

Hook ID Event Name Event Explanation
100 HKWD_KERN_FLIH Occurrence of a first level interrupt, such as an I/O interrupt, a data access page fault, or a timer interrupt (scheduler).
101 HKWD_KERN_SVC A thread has issued a system call.
102 HKWD_KERN_SLIH Occurrence of a second level interrupt, that is, first level I/O interrupts are being passed on to the second level interrupt handler which then is working directly with the device driver.
103 HKWD_KERN_SLIHRET Return from a second level interrupt to the caller (usually a first level interrupt handler).
104 HKWD_KERN_SYSCRET Return from a system call to the caller (usually a thread).
106 HKWD_KERN_DISPATCH A thread has been dispatched from the run queue to a CPU.
10C HKWD_KERN_IDLE The idle process has been dispatched.
119 HKWD_KERN_PIDSIG A signal has been sent to a process.
134 HKWD_SYSC_EXECVE An exec supervisor call (SVC) has been issued by a (forked) process.
135 HKWD_SYSC__EXIT An exit supervisor call (SVC) has been issued by a process.
139 HKWD_SYSC_FORK A fork SVC has been issued by a process.
200 HKWD_KERN_RESUME A dispatched thread is being resumed on the CPU.
210 HKWD_KERN_INITP A kernel process has been created.
38F HKWD_DR A processor has been added/removed.
465 HKWD_SYSC_CRTHREAD A thread_create SVC has been issued by a process.
605 HKWD_PTHREAD_VPSLEEP A pthread vp_sleep operation has been done by a pthread.
609 HKWD_PTHREAD_GENERAL A general pthread operation has been done by a pthread.

Trace hooks 119 and 135 are used to report on the time spent in the exit system call. Trace hooks 134, 139, 210, and 465 are used to keep track of TIDs, PIDs and process names.

Trace hooks 605 and 609 are used to report on the time spent in the pthreads library.

Examples of the curt command

Preparing the curt command input is a three-stage process. Trace and name files are generated using the following process:

  1. Build the raw trace.
    On a 4-way machine, this will create files as listed in the example code below. One raw trace file per CPU is produced. The files are named trace.raw-0, trace.raw-1, and so forth for each CPU. An additional file named trace.raw is also generated. This is a master file that has information that ties together the other CPU-specific traces.
  2. Merge the trace files.
    To merge the individual CPU raw trace files to form one trace file, run the trcrpt command. If you are tracing a uniprocessor machine, this step is not necessary.
  3. Create the supporting gennamesfile and trcnmfile files by running the gennames and trcnm commands.
    Neither the gennamesfile nor the trcnmfile file are necessary for the curt command to run. However, if you provide one or both of these files, the curt command will output names for system calls and interrupt handlers instead of just addresses. The gennames command output includes more information than the trcnm command output, and so, while the trcnmfile file will contain most of the important address to name mapping data, a gennamesfile file will enable the curt command to output more names, especially interrupt handlers. The gennames command requires root authority to run. The trcnm command can be run by any user.

The following is an example of how to generate input files for the curt command:

# HOOKS="100,101,102,103,104,106,10C,119,134,135,139,200,210,38F,465,605,609" 
# SIZE="1000000" 
# export HOOKS SIZE 
# trace -n -C all -d -j $HOOKS -L $SIZE -T $SIZE -afo trace.raw
# trcon ; sleep 5 ; trcstop 
# unset HOOKS SIZE 
# ls trace.raw* 
trace.raw   trace.raw-0  trace.raw-1  trace.raw-2  trace.raw-3 
# trcrpt -C all -r trace.raw > trace.r 
# rm trace.raw* 
# ls trace* 
trace.r 
# gennames > gennames.out 
# trcnm > trace.nm

Overview of Information Generated by the curt Command

The following is an overview of the content of the report generated by the curt command:

To create additional, specialized reports, run the curt command using the following flags:

-e Produces a report containing statistics and additional information on the System Calls Summary Report. The additional information pertains to the total, average, maximum, and minimum elapsed times that a system call was running.
-s Produces a report containing a list of errors returned by system calls.
-t Produces a report containing a detailed report on thread status that includes the amount of CPU time the thread was in application and system call mode, what system calls the thread made, processor affinity, the number of times the thread was dispatched, and to which CPU(s) it was dispatched. The report also includes dispatch wait time and details of interrupts.
-p Produces a report containing a detailed report on process status that includes the amount of CPU time the process was in application and system call mode, application time details, threads that were in the process, pthreads that were in the process, pthread calls that the process made and system calls that the process made.
-P Produces a report containing a detailed report on pthread status that includes the amount of CPU time the pthread was in application and system call mode, system calls made by the pthread, pthread calls made by the pthread, processor affinity, the number of times the pthread was dispatched and to which CPU(s) it was dispatched, thread affinity, and the number of times the pthread was dispatched and to which kernel thread(s) it was dispatched. The report also includes dispatch wait time and details of interrupts.

Default Report Generated by the curt Command

This section explains the default report created by the curt command, as follows:

# curt -i trace.r -m trace.nm -n gennames.out -o curt.out

The curt command output always includes this default report in its output, even if one of the flags described in the previous section is used.

The report is divided into the following sections:

General Information

The General Information section begins with the time and date when the report was generated. It is followed by the syntax of the curt command line that was used to produce the report.

This section also contains some information about the AIX trace file that was processed by the curt command. This information consists of the trace file's name, size, and its creation date. The command used to invoke the AIX trace facility and gather the trace file is displayed at the end of the report.

The following is a sample of the general information section:

Run on Fri May 25 11:08:46 2001 
Command line was: 
curt -i trace.r -m trace.nm -n gennames.out -o curt.out 
---- 
AIX trace file name = trace.r 
AIX trace file size = 1632496 
AIX trace file created = Fri May 25 11:04:33 2001 


Command used to gather AIX trace was: 
trace -n -C all -d -j 100,101,102,103,104,106,10C,134,139,200,465,605,609 -L 1000000 -T 1000000 -afo trace.raw

System Summary

The next section of the default report is the System Summary produced by the curt command. The following is a sample of the System Summary:

               System Summary         
               -------------- 
 processing       percent       percent   
 total time    total time     busy time        
     (msec)  (incl. idle)  (excl. idle)  processing category   
===========   ===========   ===========  ===================   
   14998.65         73.46         92.98  APPLICATION              
     591.59          2.90          3.66  SYSCALL                  
      48.33          0.24          0.30  KPROC                    
     486.19          2.38          3.00  FLIH                    
      49.10          0.24          0.30  SLIH                    
       8.83          0.04          0.05  DISPATCH (all procs. incl. IDLE)
       1.04          0.01          0.01  IDLE DISPATCH (only IDLE proc.)
-----------    ----------       -------                 
   16182.69         79.26        100.00  CPU(s) busy time       
    4234.76         20.74                IDLE
-----------    ----------    
   20417.45                              TOTAL

Avg. Thread Affinity =        0.99

This portion of the report describes the time spent by the whole system (all CPUs) in various execution modes.

The System Summary has the following fields:

processing total time Total time in milliseconds for the corresponding processing category.
percent total time Time from the first column as a percentage of the sum of total trace elapsed time for all processors. This includes whatever amount of time each processor spent running the IDLE process.
percent busy time Time from the first column as a percentage of the sum of total trace elapsed time for all processors without including the time each processor spent executing the IDLE process.
Avg. Thread Affinity Probability that a thread was dispatched to the same processor on which it last executed.

The possible execution modes or processing categories are interpreted as follows:

APPLICATION The sum of times spent by all processors in User (that is, non-privileged) mode.
SYSCALL The sum of times spent by all processors doing System Calls. This is the portion of time that a processor spends executing in the kernel code providing services directly requested by a user process.
KPROC The sum of times spent by all processors executing kernel processes other than the IDLE process. This is the portion of time that a processor spends executing specially created dispatchable processes that only execute kernel code.
FLIH The sum of times spent by all processors executing FLIHs.
SLIH The sum of times spent by all processors executing SLIHs.
DISPATCH The sum of times spent by all processors executing the AIX dispatch code. This sum includes the time spent dispatching all threads (that is, it includes dispatches of the IDLE process).
IDLE DISPATCH The sum of times spent by all processors executing the AIX dispatch code where the process being dispatched was the IDLE process. Because the DISPATCH category includes the IDLE DISPATCH category's time, the IDLE DISPATCH category's time is not separately added to calculate either CPU(s) busy time or TOTAL (see below).
CPU(s) busy time The sum of times spent by all processors executing in APPLICATION, SYSCALL, KPROC, FLIH, SLIH, and DISPATCH modes.
IDLE The sum of times spent by all processors executing the IDLE process.
TOTAL The sum of CPU(s) busy time and IDLE.

The System Summary example indicates that the CPU is spending most of its time in application mode. There is still 4234.76 ms of IDLE time so there is enough CPU to run applications. If there is insufficient CPU power, do not expect to see any IDLE time. The Avg. Thread Affinity value is 0.99 showing good processor affinity; that is, threads returning to the same processor when they are ready to be run again.

System Application Summary

The next part of the default report is the System Application Summary produced by the curt command. The following is a sample of the System Application Summary:

                     System Application Summary
                     --------------------------
 processing       percent      percent
 total time    total time  application
     (msec)  (incl. idle)        time   processing category
===========   ===========  ===========  ===================
       3.95         0.42          0.07  PTHREAD
       4.69         0.49          0.09  PDISPATCH
       0.13         0.01          0.00  PIDLE
    5356.99       563.18         99.84  OTHER
-----------    ----------      -------
    5365.77       564.11        100.00  APPLICATION

Avg. Pthread Affinity =        0.84

This portion of the report describes the time spent by the system as a whole (all CPUs) in various execution modes. The System Application Summary has the following fields:

processing total time Total time in milliseconds for the corresponding processing category.
percent total time Time from the first column as a percentage of the sum of total trace elapsed time for all processors. This includes whatever amount of time each processor spent running the IDLE process.
percent application time Time from the first column as a percentage of the sum of total trace elapsed application time for all processors
Avg. Pthread Affinity Probability that a pthread was dispatched on the same kernel thread on which it last executed.

The possible execution modes or processing categories are interpreted as follows:

PTHREAD The sum of times spent by all pthreads on all processors in traced pthread library calls.
PDISPATCH The sum of times spent by all pthreads on all processors executing the libpthreads dispatch code.
PIDLE The sum of times spent by all kernel threads on all processors executing the libpthreads vp_sleep code.
OTHER The sum of times spent by all pthreads on all processors in non-traced user mode.
APPLICATION The sum of times spent by all processors in User (that is, non-privileged) mode.

Processor Summary and Processor Application Summary

This part of the curt command output follows the System Summary and System Application Summary and is essentially the same information but presented on a processor-by-processor basis. The same description that was given for the System Summary and System Application Summary applies here, except that this report covers each processor rather than the whole system.

Below is a sample of this output:

             Processor Summary  processor number 0
             --------------------------------------- 
 processing       percent       percent
 total time    total time     busy time        
     (msec)  (incl. idle)  (excl. idle)  processing category
===========   ===========   ===========  ===================  
      45.07          0.88          5.16  APPLICATION
     591.39         11.58         67.71  SYSCALL
      47.83          0.94          5.48  KPROC
     173.78          3.40         19.90  FLIH
       9.27          0.18          1.06  SLIH
       6.07          0.12          0.70  DISPATCH (all procs. incl. IDLE)
       1.04          0.02          0.12  IDLE DISPATCH (only IDLE proc.)
-----------    ----------       -------
     873.42         17.10        100.00  CPU(s) busy time
    4232.92         82.90                IDLE
-----------    ----------
    5106.34                              TOTAL

Avg. Thread Affinity =        0.98 

Total number of process dispatches  = 1620
Total number of idle dispatches = 782

              Processor Application Summary  processor 0
              ------------------------------------------
 processing       percent       percent
 total time    total time   application
     (msec)  (incl. idle)         time   processing category
===========   ===========   ===========  ===================
       1.66          0.04          0.06  PTHREAD
       2.61          0.05          0.10  PDISPATCH
       0.00          0.00          0.00  PIDLE
    2685.12         56.67         99.84  OTHER
-----------    ----------       -------
    2689.39         56.76        100.00  APPLICATION

Avg. Pthread Affinity =        0.78 

Total number of pthread dispatches  = 104
Total number of pthread idle dispatches  = 0

               Processor Summary  processor number 1
               ---------------------------------------
 processing       percent       percent
 total time    total time     busy time
     (msec)  (incl. idle)  (excl. idle)  processing category
===========   ===========   ===========  ===================
    4985.81         97.70         97.70  APPLICATION
       0.09          0.00          0.00  SYSCALL
       0.00          0.00          0.00  KPROC
     103.86          2.04          2.04  FLIH
      12.54          0.25          0.25  SLIH
       0.97          0.02          0.02  DISPATCH (all procs. incl. IDLE)
       0.00          0.00          0.00  IDLE DISPATCH (only IDLE proc.)
-----------    ----------       -------
    5103.26        100.00        100.00  CPU(s) busy time
       0.00          0.00                IDLE
-----------    ---------- 
    5103.26                              TOTAL

Avg. Thread Affinity =        0.99 

Total number of process dispatches  = 516
Total number of idle dispatches = 0

              Processor Application Summary  processor 1
              ------------------------------------------
 processing       percent       percent
 total time    total time   application
     (msec)  (incl. idle)         time   processing category
===========   ===========   ===========  ===================
       2.29          0.05          0.09  PTHREAD
       2.09          0.04          0.08  PDISPATCH
       0.13          0.00          0.00  PIDLE
    2671.86         56.40         99.83  OTHER
-----------    ----------       -------
    2676.38         56.49        100.00  APPLICATION

Avg. Pthread Affinity =        0.83 

Total number of pthread dispatches  = 91
Total number of pthread idle dispatches  = 5



The following terms are referred to in the example above:

Total number of process dispatches
The number of times AIX dispatched any non-IDLE process on the processor.
Total number of idle dispatches
The number of IDLE process dispatches.
Total number of pthread dispatches
The number of times the libpthreads dispatcher was executed on the processor.
Total number of pthread idle dispatches
The number of vp_sleep calls.

Application Summary by Thread ID (Tid)

The Application Summary, by Tid, shows an output of all the threads that were running on the system during the time of trace collection and their CPU consumption. The thread that consumed the most CPU time during the time of the trace collection is at the top of the list.

          Application Summary (by Tid)
          ----------------------------
  -- processing total (msec) --   -- percent of total processing time --
 combined  application  syscall  combined  application      syscall  name (Pid  Tid)
 ========  ===========  =======  ========  ===========      =======  ===================
4986.2355    4986.2355   0.0000   24.4214      24.4214       0.0000  cpu(18418  32437)
4985.8051    4985.8051   0.0000   24.4193      24.4193       0.0000  cpu(19128  33557)
4982.0331    4982.0331   0.0000   24.4009      24.4009       0.0000  cpu(18894  28671)
  83.8436       2.5062  81.3374    0.4106       0.0123       0.3984  disp+work(20390  28397)
  72.5809       2.7269  69.8540    0.3555       0.0134       0.3421  disp+work(18584  32777)
  69.8023       2.5351  67.2672    0.3419       0.0124       0.3295  disp+work(19916  33033)
  63.6399       2.5032  61.1368    0.3117       0.0123       0.2994  disp+work(17580  30199)
  63.5906       2.2187  61.3719    0.3115       0.0109       0.3006  disp+work(20154  34321)
  62.1134       3.3125  58.8009    0.3042       0.0162       0.2880  disp+work(21424  31493)
  60.0789       2.0590  58.0199    0.2943       0.0101       0.2842  disp+work(21992  32539)

 ...(lines omitted)...

The output is divided into two main sections:

The Application Summary (by Tid) has the following fields:

name (Pid Tid) The name of the process associated with the thread, its process id, and its thread id.

processing total (msec)

combined The total amount of CPU time, expressed in milliseconds, that the thread was running in either application mode or system call mode.
application The amount of CPU time, expressed in milliseconds, that the thread spent in application mode.
syscall The amount of CPU time, expressed in milliseconds, that the thread spent in system call mode.

percent of total processing time

combined The amount of CPU time that the thread was running, expressed as percentage of the total processing time.
application The amount of CPU time that the thread the thread spent in application mode, expressed as percentage of the total processing time.
syscall The amount of CPU time that the thread spent in system call mode, expressed as percentage of the total processing time.

In the example above, we can investigate why the system is spending so much time in application mode by looking at the Application Summary (by Tid), where we can see the top three processes of the report are named cpu, a test program that uses a great deal of CPU time. The report shows again that the CPU spent most of its time in application mode running the cpu process. Therefore the cpu process is a candidate to be optimized to improve system performance.

Application Summary by Process ID (Pid)

The Application Summary, by Pid, has the same content as the Application Summary, by Tid, except that the threads that belong to each process are consolidated and the process that consumed the most CPU time during the monitoring period is at the beginning of the list.

The name (PID) (Thread Count) column shows the process name, its process ID, and the number of threads that belong to this process and that have been accumulated for this line of data.

                           Application Summary (by Pid)
                           ----------------------------
   -- processing total (msec) --   -- percent of total processing time -- 
  combined  application  syscall  combined  application  syscall  name (Pid)(Thread Count)
  ========  ===========  =======  ========  ===========  =======  ===================
 4986.2355    4986.2355   0.0000   24.4214      24.4214   0.0000  cpu(18418)(1)
 4985.8051    4985.8051   0.0000   24.4193      24.4193   0.0000  cpu(19128)(1)
 4982.0331    4982.0331   0.0000   24.4009      24.4009   0.0000  cpu(18894)(1)
   83.8436       2.5062  81.3374    0.4106       0.0123   0.3984  disp+work(20390)(1)
   72.5809       2.7269  69.8540    0.3555       0.0134   0.3421  disp+work(18584)(1)
   69.8023       2.5351  67.2672    0.3419       0.0124   0.3295  disp+work(19916)(1)
   63.6399       2.5032  61.1368    0.3117       0.0123   0.2994  disp+work(17580)(1)
   63.5906       2.2187  61.3719    0.3115       0.0109   0.3006  disp+work(20154)(1)
   62.1134       3.3125  58.8009    0.3042       0.0162   0.2880  disp+work(21424)(1)
   60.0789       2.0590  58.0199    0.2943       0.0101   0.2842  disp+work(21992)(1)

 ...(lines omitted)...

Application Summary (by process type)

The Application Summary (by process type) consolidates all processes of the same name and sorts them in descending order of combined processing time.

The name (thread count) column shows the name of the process, and the number of threads that belong to this process name (type) and were running on the system during the monitoring period.

                    Application Summary (by process type)
                -----------------------------------------------
    -- processing total (msec) --    -- percent of total processing time -- 
   combined  application   syscall  combined  application  syscall  name (thread count)
   ========  ===========   =======  ========  ===========  =======  ==================
 14954.0738   14954.0738    0.0000   73.2416      73.2416   0.0000  cpu(3)
   573.9466      21.2609  552.6857    2.8111       0.1041   2.7069  disp+work(9)
    20.9568       5.5820   15.3748    0.1026       0.0273   0.0753  trcstop(1)
    10.6151       2.4241    8.1909    0.0520       0.0119   0.0401  i4llmd(1)
     8.7146       5.3062    3.4084    0.0427       0.0260   0.0167  dtgreet(1)
     7.6063       1.4893    6.1171    0.0373       0.0073   0.0300  sleep(1)

 ...(lines omitted)...

Kproc Summary by Thread ID (Tid)

The Kproc Summary, by Tid, shows an output of all the kernel process threads that were running on the system during the time of trace collection and their CPU consumption. The thread that consumed the most CPU time during the time of the trace collection is at the beginning of the list.

                     Kproc Summary  (by Tid)
                     -----------------------
    -- processing total (msec) --          --   percent of total  time   -- 
   combined       kernel    operation     combined       kernel    operation  name (Pid Tid Type)
   ========       ======  ===========     ========       ======  ===========  ===================
  1930.9312    1930.9312       0.0000      13.6525      13.6525       0.0000  wait(8196  8197 W)
     2.1674       2.1674       0.0000       0.0153       0.0153       0.0000  .WSMRefreshServe(0  3 -)
     1.9034       1.9034       0.0000       0.0135       0.0135       0.0000  gil(36882  49177 -)
 

  ...(lines omitted)...

                               Kproc Types
                               -----------
 Type Function                       Operation
 ==== ============================   ==========================
  W   idle thread                    -

The Kproc Summary has the following fields:

name (Pid Tid Type) The name of the kernel process associated with the thread, its process ID, its thread ID, and its type. The kproc type is defined in the Kproc Types listing following the Kproc Summary.

processing total (msec)

combined The total amount of CPU time, expressed in milliseconds, that the thread was running in either operation or kernel mode.
kernel The amount of CPU time, expressed in milliseconds, that the thread spent in unidentified kernel mode.
operation The amount of CPU time, expressed in milliseconds, that the thread spent in traced operations.

percent of total time

combined The amount of CPU time that the thread was running, expressed as percentage of the total processing time.
kernel The amount of CPU time that the thread spent in unidentified kernel mode, expressed as percentage of the total processing time.
operation The amount of CPU time that the thread spent in traced operations, expressed as percentage of the total processing time.

Kproc Types

Type A single letter to be used as an index into this listing.
Function A description of the nominal function of this type of kernel process.
Operation A description of the traced operations for this type of kernel process.

Application Pthread Summary by process ID (Pid)

The Application Pthread Summary, by PID, shows an output of all the multi-threaded processes that were running on the system during trace collection and their CPU consumption, and that have spent time making pthread calls. The process that consumed the most CPU time during the trace collection is at the beginning of the list.

                    Application Pthread Summary (by Pid)
                    ------------------------------------
   -- processing total (msec) --     -- percent of total application time --
application       other     pthread  application       other      pthread   name (Pid)(Pthread Count)
===========  ==========  ==========  ===========  ==========   ==========   =========================
  1277.6602   1274.9354      2.7249    23.8113       23.7605       0.0508   ./pth(245964)(52)
   802.6445    801.4162      1.2283    14.9586       14.9357       0.0229   ./pth32(245962)(12)


 ...(lines omitted)...

The output is divided into two main sections:

The Application Pthread Summary has the following fields:

name (Pid) (Pthread Count) The name of the process associated with the process ID, and the number of pthreads of this process.

processing total (msec)

application The total amount of CPU time, expressed in milliseconds, that the process was running in user mode.
pthread The amount of CPU time, expressed in milliseconds, that the process spent in traced call to the pthreads library.
other The amount of CPU time, expressed in milliseconds, that the process spent in non traced user mode.

percent of total application time

application The amount of CPU time that the process was running in user mode, expressed as percentage of the total application time.
pthread The amount of CPU time that the process spent in calls to the pthreads library, expressed as percentage of the total application time.
other The amount of CPU time that the process spent in non traced user mode, expressed as percentage of the total application time.

System Calls Summary

The System Calls Summary provides a list of all the system calls that have completed execution on the system during the monitoring period. The list is sorted by the total CPU time in milliseconds consumed by each type of system call.

                              System Calls Summary
                              --------------------
     Count   Total Time   % sys  Avg Time  Min Time  Max Time  SVC (Address)
                 (msec)    time    (msec)    (msec)    (msec)
  ========  ===========  ======  ========  ========  ========  ================
       605     355.4475   1.74%    0.5875    0.0482    4.5626  kwrite(4259c4)
       733     196.3752   0.96%    0.2679    0.0042    2.9948  kread(4259e8)
         3       9.2217   0.05%    3.0739    2.8888    3.3418  execve(1c95d8)
        38       7.6013   0.04%    0.2000    0.0051    1.6137  __loadx(1c9608)
      1244       4.4574   0.02%    0.0036    0.0010    0.0143  lseek(425a60)
        45       4.3917   0.02%    0.0976    0.0248    0.1810  access(507860)
        63       3.3929   0.02%    0.0539    0.0294    0.0719  _select(4e0ee4)
         2       2.6761   0.01%    1.3380    1.3338    1.3423  kfork(1c95c8)
       207       2.3958   0.01%    0.0116    0.0030    0.1135  _poll(4e0ecc)
       228       1.1583   0.01%    0.0051    0.0011    0.2436  kioctl(4e07ac)
         9       0.8136   0.00%    0.0904    0.0842    0.0988  .smtcheckinit(1b245a8)
         5       0.5437   0.00%    0.1087    0.0696    0.1777  open(4e08d8)
        15       0.3553   0.00%    0.0237    0.0120    0.0322  .smtcheckinit(1b245cc)
         2       0.2692   0.00%    0.1346    0.1339    0.1353  statx(4e0950)
        33       0.2350   0.00%    0.0071    0.0009    0.0210  _sigaction(1cada4)
         1       0.1999   0.00%    0.1999    0.1999    0.1999  kwaitpid(1cab64)
       102       0.1954   0.00%    0.0019    0.0013    0.0178  klseek(425a48)

 ...(lines omitted)...

The System Calls Summary has the following fields:

Count The number of times that a system call of a certain type (see SVC (Address)) has been called during the monitoring period.
Total Time (msec) The total CPU time that the system spent processing these system calls, expressed in milliseconds.
% sys time The total CPU time that the system spent processing these system calls, expressed as a percentage of the total processing time.
Avg Time (msec) The average CPU time that the system spent processing one system call of this type, expressed in milliseconds.
Min Time (msec) The minimum CPU time that the system needed to process one system call of this type, expressed in milliseconds.
Max Time (msec) The maximum CPU time that the system needed to process one system call of this type, expressed in milliseconds.
SVC (Address) The name of the system call and its kernel address.

Pending System Calls Summary

The Pending System Calls Summary provides a list of all the system calls that have been executed on the system during the monitoring period but have not completed. The list is sorted by Tid.

                     Pending System Calls Summary
                     ----------------------------
Accumulated   SVC (Address)               Procname (Pid  Tid)        
Time (msec) 
============  =========================  ==========================
      0.0656  _select(4e0ee4)            sendmail(7844 5001) 
      0.0452  _select(4e0ee4)            syslogd(7514 8591) 
      0.0712  _select(4e0ee4)            snmpd(5426 9293) 
      0.0156  kioctl(4e07ac)             trcstop(47210 18379) 
      0.0274  kwaitpid(1cab64)           ksh(20276 44359) 
      0.0567  kread4259e8)               ksh(23342 50873) 

 ...(lines omitted)...

The Pending System Calls Summary has the following fields:

Accumulated Time (msec) The accumulated CPU time that the system spent processing the pending system call, expressed in milliseconds.
SVC (Address) The name of the system call and its kernel address.
Procname (Pid Tid) The name of the process associated with the thread that made the system call, its process ID, and the thread ID.

Pthread Calls Summary

The Pthread Calls Summary provides a list of all the pthread calls that have completed execution on the system during the monitoring period. The list is sorted by the total CPU time, in milliseconds, consumed by each type of pthread call.

                     Pthread Calls Summary
                     --------------------
   Count   Total Time   % sys  Avg Time  Min Time  Max Time  Pthread Routine
               (msec)    time    (msec)    (msec)    (msec)
========  ===========  ======  ========  ========  ========  ================
      62       3.6226   0.04%    0.0584    0.0318    0.1833  pthread_create
      10       0.1798   0.00%    0.0180    0.0119    0.0341  pthread_cancel
       8       0.0725   0.00%    0.0091    0.0064    0.0205  pthread_join
       1       0.0553   0.00%    0.0553    0.0553    0.0553  pthread_detach
       1       0.0229   0.00%    0.0229    0.0229    0.0229  pthread_kill

The Pthread Calls Summary report has the following fields:

Count The number of times that a pthread call of a certain type has been called during the monitoring period.
Total Time (msec) The total CPU time that the system spent processing all pthread calls of this type, expressed in milliseconds.
% sys time The total CPU time that the system spent processing all calls of this type, expressed as a percentage of the total processing time.
Avg Time (msec) The average CPU time that the system spent processing one pthread call of this type, expressed in milliseconds.
Min Time (msec) The minimum CPU time the system used to process one pthread call of this type, expressed in milliseconds.
Pthread routine The name of the routine in the pthread library.

Pending Pthread Calls Summary

The Pending Pthread Calls Summary provides a list of all the pthread calls that have been executed on the system during the monitoring period but have not completed. The list is sorted by Pid-Ptid.

            Pending Pthread Calls Summary
            -----------------------------
Accumulated   Pthread Routine  Procname (Pid  Tid  Ptid)
Time (msec)
============  ===============  ==========================
   1990.9400  pthread_join     ./pth32(245962 1007759 1)
 

The Pending Pthread System Calls Summary has the following fields:

Accumulated Time (msec) The accumulated CPU time that the system spent processing the pending pthread call, expressed in milliseconds.
Pthread Routine The name of the pthread routine of the libpthreads library.
Procname (Pid Tid Ptid) The name of the process associated with the thread and the pthread which made the pthread call, its process ID, the thread ID and the pthread ID.

FLIH Summary

The FLIH (First Level Interrupt Handler) Summary lists all first level interrupt handlers that were called during the monitoring period.

The Global FLIH Summary lists the total of first level interrupts on the system, while the Per CPU FLIH Summary lists the first level interrupts per CPU.

                                Global Flih Summary
                                -------------------
        Count  Total Time    Avg Time    Min Time    Max Time  Flih Type
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== ===========  =========
         2183    203.5524      0.0932      0.0041      0.4576   31(DECR_INTR)
          946    102.4195      0.1083      0.0063      0.6590    3(DATA_ACC_PG_FLT)
           12      1.6720      0.1393      0.0828      0.3366   32(QUEUED_INTR)
         1058    183.6655      0.1736      0.0039      0.7001    5(IO_INTR)


                               Per CPU Flih Summary
                               --------------------
 CPU Number 0:
        Count  Total Time    Avg Time    Min Time    Max Time  Flih Type
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== ===========  =========
          635     39.8413      0.0627      0.0041      0.4576   31(DECR_INTR)
          936    101.4960      0.1084      0.0063      0.6590    3(DATA_ACC_PG_FLT)
            9      1.3946      0.1550      0.0851      0.3366   32(QUEUED_INTR)
          266     33.4247      0.1257      0.0039      0.4319    5(IO_INTR)

 CPU Number 1:
        Count  Total Time    Avg Time    Min Time    Max Time  Flih Type
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== ===========  =========
            4      0.2405      0.0601      0.0517      0.0735    3(DATA_ACC_PG_FLT)
          258     49.2098      0.1907      0.0060      0.5076    5(IO_INTR)
          515     55.3714      0.1075      0.0080      0.3696   31(DECR_INTR)

                     Pending Flih Summary
                     --------------------
 Accumulated Time (msec)    Flih Type       
 ========================   ================
                   0.0123    5(IO_INTR)

 ...(lines omitted)...

The FLIH Summary report has the following fields:

Count The number of times that a first level interrupt of a certain type (see Flih Type) occurred during the monitoring period.
Total Time (msec) The total CPU time that the system spent processing these first level interrupts, expressed in milliseconds.
Avg Time (msec) The average CPU time that the system spent processing one first level interrupt of this type, expressed in milliseconds.
Min Time (msec) The minimum CPU time that the system needed to process one first level interrupt of this type, expressed in milliseconds.
Max Time (msec) The maximum CPU time that the system needed to process one first level interrupt of this type, expressed in milliseconds.
Flih Type The number and name of the first level interrupt.
Accumulated Time (msec) The accumulated CPU time that the system spent processing the pending first level interrupt, expressed in milliseconds.

FLIH types in the example

The following are FLIH types that were depicted in the above example:

DATA_ACC_PG_FLT Data access page fault
QUEUED_INTR Queued interrupt
DECR_INTR Decrementer interrupt
IO_INTR I/O interrupt

SLIH Summary

The Second level interrupt handler (SLIH) Summary lists all second level interrupt handlers that were called during the monitoring period.

The Global Slih Summary lists the total of second level interrupts on the system, while the Per CPU Slih Summary lists the second level interrupts per CPU.

                               Global Slih Summary
                               -------------------
        Count  Total Time    Avg Time    Min Time    Max Time Slih Name(Address)
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== =========== =================
           43      7.0434      0.1638      0.0284      0.3763 s_scsiddpin(1a99104)
         1015     42.0601      0.0414      0.0096      0.0913 ssapin(1990490)


                              Per CPU Slih Summary
                              --------------------
 CPU Number 0:
        Count  Total Time    Avg Time    Min Time    Max Time Slih Name(Address)
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== =========== =================
            8      1.3500      0.1688      0.0289      0.3087 s_scsiddpin(1a99104)
          258      7.9232      0.0307      0.0096      0.0733 ssapin(1990490)
 CPU Number 1:
        Count  Total Time    Avg Time    Min Time    Max Time Slih Name(Address)
                   (msec)      (msec)      (msec)      (msec)
       ====== =========== =========== =========== =========== =================
           10      1.2685      0.1268      0.0579      0.2818 s_scsiddpin(1a99104)
          248     11.2759      0.0455      0.0138      0.0641 ssapin(1990490)

 ...(lines omitted)...

The SLIH Summary report has the following fields:

Count The number of times that each second level interrupt handler was called during the monitoring period.
Total Time (msec) The total CPU time that the system spent processing these second level interrupts, expressed in milliseconds.
Avg Time (msec) The average CPU time that the system spent processing one second level interrupt of this type, expressed in milliseconds.
Min Time (msec) The minimum CPU time that the system needed to process one second level interrupt of this type, expressed in milliseconds.
Max Time (msec) The maximum CPU time that the system needed to process one second level interrupt of this type, expressed in milliseconds.
Slih Name (Address) The module name and kernel address of the second level interrupt.

Reports Generated with the -e Flag

The report generated with the -e flag includes the data shown in the default report, and also includes additional information in the System Calls Summary, the Pending System Calls Summary, the Pthread Calls Summary and the Pending Pthread Calls Summary.

The additional information in the System Calls Summary and the Pthread Calls Summary includes the total, average, maximum, and minimum elapsed time that a call was running. The additional information in the Pending System Calls Summary and the Pending Pthread Calls Summary is the accumulated elapsed time for the pending calls. This additional information is present in all the system call and pthread call reports: globally, in the process detailed report (-p), the thread detailed report (-t), and the pthread detailed report (-P).

The following is an example of the additional information reported by using the -e flag:

# curt -e -i trace.r -m trace.nm -n gennames.out -o curt.out 
# cat curt.out 

 ...(lines omitted)... 

                                   System Calls Summary
                                   --------------------
 Count  Total   % sys    Avg    Min    Max       Tot       Avg       Min      Max       SVC (Address)
         Time    time   Time   Time   Time     ETime     ETime     ETime    ETime
       (msec)         (msec) (msec) (msec)    (msec)    (msec)    (msec)   (msec)
 ===== ======== ===== ====== ====== ====== ========== ========= ========= ========= ======================
   605 355.4475 1.74% 0.5875 0.0482 4.5626 31172.7658   51.5252    0.0482  422.2323 kwrite(4259c4)
   733 196.3752 0.96% 0.2679 0.0042 2.9948 12967.9407   17.6916    0.0042  265.1204 kread(4259e8)
     3   9.2217 0.05% 3.0739 2.8888 3.3418    57.2051   19.0684    4.5475   40.0557 execve(1c95d8)
    38   7.6013 0.04% 0.2000 0.0051 1.6137    12.5002    0.3290    0.0051    3.3120 __loadx(1c9608)
  1244   4.4574 0.02% 0.0036 0.0010 0.0143     4.4574    0.0036    0.0010    0.0143 lseek(425a60)
    45   4.3917 0.02% 0.0976 0.0248 0.1810     4.6636    0.1036    0.0248    0.3037 access(507860)
    63   3.3929 0.02% 0.0539 0.0294 0.0719  5006.0887   79.4617    0.0294  100.4802 _select(4e0ee4)
     2   2.6761 0.01% 1.3380 1.3338 1.3423    45.5026   22.7513    7.5745   37.9281 kfork(1c95c8)
   207   2.3958 0.01% 0.0116 0.0030 0.1135  4494.9249   21.7146    0.0030  499.1363 _poll(4e0ecc)
   228   1.1583 0.01% 0.0051 0.0011 0.2436     1.1583    0.0051    0.0011    0.2436 kioctl(4e07ac)
     9   0.8136 0.00% 0.0904 0.0842 0.0988  4498.7472  499.8608  499.8052  499.8898 .smtcheckinit(1b245a8)
     5   0.5437 0.00% 0.1087 0.0696 0.1777     0.5437    0.1087    0.0696    0.1777 open(4e08d8)
    15   0.3553 0.00% 0.0237 0.0120 0.0322     0.3553    0.0237    0.0120    0.0322 .smtcheckinit(1b245cc)
     2   0.2692 0.00% 0.1346 0.1339 0.1353     0.2692    0.1346    0.1339    0.1353 statx(4e0950)
    33   0.2350 0.00% 0.0071 0.0009 0.0210     0.2350    0.0071    0.0009    0.0210 _sigaction(1cada4)
     1   0.1999 0.00% 0.1999 0.1999 0.1999  5019.0588 5019.0588 5019.0588 5019.0588 kwaitpid(1cab64)
   102   0.1954 0.00% 0.0019 0.0013 0.0178     0.5427    0.0053    0.0013    0.3650 klseek(425a48)

 ...(lines omitted)... 

                         Pending System Calls Summary
                         ----------------------------
Accumulated   Accumulated   SVC (Address)              Procname (Pid  Tid)     
Time (msec)   ETime (msec)
============  ============  =========================  =========================
      0.0855       93.6498  kread(4259e8)              oracle(143984 48841) 

 ...(lines omitted)...

                     Pthread Calls Summary
                     --------------------
Count   Total Time   % sys  Avg Time  Min Time  Max Time  Tot ETime  Avg ETime  Min ETime  Max ETime  Pthread Routine
           (msec)    time    (msec)    (msec)    (msec)     (msec)     (msec)     (msec)     (msec)
====   ===========  ======  ========  ========  ========   ========  =========  =========  =========  ================
  72       2.0126   0.01%    0.0280    0.0173    0.1222    13.7738     0.1913     0.0975     0.6147  pthread_create
   2       0.6948   0.00%    0.3474    0.0740    0.6208    92.3033    46.1517     9.9445    82.3588  pthread_kill
  12       0.3087   0.00%    0.0257    0.0058    0.0779    25.0506     2.0876     0.0168    10.0605  pthread_cancel
  22       0.0613   0.00%    0.0028    0.0017    0.0104  2329.0179   105.8644     0.0044  1908.3402  pthread_join
   2       0.0128   0.00%    0.0064    0.0062    0.0065     0.1528     0.0764     0.0637     0.0891  pthread_detach

                     Pending Pthread Calls Summary
                     -----------------------------
Accumulated   Accumulated   Pthread Routine  Procname (pid  tid  ptid)
Time (msec)   ETime (msec)
============  ============  ===============  =========================
     3.3102     4946.5433   pthread_join     ./pth32(282718 700515 1)
     0.0025      544.4914   pthread_join     ./pth(282720   -    1)


The system call and pthread call reports in the preceding example have the following fields in addition to the default System Calls Summary:

Tot ETime (msec) The total amount of time from when each instance of the call was started until it completed. This time will include any time spent servicing interrupts, running other processes, and so forth.
Avg ETime (msec) The average amount of time from when the call was started until it completed. This time will include any time spent servicing interrupts, running other processes, and so forth.
Min ETime (msec) The minimum amount of time from when the call was started until it completed. This time will include any time spent servicing interrupts, running other processes, and so forth.
Max ETime (msec) The maximum amount of time from when the call was started until it completed. This time will include any time spent servicing interrupts, running other processes, and so forth.
Accumulated ETime (msec) The total amount of time from when the pending call was started until the end of the trace. This time will include any time spent servicing interrupts, running other processes, and so forth.

The preceding example report shows that the maximum elapsed time for the kwrite system call was 422.2323 msec, but the maximum CPU time was 4.5626 msec. If this amount of overhead time is unusual for the device being written to, further analysis is needed.

Reports Generated with the -s Flag

The report generated with the -s flag includes the data shown in the default report, and also includes data on errors returned by system calls as shown by the following:

# curt -s -i trace.r -m trace.nm -n gennames.out -o curt.out 
# cat curt.out 

...(lines omitted)...

                      Errors Returned by System Calls
                      ------------------------------ 

Errors (errno : count : description) returned for System Call: kioctl(4e07ac)
   25 :       15 : "Not a typewriter"
Errors (errno : count : description) returned for System Call: execve(1c95d8)
    2 :        2 : "No such file or directory"

...(lines omitted)...

If a large number of errors of a specific type or on a specific system call point to a system or application problem, other debug measures can be used to determine and fix the problem.

Reports Generated with the -t Flag

The report generated with the -t flag includes the data shown in the default report, and also includes a detailed report on thread status that includes the amount of time the thread was in application and system call mode, what system calls the thread made, processor affinity, the number of times the thread was dispatched, and to which CPU(s) it was dispatched. The report also includes dispatch wait time and details of interrupts:

...(lines omitted)... 
--------------------------------------------------------------------------------
Report for Thread Id: 48841 (hex bec9) Pid: 143984 (hex 23270)
Process Name: oracle
---------------------
 Total Application Time (ms):  70.324465
 Total System Call Time (ms):  53.014910

                               Thread System Call Data
   Count   Total Time     Avg Time     Min Time     Max Time     SVC (Address)
               (msec)       (msec)       (msec)       (msec)
========  ===========  ===========  ===========  ===========  ================
      69      34.0819       0.4939       0.1666       1.2762  kwrite(169ff8)
      77      12.0026       0.1559       0.0474       0.2889  kread(16a01c)
     510       4.9743       0.0098       0.0029       0.0467  times(f1e14)
      73       1.2045       0.0165       0.0105       0.0306  select(1d1704)
      68       0.6000       0.0088       0.0023       0.0445  lseek(16a094)
      12       0.1516       0.0126       0.0071       0.0241  getrusage(f1be0)

  No Errors Returned by System Calls

                     Pending System Calls Summary
                     ----------------------------
Accumulated   SVC (Address)            
Time (msec) 
============  ==========================
      0.1420  kread(16a01c) 

 processor affinity:  0.583333

Dispatch Histogram for thread (CPUid : times_dispatched).
    CPU 0 : 23
    CPU 1 : 23
    CPU 2 : 9
    CPU 3 : 9
    CPU 4 : 8
    CPU 5 : 14
    CPU 6 : 17
    CPU 7 : 19
    CPU 8 : 1
    CPU 9 : 4
    CPU 10 : 1
    CPU 11 : 4

 total number of dispatches:  131
 total number of redispatches due to interupts being disabled:  1
 avg. dispatch wait time (ms):  8.273515

      Data on Interrupts that Occurred while Thread was Running
           Type of Interrupt       Count
   =============================== ============================
    Data Access Page Faults (DSI): 115
   Instr. Fetch Page Faults (ISI): 0
          Align. Error Interrupts: 0
         IO (external) Interrupts: 0
         Program Check Interrupts: 0
        FP Unavailable Interrupts: 0
          FP Imprecise Interrupts: 0
               RunMode Interrupts: 0
           Decrementer Interrupts: 18
   Queued (Soft level) Interrupts: 15 

...(lines omitted)...

The information in the threads summary includes the following:

Thread ID The Thread ID of the thread.
Process ID The Process ID that the thread belongs to.
Process Name The process name, if known, that the thread belongs to.
Total Application Time (ms) The amount of time, expressed in milliseconds, that the thread spent in application mode.
Total System Call Time (ms) The amount of time, expressed in milliseconds, that the thread spent in system call mode.
Thread System Call Data A system call summary for the thread; this has the same fields as the global System Call Summary. It also includes elapsed time if the -e flag is specified and error information if the -s flag is specified.
Pending System Calls Summary If the thread was executing a system call at the end of the trace, a pending system call summary will be printed. This has the Accumulated Time and Supervisor Call (SVC Address) fields. It also includes elapsed time if the -e flag is specified.
processor affinity The process affinity, which is the probability that, for any dispatch of the thread, the thread was dispatched to the same processor on which it last executed.
Dispatch Histogram for thread Shows the number of times the thread was dispatched to each CPU in the system.
total number of dispatches The total number of times the thread was dispatched (not including redispatches).
total number of redispatches due to interrupts being disabled The number of redispatches due to interrupts being disabled, which is when the dispatch code is forced to dispatch the same thread that is currently running on that particular CPU because the thread had disabled some interrupts. This total is only reported if the value is non-zero.
avg. dispatch wait time (ms) The average dispatch wait time is the average elapsed time for the thread from being undispatched and its next dispatch.
Data on Interrupts that occurred while Thread was Running Count of how many times each type of FLIH occurred while this thread was executing.

Reports Generated with the -p Flag

The report generated with the -p flag includes the data shown in the default report and also includes a detailed report for each process that includes the Process ID and name, a count and list of the thread IDs, and the count and list of the pthread IDs belonging to the process. The total application time, the system call time, and the application time details for all the threads of the process are given. Lastly, it includes summary reports of all the completed and pending system calls, and pthread calls for the threads of the process.

The following example shows the report generated for the router process (PID 129190):

Process Details for Pid: 129190     

    Process Name: router
     

    7 Tids for this Pid: 245889 245631 244599 82843 78701 75347 28941 
    9 Ptids for this Pid:  2057 1800 1543 1286 1029 772 515 258 1

Total Application Time (ms):  124.023749 
Total System Call Time (ms):  8.948695 

Application time details:
     Total Pthread Call Time (ms):  1.228271
     Total Pthread Dispatch Time (ms):  2.760476
     Total Pthread Idle Dispatch Time (ms):  0.110307
     Total Other Time (ms):  798.545446
     Total number of pthread dispatches:  53
     Total number of pthread idle dispatches:  3

                             Process System Call Data
     Count   Total Time  % sys  Avg Time  Min Time  Max Time  SVC (Address)
              (msec)     time    (msec)    (msec)    (msec)
  ========  ===========  ======  ======== ========  ========  ================
       93       3.6829   0.05%    0.0396    0.0060    0.3077  kread(19731c)
       23       2.2395   0.03%    0.0974    0.0090    0.4537  kwrite(1972f8)
       30       0.8885   0.01%    0.0296    0.0073    0.0460  select(208c5c)
        1       0.5933   0.01%    0.5933    0.5933    0.5933  fsync(1972a4)
      106       0.4902   0.01%    0.0046    0.0035    0.0105  klseek(19737c)
       13       0.3285   0.00%    0.0253    0.0130    0.0387  semctl(2089e0)
        6       0.2513   0.00%    0.0419    0.0238    0.0650  semop(2089c8)
        3       0.1223   0.00%    0.0408    0.0127    0.0730  statx(2086d4)
        1       0.0793   0.00%    0.0793    0.0793    0.0793  send(11e1ec)
        9       0.0679   0.00%    0.0075    0.0053    0.0147  fstatx(2086c8)
        4       0.0524   0.00%    0.0131    0.0023    0.0348  kfcntl(22aa14)
        5       0.0448   0.00%    0.0090    0.0086    0.0096  yield(11dbec)
        3       0.0444   0.00%    0.0148    0.0049    0.0219  recv(11e1b0)
        1       0.0355   0.00%    0.0355    0.0355    0.0355  open(208674)
        1       0.0281   0.00%    0.0281    0.0281    0.0281  close(19728c)

                     Pending System Calls Summary
                     ----------------------------
Accumulated    SVC (Address)                  Tid          
Time (msec) 
============  =========================  ================
      0.0452   select(208c5c)             245889
      0.0425   select(208c5c)             78701
      0.0285   select(208c5c)             82843
      0.0284   select(208c5c)             245631
      0.0274   select(208c5c)             244599
      0.0179   select(208c5c)             75347

 ...(omitted lines)...

                     Pthread Calls Summary
   Count   Total Time   % sys  Avg Time  Min Time  Max Time  Pthread Routine
               (msec)    time    (msec)    (msec)    (msec)
========  ===========  ======  ========  ========  ========  ================
      19       0.0477   0.00%    0.0025    0.0017    0.0104  pthread_join
       1       0.0065   0.00%    0.0065    0.0065    0.0065  pthread_detach
       1       0.6208   0.00%    0.6208    0.6208    0.6208  pthread_kill
       6       0.1261   0.00%    0.0210    0.0077    0.0779  pthread_cancel
      21       0.7080   0.01%    0.0337    0.0226    0.1222  pthread_create

                     Pending Pthread Calls Summary
                     -----------------------------
Accumulated   Pthread Routine     Tid                Ptid
Time (msec)
============  ===============  ================  ================
     3.3102   pthread_join        78701               1                             

The information in the process detailed report includes the following:

Total Application Time (ms) The amount of time, expressed in milliseconds, that the process spent in application mode.
Total System Call Time (ms) The amount of time, expressed in milliseconds, that the process spent in system call mode.

The information in the application time details report includes the following:

Total Pthread Call Time The amount of time, expressed in milliseconds, that the process spent in traced pthread library calls.
Total Pthread Dispatch Time The amount of time, expressed in milliseconds, that the process spent in libpthreads dispatch code.
Total Pthread Idle Dispatch Time The amount of time, expressed in milliseconds, that the process spent in libpthreads vp_sleep code.
Total Other Time The amount of time, expressed in milliseconds, that the process spent in non-traced user mode code.
Total number of pthread dispatches The total number of times a pthread belonging to the process was dispatched by the libpthreads dispatcher.
Total number of pthread idle dispatches The total number of times a thread belonging to the process was in the libpthreads vp_sleep code.

The summary information in the report includes the following:

Process System Call Data A system call summary for the process; this has the same fields as the global System Call Summary. It also includes elapsed time information if the -e flag is specified and error information if the -s flag is specified.
Pending System Calls Summary If the process was executing a system call at the end of the trace, a pending system call summary will be printed. This has the Accumulated Time and Supervisor Call (SVC Address) fields. It also includes elapsed time information if the -e flag is specified.
Pthread Calls Summary A summary of the pthread calls for the process. This has the same fields as the global pthread Calls Summary. It also includes elapsed time information if the -e flag is specified.
Pending Pthread Calls Summary If the process was executing pthread library calls at the end of the trace, a pending pthread call summary will be printed. This has the Accumulated Time and Pthread Routine fields. It also includes elapsed time information if the -e flag is specified.

Reports Generated with the -P Flag

The report generated with the -P flag includes the data shown in the default report and also includes a detailed report on pthread status that includes the following:

The report also includes dispatch wait time and details of interrupts.

The following is an example of a report generated with the -P flag:

Report for Pthread Id: 1 (hex 1) Pid: 245962 (hex 3c0ca)
Process Name: ./pth32
---------------------
 Total Application Time (ms):  3.919091
 Total System Call Time (ms):  8.303156

 Application time details:
     Total Pthread Call Time (ms):  1.139372
     Total Pthread Dispatch Time (ms):  0.115822
     Total Pthread Idle Dispatch Time (ms):  0.036630
     Total Other Time (ms):  2.627266

                            Phread System Call Data
   Count   Total Time  Avg Time  Min Time  Max Time     SVC (Address)
               (msec)    (msec)    (msec)    (msec)
========  ===========  ========  ========  ========  ================
       1       3.3898    3.3898    3.3898    3.3898  _exit(409e50)
      61       0.8138    0.0133    0.0089    0.0254  kread(5ffd78)
      11       0.4616    0.0420    0.0262    0.0835  thread_create(407360)
      22       0.2570    0.0117    0.0062    0.0373  mprotect(6d5bd8)
      12       0.2126    0.0177    0.0100    0.0324  thread_setstate(40a660)
     115       0.1875    0.0016    0.0012    0.0037  klseek(5ffe38)
      12       0.1061    0.0088    0.0032    0.0134  sbrk(6d4f90)
      23       0.0803    0.0035    0.0018    0.0072  trcgent(4078d8)

...(lines omitted)...

                     Pending System Calls Summary
                     ----------------------------
Accumulated   SVC (Address)
Time (msec)
============  ==========================
      0.0141  thread_tsleep(40a4f8)


                     Pthread Calls Summary
   Count   Total Time   % sys  Avg Time  Min Time  Max Time  Pthread Routine
               (msec)    time    (msec)    (msec)    (msec)
========  ===========  ======  ========  ========  ========  ================
      11       0.9545   0.01%    0.0868    0.0457    0.1833  pthread_create
       8       0.0725   0.00%    0.0091    0.0064    0.0205  pthread_join
       1       0.0553   0.00%    0.0553    0.0553    0.0553  pthread_detach
       1       0.0341   0.00%    0.0341    0.0341    0.0341  pthread_cancel
       1       0.0229   0.00%    0.0229    0.0229    0.0229  pthread_kill

                     Pending Pthread Calls Summary
                     -----------------------------
Accumulated   Pthread Routine
Time (msec)
============  ===============
     0.0025   pthread_join


 processor affinity:  0.600000

Processor Dispatch Histogram for pthread (CPUid : times_dispatched):
    CPU 0 : 4
    CPU 1 : 1

 total number of dispatches  :  5
 avg. dispatch wait time (ms):  798.449725

 Thread affinity:  0.333333

Thread Dispatch Histogram for pthread (thread id :  number dispatches):
    Thread id 688279 : 1
    Thread id 856237 : 1
    Thread id 1007759 : 1

 total number of pthread dispatches:  3
 avg. dispatch wait time (ms):  1330.749542

      Data on Interrupts that Occurred while Phread was Running
           Type of Interrupt       Count
   =============================== ============================
    Data Access Page Faults (DSI): 452
   Instr. Fetch Page Faults (ISI): 0
          Align. Error Interrupts: 0
         IO (external) Interrupts: 0
         Program Check Interrupts: 0
        FP Unavailable Interrupts: 0
          FP Imprecise Interrupts: 0
               RunMode Interrupts: 0
           Decrementer Interrupts: 2
   Queued (Soft level) Interrupts: 0

The information in the pthreads summary report includes the following:

Pthread ID The Pthread ID of the thread.
Process ID The Process ID that the pthread belongs to.
Process Name The process name, if known, that the pthread belongs to.
Total Application Time (ms) The amount of time, expressed in milliseconds, that the pthread spent in application mode.
Total System Call Time (ms) The amount of time, expressed in milliseconds, that the pthread spent in system call mode.

The information in the application time details report includes the following:

Total Pthread Call Time The amount of time, expressed in milliseconds, that the pthread spent in traced pthread library calls.
Total Pthread Dispatch Time The amount of time, expressed in milliseconds, that the pthread spent in libpthreads dispatch code.
Total Pthread Idle Dispatch Time The amount of time, expressed in milliseconds, that the pthread spent in libpthreads vp_sleep code.
Total Other Time The amount of time, expressed in milliseconds, that the pthread spent in non-traced user mode code.
Total number of pthread dispatches The total number of times a pthread belonging to the process was dispatched by the libpthreads dispatcher.
Total number of pthread idle dispatches The total number of times a thread belonging to the process was in the libpthreads vp_sleep code.

The summary information in the report includes the following:

Pthread System Call Data A system call summary for the pthread; this has the same fields as the global System Call Summary. It also includes elapsed time information if the -e flag is specified and error information if the -s flag is specified.
Pending System Calls Summary If the pthread was executing a system call at the end of the trace, a pending system call summary will be printed. This has the Accumulated Time and Supervisor Call (SVC Address) fields. It also includes elapsed time information if the -e flag is specified.
Pthread Calls Summary A summary of the pthread library calls for the pthread. This has the same fields as the global pthread Calls Summary. It also includes elapsed time information if the -e flag is specified.
Pending Pthread Calls Summary If the pthread was executing a pthread library call at the end of the trace, a pending pthread call summary will be printed. This has the Accumulated Time and Pthread Routine fields. It also includes elapsed time information if the -e flag is specified.

The pthreads summary report also includes the following information:

processor affinity Probability that for any dispatch of the pthread, the pthread was dispatched to the same processor on which it last executed.
Processor Dispatch Histogram for pthread The number of times that the pthread was dispatched to each CPU in the system.
avg. dispatch wait time The average elapsed time for the pthread from being undispatched and its next dispatch.
Thread affinity The probability that for any dispatch of the pthread, the pthread was dispatched to the same kernel thread on which it last executed
Thread Dispatch Histogram for pthread The number of times that the pthread was dispatched to each kernel thread in the process.
total number of pthread dispatches The total number of times the pthread was dispatched by the libpthreads dispatcher.
Data on Interrupts that occurred while Pthread was Running The number of times each type of FLIH occurred while the pthread was executing.

[ Top of Page | Previous Page | Next Page | Contents | Index | Library Home | Legal | Search ]