[Bug: 21.5-b28] performance on aix, cpu hog, another session
gprof output
Thomas Mittelstaedt
T.Mittelstaedt at cadenas.de
Wed Mar 12 10:38:27 EDT 2008
Using trace and curt, I produced another performance output, which is
attached.
Maybe it helps.
Thomas Mittelstaedt schrieb:
> Okay, I have attached the truss output with the start:
>
>
>
> Jerry James schrieb:
>
>> Thomas,
>>
>> Thanks for going to the effort of collecting this profiling data. It
>> gives us some interesting information.
>>
>> 2008/3/11 Thomas Mittelstaedt <T.Mittelstaedt at cadenas.de>:
>>
>>
>>> ngranularity: Jedes gefundene Beispiel deckt 4 Byte ab. Zeit: 97,87 Sekunden
>>>
>>> % kumulativ selbst selbst gesamt
>>> Zeit Sekunden Sekunden Aufrufe ms/Aufruf ms/Aufruf Name
>>> 0,2 0,21 0,21 .__is_wctype_sb [1]
>>>
>>>
>> [snip]
>>
>>
>>
>>> 0,0 1,00 0,01 .xtCreate [48]
>>>
>>>
>> So the top 48 time hogs together consume a grand total of 1.00 seconds
>> out of 97.87 seconds of execution. Your other profile was similar:
>> out of 56.55 seconds of execution, the top 43 collectively consumed
>> 0.73 seconds of execution. This indicates that the performance
>> problems you are seeing are not occurring in the profiled (i.e.,
>> XEmacs) code. We appear to either be triggering a performance bug in
>> some library, or using some library in a suboptimal way. In either
>> case, this is as far as a profiler is going to take us.
>>
>> I'm still curious about the large number of kioctl calls in the truss
>> output you showed us earlier. Do you know why that output did not
>> start with the launching of the XEmacs executable? Can you get us
>> truss output that does start from launch? I want to know what file
>> descriptor is the target of all that manipulation. It may be a red
>> herring, but I think it's worth checking out.
>>
>> Thank you,
>>
>>
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> XEmacs-Beta mailing list
>> XEmacs-Beta at xemacs.org
>> http://calypso.tux.org/cgi-bin/mailman/listinfo/xemacs-beta
>>
-------------- next part --------------
Run on Wed Mar 12 14:45:39 2008
Command line was:
curt -i trace.r
----
AIX trace file name = trace.r
AIX trace file size = 1557260
AIX trace file created = Wed Mar 12 14:40:57 2008
Command used to gather AIX trace was:
trace -n -C all -d -j 100,101,102,103,104,106,10C,119,134,135,139,200,210,38F,465 -L 1000000 -T 1000000 -afo trace.raw
System Summary
--------------
processing percent percent
total time total time busy time
(msec) (incl. idle) (excl. idle) processing category
=========== =========== =========== ===================
1802.48 21.76 95.18 APPLICATION
56.99 0.69 3.01 SYSCALL
6.97 0.08 0.37 KPROC (not including IDLE)
0.00 0.00 0.00 NFS
15.89 0.19 0.84 FLIH
9.56 0.12 0.50 SLIH
1.88 0.02 0.10 DISPATCH (all procs. incl. IDLE)
0.83 0.01 0.04 IDLE DISPATCH (only IDLE proc.)
----------- ---------- -------
1893.76 22.86 100.00 CPU(s) busy time
6389.71 77.14 IDLE
----------- ----------
8283.47 TOTAL
Avg. Thread Affinity = 1.00
Processor Summary processor number 0
---------------------------------------
processing percent percent
total time total time busy time
(msec) (incl. idle) (excl. idle) processing category
=========== =========== =========== ===================
1802.48 21.76 95.18 APPLICATION
56.99 0.69 3.01 SYSCALL
6.97 0.08 0.37 KPROC (not including IDLE)
0.00 0.00 0.00 NFS
15.89 0.19 0.84 FLIH
9.56 0.12 0.50 SLIH
1.88 0.02 0.10 DISPATCH (all procs. incl. IDLE)
0.83 0.01 0.04 IDLE DISPATCH (only IDLE proc.)
----------- ---------- -------
1893.76 22.86 100.00 CPU(s) busy time
6389.71 77.14 IDLE
----------- ----------
8283.47 TOTAL
Avg. Thread Affinity = 1.00
Total number of process dispatches = 600
Total number of idle dispatches = 833
Application Summary (by Tid)
----------------------------
-- processing total (msec) -- -- percent of total processing time --
combined application syscall combined application syscall name (Pid Tid)
======== =========== ======= ======== =========== ======= ===================
1821.7942 1792.4698 29.3243 21.9931 21.6391 0.3540 xemacs-21.5-b28(282678 610349)
17.6971 0.0167 17.6804 0.2136 0.0002 0.2134 syncd(102464 163921)
13.3114 8.3187 4.9926 0.1607 0.1004 0.0603 dtgreet(77904 118885)
3.3304 0.3160 3.0144 0.0402 0.0038 0.0364 sleep(262250 577779)
1.3896 0.3596 1.0300 0.0168 0.0043 0.0124 bash(221186 393303)
0.8612 0.4053 0.4560 0.0104 0.0049 0.0055 X(53414 90253)
0.3231 0.1086 0.2144 0.0039 0.0013 0.0026 syncd(102464 151633)
0.2395 0.1089 0.1306 0.0029 0.0013 0.0016 sendmail(147550 233619)
0.1817 0.0383 0.1434 0.0022 0.0005 0.0017 aixmibd(168026 254085)
0.0132 0.0132 0.0000 0.0002 0.0002 0.0000 (258072 675893)
Application Summary (by Pid)
----------------------------
-- processing total (msec) -- -- percent of total processing time --
combined application syscall combined application syscall name (Pid)(Thread Count)
======== =========== ======= ======== =========== ======= ===================
1821.7942 1792.4698 29.3243 21.9931 21.6391 0.3540 xemacs-21.5-b28(282678)(1)
18.0202 0.1253 17.8948 0.2175 0.0015 0.2160 syncd(102464)(2)
13.3114 8.3187 4.9926 0.1607 0.1004 0.0603 dtgreet(77904)(1)
3.3304 0.3160 3.0144 0.0402 0.0038 0.0364 sleep(262250)(1)
1.3896 0.3596 1.0300 0.0168 0.0043 0.0124 bash(221186)(1)
0.8612 0.4053 0.4560 0.0104 0.0049 0.0055 X(53414)(1)
0.2395 0.1089 0.1306 0.0029 0.0013 0.0016 sendmail(147550)(1)
0.1817 0.0383 0.1434 0.0022 0.0005 0.0017 aixmibd(168026)(1)
0.0132 0.0132 0.0000 0.0002 0.0002 0.0000 (258072)(1)
Application Summary (by process type)
------------------------------------
-- processing total (msec) -- -- percent of total processing time --
combined application syscall combined application syscall name (thread count)
======== =========== ======= ======== =========== ======= ==============
1821.7942 1792.4698 29.3243 21.9931 21.6391 0.3540 xemacs-21.5-b28(1)
18.0202 0.1253 17.8948 0.2175 0.0015 0.2160 syncd(2)
13.3114 8.3187 4.9926 0.1607 0.1004 0.0603 dtgreet(1)
3.3304 0.3160 3.0144 0.0402 0.0038 0.0364 sleep(1)
1.3896 0.3596 1.0300 0.0168 0.0043 0.0124 bash(1)
0.8612 0.4053 0.4560 0.0104 0.0049 0.0055 X(1)
0.2395 0.1089 0.1306 0.0029 0.0013 0.0016 sendmail(1)
0.1817 0.0383 0.1434 0.0022 0.0005 0.0017 aixmibd(1)
0.0132 0.0132 0.0000 0.0002 0.0002 0.0000 (1)
Kproc Summary (by Tid)
-----------------------
-- processing total (msec) -- -- percent of total time -- name (Pid Tid Type)
combined kernel operation combined kernel operation
======== ====== =========== ======== ====== =========== ===================
6389.7062 6389.7062 0.0000 77.1380 77.1380 0.0000 wait(8196 8197 W)
1.3817 1.3817 0.0000 0.0167 0.0167 0.0000 swapper(0 3 -)
0.9024 0.9024 0.0000 0.0109 0.0109 0.0000 rpc.lockd(213114 344233 -)
0.8501 0.8501 0.0000 0.0103 0.0103 0.0000 gil(40980 53275 -)
0.8283 0.8283 0.0000 0.0100 0.0100 0.0000 gil(40980 57373 -)
0.8182 0.8182 0.0000 0.0099 0.0099 0.0000 gil(40980 61471 -)
0.7951 0.7951 0.0000 0.0096 0.0096 0.0000 gil(40980 49177 -)
0.7629 0.7629 0.0000 0.0092 0.0092 0.0000 nfsd(204900 299155 -)
0.1632 0.1632 0.0000 0.0020 0.0020 0.0000 rpc.lockd(213114 348331 -)
0.1485 0.1485 0.0000 0.0018 0.0018 0.0000 nfsd(204900 303253 -)
0.0725 0.0725 0.0000 0.0009 0.0009 0.0000 netm(36882 36883 -)
0.0471 0.0471 0.0000 0.0006 0.0006 0.0000 xmgc(32784 32785 -)
0.0270 0.0270 0.0000 0.0003 0.0003 0.0000 pilegc(28686 28687 -)
0.0174 0.0174 0.0000 0.0002 0.0002 0.0000 rpc.lockd(213114 336055 -)
0.0170 0.0170 0.0000 0.0002 0.0002 0.0000 nfsd(204900 290959 -)
0.0161 0.0161 0.0000 0.0002 0.0002 0.0000 nfsd(204900 307351 -)
0.0153 0.0153 0.0000 0.0002 0.0002 0.0000 pilegc(28686 65569 -)
0.0152 0.0152 0.0000 0.0002 0.0002 0.0000 nfsd(204900 315547 -)
0.0143 0.0143 0.0000 0.0002 0.0002 0.0000 rpc.lockd(213114 352429 -)
0.0121 0.0121 0.0000 0.0001 0.0001 0.0000 rpc.lockd(213114 364723 -)
0.0116 0.0116 0.0000 0.0001 0.0001 0.0000 nfsd(204900 319645 -)
0.0114 0.0114 0.0000 0.0001 0.0001 0.0000 rpc.lockd(213114 368821 -)
0.0112 0.0112 0.0000 0.0001 0.0001 0.0000 nfsd(204900 323743 -)
0.0110 0.0110 0.0000 0.0001 0.0001 0.0000 nfsd(204900 274585 -)
0.0104 0.0104 0.0000 0.0001 0.0001 0.0000 rpc.lockd(213114 377017 -)
0.0096 0.0096 0.0000 0.0001 0.0001 0.0000 rpc.lockd(213114 372919 -)
Kproc Types
-----------
Type Function Operation
==== ============================ ==========================
W idle thread -
N NFS daemon NFS Remote Procedure Calls
System Calls Summary
--------------------
Count Total Time % sys Avg Time Min Time Max Time SVC (Address)
(msec) time (msec) (msec) (msec)
======== =========== ====== ======== ======== ======== ================
1 17.6516 0.21% 17.6516 17.6516 17.6516 syn(6ef400)
2927 17.4595 0.21% 0.0060 0.0017 0.0403 _poll(6f0198)
285 8.1473 0.10% 0.0286 0.0044 0.0806 kwrite(5f4dc0)
3557 7.9664 0.10% 0.0022 0.0012 0.0547 kioctl(6ef028)
1 1.7041 0.02% 1.7041 1.7041 1.7041 execve(3e1cd0)
17 1.1906 0.01% 0.0700 0.0022 0.6758 __loadx(721e28)
1 0.6211 0.01% 0.6211 0.6211 0.6211 kfork(3e1cb0)
66 0.3402 0.00% 0.0052 0.0041 0.0101 incinterval(3e54a0)
11 0.3285 0.00% 0.0299 0.0129 0.0601 statx(6ef388)
15 0.3096 0.00% 0.0206 0.0191 0.0235 (unknown)(362f7b0)
20 0.1886 0.00% 0.0094 0.0088 0.0104 thread_waitact(3e5050)
67 0.1702 0.00% 0.0025 0.0014 0.0169 kread(5f4e08)
1 0.1317 0.00% 0.1317 0.1317 0.1317 _select(6f01c8)
24 0.1297 0.00% 0.0054 0.0045 0.0098 (unknown)(362f7f8)
34 0.1001 0.00% 0.0029 0.0026 0.0067 ksetcontext_sigreturn(3e5758)
1 0.0776 0.00% 0.0776 0.0776 0.0776 statfs(721ac8)
1 0.0506 0.00% 0.0506 0.0506 0.0506 readlink(6ef3b8)
24 0.0477 0.00% 0.0020 0.0012 0.0032 (unknown)(362f828)
1 0.0433 0.00% 0.0433 0.0433 0.0433 open(6ef298)
24 0.0413 0.00% 0.0017 0.0011 0.0025 (unknown)(362f810)
1 0.0360 0.00% 0.0360 0.0360 0.0360 access(721a20)
15 0.0334 0.00% 0.0022 0.0012 0.0072 sigprocmask(3e4f78)
16 0.0209 0.00% 0.0013 0.0011 0.0019 appgettimer(3e5470)
21 0.0206 0.00% 0.0010 0.0007 0.0018 yield(3e4930)
7 0.0137 0.00% 0.0020 0.0016 0.0028 _sigaction(3e4f48)
1 0.0086 0.00% 0.0086 0.0086 0.0086 lseek(5f4ef8)
18 0.0085 0.00% 0.0005 0.0003 0.0010 getuidx(5f5270)
18 0.0078 0.00% 0.0004 0.0003 0.0007 getgidx(6ef988)
2 0.0056 0.00% 0.0028 0.0028 0.0028 _setpgid(5f5090)
3 0.0047 0.00% 0.0016 0.0007 0.0022 sbrk(6f0dc8)
1 0.0045 0.00% 0.0045 0.0045 0.0045 kfork-child(1)
4 0.0034 0.00% 0.0008 0.0006 0.0010 _getpid(5f5120)
1 0.0023 0.00% 0.0023 0.0023 0.0023 kwa(3e4900)
Pending System Calls Summary
----------------------------
Accumulated SVC (Address) Procname (Pid Tid)
Time (msec)
============ ========================= ==========================
0.0139 (unknown)(362f7b0) X(53414 90253)
0.0122 _poll(6f0198) dtgreet(77904 118885)
0.0053 thread_waitact(3e5050) syncd(102464 151633)
0.0287 _nsleep(3e5368) syncd(102464 163921)
0.0189 _select(6f01c8) sendmail(147550 233619)
0.0118 _select(6f01c8) aixmibd(168026 254085)
0.0068 kwa(3e4900) bash(221186 393303)
0.0154 _nsleep(3e5368) sleep(262250 577779)
0.0034 _poll(6f0198) xemacs-21.5-b28(282678 610349)
Global Flih Summary
-------------------
Count Total Time Avg Time Min Time Max Time Flih Type
(msec) (msec) (msec) (msec)
====== =========== =========== =========== =========== =========
1 0.0047 0.0047 0.0047 0.0047 32(QUEUED_INTR)
299 0.9609 0.0032 0.0011 0.0385 5(IO_INTR)
1238 12.5834 0.0102 0.0006 0.0245 31(DECR_INTR)
171 2.3367 0.0137 0.0021 0.0372 3(DATA_ACC_PG_FLT)
Per CPU Flih Summary
--------------------
CPU Number 0:
Count Total Time Avg Time Min Time Max Time Flih Type
(msec) (msec) (msec) (msec)
====== =========== =========== =========== =========== =========
1 0.0047 0.0047 0.0047 0.0047 32(QUEUED_INTR)
299 0.9609 0.0032 0.0011 0.0385 5(IO_INTR)
1238 12.5834 0.0102 0.0006 0.0245 31(DECR_INTR)
171 2.3367 0.0137 0.0021 0.0372 3(DATA_ACC_PG_FLT)
Global Slih Summary
-------------------
Count Total Time Avg Time Min Time Max Time Slih Name(Address)
(msec) (msec) (msec) (msec)
====== =========== =========== =========== =========== =================
21 0.2115 0.0101 0.0070 0.0197 ssc_intr(346dc68)
278 9.3457 0.0336 0.0187 0.0522 (unknown)(35999b8)
Per CPU Slih Summary
--------------------
CPU Number 0:
Count Total Time Avg Time Min Time Max Time Slih Name(Address)
(msec) (msec) (msec) (msec)
====== =========== =========== =========== =========== =================
21 0.2115 0.0101 0.0070 0.0197 ssc_intr(346dc68)
278 9.3457 0.0336 0.0187 0.0522 (unknown)(35999b8)
(End of CURT Output)
More information about the XEmacs-Beta
mailing list
