* slow output in *compilation* buffer
@ 2009-08-22 8:23 Dan Nicolaescu
2009-08-23 1:28 ` Stefan Monnier
0 siblings, 1 reply; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-22 8:23 UTC (permalink / raw)
To: emacs-devel
Running a compilation job the produces a lot of text output with M-x
compile is much slower than running it in a shell.
For example
With emacs/lisp as the current directory, doing
M-x compile RET grep -nH -e emacs *.el */*.el RET
takes 25 seconds
The output is 4500 lines
Running the same command in an xterm takes 1.5 seconds!
gprof data:
% cumulative self self total
time seconds seconds calls s/call s/call name
31.19 2.72 2.72 52618323 0.00 0.00 lookup_char_property
20.30 4.49 1.77 51726150 0.00 0.00 previous_interval
12.16 5.55 1.06 208889310 0.00 0.00 Fcdr
5.85 6.06 0.51 52444384 0.00 0.00 Fassq
5.39 6.53 0.47 4573 0.00 0.00 Fprevious_single_property_change
2.64 6.76 0.23 8860105 0.00 0.00 mark_object
2.52 6.98 0.22 10621 0.00 0.00 Fsetcar
2.29 7.18 0.20 52618300 0.00 0.00 textget
1.83 7.34 0.16 59828 0.00 0.00 re_search_2
1.72 7.49 0.15 305181 0.00 0.00 re_match_2_internal
1.03 7.58 0.09 82087 0.00 0.00 Fbyte_code
0.80 7.65 0.07 9094 0.00 0.00 adjust_for_invis_intang
0.80 7.72 0.07 581767 0.00 0.00 find_interval
0.69 7.78 0.06 295253 0.00 0.00 next_interval
0.69 7.84 0.06 21 0.00 0.02 Fgarbage_collect
0.57 7.89 0.05 23886 0.00 0.00 mark_vectorlike
Observations:
- there's a lot of garbage collection going on
- Fprevious_single_property_change is probably mostly called from
compilation-error-properties
Doing
M-x (setq compilation-error-regexp-alist nil) RET
then
M-x compile RET grep -nH -e emacs *.el */*.el RET
takes 3 seconds.
So it seems that fontification (and things related to it) are very very expensive.
Can someone familiar with the code in question take a look and figure
out how to optimize this?
Thanks
--dan
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-22 8:23 slow output in *compilation* buffer Dan Nicolaescu
@ 2009-08-23 1:28 ` Stefan Monnier
2009-08-23 6:27 ` Dan Nicolaescu
2009-08-24 18:52 ` Dan Nicolaescu
0 siblings, 2 replies; 11+ messages in thread
From: Stefan Monnier @ 2009-08-23 1:28 UTC (permalink / raw)
To: Dan Nicolaescu; +Cc: emacs-devel
> % cumulative self self total
> time seconds seconds calls s/call s/call name
> 31.19 2.72 2.72 52618323 0.00 0.00 lookup_char_property
> 20.30 4.49 1.77 51726150 0.00 0.00 previous_interval
> 12.16 5.55 1.06 208889310 0.00 0.00 Fcdr
> 5.85 6.06 0.51 52444384 0.00 0.00 Fassq
> 5.39 6.53 0.47 4573 0.00 0.00 Fprevious_single_property_change
> 2.64 6.76 0.23 8860105 0.00 0.00 mark_object
> 2.52 6.98 0.22 10621 0.00 0.00 Fsetcar
> 2.29 7.18 0.20 52618300 0.00 0.00 textget
> 1.83 7.34 0.16 59828 0.00 0.00 re_search_2
> 1.72 7.49 0.15 305181 0.00 0.00 re_match_2_internal
> 1.03 7.58 0.09 82087 0.00 0.00 Fbyte_code
> 0.80 7.65 0.07 9094 0.00 0.00 adjust_for_invis_intang
> 0.80 7.72 0.07 581767 0.00 0.00 find_interval
> 0.69 7.78 0.06 295253 0.00 0.00 next_interval
> 0.69 7.84 0.06 21 0.00 0.02 Fgarbage_collect
> 0.57 7.89 0.05 23886 0.00 0.00 mark_vectorlike
- not sure why it's GCing that much, but it sounds like something that
can be improved.
- the re_* part of the profile is hard to improve with a quick fix,
I think: it just represents regexp-searching every one of the regexps
in compilation-error-regexp-alist in turn. Of course, there is a way
to do that (a lot) faster, by compiling all those regexps into a DFA.
- why does the gprof data only seem to account for a bit less than 10s
when you say it takes 25s to complete?
- It seems that they the calls to the interval code come from
compilation-error-properties, but that function should only be called
for regexps that do match, which shouldn't be that many. Can you look
at the text to see if there really are that many matches? BTW, we
should probably be able to make compile.el a bit lazier (i.e. the
font-lock-phase part of the code should do a bit less work by moving
it to the next-error-phase code).
Another thing: the compilation code currently uses font-lock-keywords,
but it should probably be changed to use font-lock-syntactic-keywords
instead (which should make it unnecessary to disable jit-lock).
> So it seems that fontification (and things related to it) are very very expensive.
compile.el does its work via font-lock, so I do expect most/all of the
time to be spent there.
Stefan
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-23 1:28 ` Stefan Monnier
@ 2009-08-23 6:27 ` Dan Nicolaescu
2009-08-25 17:21 ` Stefan Monnier
2009-08-24 18:52 ` Dan Nicolaescu
1 sibling, 1 reply; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-23 6:27 UTC (permalink / raw)
To: Stefan Monnier; +Cc: emacs-devel
Stefan Monnier <monnier@iro.umontreal.ca> writes:
> > % cumulative self self total
> > time seconds seconds calls s/call s/call name
> > 31.19 2.72 2.72 52618323 0.00 0.00 lookup_char_property
> > 20.30 4.49 1.77 51726150 0.00 0.00 previous_interval
> > 12.16 5.55 1.06 208889310 0.00 0.00 Fcdr
> > 5.85 6.06 0.51 52444384 0.00 0.00 Fassq
> > 5.39 6.53 0.47 4573 0.00 0.00 Fprevious_single_property_change
> > 2.64 6.76 0.23 8860105 0.00 0.00 mark_object
> > 2.52 6.98 0.22 10621 0.00 0.00 Fsetcar
> > 2.29 7.18 0.20 52618300 0.00 0.00 textget
> > 1.83 7.34 0.16 59828 0.00 0.00 re_search_2
> > 1.72 7.49 0.15 305181 0.00 0.00 re_match_2_internal
> > 1.03 7.58 0.09 82087 0.00 0.00 Fbyte_code
> > 0.80 7.65 0.07 9094 0.00 0.00 adjust_for_invis_intang
> > 0.80 7.72 0.07 581767 0.00 0.00 find_interval
> > 0.69 7.78 0.06 295253 0.00 0.00 next_interval
> > 0.69 7.84 0.06 21 0.00 0.02 Fgarbage_collect
> > 0.57 7.89 0.05 23886 0.00 0.00 mark_vectorlike
>
> - not sure why it's GCing that much, but it sounds like something that
> can be improved.
> - the re_* part of the profile is hard to improve with a quick fix,
> I think: it just represents regexp-searching every one of the regexps
> in compilation-error-regexp-alist in turn. Of course, there is a way
> to do that (a lot) faster, by compiling all those regexps into a DFA.
That sounds like a good idea, but it does not look like it will have a
huge impact?
> - why does the gprof data only seem to account for a bit less than 10s
> when you say it takes 25s to complete?
Don't know. I double checked and it's consistent. Maybe oprofile can
reveal more, I might try that too when I get a chance if nobody beats
me to it.
> - It seems that they the calls to the interval code come from
> compilation-error-properties, but that function should only be called
> for regexps that do match, which shouldn't be that many. Can you look
> at the text to see if there really are that many matches? BTW, we
> should probably be able to make compile.el a bit lazier (i.e. the
> font-lock-phase part of the code should do a bit less work by moving
> it to the next-error-phase code).
The output is about 4500 lines, they all match.
BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
> Another thing: the compilation code currently uses font-lock-keywords,
> but it should probably be changed to use font-lock-syntactic-keywords
> instead (which should make it unnecessary to disable jit-lock).
>
> > So it seems that fontification (and things related to it) are very very expensive.
>
> compile.el does its work via font-lock, so I do expect most/all of the
> time to be spent there.
They time spent there seems a bit excessive, so maybe something strange
is going on...
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-23 1:28 ` Stefan Monnier
2009-08-23 6:27 ` Dan Nicolaescu
@ 2009-08-24 18:52 ` Dan Nicolaescu
2009-08-24 19:13 ` Chong Yidong
2009-08-24 20:24 ` Dan Nicolaescu
1 sibling, 2 replies; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-24 18:52 UTC (permalink / raw)
To: Stefan Monnier; +Cc: emacs-devel
Stefan Monnier <monnier@iro.umontreal.ca> writes:
> > % cumulative self self total
> > time seconds seconds calls s/call s/call name
> > 31.19 2.72 2.72 52618323 0.00 0.00 lookup_char_property
> > 20.30 4.49 1.77 51726150 0.00 0.00 previous_interval
> > 12.16 5.55 1.06 208889310 0.00 0.00 Fcdr
> > 5.85 6.06 0.51 52444384 0.00 0.00 Fassq
> > 5.39 6.53 0.47 4573 0.00 0.00 Fprevious_single_property_change
> > 2.64 6.76 0.23 8860105 0.00 0.00 mark_object
> > 2.52 6.98 0.22 10621 0.00 0.00 Fsetcar
> > 2.29 7.18 0.20 52618300 0.00 0.00 textget
> > 1.83 7.34 0.16 59828 0.00 0.00 re_search_2
> > 1.72 7.49 0.15 305181 0.00 0.00 re_match_2_internal
> > 1.03 7.58 0.09 82087 0.00 0.00 Fbyte_code
> > 0.80 7.65 0.07 9094 0.00 0.00 adjust_for_invis_intang
> > 0.80 7.72 0.07 581767 0.00 0.00 find_interval
> > 0.69 7.78 0.06 295253 0.00 0.00 next_interval
> > 0.69 7.84 0.06 21 0.00 0.02 Fgarbage_collect
> > 0.57 7.89 0.05 23886 0.00 0.00 mark_vectorlike
>
> compile.el does its work via font-lock, so I do expect most/all of the
> time to be spent there.
Another data point, take the process output out of the equation:
grep -nH -e emacs *.el */*.el > /tmp/t.grep
emacs -Q /tmp/t.grep
M-x compilation-mode RET
M-x font-lock-fontify-buffer RET [this might not be necessary]
% cumulative self self total
time seconds seconds calls s/call s/call name
35.13 5.54 5.54 102003560 0.00 0.00 lookup_char_property
22.45 9.08 3.54 101705026 0.00 0.00 previous_interval
13.57 11.22 2.14 408455379 0.00 0.00 Fcdr
6.59 12.26 1.04 9018 0.00 0.00 Fprevious_single_property_change
5.83 13.18 0.92 101946549 0.00 0.00 Fassq
2.98 13.65 0.47 18460 0.00 0.00 Fsetcar
1.71 13.92 0.27 9370435 0.00 0.00 mark_object
1.59 14.17 0.25 102003522 0.00 0.00 textget
1.46 14.40 0.23 54635 0.00 0.00 re_search_2
1.14 14.58 0.18 134737 0.00 0.00 Fbyte_code
0.95 14.73 0.15 adjust_for_invis_intang
0.95 14.88 0.15 525629 0.00 0.00 re_match_2_internal
0.82 15.01 0.13 262725 0.00 0.00 next_interval
0.63 15.11 0.10 2698 0.00 0.00 Frassq
0.44 15.18 0.07 22 0.00 0.02 Fgarbage_collect
0.32 15.23 0.05 541671 0.00 0.00 Ffuncall
0.32 15.28 0.05 22906 0.00 0.00 mark_vectorlike
0.19 15.31 0.03 584428 0.00 0.00 balance_an_interval
0.13 15.33 0.02 2333591 0.00 0.00 multibyte_char_to_unibyte_safe
0.13 15.35 0.02 315105 0.00 0.00 find_interval
0.13 15.37 0.02 133764 0.00 0.00 funcall_lambda
0.13 15.39 0.02 91236 0.00 0.00 add_properties
0.13 15.41 0.02 18261 0.00 0.00 set_point_both
0.13 15.43 0.02 9448 0.00 0.00 balance_intervals_internal
0.13 15.45 0.02 5316 0.00 0.00 set_buffer_internal_1
0.13 15.47 0.02 92 0.00 0.00 mark_glyph_matrix
0.13 15.49 0.02 Fmemory_limit
0.06 15.50 0.01 1006998 0.00 0.00 specbind
0.06 15.51 0.01 718455 0.00 0.00 Fcons
0.06 15.52 0.01 621053 0.00 0.00 Faref
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-24 18:52 ` Dan Nicolaescu
@ 2009-08-24 19:13 ` Chong Yidong
2009-08-24 19:36 ` Dan Nicolaescu
2009-08-24 20:24 ` Dan Nicolaescu
1 sibling, 1 reply; 11+ messages in thread
From: Chong Yidong @ 2009-08-24 19:13 UTC (permalink / raw)
To: Dan Nicolaescu; +Cc: Stefan Monnier, emacs-devel
Dan Nicolaescu <dann@ics.uci.edu> writes:
> Another data point, take the process output out of the equation:
> grep -nH -e emacs *.el */*.el > /tmp/t.grep
>
> emacs -Q /tmp/t.grep
> M-x compilation-mode RET
> M-x font-lock-fontify-buffer RET [this might not be necessary]
Could you also try with the Emacs 22 version of
compilation-error-regexp-alist-alist?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-24 19:13 ` Chong Yidong
@ 2009-08-24 19:36 ` Dan Nicolaescu
0 siblings, 0 replies; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-24 19:36 UTC (permalink / raw)
To: Chong Yidong; +Cc: Stefan Monnier, emacs-devel
Chong Yidong <cyd@stupidchicken.com> writes:
> Dan Nicolaescu <dann@ics.uci.edu> writes:
>
> > Another data point, take the process output out of the equation:
> > grep -nH -e emacs *.el */*.el > /tmp/t.grep
> >
> > emacs -Q /tmp/t.grep
> > M-x compilation-mode RET
> > M-x font-lock-fontify-buffer RET [this might not be necessary]
>
> Could you also try with the Emacs 22 version of
> compilation-error-regexp-alist-alist?
It was easier to just try with emacs 22's version of compile.elc:
time seconds seconds calls s/call s/call name
36.30 5.96 5.96 101988546 0.00 0.00 lookup_char_property
20.46 9.32 3.36 101705047 0.00 0.00 previous_interval
16.69 12.06 2.74 408403635 0.00 0.00 Fcdr
6.03 13.05 0.99 101936877 0.00 0.00 Fassq
4.57 13.80 0.75 9018 0.00 0.00 Fprevious_single_property_change
3.47 14.37 0.57 18432 0.00 0.00 Fsetcar
1.52 14.62 0.25 8893438 0.00 0.00 mark_object
1.46 14.86 0.24 1393971 0.00 0.00 re_match_2_internal
1.16 15.05 0.19 2 0.10 0.10 adjust_for_invis_intang
1.10 15.23 0.18 134046 0.00 0.00 Fbyte_code
0.97 15.39 0.16 101988546 0.00 0.00 textget
0.97 15.55 0.16 51481 0.00 0.00 re_search_2
0.73 15.67 0.12 2686 0.00 0.00 Frassq
0.37 15.73 0.06 259939 0.00 0.00 next_interval
0.37 15.79 0.06 21 0.00 0.02 Fgarbage_collect
0.30 15.84 0.05 19575 0.00 0.00 mark_vectorlike
0.24 15.88 0.04 501674 0.00 0.00 unbind_to
0.18 15.91 0.03 1046758 0.00 0.00 specbind
0.18 15.94 0.03 307777 0.00 0.00 find_interval
0.18 15.97 0.03 11545 0.00 0.00 Flocal_variable_p
0.12 15.99 0.02 618496 0.00 0.00 Faref
0.12 16.01 0.02 539810 0.00 0.00 Ffuncall
0.12 16.03 0.02 116540 0.00 0.00 Fstring_equal
0.12 16.05 0.02 64204 0.00 0.00 Fadd_text_properties
0.12 16.07 0.02 63142 0.00 0.00 internal_equal
0.12 16.09 0.02 28438 0.00 0.00 set_internal
0.12 16.11 0.02 21596 0.00 0.00 re_compile_pattern
0.06 16.12 0.01 612304 0.00 0.00 Fcar
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-24 18:52 ` Dan Nicolaescu
2009-08-24 19:13 ` Chong Yidong
@ 2009-08-24 20:24 ` Dan Nicolaescu
1 sibling, 0 replies; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-24 20:24 UTC (permalink / raw)
To: Stefan Monnier; +Cc: emacs-devel
Dan Nicolaescu <dann@ics.uci.edu> writes:
> Stefan Monnier <monnier@iro.umontreal.ca> writes:
>
> > > % cumulative self self total
> > > time seconds seconds calls s/call s/call name
> > > 31.19 2.72 2.72 52618323 0.00 0.00 lookup_char_property
> > > 20.30 4.49 1.77 51726150 0.00 0.00 previous_interval
> > > 12.16 5.55 1.06 208889310 0.00 0.00 Fcdr
> > > 5.85 6.06 0.51 52444384 0.00 0.00 Fassq
> > > 5.39 6.53 0.47 4573 0.00 0.00 Fprevious_single_property_change
> > > 2.64 6.76 0.23 8860105 0.00 0.00 mark_object
> > > 2.52 6.98 0.22 10621 0.00 0.00 Fsetcar
> > > 2.29 7.18 0.20 52618300 0.00 0.00 textget
> > > 1.83 7.34 0.16 59828 0.00 0.00 re_search_2
> > > 1.72 7.49 0.15 305181 0.00 0.00 re_match_2_internal
> > > 1.03 7.58 0.09 82087 0.00 0.00 Fbyte_code
> > > 0.80 7.65 0.07 9094 0.00 0.00 adjust_for_invis_intang
> > > 0.80 7.72 0.07 581767 0.00 0.00 find_interval
> > > 0.69 7.78 0.06 295253 0.00 0.00 next_interval
> > > 0.69 7.84 0.06 21 0.00 0.02 Fgarbage_collect
> > > 0.57 7.89 0.05 23886 0.00 0.00 mark_vectorlike
> >
> > compile.el does its work via font-lock, so I do expect most/all of the
> > time to be spent there.
>
> Another data point, take the process output out of the equation:
> grep -nH -e emacs *.el */*.el > /tmp/t.grep
>
> emacs -Q /tmp/t.grep
> M-x compilation-mode RET
> M-x font-lock-fontify-buffer RET [this might not be necessary]
>
>
> % cumulative self self total
> time seconds seconds calls s/call s/call name
> 35.13 5.54 5.54 102003560 0.00 0.00 lookup_char_property
> 22.45 9.08 3.54 101705026 0.00 0.00 previous_interval
> 13.57 11.22 2.14 408455379 0.00 0.00 Fcdr
> 6.59 12.26 1.04 9018 0.00 0.00 Fprevious_single_property_change
> 5.83 13.18 0.92 101946549 0.00 0.00 Fassq
> 2.98 13.65 0.47 18460 0.00 0.00 Fsetcar
> 1.71 13.92 0.27 9370435 0.00 0.00 mark_object
> 1.59 14.17 0.25 102003522 0.00 0.00 textget
> 1.46 14.40 0.23 54635 0.00 0.00 re_search_2
> 1.14 14.58 0.18 134737 0.00 0.00 Fbyte_code
> 0.95 14.73 0.15 adjust_for_invis_intang
> 0.95 14.88 0.15 525629 0.00 0.00 re_match_2_internal
> 0.82 15.01 0.13 262725 0.00 0.00 next_interval
> 0.63 15.11 0.10 2698 0.00 0.00 Frassq
> 0.44 15.18 0.07 22 0.00 0.02 Fgarbage_collect
> 0.32 15.23 0.05 541671 0.00 0.00 Ffuncall
> 0.32 15.28 0.05 22906 0.00 0.00 mark_vectorlike
> 0.19 15.31 0.03 584428 0.00 0.00 balance_an_interval
> 0.13 15.33 0.02 2333591 0.00 0.00 multibyte_char_to_unibyte_safe
> 0.13 15.35 0.02 315105 0.00 0.00 find_interval
> 0.13 15.37 0.02 133764 0.00 0.00 funcall_lambda
> 0.13 15.39 0.02 91236 0.00 0.00 add_properties
> 0.13 15.41 0.02 18261 0.00 0.00 set_point_both
> 0.13 15.43 0.02 9448 0.00 0.00 balance_intervals_internal
> 0.13 15.45 0.02 5316 0.00 0.00 set_buffer_internal_1
> 0.13 15.47 0.02 92 0.00 0.00 mark_glyph_matrix
> 0.13 15.49 0.02 Fmemory_limit
> 0.06 15.50 0.01 1006998 0.00 0.00 specbind
> 0.06 15.51 0.01 718455 0.00 0.00 Fcons
> 0.06 15.52 0.01 621053 0.00 0.00 Faref
And another data point and some explanation.
Using -Q -nw instead of just -Q:
% cumulative self self total
time seconds seconds calls s/call s/call name
34.58 5.19 5.19 101981134 0.00 0.00 lookup_char_property
21.19 8.37 3.18 101705010 0.00 0.00 previous_interval
13.06 10.33 1.96 408395117 0.00 0.00 Fcdr
6.73 11.34 1.01 9018 0.00 0.00 Fprevious_single_property_change
6.73 12.35 1.01 101923589 0.00 0.00 Fassq
3.06 12.81 0.46 18459 0.00 0.00 Fsetcar
1.93 13.10 0.29 514797 0.00 0.00 re_match_2_internal
1.73 13.36 0.26 5072134 0.00 0.00 mark_object
1.60 13.60 0.24 31816 0.00 0.00 re_search_2
1.27 13.79 0.19 133095 0.00 0.00 Fbyte_code
1.20 13.97 0.18 256789 0.00 0.00 next_interval
1.07 14.13 0.16 2555 0.00 0.00 Frassq
1.07 14.29 0.16 adjust_for_invis_intang
1.00 14.44 0.15 101981134 0.00 0.00 textget
0.40 14.50 0.06 300850 0.00 0.00 find_interval
0.40 14.56 0.06 19 0.00 0.02 Fgarbage_collect
0.27 14.60 0.04 132114 0.00 0.00 funcall_lambda
so roughly 40% less mark_object calls.
Why?
Although I use LANG=C, when using the X11 version (with this font:
-b&h-lucidatypewriter-medium-r-normal-sans-12-120-75-75-m-70-iso8859-1)
these charsets are read during startup:
emacs/etc/charsets/MULE-tibetan.map
emacs/etc/charsets/MULE-ethiopic.map
emacs/etc/charsets/MULE-ipa.map
emacs/etc/charsets/symbol.map
emacs/etc/charsets/JISX0208.map
emacs/etc/charsets/GB2312.map
emacs/etc/charsets/BIG5.map
emacs/etc/charsets/CNS-1.map
emacs/etc/charsets/KSC5601.map
and it seems that creates a lot of lisp objects.
Is it necessary to read all these charsets?
Creating that many lisp objects has second order effects on GC speed,
and cache performance.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-23 6:27 ` Dan Nicolaescu
@ 2009-08-25 17:21 ` Stefan Monnier
2009-08-25 21:37 ` David Kastrup
2009-08-26 7:33 ` Dan Nicolaescu
0 siblings, 2 replies; 11+ messages in thread
From: Stefan Monnier @ 2009-08-25 17:21 UTC (permalink / raw)
To: Dan Nicolaescu; +Cc: emacs-devel
>> - the re_* part of the profile is hard to improve with a quick fix,
>> I think: it just represents regexp-searching every one of the regexps
>> in compilation-error-regexp-alist in turn. Of course, there is a way
>> to do that (a lot) faster, by compiling all those regexps into a DFA.
> That sounds like a good idea, but it does not look like it will have a
> huge impact?
No, indeed, luckily.
>> - why does the gprof data only seem to account for a bit less than 10s
>> when you say it takes 25s to complete?
> Don't know. I double checked and it's consistent. Maybe oprofile can
> reveal more, I might try that too when I get a chance if nobody beats
> me to it.
Maybe it's just the user-time vs system-time.
>> - It seems that they the calls to the interval code come from
>> compilation-error-properties, but that function should only be called
>> for regexps that do match, which shouldn't be that many. Can you look
>> at the text to see if there really are that many matches? BTW, we
>> should probably be able to make compile.el a bit lazier (i.e. the
>> font-lock-phase part of the code should do a bit less work by moving
>> it to the next-error-phase code).
> The output is about 4500 lines, they all match.
Ah, I see. So yes, the likely solution is to make compile.el lazier:
use font-lock-syntactic-keywords and jit-lock (so the text past the end
of the window doesn't need to be scanned right away), and postpone more
of the work to next-error.
> BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
That sucks. What does rgrep do so differently to make it even worse?
> They time spent there seems a bit excessive, so maybe something strange
> is going on...
That's also possible.
Stefan
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-25 17:21 ` Stefan Monnier
@ 2009-08-25 21:37 ` David Kastrup
2009-08-26 7:33 ` Dan Nicolaescu
1 sibling, 0 replies; 11+ messages in thread
From: David Kastrup @ 2009-08-25 21:37 UTC (permalink / raw)
To: emacs-devel
Stefan Monnier <monnier@IRO.UMontreal.CA> writes:
>>> - the re_* part of the profile is hard to improve with a quick fix,
>>> I think: it just represents regexp-searching every one of the regexps
>>> in compilation-error-regexp-alist in turn. Of course, there is a way
>>> to do that (a lot) faster, by compiling all those regexps into a DFA.
>> That sounds like a good idea, but it does not look like it will have a
>> huge impact?
>
> No, indeed, luckily.
>
>>> - why does the gprof data only seem to account for a bit less than 10s
>>> when you say it takes 25s to complete?
>> Don't know. I double checked and it's consistent. Maybe oprofile can
>> reveal more, I might try that too when I get a chance if nobody beats
>> me to it.
>
> Maybe it's just the user-time vs system-time.
>
>>> - It seems that they the calls to the interval code come from
>>> compilation-error-properties, but that function should only be called
>>> for regexps that do match, which shouldn't be that many. Can you look
>>> at the text to see if there really are that many matches? BTW, we
>>> should probably be able to make compile.el a bit lazier (i.e. the
>>> font-lock-phase part of the code should do a bit less work by moving
>>> it to the next-error-phase code).
>> The output is about 4500 lines, they all match.
>
> Ah, I see. So yes, the likely solution is to make compile.el lazier:
> use font-lock-syntactic-keywords and jit-lock (so the text past the end
> of the window doesn't need to be scanned right away), and postpone more
> of the work to next-error.
>
>> BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
>
> That sucks. What does rgrep do so differently to make it even worse?
>
>> They time spent there seems a bit excessive, so maybe something strange
>> is going on...
>
> That's also possible.
Does
(setq process-adaptive-read-buffering nil)
make a difference? I have the suspicion that this still exhibits
pathological behavior sometimes.
--
David Kastrup
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-25 17:21 ` Stefan Monnier
2009-08-25 21:37 ` David Kastrup
@ 2009-08-26 7:33 ` Dan Nicolaescu
2009-08-26 18:56 ` Stefan Monnier
1 sibling, 1 reply; 11+ messages in thread
From: Dan Nicolaescu @ 2009-08-26 7:33 UTC (permalink / raw)
To: Stefan Monnier; +Cc: emacs-devel
Stefan Monnier <monnier@IRO.UMontreal.CA> writes:
> >> - It seems that they the calls to the interval code come from
> >> compilation-error-properties, but that function should only be called
> >> for regexps that do match, which shouldn't be that many. Can you look
> >> at the text to see if there really are that many matches? BTW, we
> >> should probably be able to make compile.el a bit lazier (i.e. the
> >> font-lock-phase part of the code should do a bit less work by moving
> >> it to the next-error-phase code).
> > The output is about 4500 lines, they all match.
>
> Ah, I see. So yes, the likely solution is to make compile.el lazier:
> use font-lock-syntactic-keywords and jit-lock (so the text past the end
> of the window doesn't need to be scanned right away), and postpone more
> of the work to next-error.
elp says that most time is spent in `compilation-error-properties', if
that helps...
> > BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
>
> That sucks. What does rgrep do so differently to make it even worse?
My guess would be more highlighting: it also highlights the matched words on
each line.
> > > They time spent there seems a bit excessive, so maybe something strange
> > is going on...
>
> That's also possible.
% cumulative self self total
time seconds seconds calls s/call s/call name
33.02 2.46 2.46 50974295 0.00 0.00 lookup_char_property
21.61 4.07 1.61 50847996 0.00 0.00 previous_interval
13.83 5.10 1.03 204112526 0.00 0.00 Fcdr
7.25 5.64 0.54 50946735 0.00 0.00 Fassq
6.17 6.10 0.46 4509 0.00 0.00 Fprevious_single_property_change
elp says there are 9018 calls to `compilation-error-properties'
The file has 4509 lines, and it's fontified twice (M-x compilation-mode + M-x font-lock-fontify-buffer)
That means 50974295/4509 = 11305 lookup_char_property calls per Fprevious_single_property_change ...
that sounds a bit excessive.
Now lets just double the input file (cat input input > input2) and
perform the same experiment on the new file.
% cumulative self self total
time seconds seconds calls s/call s/call name
37.86 12.09 12.09 203594871 0.00 0.00 lookup_char_property
21.20 18.86 6.77 203351394 0.00 0.00 previous_interval
17.38 24.41 5.55 814793814 0.00 0.00 Fcdr
5.98 26.32 1.91 9018 0.00 0.00 Fprevious_single_property_change
203594871/9018 = 22576
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: slow output in *compilation* buffer
2009-08-26 7:33 ` Dan Nicolaescu
@ 2009-08-26 18:56 ` Stefan Monnier
0 siblings, 0 replies; 11+ messages in thread
From: Stefan Monnier @ 2009-08-26 18:56 UTC (permalink / raw)
To: Dan Nicolaescu; +Cc: emacs-devel
>> Ah, I see. So yes, the likely solution is to make compile.el lazier:
>> use font-lock-syntactic-keywords and jit-lock (so the text past the end
>> of the window doesn't need to be scanned right away), and postpone more
>> of the work to next-error.
> elp says that most time is spent in `compilation-error-properties', if
> that helps...
Yes. We should remove the call to previous-single-property-change from
that function and move it to next-error instead.
After all, the property we look for is almost never used, so
this previous-single-property-change takes time O(N) where N is the
amount of output that has already been received. So overall, it causes
an O(N^2) behavior since it is called O(N) times.
>> > BTW, doing the same search with M-x rgrep is MUCH MUCH slower.
>> That sucks. What does rgrep do so differently to make it even worse?
> My guess would be more highlighting: it also highlights the matched
> words on each line.
That's possible, but I'd expect there's something more at play here.
> That means 50974295/4509 = 11305 lookup_char_property calls per Fprevious_single_property_change ...
> that sounds a bit excessive.
Since lookup_char_property will be called for each interval (i.e. chunk
of text with the same text-properties) between point and the previous
position where the property of interest is changed (which will usually
be (point-min) in our case), I think it's about right (let's see: 4500
lines, each line has at least 3-4 chunks with different properties, for
a total of about 20000 chunks, so about 10000 scanned per call on
average).
Stefan
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2009-08-26 18:56 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-08-22 8:23 slow output in *compilation* buffer Dan Nicolaescu
2009-08-23 1:28 ` Stefan Monnier
2009-08-23 6:27 ` Dan Nicolaescu
2009-08-25 17:21 ` Stefan Monnier
2009-08-25 21:37 ` David Kastrup
2009-08-26 7:33 ` Dan Nicolaescu
2009-08-26 18:56 ` Stefan Monnier
2009-08-24 18:52 ` Dan Nicolaescu
2009-08-24 19:13 ` Chong Yidong
2009-08-24 19:36 ` Dan Nicolaescu
2009-08-24 20:24 ` Dan Nicolaescu
Code repositories for project(s) associated with this external index
https://git.savannah.gnu.org/cgit/emacs.git
https://git.savannah.gnu.org/cgit/emacs/org-mode.git
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.