CURT -- THE “CPU USAGE REPORTING TOOL”

This article originally appeared in IBM Systems Magazine. The original paste up has been lost, so this is a posting of the edited, final article I submitted to the magazine.

CURT?--?THE “CPU USAGE REPORTING TOOL”

?The AIX CPU Usage Reporting Tool -- or "CURT" – is a part of the bos.perf.tools fileset and ships with every AIX distribution. CURT adds great depth to your performance analysis arsenal and should be included in any deep dive into performance issues.

CURT reports are extracted from raw -- as opposed to formatted -- AIX kernel trace data, so you'll need to run a kernel trace and have the output available for this exercise. The trace data should also include performance information for every CPU in your system (and yes, you can use CURT to zero in on individual CPUs). There are about a million flag combinations to the trace tool; the sample syntax I give here will record information for every CPU, run for five seconds and write its data to the trace.raw file, then self-terminate. This is the syntax I use in my daily performance data collection activities (Note: To issue any of the commands presented in this article, you must be working as root.):

trace?-a?-fn?-o?trace.raw?-T40M?-L80M?;?sleep?5?;?trcstop

We also need information about kernel extensions, shared libraries, processes and symbols that CURT uses. So, we need to create a “gensyms” file that stores this information. Creating your gensyms file is easy, just run this command:

gensyms?>?gensyms.out

This will take a while, so let it chug. Once you have your gensyms.out file, you're ready to extract a CURT report from your raw trace data. Over the years, I've relied on a combination of CURT flags that work well for me, which you'll see here. But by all means, use the flags that you feel most comfortable with and work best in your environment. Here is my preferred CURT extraction syntax:

curt?-i?trace.raw?-n?gensyms.out?-o?curt.all?-Ptse

This syntax tells CURT to extract its information from the trace.raw file, use the gensyms.out file for, among other things, name-to-address mappings, write its data to the curt.all ("all" in this case meaning a report will be generated that covers activity on all logical processors), and include detailed process, thread, system call and elapsed time information for system calls and posix threads.

Now that you've generated your CURT report, let's take a look at some of the data it has produced. This first screen full of information is typical of most CURT reports:

Run on Wed Feb 17 14:40:00 2016

Command line was:

curt -i trace.out -n gensyms.out -o curt.all -Ptse

AIX trace file name = trace.out

AIX trace file size = 3053744

Fri Feb 12 17:18:51 2016

System: AIX 7.1 Node: lpar Machine: 00000000000

AIX trace file created = Fri Feb 12 17:18:51 2016

?

Command used to gather AIX trace was:

?trace -a -fn -o trace.out -T40M -L80M

?

??????????????????????????System Summary

????????????????????--------------

?processing??????percent??????????percent

?total time???total time????????busy time

????(msec)?(incl. idle)?????(excl. idle)????processing category

===========??===========??????===========????===================

??????5.05?????????0.01????????19.17???????APPLICATION

??????5.33?????????0.01????????20.20???????SYSCALL

??????0.65?????????0.00?????????2.47???????HCALL

??????1.86?????????0.01?????????7.05???????KPROC (excluding IDLE and NFS)

??????0.00?????????0.00?????????0.00???????NFS

?????11.67?????????0.03????????44.24???????FLIH

??????0.33?????????0.00?????????1.26???????SLIH

??????1.48?????????0.00?????????5.61???????DISPATCH (all procs. incl. IDLE)

??????0.71?????????0.00?????????2.69???????IDLE DISPATCH (only IDLE proc.)

-----------???----------??????-------

?????26.37?????????0.07???????100.00?CPU(s) busy time

??36484.19????????99.93???????????????IDLE

-----------???----------

??36510.56?????????????????????????????TOTAL

?

Avg. Thread Affinity = 0.98

Total Physical CPU time (msec) = 30087.32

Physical CPU percentage???????= 99.89

