11:43 a.m.
Jan Rychter wrote:
>>>>>"Ben" == Ben Wing <ben(a)xemacs.org>
writes:
>>>>>
>>>>>
Ben> Hrvoje Niksic wrote:
>> Ben Wing <ben(a)xemacs.org> writes:
>>> Hrvoje, if you're willing to try some profiling in a current 21.5,
>> I don't have time for it now, and I'm reluctant to work on the 21.5
>> code base anyway, because of the reasons outlined earlier. I
>> started this thread to make other people aware of the problem.
>>
>> Creating a large nnml group shouldn't be hard. For example, enter
>> Gnus, press "n" when asked to go offline, then press "y"
when asked
>> whether to continue. You can create an empty nnml group using `G m
>> testgroup RET nnml RET'. Then enter an existing mbox using `G f
>> <file-name> RET' (don't mind if this is slow, it's supposed to
be
>> slow). Press `C-x h' to select the whole buffer, followed by `B c
>> nnml:tesgroup RET'. You should have a working nnml group with a
>> bunch of messages.
Ben> well, we all have limited time. if you ever change your mind, i'd
Ben> be glad for your help. in practice, profiling 21.5 is more useful
Ben> than
Ben> 21.4 since very little more work will be done on 21.4.
Is this what you were after? This is from a profile-key-sequence in
21.5b20 on Linux, no error checking, entering a large (2200 articles)
nnml group.
Function Name Ticks/Total %Usage Calls GC-Usage/ Total
===========================================/===== ====== ===== ========/=======
(in garbage collection) 4458/ 4458 51.247 156
(profile overhead) 1036/ 1036 11.909
(in map-extents-internal) 750/ 755 8.622 218120 1152928/1152928
looking-at 332/ 337 3.817 88212 3140404/3140404
bq-process-2 290/ 1978 3.334 887495 15788648/21176540
featurep 190/ 190 2.184 100986
re-search-forward 146/ 149 1.678 89140 1182416/1182416
kill-all-local-variables 145/ 145 1.667 5198
gnus-xmas-format 84/ 625 0.966 5200 187488/6891068
string-match 75/ 75 0.862 35722 594960/ 594960
kill-buffer 66/ 131 0.759 10726 257448/ 772296
gnus-user-format-function-b 61/ 5068 0.701 2598 328568/53798736
byte-code 47/ 957 0.540 21691 1676504/9915304
gnus-summary-prepare-threads 44/ 7513 0.506 1 441084/67178696
decode-coding-region 42/ 43 0.483 5217 626040/ 626040
gnus-simplify-subject-fuzzy 38/ 281 0.437 4892 96/ 915424
(in char-byte conversion) 38/ 38 0.437 2060174
get-buffer-create 38/ 41 0.437 21122 11500600/11500600
bbdb-records 36/ 684 0.414 7413 480/8779088
bq-process-1 36/ 49 0.414 317845 4991652/4991652
replace-match 34/ 35 0.391 21075 3152/ 3152
verify-visited-file-modtime 29/ 31 0.333 4817 238832/ 238832
mm-subst-char-in-string 26/ 25 0.299 10551 1080/ 1248
gnus-set-work-buffer 25/ 32 0.287 4893 0/ 28
#<compiled-function nil "...(157)" [gnus-tmp-replied gnus-tmp-unread
gnus-tmp-header gnus-tmp-lines need val gnus-user-format-function-b char-to-string
gnus-put-text-property gnus-xmas-format %s%s %s%s 4 gnus-correct-length 0 make-string ?\
nil eval gnus-summary-from-or-to-or-newsgroups 20 gnus-correct-substring %s: %s
int-to-string gnus-summary-number-of-articles-in-thread boundp thread 2
gnus-tmp-score-char gnus-tmp-indentation gnus-tmp-opening-bracket gnus-tmp-from
gnus-tmp-closing-bracket gnus-mouse-face-prop gnus-mouse-face gnus-tmp-level
gnus-tmp-subject-or-nil] 12>
24/ 7068 0.276 2598 227004/65137268
cond 23/ 693 0.264 38666 0/6209820
let 20/ 4313 0.230 25140 0/44675488
save-current-buffer 19/ 4274 0.218 10388 0/44145164
search-forward 18/ 30 0.207 28533
buffer-local-variables 18/ 32 0.207 7415 8544912/8544912
put-text-property 17/ 88 0.195 16803 1149592/1149592
forward-word 16/ 16 0.184 11488 1178892/1178892
setq 16/ 63 0.184 170408 0/ 450608
char-syntax 16/ 16 0.184 310 1528956/1528956
match-string 15/ 16 0.172 52795 589708/ 589708
#<compiled-function (&rest args) "...(28)" [result args reverse cons] 4
663101>
15/ 92 0.172 28659 3553764/4700124
insert-file-contents-internal 14/ 14 0.161 1 128/ 128
sort 14/ 31 0.161 636
char-width 13/ 246 0.149 95419
set-buffer 13/ 13 0.149 10388
subst-char-in-region 11/ 178 0.126 2 48/ 48
when 11/ 2196 0.126 67203 432/27534744
gnus-summary-number-of-articles-in-thread
11/ 11 0.126 3835 0/ 14844
erase-buffer 11/ 11 0.126 10103 0/ 84
#<compiled-function (char) "...(8)" [char length char-width] 3>
10/ 257 0.115 89938
generate-new-buffer-name 10/ 10 0.115 10724 17192/ 17192
while 10/ 4018 0.115 37675 0/43926860
if 9/ 2004 0.103 138500 0/22217668
bq-list* 9/ 483 0.103 28659 216/7168788
charset-property 8/ 8 0.092 95419
skip-chars-forward 8/ 8 0.092 44460
mapcar 7/ 279 0.080 23315 1200396/1249544
bq-comma 6/ 8 0.069 47765 573180/ 573180
#<compiled-function (buffer &rest body) "...(8)" [body buffer
save-current-buffer set-buffer] 3 696316>
6/ 11 0.069 10388 1433568/1433568
read 6/ 21 0.069 9452
vectorp 6/ 5 0.069 892167
insert-buffer-substring 6/ 7 0.069 3768 190284/ 190284
buffer-string 6/ 34 0.069 20434 0/ 963120
backquote 6/ 2539 0.069 12149 0/29294804
save-excursion 6/ 858 0.069 4372 0/5875944
append 5/ 5 0.057 11650 74592/ 74592
or 5/ 154 0.057 91182 0/ 938124
insert 5/ 5 0.057 5519 0/ 168
mail-decode-encoded-word-string 5/ 462 0.057 5206 11544/7426796
gnus-extract-address-components 5/ 43 0.057 2598 425820/ 879336
mm-decode-coding-string 5/ 359 0.057 5217 216/6885340
gnus-summary-highlight-line 5/ 61 0.057 2598 0/ 197564
reverse 5/ 6 0.057 29590 1182936/1182936
gnus-score-string< 5/ 5 0.057 40193
member* 4/ 7 0.046 10726 514848/ 514848
scan-sexps 4/ 4 0.046 3496 350064/ 350064
gnus-summary-limit-children 4/ 4 0.046 2602 31152/ 35016
buffer-substring 4/ 7 0.046 20434 963120/ 963120
condition-case 4/ 40 0.046 3497 0/ 350100
bbdb-buffer 3/ 3 0.034 7413
gnus-score-followup 3/ 42 0.034 1 31272/ 159072
prin1-to-string 3/ 3 0.034 1 59390/ 59390
list 3/ 6 0.034 69467 2469660/2469660
mm-decode-coding-region 3/ 4 0.034 340 40800/ 40800
#<subr when> 3/ 18 0.034 67203 6467640/6467640
progn 3/ 1886 0.034 49249 0/21574624
charset-width 3/ 20 0.034 95419
narrow-to-region 3/ 5 0.034 12224 96/ 96
select-buffer-killed-text 2/ 8 0.023 10726
intern 2/ 2 0.023 11039 120456/ 120456
and 2/ 189 0.023 172066 0/1344516
unless 2/ 25 0.023 5192 0/ 458364
eval 2/ 7073 0.023 10406 0/65145236
gnus-correct-substring 2/ 15 0.023 261 23920/ 23920
regexp-quote 2/ 2 0.023 3198 126352/ 126352
point-at-eol 2/ 3 0.023 5207
mail-extract-address-components 2/ 4315 0.023 2598 0/44675156
get-text-property 2/ 16 0.023 16267
gnus-score-string 2/ 17 0.023 1 31224/ 158524
assq 2/ 2 0.023 21566
eq 2/ 0 0.023 216156
gnus-put-text-property-excluding-characters-with-faces
2/ 38 0.023 2599 116/ 197640
next-single-property-change 2/ 9 0.023 3226
gnuserv-buffer-clients 2/ 2 0.023 10726
gnus-score-headers 2/ 61 0.023 1 124908/ 461004
char-charset 2/ 2 0.023 95419
set-text-properties 2/ 3 0.023 2598
get-buffer 2/ 2 0.023 4925
(in redisplay) 2/ 2 0.023 7 7188/ 8124
gnus-thread-sort-by-number 2/ 2 0.023 17889
downcase-region 2/ 2 0.023 2596
bq-process 2/ 2011 0.023 12149 24/21353504
gnus-correct-length 2/ 278 0.023 10395 0/1079256
with-current-buffer 2/ 4309 0.023 10388 24/44675156
fundamental-mode 2/ 147 0.023 5196 72/ 72
(in internal-external conversion) 2/ 2 0.023 4851
funcall 2/ 7071 0.023 2603 0/65143140
delete-other-windows 2/ 2 0.023 1 6912/ 6912
goto-char 2/ 3 0.023 52737
select-buffer-killed-default 2/ 5 0.023 10726
natnump 2/ 3 0.023 40868
syntax-string-to-code 1/ 1 0.011 594 0/ 42768
mail-extr-safe-move-sexp 1/ 43 0.011 3496 0/ 350064
eobp 1/ 1 0.011 35836
gnus-inverse-list-range-intersection 1/ 1 0.011 1
copy-sequence 1/ 1 0.011 1735 66576/ 66576
put-char-table 1/ 1 0.011 594
gnus-list-of-unread-articles 1/ 1 0.011 2 53400/ 53400
gnus-thread-loop-p 1/ 1 0.011 322 9036/ 9036
delq 1/ 1 0.011 9573
quote 1/ 1 0.011 208182
#<compiled-function nil "...(166)" [gnus-dormant-mark uncached default-low
default-high score mark gnus-summary-cancelled gnus-summary-high-undownloaded
gnus-summary-low-undownloaded gnus-summary-normal-undownloaded gnus-summary-high-ticked
gnus-summary-low-ticked gnus-summary-normal-ticked gnus-summary-high-ancient
gnus-summary-low-ancient gnus-summary-normal-ancient gnus-summary-high-unread
gnus-summary-low-unread gnus-summary-normal-unread gnus-summary-high-read
gnus-summary-low-read gnus-summary-normal-read gnus-ticked-mark gnus-ancient-mark
gnus-unread-mark gnus-canceled-mark] 2>
1/ 1 0.011 2598
gnus-summary-from-or-to-or-newsgroups 1/ 48 0.011 2598 76/ 965208
gnus-sorted-nunion 1/ 1 0.011 1 26712/ 26712
not 1/ 1 0.011 57611
browse-url-delete-temp-file 1/ 1 0.011 10726
bbdb-record-name 1/ 1 0.011 1570
check-menu-syntax 1/ 4 0.011 634 0/ 256
mail-extr-skip-whitespace-forward 1/ 13 0.011 38978
make-string 1/ 2 0.011 7171 179848/ 179848
gnus-remove-from-range 1/ 9 0.011 2 0/ 83016
nnheader-nov-delete-outside-range 1/ 4 0.011 1
cons 1/ 2 0.011 76702 920424/ 920424
bbdb-record-getprop 1/ 1 0.011 1784
make-vector 1/ 1 0.011 3 21552/ 21552
gnus-update-read-articles 1/ 10 0.011 1 41856/ 125048
char-to-string 1/ 2 0.011 13586 326064/ 326064
run-hooks 1/ 67 0.011 2609 0/ 231500
rfc2047-decode-encoded-words 1/ 65 0.011 171 12964/ 504656
delete-region 1/ 1 0.011 632
coding-system-property 1/ 1 0.011 576 59696/ 59696
quoted-printable-decode-region 1/ 1 0.011 137 4560/ 4600
point-max 1/ 1 0.011 18830
>= 1/ 1 0.011 27504
> 1/ 1 0.011 22181
>
>
fume-narrow-to-region 1/ 1 0.011 12224
widen 1/ 2 0.011 7796 48/ 48
gnus-run-hooks 1/ 64 0.011 2607 31296/ 256676
[... rest snipped ...]
Let me know if you want the full profile, or one from a recent CVS
build.
yuck. there is a *fantastic* amount of garbage being generated. 65 MB
for 2200 messages! (how big is the file itself?)
things to try:
[1] silly question -- did you build with optimization (configure
--with-optimization)? you should.
[2] make sure you do all your tests with `xemacs --vanilla' (see
comments below).
[1] use latest cvs if it's not too hard.
[2] first do a build with and without `with-kkcc=no'/`with-mc-alloc=no'
to see if the new garbage collector and allocator are making things
worse, and if so by how much.
[3] then, increase gc-cons-threshold to at least 2000000, if not higher,
and redo the profiling. (it was recently raised to 2000000)
anyway, clearly mule is *not* at fault here; look at the small amount of
time going to `(in char-byte conversion)' and `(in internal-external
conversion)'.
-------------------
[btw: following is a version of jan's profile, resorted to show maximum
gc uage in each function. (the left figure shows allocation in this
profile unit only, while the right shows allocation in this and all
children profile units. a "profile unit" is more or less a lisp
function, but can be smaller in some cases and includes many of the
native subsystems that potentially take lots of time.)]
but just look at the amount of cumulative time spent in backquote
processing (Chief Offender), and the 29 megs of crap generated! this
should *really* happen at compile time, so something is majorly wrong
here. Jan, are parts of GNUS somehow uncompiled or out-of-date (in
which case the interpreted versions will be used instead)? Do you have
some personal code you stick into certain hooks that is uncompiled and
uses backquotes?
If not either of these, I can only assume that GNUS itself is doing
something horrendous with backquotes that results in run-time expansion;
and it probably isn't doing the same under GNU Emacs.
Offender #2 is get-buffer-create, called 21122 times for 2200 articles,
and mostly (it seems) actually creating a buffer.
this seems an awful lot of buffer creation. if this still appears after
Jan runs --vanilla, could someone help track down what's happening?
Same for buffer-local-variables'. #<subr when> is once again a case of
a macro not getting compiled correctly. bq-process-1 is part of the
backquote mechanism, like bq-process-2; after that, i'm not really
sure. i need to put back the compiled-fun annotation "hack" that steve
baur (?) didn't like but which is great for these cases.
after this, `looking-at' should probably not be generating lisp objects.
`list' does it as part of its job, and so does the byte-compiler in
certain cases.
map_extents() is also highly suspicious, as it shouldn't really be
allocating.
Function Name Ticks/Total %Usage Calls GC-Usage/ Total
===========================================/===== ====== ===== ========/=======
bq-process-2 290/ 1978 3.334 887495 15788648/21176540
get-buffer-create 38/ 41 0.437 21122 11500600/11500600
buffer-local-variables 18/ 32 0.207 7415 8544912/8544912
#<subr when> 3/ 18 0.034 67203 6467640/6467640
bq-process-1 36/ 49 0.414 317845 4991652/4991652
#<compiled-function (&rest args) "...(28)" [result args reverse cons] 4
663101> 15/ 92 0.172 28659
3553764/4700124
looking-at 332/ 337 3.817 88212 3140404/3140404
list 3/ 6 0.034 69467 2469660/2469660
byte-code 47/ 957 0.540 21691 1676504/9915304
char-syntax 16/ 16 0.184 310 1528956/1528956
#<compiled-function (buffer &rest body) "...(8)" [body buffer
save-current-buffer set-buffer] 3 696316> 6/
11 0.069 10388 1433568/1433568
mapcar 7/ 279 0.080 23315 1200396/1249544
reverse 5/ 6 0.057 29590 1182936/1182936
re-search-forward 146/ 149 1.678 89140 1182416/1182416
forward-word 16/ 16 0.184 11488 1178892/1178892
(in map-extents-internal) 750/ 755 8.622 218120 1152928/1152928
put-text-property 17/ 88 0.195 16803 1149592/1149592
buffer-substring 4/ 7 0.046 20434 963120/ 963120
cons 1/ 2 0.011 76702 920424/ 920424
decode-coding-region 42/ 43 0.483 5217 626040/ 626040
string-match 75/ 75 0.862 35722 594960/ 594960
match-string 15/ 16 0.172 52795 589708/ 589708
bq-comma 6/ 8 0.069 47765 573180/ 573180
member* 4/ 7 0.046 10726 514848/ 514848
gnus-summary-prepare-threads 44/ 7513 0.506 1 441084/67178696
gnus-extract-address-components 5/ 43 0.057 2598 425820/ 879336
scan-sexps 4/ 4 0.046 3496 350064/ 350064
gnus-user-format-function-b 61/ 5068 0.701 2598 328568/53798736
char-to-string 1/ 2 0.011 13586 326064/ 326064
kill-buffer 66/ 131 0.759 10726 257448/ 772296
verify-visited-file-modtime 29/ 31 0.333 4817 238832/ 238832