bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Lars Hamren]

The first few compiles, using "compile" to invode  GNU make,
from within Emacs, run at "command-line speed" but then the overall
time increases. The first 10 compiles are OK, but after about 20 compiles,
a compilation that  "time make -k" reports as taking

	real	0m0.127s
	user	0m0.100s
	sys	0m0.016s

takes more than five seconds. Then I give up and restart Emacs, and
everything is fine for another 10 compiles. And so on.

Here is some output from "strace emacs"

	socket(PF_FILE, SOCK_STREAM, 0)         = 3 <0.000016>
	connect(3, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"}, 20) = 0 <0.000015>

Here I attach strace to a running emacs just before i start compilation
and detach as soon as the compilation is done. The first few selects are
probably from before the time I press enter to execute the compile command.

	select(4, [3], NULL, NULL, {0, 297904}) = 0 (Timeout) <0.298232>
	select(4, [3], NULL, NULL, {0, 498307}) = 0 (Timeout) <0.498832>
	select(4, [3], NULL, NULL, {0, 498294}) = 0 (Timeout) <0.498820>
	select(4, [3], NULL, NULL, {0, 498292}) = 0 (Timeout) <0.498818>
	select(4, [3], NULL, NULL, {0, 498250}) = 0 (Timeout) <0.498776>
	select(4, [3], NULL, NULL, {0, 498299}) = 1 (in [3], left {0, 444141}) <0.054181>
	select(4, [3], NULL, NULL, {0, 441524}) = 1 (in [3], left {0, 320780}) <0.120760>
	select(4, [3], NULL, NULL, {0, 312270}) = 1 (in [3], left {0, 311270}) <0.001084>
	select(4, [3], NULL, NULL, {0, 282200}) = 0 (Timeout) <0.282507>
	select(4, [3], NULL, NULL, {0, 498525}) = 1 (in [3], left {0, 21105}) <0.477438>
	select(4, [3], NULL, NULL, {0, 499408}) = 0 (Timeout) <0.499936>
	select(4, [3], NULL, NULL, {0, 498927}) = 1 (in [3], left {0, 272045}) <0.226897>
	select(5, [3 4], NULL, NULL, {0, 499323}) = 1 (in [4], left {0, 479747}) <0.019591>
	select(5, [3], NULL, NULL, {0, 20000})  = 0 (Timeout) <0.020070>
	select(5, [3 4], NULL, NULL, {0, 442695}) = 1 (in [4], left {0, 442690}) <0.000016>
	select(5, [3], NULL, NULL, {0, 0})      = 0 (Timeout) <0.000008>
	select(4, [3], NULL, NULL, {0, 494042}) = 0 (Timeout) <0.494564>        <---- Much waiting here
	select(4, [3], NULL, NULL, {0, 498322}) = 0 (Timeout) <0.498847>
	select(4, [3], NULL, NULL, {0, 498336}) = 0 (Timeout) <0.498862>
	select(4, [3], NULL, NULL, {0, 498261}) = 0 (Timeout) <0.498784>
	select(4, [3], NULL, NULL, {0, 498320}) = 0 (Timeout) <0.498847>
	select(4, [3], NULL, NULL, {0, 498260}) = 0 (Timeout) <0.498786>
	select(4, [3], NULL, NULL, {0, 498325}) = 0 (Timeout) <0.498853>
	select(4, [3], NULL, NULL, {0, 498215}) = 0 (Timeout) <0.498737>
	select(4, [3], NULL, NULL, {0, 498057}) = 1 (in [3], left {0, 445670}) <0.052400>
	select(4, [3], NULL, NULL, {0, 445001}) = 1 (in [3], left {0, 349721}) <0.095295>
	select(4, [3], NULL, NULL, {0, 347501}) = 1 (in [3], left {0, 345858}) <0.001656>
	select(4, [3], NULL, NULL, {0, 345151}) = 1 (in [3], left {0, 342229}) <0.002978>
	select(4, [3], NULL, NULL, {0, 340611}) = 1 (in [3], left {0, 268540}) <0.072088>
	select(4, [3], NULL, NULL, {0, 259972}) = 1 (in [3], left {0, 259075}) <0.000975>
	select(4, [3], NULL, NULL, {0, 228314}) = 0 (Timeout) <0.228570>
	select(4, [3], NULL, NULL, {0, 498550} <unfinished ...>

Environment

	Ubuntu 10.04 (and earlier, on 9.04)
	Linux: 2.6.32-24-generic
	Emacs 23.1.2 (my own emacs build)
         Emacs 22.2.1 (Ubuntu package)

Googling, I can find nothing about this problem.

/Lars
-------------------------------------------------------------------
Lars Hamrén              Tel...: +46(46)189090
Svensk Datorutveckling   e-post: hamren@sdu.se
Vadmöllan 211            WWW...: www.sdu.se
S-225 94 Lund
Sweden

bug#7069: Problem only with "compile", not with "shell-command"

[Lars Hamren]

If I try to run the same compilation with "shell-command",
then there is no problem. The sub-process terminates quickly
and the buffer is updated immediately.

So, there does not seem to be a problem with sub-processes as such.

/Lars Hamrén

bug#7069: Clarification

[Lars Hamren]

The problem, as far as I can determine, is not that the compilation
process takes longer, but that buffer/window update is slow.

For long compilations, with output more than a few kB, output is
"chunky". Updates seem to be in multiples of 4 kB, with delays
between them. Running strace supports this assumption.

I tried this as a "compilation":

      time find /path/to/somewhere -ls

With "compile" (slow, chunky buffer update)

	real	0m30.488s
	user	0m0.032s
	sys	0m0.036s

With "shell-command" (immediate buffer update)

	real	0m0.027s
	user	0m0.020s
	sys	0m0.008s

 From Bash, not within emacs

	real    0m0.028s
	user    0m0.016s
	sys     0m0.012s

User and system times are effectively the same, but real
time differs by a factor of 1000.

/Lars Hamrén

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Jan Djärv]

I can't repeat this.  The "Much waiting here" you mark below is Emacs waiting 
for your X server to send something, so it doesn't say anything.
As there is only one fd in the select, the compilation must have finished 
before this.

For an strace to be useful, you need to see what emacs reads from the 
compilation and when and compare this to the "real" output.  If there is a 
notable delay for when Emacs reads from the compilation process, there might 
be a problem.  For now it just looks like your X server has some bug or is 
busy doing something else, so it doesn't have time to update Emacs windows.

You also failed to say if this happens with emacs -Q.  Is Emacs stuck when 
this happens or can you edit in other buffers?

Please use M-x report-emacs-bug next time to include relevant information 
about your Emacs.

	Jan D.

2010-09-19 02:38, Lars Hamren skrev:
> The first few compiles, using "compile" to invode  GNU make,
> from within Emacs, run at "command-line speed" but then the overall
> time increases. The first 10 compiles are OK, but after about 20 compiles,
> a compilation that "time make -k" reports as taking
>
> real 0m0.127s
> user 0m0.100s
> sys 0m0.016s
>
> takes more than five seconds. Then I give up and restart Emacs, and
> everything is fine for another 10 compiles. And so on.
>
> Here is some output from "strace emacs"
>
> socket(PF_FILE, SOCK_STREAM, 0) = 3 <0.000016>
> connect(3, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"}, 20) = 0
> <0.000015>
>
> Here I attach strace to a running emacs just before i start compilation
> and detach as soon as the compilation is done. The first few selects are
> probably from before the time I press enter to execute the compile command.
>
> select(4, [3], NULL, NULL, {0, 297904}) = 0 (Timeout) <0.298232>
> select(4, [3], NULL, NULL, {0, 498307}) = 0 (Timeout) <0.498832>
> select(4, [3], NULL, NULL, {0, 498294}) = 0 (Timeout) <0.498820>
> select(4, [3], NULL, NULL, {0, 498292}) = 0 (Timeout) <0.498818>
> select(4, [3], NULL, NULL, {0, 498250}) = 0 (Timeout) <0.498776>
> select(4, [3], NULL, NULL, {0, 498299}) = 1 (in [3], left {0, 444141})
> <0.054181>
> select(4, [3], NULL, NULL, {0, 441524}) = 1 (in [3], left {0, 320780})
> <0.120760>
> select(4, [3], NULL, NULL, {0, 312270}) = 1 (in [3], left {0, 311270})
> <0.001084>
> select(4, [3], NULL, NULL, {0, 282200}) = 0 (Timeout) <0.282507>
> select(4, [3], NULL, NULL, {0, 498525}) = 1 (in [3], left {0, 21105})
> <0.477438>
> select(4, [3], NULL, NULL, {0, 499408}) = 0 (Timeout) <0.499936>
> select(4, [3], NULL, NULL, {0, 498927}) = 1 (in [3], left {0, 272045})
> <0.226897>
> select(5, [3 4], NULL, NULL, {0, 499323}) = 1 (in [4], left {0, 479747})
> <0.019591>
> select(5, [3], NULL, NULL, {0, 20000}) = 0 (Timeout) <0.020070>
> select(5, [3 4], NULL, NULL, {0, 442695}) = 1 (in [4], left {0, 442690})
> <0.000016>
> select(5, [3], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000008>
> select(4, [3], NULL, NULL, {0, 494042}) = 0 (Timeout) <0.494564> <----
> Much waiting here
> select(4, [3], NULL, NULL, {0, 498322}) = 0 (Timeout) <0.498847>
> select(4, [3], NULL, NULL, {0, 498336}) = 0 (Timeout) <0.498862>
> select(4, [3], NULL, NULL, {0, 498261}) = 0 (Timeout) <0.498784>
> select(4, [3], NULL, NULL, {0, 498320}) = 0 (Timeout) <0.498847>
> select(4, [3], NULL, NULL, {0, 498260}) = 0 (Timeout) <0.498786>
> select(4, [3], NULL, NULL, {0, 498325}) = 0 (Timeout) <0.498853>
> select(4, [3], NULL, NULL, {0, 498215}) = 0 (Timeout) <0.498737>
> select(4, [3], NULL, NULL, {0, 498057}) = 1 (in [3], left {0, 445670})
> <0.052400>
> select(4, [3], NULL, NULL, {0, 445001}) = 1 (in [3], left {0, 349721})
> <0.095295>
> select(4, [3], NULL, NULL, {0, 347501}) = 1 (in [3], left {0, 345858})
> <0.001656>
> select(4, [3], NULL, NULL, {0, 345151}) = 1 (in [3], left {0, 342229})
> <0.002978>
> select(4, [3], NULL, NULL, {0, 340611}) = 1 (in [3], left {0, 268540})
> <0.072088>
> select(4, [3], NULL, NULL, {0, 259972}) = 1 (in [3], left {0, 259075})
> <0.000975>
> select(4, [3], NULL, NULL, {0, 228314}) = 0 (Timeout) <0.228570>
> select(4, [3], NULL, NULL, {0, 498550} <unfinished ...>
>
> Environment
>
> Ubuntu 10.04 (and earlier, on 9.04)
> Linux: 2.6.32-24-generic
> Emacs 23.1.2 (my own emacs build)
> Emacs 22.2.1 (Ubuntu package)
>
> Googling, I can find nothing about this problem.
>
> /Lars
> -------------------------------------------------------------------
> Lars Hamrén Tel...: +46(46)189090
> Svensk Datorutveckling e-post: hamren@sdu.se
> Vadmöllan 211 WWW...: www.sdu.se
> S-225 94 Lund
> Sweden
>
>

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Stefan Monnier]

severity 7069 important
thanks

> The first few compiles, using "compile" to invode  GNU make,
> from within Emacs, run at "command-line speed" but then the overall
> time increases.  The first 10 compiles are OK, but after about 20 compiles,
> a compilation that  "time make -k" reports as taking

Thanks for the report.  This looks like a serious problem.
I don't have time to look into it right now, but just letting you know
that your plea hasn't fallen down /dev/null.


        Stefan

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Lars Hamren]

Hi,

I have found the cause of this problem.

It goes away if I remove this code from my .emacs:

	(add-hook 'compilation-mode-hook
	  (lambda () (setq compilation-error-regexp-alist
	      (cons
	       ;; Quartus II error messages
	       '(".*Verilog .* at \\(.+\\)(\\([0-9]+\\)): .*" 1 2)
	      compilation-error-regexp-alist))))

I haven't looked further into why this should be a problem. The regexp
is quite simple, and doesn't match when compiling with g++.

Kind regards
/Lars
-------------------------------------------------------------------
Lars Hamrén              WWW...: www.sdu.se
Svensk Datorutveckling   Email.: hamren@sdu.se
Vadmöllan 211            Tel...: +46( 46)189090
S-225 94 Lund            Mobile: +46(705)189090
Sweden

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Stefan Monnier]

> 	(add-hook 'compilation-mode-hook
> 	  (lambda () (setq compilation-error-regexp-alist
> 	      (cons
> 	       ;; Quartus II error messages
> 	       '(".*Verilog .* at \\(.+\\)(\\([0-9]+\\)): .*" 1 2)
> 	      compilation-error-regexp-alist))))

There are various optimizations you can do on this regexp (such as
remove the trailing ".*"), but the only one I can see that should make
a significant difference in terms of performance is the leading ".*".
I.e. remove the ".*" at the beginning (compilation regexps are not
anchored at the BOL since Emacs-22, IIRC).  This should speed things up
significantly.  If you insist on keeping the ".*" because you like the
resulting highlighting, then add a "^" before it.
  
> I haven't looked further into why this should be a problem.

I can't think of any reason why this regexp should make compilation
become slower (I can see why it would make it slow, but unless lines
become longer over time, it should keep the same slowness at the end as
it had at the beginning).

Then again, this may depend on the version of Emacs you're using.
I've made some changes to the way compilation messages are parsed in the
upcoming Emacs-24 code (not specifically for performance reasons, but it
does impact performance), so if you could try out the development code
that would be helpful: I'd like to resolve such performance bugs before
Emacs-24 is released.

> The regexp is quite simple, and doesn't match when compiling with g++.

Depending on the shape of the regexp, the "doesn't match" case can be
the worst case, because the regexp-matcher has to try *all* the possible
ways in which it might match before reporting a match failure, whereas
a successful match would stop as soon as the first way to match
is found.


        Stefan

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Daniel Colascione]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 4/20/11 6:10 AM, Stefan Monnier wrote:
>> 	(add-hook 'compilation-mode-hook
>> 	  (lambda () (setq compilation-error-regexp-alist
>> 	      (cons
>> 	       ;; Quartus II error messages
>> 	       '(".*Verilog .* at \\(.+\\)(\\([0-9]+\\)): .*" 1 2)
>> 	      compilation-error-regexp-alist))))
[snip]
>> I haven't looked further into why this should be a problem.
> 
> I can't think of any reason why this regexp should make compilation
> become slower (I can see why it would make it slow, but unless lines
> become longer over time, it should keep the same slowness at the end as
> it had at the beginning).

