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 Hypervisor Calls Summary, the Pending Hypervisor Calls Summary, the System NFS Calls Summary, the Pending NFS Calls Summary, the Pthread Calls Summary and the Pending Pthread Calls Summary.
The additional information in the System Calls Summary, Hypervisor Calls Summary, System NFS 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, Pending Hypervisor Calls Summary, Pending NFS 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, hypervisor call, NFS 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:
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.
# curt -e -i trace.r -m trace.nm -n gensyms.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)...
Hypervisor Calls Summary
------------------------
Count Total Time % sys Avg Time Min Time Max Time Tot ETime Avg ETime Min ETime Max ETime HCALL (Address)
(msec) time (msec) (msec) (msec) (msec) (msec) (msec) (msec)
======== =========== ====== ======== ======== ======== ======== ========= ========= ========= =================
4 0.0077 0.00% 0.0019 0.0014 0.0025 0.0077 0.0019 0.0014 0.0025 H_XIRR(3ada19c)
4 0.0070 0.00% 0.0017 0.0015 0.0021 0.0070 0.0017 0.0015 0.0021 H_EOI(3ad6564)
Pending Hypervisor Calls Summary
--------------------------------
Accumulated Accumulated HCALL (Address) Procname (Pid Tid)
Time (msec) ETime (msec)
============ ============ ========================= =========================
0.0855 93.6498 H_XIRR(3ada19c) syncd(3916 5981)
System NFS Calls Summary
------------------------
Count Total Time Avg Time Min Time Max Time % Tot Total ETime Avg ETime Min ETime Max ETime % Tot % Tot Opcode
(msec) (msec) (msec) (msec) Time (msec) (msec) (msec) (msec) ETime Count
======== =========== ======== ======== ======== ===== =========== ========= ========= ========= ===== ===== =============
6647 456.1029 0.0686 0.0376 0.6267 15.83 9267.7256 1.3943 0.0376 304.9501 14.63 27.88 RFS3_LOOKUP
2694 147.1680 0.0546 0.0348 0.5517 5.11 1474.4267 0.5473 0.0348 25.9402 2.33 11.30 RFS3_GETATTR
1702 85.8328 0.0504 0.0339 0.5793 2.98 146.4281 0.0860 0.0339 5.7539 0.23 7.14 RFS3_READLINK
1552 78.1015 0.0503 0.0367 0.5513 2.71 153.5844 0.0990 0.0367 7.5125 0.24 6.51 RFS3_ACCESS
235 33.3158 0.1418 0.0890 0.3312 1.16 1579.4557 6.7211 0.0890 56.0876 2.49 0.99 RFS3_SETATTR
21 5.5979 0.2666 0.0097 0.8142 82.79 127.2616 6.0601 0.0097 89.0570 99.37 25.00 NFS4_WRITE
59 1.1505 0.0195 0.0121 0.0258 17.01 0.7873 0.0133 0.0093 0.0194 0.61 70.24 NFS4_ATTRCACHE
4 0.0135 0.0034 0.0026 0.0044 0.20 0.0135 0.0034 0.0026 0.0044 0.01 4.76 NFS4_GET_UID_GID
...(line omitted)...
Pending NFS Calls Summary
-------------------------
Accumulated Accumulated Sequence Number Procname (Pid Tid)
Time (msec) ETime (msec) Opcode
============ ============ =============== ==========================
0.0831 15.1581 1038711932 nfsd(1007854 331969)
0.0833 13.8889 1038897247 nfsd(1007854 352459)
0.0087 10.8976 NFS4_ATTRCACHE kbiod(100098 678934)
...(line 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)| Item | Descriptor |
|---|---|
| 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. |