[Bug: 21.5-b28] performance on aix, cpu hog, another session
gprof output
Thomas Mittelstaedt
T.Mittelstaedt at cadenas.de
Tue Mar 11 12:42:36 EDT 2008
Attached is the output from another session, a little bit longer one.
Xemacs ran at about 50% cpu.
Thomas Mittelstaedt schrieb:
> Well,
>
> I managed to build xemacs with -pg on compile and link. Attached is the
> output of
> gprof, which is the one the system provides.
> In that sample session, xemacs ran at more that 40% cpu.
> I also switched window managers from wmaker to icewm. But still, xemacs
> would consume a lot of
> cpu in the (large) range of 20-40%.
>
> Hope this helps.
> thomas
>
>
> Jerry James schrieb:
>
>> Hi Thomas,
>>
>> 2008/3/11 Thomas Mittelstaedt <T.Mittelstaedt at cadenas.de>:
>>
>>
>>> ================================================================
>>> Dear Bug Team!
>>>
>>> xemacs is slow on aix. Selecting things with the mouse is sluggish and
>>> xemacs permanently uses
>>> more than 30% cpu. I am running it under gdb, when i interrupt via
>>> control-C, bt shows me the following:
>>>
>>>
>> [snip]
>>
>>
>>
>>> I have also attached the output of truss.
>>>
>>>
>> The truss output starts after file descriptor 8 is already defined.
>> Since most of the truss output consists of kioctl calls on fd 8, I'd
>> like to know what that is. On the other hand, I'm not sure that truss
>> is the right tool for the job. What we really need to see is some
>> profiling output. Are you able to get that for us? Thanks,
>>
>>
-------------- next part --------------
graph-Profile aufrufen:
Die Summe von selbst und untergeordneten ist die übergeordnete
Sortierung
für diese Liste.
Funktionseinträge:
Index der Index für diese Funktion in der Aufrufliste für graph,
als eine Hilfe, es zu positionieren (siehe unten).
%Zeit Prozentsatz der gesamten Zeit für das Programm
festgelegt für von dieser Funktion und ihrer
Untergeordneten.
selbst die Anzahl von Sekunden, die für diese Funktion benötigt wird
sich selbst.
Untergeordnete
die Anzahl von Sekunden, die in den untergeordneten Funktionen von
dieser Funktion im Auftrag dieser Funktion verwendet werden.
aufgerufen wie oft diese Funktion aufgerufen wurde (andere
als rekursive Aufrufe).
selbst wie oft sich diese Funktion selbst rekursive
aufgerufen hat.
Name der Name dieser Funktion mit einem Hinweis auf
die Mitgliedschaft in einem Zyklus, falls vorhanden.
Index der Index für diese Funktion in der Aufrufliste für graph,
als eine Hilfe diesen zu finden.
Übergeordnete Funktion (parent) Listen:
selbst* die Anzahl der Sekunden, die diese Funktion als Selbstzeit
benötigt, die abhängt von den Aufrufen dieser übergeordneten
(parent) Funktion.
untergeordnete*
die Anzahl der Sekunden, der dieser Funktion untergeordneten Zeit,
die abhängt von den Aufrufen von der
übergeordneten Funktion (parent).
aufgerufen** Anzahl der Aufrufe dieser Funktion von
ihrer übergeordneten Funktion (parent). Dies ist der Zähler des
Bruches, der die Zeit dieser Funktion verteilt auf
deren übergeordnete Funktionen.
gesamt* Häufigkeit, mit der diese Funktion aufgerufen wurden von
allen deren übergeordneten Funktionen. Das ist der Nenner des
Fortpflanungsbruches.
übergeordnete Funktionen der Name dieser übergeordneten Funktion mit einem
Hinweise auf die Mitgliedschaft der übergeordneten Funktion in
einem Zyklus, falls zutreffend.
Index der Index dieser übergeordneten Funktion in der graph-Aufrufliste,
als eine Hilfe, diese zu positionieren.
Auflistung der untergeordneten Funktionen:
selbst* Anzahl von Sekunden, die diese untergeordnete Funktion als
eigene Zeit (self time) benötigt, ist abhängig davon,
ob von dieser Funktion aufgerufen wurde.
untergeordnet*
die Anzahl der Sekunden, die dieser untergeordneten Funktion weiter
untergeordneten Funktion benötigt, die abhängig davon ist, ob sie
von dieser Funktion aufgerufen wird.
aufgerufen** die Häufigkeit, mit der diese untergeordnete Funktion von
dieser Funktion aufgerufen wird. Dies ist der Zähler des
Fortpflanzungsbruches für diese untergeordnete Funktion (child).
gesamt* die Häufigkeit, mit der diese untergeordnete Funktion von
Funktionen aufgerufen wurde. Das ist der Nenner des
Fortpflanzungbruches.
untergeordnete Funktionen der Name dieser untergeordneten Funktion und ein
Hinweis auf ihre Mitgliedschaft in einem Zyklus, falls zutreffend.
Index der Index dieser untergeordneten Funktion in einer graph-Aufrufliste,
als eine Hilfe, diesen zu lokalisieren.
* diese Felder sind für übergeordnete Funktionen ausgelassen (oder
untergeordnete Funktionen) im selben Zyklus als die Funktion. Wenn
die Funktion (oder die untergeordnete) ein Mitglied des Zyklus ist,
die verbreitete Zeit und der verbreitete Nenner
repräsentieren die selbst benötigte Zeit und die untergeordnete Zeit
des Zyklus als Ganzes.
** nur statische über- und untergeordnete Funktionen werden angezeigt
von einem Aufrufzähler von 0.
Zykluslisten:
der Zyklus als Ganzes ist mit den gleichen Felder als
Funktionseintrag aufgelistet. Darunter sind die Mitglieder des
Zyklus aufgelistet und ihre Beiträge
zu der Zeit und den Aufrufzählungen dieses Zyklus.
ngranularity: Jedes gefundene Beispiel deckt 4 Byte ab. Zeit: 1,00 Sekunden
angerufen/gesamt übergeordn. Verz.
Index %Zeit selbst Nachfolgende angerufen+selbst Name Index
angerufen/gesamt untergeordn.Verz.
6.6s <spontan>
[1] 21,0 0,21 0,00 .__is_wctype_sb [1]
-----------------------------------------------
6.6s <spontan>
[2] 11,0 0,11 0,00 .iscntrl [2]
-----------------------------------------------
6.6s <spontan>
[3] 8,0 0,08 0,00 ._XrmInternalStringToQuark [3]
-----------------------------------------------
6.6s <spontan>
[4] 3,0 0,03 0,00 .XtIsSubclass [4]
-----------------------------------------------
6.6s <spontan>
[5] 3,0 0,03 0,00 ._ptrgl [5]
-----------------------------------------------
6.6s <spontan>
[6] 3,0 0,03 0,00 .free_y [6]
-----------------------------------------------
6.6s <spontan>
[7] 3,0 0,03 0,00 .memchr [7]
-----------------------------------------------
6.6s <spontan>
[8] 2,0 0,02 0,00 .XtIsManaged [8]
-----------------------------------------------
6.6s <spontan>
[9] 2,0 0,02 0,00 ._XRead [9]
-----------------------------------------------
6.6s <spontan>
[10] 2,0 0,02 0,00 ._XWaitForReadable [10]
-----------------------------------------------
6.6s <spontan>
[11] 2,0 0,02 0,00 .__divu64 [11]
-----------------------------------------------
6.6s <spontan>
[12] 2,0 0,02 0,00 .malloc_y [12]
-----------------------------------------------
6.6s <spontan>
[13] 2,0 0,02 0,00 .read [13]
-----------------------------------------------
6.6s <spontan>
[14] 2,0 0,02 0,00 .strlen [14]
-----------------------------------------------
6.6s <spontan>
[15] 1,0 0,01 0,00 .CallSetValues [15]
-----------------------------------------------
6.6s <spontan>
[16] 1,0 0,01 0,00 .GetValues [16]
-----------------------------------------------
6.6s <spontan>
[17] 1,0 0,01 0,00 .GetValuesHook [17]
-----------------------------------------------
6.6s <spontan>
[18] 1,0 0,01 0,00 .GetValuesHook [18]
-----------------------------------------------
6.6s <spontan>
[19] 1,0 0,01 0,00 .ParseTable [19]
-----------------------------------------------
6.6s <spontan>
[20] 1,0 0,01 0,00 .SetValues [20]
-----------------------------------------------
6.6s <spontan>
[21] 1,0 0,01 0,00 .Ssavef28 [21]
-----------------------------------------------
6.6s <spontan>
[22] 1,0 0,01 0,00 .XClipBox.GL [22]
-----------------------------------------------
6.6s <spontan>
[23] 1,0 0,01 0,00 .XEventsQueued [23]
-----------------------------------------------
6.6s <spontan>
[24] 1,0 0,01 0,00 .XEventsQueued.GL [24]
-----------------------------------------------
6.6s <spontan>
[25] 1,0 0,01 0,00 .XGetWindowAttributes [25]
-----------------------------------------------
6.6s <spontan>
[26] 1,0 0,01 0,00 .XInternAtom.GL [26]
-----------------------------------------------
6.6s <spontan>
[27] 1,0 0,01 0,00 .XrmQuarkToString [27]
-----------------------------------------------
6.6s <spontan>
[28] 1,0 0,01 0,00 .XrmStringToQuarkList [28]
-----------------------------------------------
6.6s <spontan>
[29] 1,0 0,01 0,00 .XtDispatchEvent [29]
-----------------------------------------------
6.6s <spontan>
[30] 1,0 0,01 0,00 .XtScreenOfObject.GL [30]
-----------------------------------------------
6.6s <spontan>
[31] 1,0 0,01 0,00 .XtWindowOfObject [31]
-----------------------------------------------
6.6s <spontan>
[32] 1,0 0,01 0,00 ._Errno.GL [32]
-----------------------------------------------
6.6s <spontan>
[33] 1,0 0,01 0,00 ._X11TransBytesReadable [33]
-----------------------------------------------
6.6s <spontan>
[34] 1,0 0,01 0,00 ._XmStringNCreate [34]
-----------------------------------------------
6.6s <spontan>
[35] 1,0 0,01 0,00 ._XtCreateIndirectionTable [35]
-----------------------------------------------
6.6s <spontan>
[36] 1,0 0,01 0,00 ._XtGetPerDisplay [36]
-----------------------------------------------
6.6s <spontan>
[37] 1,0 0,01 0,00 ._XtGetSubresources [37]
-----------------------------------------------
6.6s <spontan>
[38] 1,0 0,01 0,00 .__ioctl [38]
-----------------------------------------------
6.6s <spontan>
[39] 1,0 0,01 0,00 ._doprnt [39]
-----------------------------------------------
6.6s <spontan>
[40] 1,0 0,01 0,00 .free_y_heap [40]
-----------------------------------------------
6.6s <spontan>
[41] 1,0 0,01 0,00 .gettimeofday [41]
-----------------------------------------------
6.6s <spontan>
[42] 1,0 0,01 0,00 .kread.GL [42]
-----------------------------------------------
6.6s <spontan>
[43] 1,0 0,01 0,00 .pre_ioctl [43]
-----------------------------------------------
6.6s <spontan>
[44] 1,0 0,01 0,00 .seekdir [44]
-----------------------------------------------
6.6s <spontan>
[45] 1,0 0,01 0,00 .strcmp [45]
-----------------------------------------------
6.6s <spontan>
[46] 1,0 0,01 0,00 .time_base_to_time [46]
-----------------------------------------------
6.6s <spontan>
[47] 1,0 0,01 0,00 .write [47]
-----------------------------------------------
6.6s <spontan>
[48] 1,0 0,01 0,00 .xtCreate [48]
-----------------------------------------------
unstrukturiertes (flat) Profil:
% Prozentsatz der gesamten Ausführungszeit des
Zeit Programm, das von dieser Funktion verwendet wird.
kumulieren der Anzahl von Sekunden einer Ausführungssumme
Sekunden für bei dieser Funktion und den oben aufgelisteten.
selbst Anzahl von Sekunden, die dafür festgehalten wurden
Sekunden Funktion alleine. Dies ist die Hauptsortierung für diese
Auflistung.
Aufrufe Häufigkeit, mit der diese Funktion aufgerufen wurde, wenn
diese Funktion im Profil ist, sonst blank.
selbst die durchschnittliche Zahl von Millisekunden, die mit dieser
ms/Aufruf Funktion pro Aufruf verbracht werden, wenn sich diese Funktion im
Profil befindet,
sonst blank.
gesamt die durchschnittliche Anzahl von Millisekunden, die mit dieser
ms/Aufruf Funktion und deren Untergeordneten pro Aufruf verbracht werden,
wenn diese
Funktion sich im Profil befindet, sonst blank.
Name der Name dieser Funtion. Dies ist die untergeordnete Sortierung
für diese Liste. Der Index zeigt die Position von
der Funktion in der gprof-Liste. Wenn der Index
in runden Klammern steht, wird angezeigt, wo sie sich befinden
sollte in der gprof-Liste, wenn sie gedruckt werden soll.
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]
0,1 0,32 0,11 .iscntrl [2]
0,1 0,40 0,08 ._XrmInternalStringToQuark [3]
0,0 0,43 0,03 .XtIsSubclass [4]
0,0 0,46 0,03 ._ptrgl [5]
0,0 0,49 0,03 .free_y [6]
0,0 0,52 0,03 .memchr [7]
0,0 0,54 0,02 .XtIsManaged [8]
0,0 0,56 0,02 ._XRead [9]
0,0 0,58 0,02 ._XWaitForReadable [10]
0,0 0,60 0,02 .__divu64 [11]
0,0 0,62 0,02 .malloc_y [12]
0,0 0,64 0,02 .read [13]
0,0 0,66 0,02 .strlen [14]
0,0 0,67 0,01 .CallSetValues [15]
0,0 0,68 0,01 .GetValues [16]
0,0 0,69 0,01 .GetValuesHook [17]
0,0 0,70 0,01 .GetValuesHook [18]
0,0 0,71 0,01 .ParseTable [19]
0,0 0,72 0,01 .SetValues [20]
0,0 0,73 0,01 .Ssavef28 [21]
0,0 0,74 0,01 .XClipBox.GL [22]
0,0 0,75 0,01 .XEventsQueued [23]
0,0 0,76 0,01 .XEventsQueued.GL [24]
0,0 0,77 0,01 .XGetWindowAttributes [25]
0,0 0,78 0,01 .XInternAtom.GL [26]
0,0 0,79 0,01 .XrmQuarkToString [27]
0,0 0,80 0,01 .XrmStringToQuarkList [28]
0,0 0,81 0,01 .XtDispatchEvent [29]
0,0 0,82 0,01 .XtScreenOfObject.GL [30]
0,0 0,83 0,01 .XtWindowOfObject [31]
0,0 0,84 0,01 ._Errno.GL [32]
0,0 0,85 0,01 ._X11TransBytesReadable [33]
0,0 0,86 0,01 ._XmStringNCreate [34]
0,0 0,87 0,01 ._XtCreateIndirectionTable [35]
0,0 0,88 0,01 ._XtGetPerDisplay [36]
0,0 0,89 0,01 ._XtGetSubresources [37]
0,0 0,90 0,01 .__ioctl [38]
0,0 0,91 0,01 ._doprnt [39]
0,0 0,92 0,01 .free_y_heap [40]
0,0 0,93 0,01 .gettimeofday [41]
0,0 0,94 0,01 .kread.GL [42]
0,0 0,95 0,01 .pre_ioctl [43]
0,0 0,96 0,01 .seekdir [44]
0,0 0,97 0,01 .strcmp [45]
0,0 0,98 0,01 .time_base_to_time [46]
0,0 0,99 0,01 .write [47]
0,0 1,00 0,01 .xtCreate [48]
Index nach Funktionsnamen sortiert
[15] .CallSetValues [4] .XtIsSubclass [5] ._ptrgl
[16] .GetValues [30] .XtScreenOfObject.G [6] .free_y
[18] .GetValuesHook [31] .XtWindowOfObject [40] .free_y_heap
[17] .GetValuesHook [32] ._Errno.GL [41] .gettimeofday
[19] .ParseTable [33] ._X11TransBytesRead [2] .iscntrl
[20] .SetValues [9] ._XRead [42] .kread.GL
[21] .Ssavef28 [10] ._XWaitForReadable [12] .malloc_y
[22] .XClipBox.GL [34] ._XmStringNCreate [7] .memchr
[23] .XEventsQueued [3] ._XrmInternalString [43] .pre_ioctl
[24] .XEventsQueued.GL [35] ._XtCreateIndirecti [13] .read
[25] .XGetWindowAttribut [36] ._XtGetPerDisplay [44] .seekdir
[26] .XInternAtom.GL [37] ._XtGetSubresources [45] .strcmp
[27] .XrmQuarkToString [11] .__divu64 [14] .strlen
[28] .XrmStringToQuarkLi [38] .__ioctl [46] .time_base_to_time
[29] .XtDispatchEvent [1] .__is_wctype_sb [47] .write
[8] .XtIsManaged [39] ._doprnt [48] .xtCreate
More information about the XEmacs-Beta
mailing list