He's adding an entry to compilation-error-regexp-alist every time he
compiles, and this variable is not buffer local. After the 20th
compilation, Emacs tries 20 times harder to match this regular expression.

He should be using add-to-list or (pushnew mumble :test #'equal).
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (Darwin)

iEYEARECAAYFAk20y4YACgkQ17c2LVA10VsQ0wCg3bzMD1o0IRivJBy4re3yofcv
K/MAniiaVMysZW/7RGG1QS1E9RAIxNT5
=C03A
-----END PGP SIGNATURE-----

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Stefan Monnier]

>>> (add-hook 'compilation-mode-hook
>>> (lambda () (setq compilation-error-regexp-alist
>>> (cons
>>> ;; Quartus II error messages
>>> '(".*Verilog .* at \\(.+\\)(\\([0-9]+\\)): .*" 1 2)
>>> compilation-error-regexp-alist))))
> [snip]
>>> I haven't looked further into why this should be a problem.
>> 
>> I can't think of any reason why this regexp should make compilation
>> become slower (I can see why it would make it slow, but unless lines
>> become longer over time, it should keep the same slowness at the end as
>> it had at the beginning).

> He's adding an entry to compilation-error-regexp-alist every time he
> compiles,

Duh, good catch, thank you,


        Stefan

bug#7069: Compilation from within emacs becomes slower and slower until Emacs is restarted

[Lars Hamren]

On 04/25/11 14:28, Stefan Monnier wrote:
>> He's adding an entry to compilation-error-regexp-alist every time he
>> >  compiles,
> Duh, good catch, thank you,

Second that.

Sorry to have wasted everybody's time :-(

Kind regards
/Lars
-------------------------------------------------------------------
Lars Hamrén              WWW...: www.sdu.se
Svensk Datorutveckling   Email.: hamren@sdu.se
Vadmöllan 211            Tel...: +46( 46)189090
S-225 94 Lund            Mobile: +46(705)189090
Sweden