First, we have header information that tells you things like the time and date CURT was run, the syntax used to extract the CURT report from the raw trace file -- as well as the trace syntax itself -- and the name of your system with its AIX level. You will then be presented with a system summary that shows you the averages of many important performance counters. You see the amount of time your CPUs spent handling application requests and servicing system calls, as well as the amount of time they spent handling Hypervisor calls. "Kproc" tells you how much time was spent executing kernel processes other than wait and NFS kprocs; NFS has its own summary which is next in the list. First and Second Level Interrupt Handlers (FLIH and SLIH) are next, followed by the amount of time the CPUs spent dispatching all threads. Idle Dispatch tells you how much time was spent dispatching the idle (or "wait") process. Since idle dispatch time obviously doesn't contribute to a CPU's busy time, it's broken out separately from the "dispatch" category. You then have several categories where all of these counters are summed.?

At this point, you should see how intuitive and self-explanatory CURT data is. It takes the study of just a few CURT reports to become proficient with the utility. As noted, I use a certain set of flags with CURT. Now we can look at these, along with some of their output:

1) The?-P?flag outputs detailed process information:

??????????????????Application Summary (by Pid)

????????????????????----------------------------

???-- processing total (msec) --?????????-- percent of total processing time --

??combined?application?????syscall????combined?application?????syscall?name (Pid)(Thread???????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????Count)

??========?===========?????=======????========?===========?????=======?===================

????4.9167??????2.2622??????2.6545??????0.0135??????0.0062??????0.0073?trcstop(5767334)(1)

????1.7363??????0.7728??????0.9634??????0.0048??????0.0021??????0.0026?sleep(5767332)(1)

????1.0684??????1.0684??????0.0000??????0.0029??????0.0029??????0.0000?getty(7078106)(1)

????0.7694??????0.1377??????0.6317??????0.0021??????0.0004??????0.0017?ksh(7471348)(1)

The above screenshot is representative of several different versions of process data in the CURT report. Here, you see the name of your process with the number of threads it's spawned, along with the amount of time that process spent handling application and system calls. You also have that same time expressed in milliseconds; this is especially useful when you're trying to determine is a process is hogging your CPUs at the expense of other perhaps more deserving processes in your system.

2) The?-t flag outputs detailed thread information:

-----------------------------------------------------------------------------

Report for Thread Id: 20775057 (hex 13d0091) Pid: 5767332 (hex 5800a4)

Process Name: sleep

---------------------

?Total Application Time (ms):?0.772834

?Total System Call Time (ms):?0.963434

?Total Hypervisor Call Time (ms):?0.000000

?

??????????????????????????Thread System Call Summary

??????????????????????????--------------------------

Count??Total Time?Avg Time?Min Time?Max Time?Tot ETime?Avg ETime?Min ETime?Max ETime????SVC (Address)

?????????????(msec)???(msec)???(msec)???(msec)????(msec)????(msec)????(msec)????(msec)

========?===========?========?========?========?=========?=========?=========?=========???????

18??????0.2913???0.0162???0.0006???0.1045????0.3085????0.0171????0.0006????0.1217__loadx(3248380)

?1??????0.2591???0.2591???0.2591???0.2591????0.2591????0.2591????0.2591????0.2591?_exit(32389e8)

?1??????0.2363???0.2363???0.2363???0.2363????0.2502????0.2502????0.2502????0.2502?execve(32341b8)

.....lines omitted .....

Here, you're presented with detailed info on your working threads, such as their name, the time they spent handling application and system calls and the timings for those individual calls expressed in milliseconds. Thread details are rather lengthy, so I've had to omit some of their data. But thread details also tell you about hypervisor calls the thread made, any errors encountered while handling system calls (which are displayed when you invoke the -s flag) and the all-important affinity counters. The -e flag, which is also represented here, gives us all the elapsed time counters.

This is just a small sampling of the performance data a CURT report provides. Experiment with the other flags; try them in different combinations. Don't worry, you can't break anything. All of the actual processing has already been done by the AIX kernel trace utility.

CURT is invaluable for CPU evaluations. I'm certain once you use it a few times, you'll include itasa matter of routine in all your deep performance evaluations.