2:38 p.m.
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(a)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(a)xemacs.org
> http://calypso.tux.org/cgi-bin/mailman/listinfo/xemacs-beta
>
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)
_______________________________________________
XEmacs-Beta mailing list
XEmacs-Beta(a)xemacs.org
http://calypso.tux.org/cgi-bin/mailman/listinfo/xemacs-beta