bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

Hi,

Decided to try pretest of 26.0.90 and immediately discovered that it is 
slower than, for example, 'e7f65187580342171dd9ad32e570c50c96badb13' 
which I used before.  In particular, thanks to a couple of hours of 
bisecting, I found that the '20a09de953f437109a098fa8c4d380663d921481' 
merge increased my Emacs configuration loading time from 9 s to 60 s, 
which is unacceptable.  I have no idea how this made it's way to the 
'master' branch.  Furthermore, other operations like navigation across 
windows or performing an incremental search are also noticeably slower, 
i.e. they stutter annoyingly, and from what I see is a result of 
extensive GC spam which did not occur in previous versions.  Looks like 
something core has really been changed and potentially broken.  This 
needs investigation; let me know what can I do for you guys from my 
side.  Thanks.

Regards,
Alexander

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

tags 29095 + moreinfo
quit

Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:

> Hi,
>
> Decided to try pretest of 26.0.90 and immediately discovered that it
> is slower than, for example,
> 'e7f65187580342171dd9ad32e570c50c96badb13' which I used before.  In
> particular, thanks to a couple of hours of bisecting, I found that the
> '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs
> configuration loading time from 9 s to 60 s, which is unacceptable.

I know what you mean by "which is unacceptable", but somehow on first
reading it strikes me as rather bossy and entitled.

> I have no idea how this made it's way to the 'master' branch.

This sentence kind of suggests you think that the 'master' branch is
supposed to be the most stable, but it's rather emacs-26 (being the
release branch) which is intended to be more stable.  Note that
e7f6518758 which you said is okay, is contained in both emacs-26 and
master.

> Furthermore, other operations like navigation across windows or
> performing an incremental search are also noticeably slower, i.e. they
> stutter annoyingly, and from what I see is a result of extensive GC
> spam which did not occur in previous versions.  Looks like something
> core has really been changed and potentially broken.  This needs
> investigation; let me know what can I do for you guys from my side.
> Thanks.

I see two possible directions to investigate:

1. You bisect farther along the emacs-26 branch, as a merge commit
collects a whole bunch of changes, and so doesn't really narrow things
down at all.

2. You bisect and/or profile your Emacs configuration to see what part
is taking so long.  Ideally post something that can reproduce the
slowness starting from 'emacs -Q'.  Currently, your report pretty much
just says "*something* is slow", which nobody can really do anything
with.

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

On 11/01/2017 02:31 AM, Noam Postavsky wrote:
> tags 29095 + moreinfo
> quit
> 
> Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:
> 
>> Hi,
>>
>> Decided to try pretest of 26.0.90 and immediately discovered that it
>> is slower than, for example,
>> 'e7f65187580342171dd9ad32e570c50c96badb13' which I used before.  In
>> particular, thanks to a couple of hours of bisecting, I found that the
>> '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs
>> configuration loading time from 9 s to 60 s, which is unacceptable.
> 
> I know what you mean by "which is unacceptable", but somehow on first
> reading it strikes me as rather bossy and entitled.

Apologies, didn't want it to sound like that.  Was truly frustrated by 
the experience.  The problem was also that until the very last moment I 
refused to believe that I would really hit something like this on a 
"pretest" tag from the 'master' branch.  I did OS upgrade recently as 
well, so I first started to profile my SSD RAID for possible performance 
degradation (as Emacs reads lots of file at startup) and look for any 
issues I could have introduced in the custom Linux kernel.  I rolled 
back Emacs only as the very last resort and to my (unpleasant) surprise 
that was the culprit.

>> I have no idea how this made it's way to the 'master' branch.
> 
> This sentence kind of suggests you think that the 'master' branch is
> supposed to be the most stable, but it's rather emacs-26 (being the
> release branch) which is intended to be more stable.  Note that
> e7f6518758 which you said is okay, is contained in both emacs-26 and
> master.

As my original findings (namely merge commit from the 'emacs-26' branch) 
demonstrated, there is no stable branch at the moment as the faulty 
commit is now present in both.  In fact, the 'emacs-26' was merged to 
master (and not vice versa), so it's the issue that came from what you 
call a "stable" branch.  This is another surprise for me.

>> Furthermore, other operations like navigation across windows or
>> performing an incremental search are also noticeably slower, i.e. they
>> stutter annoyingly, and from what I see is a result of extensive GC
>> spam which did not occur in previous versions.  Looks like something
>> core has really been changed and potentially broken.  This needs
>> investigation; let me know what can I do for you guys from my side.
>> Thanks.
> 
> I see two possible directions to investigate:
> 
> 1. You bisect farther along the emacs-26 branch, as a merge commit
> collects a whole bunch of changes, and so doesn't really narrow things
> down at all.

And that's what I just finished doing, voilà:

e1f6e3127a292e6ba66d27c49ddda4fe949569f5
Author:     Noam Postavsky
AuthorDate: Wed Aug 30 23:12:22 2017 -0400
Commit:     Noam Postavsky
CommitDate: Fri Sep 29 18:40:06 2017 -0400

And yes, of course, as soon as I found this by spending a couple of 
hours more doing bisecting, I did immediately set 
`x-wait-for-event-timeout' to nil and the startup problem was gone. 
However, I'm still gravely concerned that such defaults (100 ms GUI 
delays) suddenly get added (whatever the reason for this new option was) 
and affect both branches.

Now, that was only the first part.  I'm still going to continue 
bisecting further why there are new obvious issues with garbage 
collecting (as those seem to be somewhere deeper in the 'emacs-26' 
branch).  For instance, while I was doing bisecting for the above 
finding, I kept rebuilding the Emacs package from scratch in a clean 
environment and I did so using `compilation-mode'.  As the output from 
the build kept arriving to the *compilation* buffer, I kept getting 
"Garbage collecting...done" spam (at random times), stuttering the 
output coming into *compilation* buffer.  You don't have to explain to 
me here anything about GC, I am well aware of all of these issues.  The 
point is that such frequent GC spam and stuttering of output did not 
happen before and I didn't change GC settings.  Now, this is not even 
the most irritating about this, it's rather that frequently it happens 
so that "Garbage collecting...done" would just hang out there and the 
build output would stop completely, in fact, the whole Emacs is blocked 
waiting for something to happen from GC but either that GC either hangs 
itself or it takes too long that I lose my patience.  What I had to do 
in such cases, is simply spam <C-g> just so that Emacs aborts those 
faulty GC attempts, unblocks, and I can finally see my build output 
being aggressively flushed into the *compilation* buffer (as the build 
is in reality already much further away from the point where the output 
stopped).

Regards,
Alexander

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:

>> I know what you mean by "which is unacceptable", but somehow on first
>> reading it strikes me as rather bossy and entitled.
>
> Apologies, didn't want it to sound like that.

Indeed, I didn't really think so.  But I've been thinking a lot about
how to avoid threads which devolve into bitter sniping (which is more
common than I'd like in emacs-devel/bugs), and I think calling such
things out at the beginning could help avoid misunderstandings.

> As my original findings (namely merge commit from the 'emacs-26'
> branch) demonstrated, there is no stable branch at the moment as the
> faulty commit is now present in both.  In fact, the 'emacs-26' was
> merged to master (and not vice versa), so it's the issue that came
> from what you call a "stable" branch.  This is another surprise for
> me.

In this context, "stable" just means no features are getting added.
Ideally no bugs either, but sometimes bug fixes end up adding bugs too.

> And that's what I just finished doing, voilà:
>
> e1f6e3127a292e6ba66d27c49ddda4fe949569f5
> Author:     Noam Postavsky
> AuthorDate: Wed Aug 30 23:12:22 2017 -0400

Hah!  It was me ;)

> And yes, of course, as soon as I found this by spending a couple of
> hours more doing bisecting, I did immediately set
> `x-wait-for-event-timeout' to nil and the startup problem was
> gone. However, I'm still gravely concerned that such defaults (100 ms
> GUI delays) suddenly get added (whatever the reason for this new
> option was) and affect both branches.

Versions 25.3 and lower all had this wait, and removing it cause some
problems for other users (see Bug#25521 and Bug#25511).  Therefore it
was restored in emacs-26 (and (almost) everything in emacs-26 goes to
master) with the option to remove it.  In fact, the wait used to be
unbounded, so a timeout is something of a compromise.

What confuses me though, is how a 100ms delay is adding ~50s to your
starup time?!  Or are you just creating 500 frames on startup?

> As the output from the build kept arriving to the *compilation*
> buffer, I kept getting "Garbage collecting...done" spam (at random
> times), stuttering the output coming into *compilation* buffer.  You
> don't have to explain to me here anything about GC, I am well aware of
> all of these issues.

Just to clarify, you have garbage-collection-messages set to non-nil on
purpose?

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

> What confuses me though, is how a 100ms delay is adding ~50s to your
> starup time?!  Or are you just creating 500 frames on startup?

Hah, of course not.  So I took some additional time to investigate where 
this comes from and in turned out to be very simple:

(setq-default minibuffer-auto-raise t)

causes this.  I think this needs to be addressed.  Either by documenting 
this side effect or finding a better solution.

>> As the output from the build kept arriving to the *compilation*
>> buffer, I kept getting "Garbage collecting...done" spam (at random
>> times), stuttering the output coming into *compilation* buffer.  You
>> don't have to explain to me here anything about GC, I am well aware of
>> all of these issues.
> 
> Just to clarify, you have garbage-collection-messages set to non-nil on
> purpose?

On purpose.  I want to know why Emacs stutters, so I monitor this in 
order to come up with better GC parameters for my workflows.  Anyway, I 
figured out why this GC issue was happening.  It's a bug with 
`magit-filenotify' package, which I've already reported and found 
workaround for.  So apart from my concerns about `minibuffer-auto-raise' 
and `x-wait-for-event-timeout', looks good so far.

Regards,
Alexander

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:

>> What confuses me though, is how a 100ms delay is adding ~50s to your
>> starup time?!  Or are you just creating 500 frames on startup?
>
> Hah, of course not.  So I took some additional time to investigate
> where this comes from and in turned out to be very simple:
>
> (setq-default minibuffer-auto-raise t)
>
> causes this.  I think this needs to be addressed.  Either by
> documenting this side effect or finding a better solution.

Ah, so if I understand correctly, because of the minibuffer-auto-raise
setting, every time a message is printed Emacs tries to make the frame
visible, and because of x-wait-for-event-timeout, it waits for 100ms
each time.  So if you get around ~500 messages during startup, it would
take about 50 seconds, thus explaining the increase you observed?

Perhaps the thing to do is simply to disable x-wait-for-event-timeout if
we end up hitting the timeout.  Under most window managers the frame
becomes visible much faster than 100ms anyway, as far as I know.

> I figured out why this GC issue was happening.  It's a bug with
> `magit-filenotify' package, which I've already reported and found
> workaround for.  So apart from my concerns about
> `minibuffer-auto-raise' and `x-wait-for-event-timeout', looks good so
> far.

Ah yes, I saw that.  It looks like it's not actually a GC issue as such,
but an (asynchronous) infinite loop that generates a lot of garbage (and
hence work for the GC).

https://github.com/ruediger/magit-filenotify/issues/20

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

On 11/05/2017 12:53 AM, Noam Postavsky wrote:
> Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:
> 
>>> What confuses me though, is how a 100ms delay is adding ~50s to your
>>> starup time?!  Or are you just creating 500 frames on startup?
>>
>> Hah, of course not.  So I took some additional time to investigate
>> where this comes from and in turned out to be very simple:
>>
>> (setq-default minibuffer-auto-raise t)
>>
>> causes this.  I think this needs to be addressed.  Either by
>> documenting this side effect or finding a better solution.
> 
> Ah, so if I understand correctly, because of the minibuffer-auto-raise
> setting, every time a message is printed Emacs tries to make the frame
> visible, and because of x-wait-for-event-timeout, it waits for 100ms
> each time.  So if you get around ~500 messages during startup, it would
> take about 50 seconds, thus explaining the increase you observed?
> 
> Perhaps the thing to do is simply to disable x-wait-for-event-timeout if
> we end up hitting the timeout.  Under most window managers the frame
> becomes visible much faster than 100ms anyway, as far as I know.

Do you mean to set it to nil as the timeout is hit for the first time?

>> I figured out why this GC issue was happening.  It's a bug with
>> `magit-filenotify' package, which I've already reported and found
>> workaround for.  So apart from my concerns about
>> `minibuffer-auto-raise' and `x-wait-for-event-timeout', looks good so
>> far.
> 
> Ah yes, I saw that.  It looks like it's not actually a GC issue as such,
> but an (asynchronous) infinite loop that generates a lot of garbage (and
> hence work for the GC).
> 
> https://github.com/ruediger/magit-filenotify/issues/20

Indeed, thanks for rephrasing it.

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 > Perhaps the thing to do is simply to disable x-wait-for-event-timeout if
 > we end up hitting the timeout.  Under most window managers the frame
 > becomes visible much faster than 100ms anyway, as far as I know.

If and when we do that, we should also warn and inform the user.  And we
probably should collect information about those window managers that are
not able to inform us in due time that the frame has become visible.

And maybe we're also still missing one or the other case where we could
set the visibility of the frame.  Alexander, can you try using the
debugger to see if Emacs receives any events that OT1H do not call
SET_FRAME_VISIBLE (f, 1) but OTOH still qualify as ones that make sense
only if the frame is visible?  I know it's a vague question but this is
primarily a timing issue and as such rather subtle.

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

[-- Attachment #1: Type: text/plain, Size: 1169 bytes --]

martin rudalics <rudalics@gmx.at> writes:

>> Perhaps the thing to do is simply to disable x-wait-for-event-timeout if
>> we end up hitting the timeout.  Under most window managers the frame
>> becomes visible much faster than 100ms anyway, as far as I know.
>
> If and when we do that, we should also warn and inform the user.  And we
> probably should collect information about those window managers that are
> not able to inform us in due time that the frame has become visible.

Not sure what Alexander is using, but under i3 the problem is simply
that the frame doesn't become visible until the user switches to the
virtual workspace where Emacs is.  So it's not that we have a visible
frame which the window manager fails to inform us about in time, rather
the frame just doesn't become visible in time.

It occurs to me that another possibility is simply to disable the
timeout when doing the auto-raise.  We have the timeout due some users'
configurations accidentally relying on the fact that a frame will be
visible after make-frame returns, but it seems unlikely that anyone
would manage to rely on the frame being visible after a call to
`message' occurs.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: patch --]
[-- Type: text/x-diff, Size: 1539 bytes --]

From 9ab2cb84378dd73bd599a8445c32e305bb342819 Mon Sep 17 00:00:00 2001
From: Noam Postavsky <npostavs@gmail.com>
Date: Tue, 7 Nov 2017 03:41:34 -0500
Subject: [PATCH] Don't wait for X events when auto-raising frame (Bug#29095)

* src/xdisp.c (message3_nolog)
(setup_echo_area_for_printing): Let-bind x-wait-for-event-timeout to
nil while calling raise-frame.
---
 src/xdisp.c | 13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

diff --git a/src/xdisp.c b/src/xdisp.c
index 69b74dc629..18fd8c32b9 100644
--- a/src/xdisp.c
+++ b/src/xdisp.c
@@ -10530,7 +10530,12 @@ message3_nolog (Lisp_Object m)
 	{
 	  set_message (m);
 	  if (minibuffer_auto_raise)
-	    Fraise_frame (frame);
+            {
+              ptrdiff_t count = SPECPDL_INDEX ();
+              specbind (Qx_wait_for_event_timeout, Qnil);
+              Fraise_frame (frame);
+              unbind_to (count, Qnil);
+            }
 	  /* Assume we are not echoing.
 	     (If we are, echo_now will override this.)  */
 	  echo_message_buffer = Qnil;
@@ -10971,7 +10976,11 @@ setup_echo_area_for_printing (bool multibyte_p)
 	  struct frame *sf = SELECTED_FRAME ();
 	  Lisp_Object mini_window;
 	  mini_window = FRAME_MINIBUF_WINDOW (sf);
-	  Fraise_frame  (WINDOW_FRAME (XWINDOW (mini_window)));
+
+          ptrdiff_t count = SPECPDL_INDEX ();
+          specbind (Qx_wait_for_event_timeout, Qnil);
+          Fraise_frame (WINDOW_FRAME (XWINDOW (mini_window)));
+          unbind_to (count, Qnil);
 	}
 
       message_log_maybe_newline ();
-- 
2.11.0

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

[-- Attachment #1: Type: text/plain, Size: 352 bytes --]

Noam Postavsky <npostavs@users.sourceforge.net> writes:

>>From 9ab2cb84378dd73bd599a8445c32e305bb342819 Mon Sep 17 00:00:00 2001
> From: Noam Postavsky <npostavs@gmail.com>
> Date: Tue, 7 Nov 2017 03:41:34 -0500
> Subject: [PATCH] Don't wait for X events when auto-raising frame (Bug#29095)

Sorry, forgot the DEFSYM.  Here's a patch which compiles.


[-- Attachment #2: patch --]
[-- Type: text/plain, Size: 1992 bytes --]

From 37e98e2b1ecaa0e594bd5a92fbf8f55e7c918fde Mon Sep 17 00:00:00 2001
From: Noam Postavsky <npostavs@gmail.com>
Date: Tue, 7 Nov 2017 03:41:34 -0500
Subject: [PATCH] Don't wait for X events when auto-raising frame (Bug#29095)

* src/xdisp.c (message3_nolog)
(setup_echo_area_for_printing): Let-bind x-wait-for-event-timeout to
nil while calling raise-frame.
---
 src/xdisp.c | 13 +++++++++++--
 src/xterm.c |  1 +
 2 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/src/xdisp.c b/src/xdisp.c
index 69b74dc629..18fd8c32b9 100644
--- a/src/xdisp.c
+++ b/src/xdisp.c
@@ -10530,7 +10530,12 @@ message3_nolog (Lisp_Object m)
 	{
 	  set_message (m);
 	  if (minibuffer_auto_raise)
-	    Fraise_frame (frame);
+            {
+              ptrdiff_t count = SPECPDL_INDEX ();
+              specbind (Qx_wait_for_event_timeout, Qnil);
+              Fraise_frame (frame);
+              unbind_to (count, Qnil);
+            }
 	  /* Assume we are not echoing.
 	     (If we are, echo_now will override this.)  */
 	  echo_message_buffer = Qnil;
@@ -10971,7 +10976,11 @@ setup_echo_area_for_printing (bool multibyte_p)
 	  struct frame *sf = SELECTED_FRAME ();
 	  Lisp_Object mini_window;
 	  mini_window = FRAME_MINIBUF_WINDOW (sf);
-	  Fraise_frame  (WINDOW_FRAME (XWINDOW (mini_window)));
+
+          ptrdiff_t count = SPECPDL_INDEX ();
+          specbind (Qx_wait_for_event_timeout, Qnil);
+          Fraise_frame (WINDOW_FRAME (XWINDOW (mini_window)));
+          unbind_to (count, Qnil);
 	}
 
       message_log_maybe_newline ();
diff --git a/src/xterm.c b/src/xterm.c
index dbb8349452..d021546c5e 100644
--- a/src/xterm.c
+++ b/src/xterm.c
@@ -13325,6 +13325,7 @@ syms_of_xterm (void)
 so it is important to limit the wait.
 
 If set to a non-float value, there will be no wait at all.  */);
+  DEFSYM (Qx_wait_for_event_timeout, "x-wait-for-event-timeout");
   Vx_wait_for_event_timeout = make_float (0.1);
 
   DEFVAR_LISP ("x-keysym-table", Vx_keysym_table,
-- 
2.11.0

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 > Not sure what Alexander is using, but under i3 the problem is simply
 > that the frame doesn't become visible until the user switches to the
 > virtual workspace where Emacs is.  So it's not that we have a visible
 > frame which the window manager fails to inform us about in time, rather
 > the frame just doesn't become visible in time.

But as long as a user doesn't switch to that workspace she won't observe
that making a new frame is slower. So I seem to be missing something.

Anyway, we probably should add to /etc/PROBLEMS lines like

"If a new Emacs frame is supposed to appear on a different virtual
workspace, Emacs may not be notified about the visibility of the frame
until the user switches to that workspace.  If this causes ... one
remedy is to customize ..."

And I'd still be interested in Sasha's use case.

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

martin rudalics <rudalics@gmx.at> writes:

>> Not sure what Alexander is using, but under i3 the problem is simply
>> that the frame doesn't become visible until the user switches to the
>> virtual workspace where Emacs is.  So it's not that we have a visible
>> frame which the window manager fails to inform us about in time, rather
>> the frame just doesn't become visible in time.
>
> But as long as a user doesn't switch to that workspace she won't observe
> that making a new frame is slower. So I seem to be missing something.

She can observe it indirectly via lisp code.

> Anyway, we probably should add to /etc/PROBLEMS lines like
>
> "If a new Emacs frame is supposed to appear on a different virtual
> workspace, Emacs may not be notified about the visibility of the frame
> until the user switches to that workspace.

Hmm, not sure.  This sounds to me like "Emacs may not be notified about
the visibility of the frame until the frame is visible".  Which doesn't
seem like something which belongs in /etc/PROBLEMS.

>> It occurs to me that another possibility is simply to disable the
>> timeout when doing the auto-raise.  We have the timeout due some users'
>> configurations accidentally relying on the fact that a frame will be
>> visible after make-frame returns, but it seems unlikely that anyone
>> would manage to rely on the frame being visible after a call to
>> `message' occurs.
>
> But missing a message from an auto-raising frame does not sound like a
> good idea either.  That is, if the timeout is supposed to catch a
> problem with the Emacs/window manager interaction and to prevent Emacs
> from proceeding until some user decision based on something to be
> shown in a visible frame has been made.

I was operating under the assumption that the timeout is for the benefit
of the user's lisp code, not their interactions with the UI.  Not sure
the timeout would be that helpful for missing messages; under normal
circumstances it's not even hit, and 100ms goes by pretty quickly for a
human...

> I wish we would have had the courage to go through with your first
> solution - omit such waits completely.  I'm still surprised that we had
> so few complaints back then ...

I would still like to phase it out.  Maybe we could set the default to
nil for Emacs 27?

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 >> But as long as a user doesn't switch to that workspace she won't observe
 >> that making a new frame is slower. So I seem to be missing something.
 >
 > She can observe it indirectly via lisp code.

But Alexander said

  Furthermore, other operations like navigation across windows or
  performing an incremental search are also noticeably slower, i.e. they
  stutter annoyingly, and from what I see is a result of extensive GC
  spam which did not occur in previous versions.  Looks like something

so he must have had a direct, immediate experience.

 >> Anyway, we probably should add to /etc/PROBLEMS lines like
 >>
 >> "If a new Emacs frame is supposed to appear on a different virtual
 >> workspace, Emacs may not be notified about the visibility of the frame
 >> until the user switches to that workspace.
 >
 > Hmm, not sure.  This sounds to me like "Emacs may not be notified about
 > the visibility of the frame until the frame is visible".  Which doesn't
 > seem like something which belongs in /etc/PROBLEMS.

Apparently there are corner cases (like that of the virtual workspaces)
where we cannot fulfill a contract that ‘make-frame’ and
‘make-frame-visible’ supply a visible frame at the time the operation
terminates.  So either we should not provide such a contract in the
first place or mention that in some cases there are obvious problems.

 > I was operating under the assumption that the timeout is for the benefit
 > of the user's lisp code, not their interactions with the UI.  Not sure
 > the timeout would be that helpful for missing messages; under normal
 > circumstances it's not even hit, and 100ms goes by pretty quickly for a
 > human...

I think that Lisp code (1) must be able to deal with the fact that any
frame is currently invisible and (2) should never wait until a frame
gets visible.  In my experience being nice to Lisp code sooner or later
fails.

 > I would still like to phase it out.  Maybe we could set the default to
 > nil for Emacs 27?

I'd set the default to nil for the release.  Did we have any open bugs
when you added that option?

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

martin rudalics <rudalics@gmx.at> writes:

>>> But as long as a user doesn't switch to that workspace she won't observe
>>> that making a new frame is slower. So I seem to be missing something.
>>
>> She can observe it indirectly via lisp code.
>
> But Alexander said
>
>  Furthermore, other operations like navigation across windows or
>  performing an incremental search are also noticeably slower, i.e. they
>  stutter annoyingly, and from what I see is a result of extensive GC
>  spam which did not occur in previous versions.  Looks like something
>
> so he must have had a direct, immediate experience.

Ah, perhaps you missed it, that's actually a separate problem.  See
latter halves of #22 & #25.

https://debbugs.gnu.org/cgi/bugreport.cgi?bug=29095#22
https://debbugs.gnu.org/cgi/bugreport.cgi?bug=29095#25

>> I would still like to phase it out.  Maybe we could set the default to
>> nil for Emacs 27?
>
> I'd set the default to nil for the release.  Did we have any open bugs
> when you added that option?

As far as I know, the only cases of trouble due to not waiting were
Bug#25521 and Bug#25511.

I would note that the dependency on frame visibility is somewhat
non-obvious in both cases (the dependency in the #25521 case is now
eliminated by changing select-frame-by-name).  So talking about
visibility in etc/PROBLEMS is not necessarily of much use.

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 >> But Alexander said
 >>
 >>   Furthermore, other operations like navigation across windows or
 >>   performing an incremental search are also noticeably slower, i.e. they
 >>   stutter annoyingly, and from what I see is a result of extensive GC
 >>   spam which did not occur in previous versions.  Looks like something
 >>
 >> so he must have had a direct, immediate experience.
 >
 > Ah, perhaps you missed it, that's actually a separate problem.  See
 > latter halves of #22 & #25.
 >
 > https://debbugs.gnu.org/cgi/bugreport.cgi?bug=29095#22
 > https://debbugs.gnu.org/cgi/bugreport.cgi?bug=29095#25

I didn't miss those and I have no explanation why his minibuffer doesn't
show up  Do you?

 > As far as I know, the only cases of trouble due to not waiting were
 > Bug#25521 and Bug#25511.

And we closed them both.

 > I would note that the dependency on frame visibility is somewhat
 > non-obvious in both cases (the dependency in the #25521 case is now
 > eliminated by changing select-frame-by-name).  So talking about
 > visibility in etc/PROBLEMS is not necessarily of much use.

IIUC we have three issues here:

(1) Since we always used some sort of waiting, some code that relied on
its presence but (IMHO) should never have been written that way, was
executed as intended by the author.  Bug#25521 was such a case.  I think
this issue should be fixed by supplying the entire available information
(like the expected frame size or the asked for name) at the time the
frame is created.  If anything changes later, we'll inform about that
change in due time.

(2) Apparently sometimes the window system / manager does not inform us
that a frame has become visible although the frame apparently has become
visible.  If I'm not mistaken that's what Alexander sees (or is not able
to see).

(3) Sometimes for a frame it may take forever to become visible.  That's
the case you cited earlier with a frame that is expected to pop up on a
different workspace.

In some sense all of these are problems we have not completely resolved
for at least one sort of timeout a user chooses.

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

Hi guys,

On 11/09/2017 07:12 PM, martin rudalics wrote:
> (2) Apparently sometimes the window system / manager does not inform us
> that a frame has become visible although the frame apparently has become
> visible.  If I'm not mistaken that's what Alexander sees (or is not able
> to see).

Apologies for the delay, I was off to another town for a couple of days. 
  So let me provide some more details of what's going on and what is the 
use case.  It's actually nothing special, and that's why I'm also 
confused how nobody noticed that before.  All I do is just start new 
Emacs instance.  My (tiling) window manager is BSPWM 
<https://github.com/baskerville/bspwm>.  Now let's see what happens when

- `minibuffer-auto-raise' is nil,
- `x-wait-for-event-timeout' is 0.1 (default):

NOTE: [after-init] marks the point in time when executions of all 
functions attached to `after-init-hook' are finished.

(... *cough* ... I got tons of packages, sorry ... *cough* ... )

Initializing...
Loading ~/.emacs.d/init.el...
Loading tramp...done
Loading ~/.custom.el...done
Compiling ~/.emacs.d/init/...
Checking ~/.emacs.d/init/... [181 times]
Done (Total of 0 files compiled, 180 skipped)
Compiling ~/.emacs.d/init/...done
Configuring package auto-compile...done
Loading package with-after-load...
Configuring package with-after-load...done
Loading package with-after-load...done
Configuring package menu-bar...done
Configuring package tool-bar...done
Configuring package scroll-bar...done
Configuring package simple...done
Configuring package button...done
Configuring package completion-list...done
Configuring package mouse...done
Configuring package special...done
Configuring package tabulated-list...done
Configuring package font-lock...done
Configuring package fill...done
Configuring package auto-fill...done
Configuring package newcomment...done
Configuring package wid-edit...done
Configuring package window...done
Configuring package minibuffer...done
Configuring package minibuffer-line...done
Configuring package easymenu...done
Configuring package eldoc...done
Configuring package elisp-mode...done
Configuring package lisp-mode...done
Configuring package prog-mode...done
Configuring package text-mode...done
Configuring package files...done
Loading package git...
Configuring package git...done
Loading package git...done
Configuring package ansi-color...done
Configuring package comint...done
Configuring package shell...done
Configuring package select...done
Loading package dired...
Configuring package dired...done
Loading package dired...done
Configuring package dired-x...done
Configuring package compile...done
Configuring package elec-pair...done
Configuring package mb-depth...done
Configuring package tramp...done
Configuring package password-cache...done
Configuring package vc-hooks...done
Loading ~/.emacs.d/init.el...done (2.808s)
Initializing...done (3.256s)
Configuring package evil-vars...done
Configuring package evil-core...done
Configuring package evil-states...done
Configuring package evil-search...done
Configuring package evil...
Configuring package evil-surround...done
Configuring package evil...done
Configuring package devil-vars...done
Configuring package devil-ex...done
Configuring package avy...done
Configuring package devil-maps...done
Configuring package devil...done
Configuring package flx...done
Configuring package ivy...done
Configuring package counsel...done
Configuring package savehist...done
Configuring package server...done
Configuring package hl-todo...done
Configuring package hl-line...done
Configuring package recentf...
Loading ~/.emacs.d/.recentf.el (source)...done
Configuring package recentf-ext...done
Configuring package sync-recentf...done
Configuring package recentf...done (0.135s)
Configuring package help-mode...done
Configuring package with-editor...done
Configuring package git-commit...done
Configuring package pdf-tools...done
Configuring package diff...done
Configuring package undo-tree...done
Configuring package ycmd...done
Configuring package flycheck...done
Configuring package flycheck-ycmd...done
Configuring package php-extras...done
Configuring package company...done
Configuring package company-ycmd...done
Configuring package company-flx...done
Configuring package paren...done
Configuring package highlight-escape-sequences...done
Loading ~/.emacs.d/init.el...done (6.496s) [after-init]

Notice how configuring of package `recentf' suddenly appears to stand 
out and it contains that single 100 ms delay.  Curiously no matter how 
many times I restart Emacs, it's always `recentf' that gets this delay. 
I have no idea why but it's for sure related.  Anyway, let's disregard 
it for a moment and assume that it is still fine.  Now let's see what 
happens when

- `minibuffer-auto-raise' is t,
- `x-wait-for-event-timeout' is 0.1 (default):

Initializing...
Loading ~/.emacs.d/init.el...
Loading tramp...done
Loading ~/.custom.el...done
Compiling ~/.emacs.d/init/...
Checking ~/.emacs.d/init/... [181 times]
Done (Total of 0 files compiled, 180 skipped)
Compiling ~/.emacs.d/init/...done
Configuring package auto-compile...done
Loading package with-after-load...
Configuring package with-after-load...done
Loading package with-after-load...done
Configuring package menu-bar...done
Configuring package tool-bar...done
Configuring package scroll-bar...done
Configuring package simple...done
Configuring package button...done
Configuring package completion-list...done
Configuring package mouse...done
Configuring package special...done
Configuring package tabulated-list...done
Configuring package font-lock...done
Configuring package fill...done
Configuring package auto-fill...done
Configuring package newcomment...done
Configuring package wid-edit...done
Configuring package window...done
---------------------------------------------------------
 >>> *minibuffer-auto-raise is set to t at this point* <<<
---------------------------------------------------------
Configuring package minibuffer-line...done (0.106s)
Configuring package easymenu...done (0.102s)
Configuring package eldoc...done (0.103s)
Configuring package elisp-mode...done (0.104s)
Configuring package lisp-mode...done (0.103s)
Configuring package prog-mode...done (0.104s)
Configuring package text-mode...done (0.104s)
Configuring package files...done (0.104s)
Loading package git...
Configuring package git...done (0.103s)
Loading package git...done (0.336s)
Configuring package ansi-color...done (0.104s)
Configuring package comint...done (0.105s)
Configuring package shell...done (0.102s)
Configuring package select...done (0.102s)
Loading package dired...
Configuring package dired...done (0.114s)
Loading package dired...done (0.339s)
Configuring package dired-x...done (0.102s)
Configuring package compile...done (0.104s)
Configuring package elec-pair...done (0.104s)
Configuring package mb-depth...done (0.104s)
Configuring package tramp...done (0.104s)
Configuring package password-cache...done (0.104s)
Configuring package vc-hooks...done (0.104s)
Loading ~/.emacs.d/init.el...done (24.086s)
Initializing...done (24.532s)
Configuring package evil-vars...done (0.104s)
Configuring package evil-core...done (0.102s)
Configuring package evil-states...done (0.107s)
Configuring package evil-search...done (0.103s)
Configuring package evil...
Configuring package evil-surround...done (0.104s)
Configuring package evil...done (0.319s)
Configuring package devil-vars...done (0.103s)
Configuring package devil-ex...done (0.102s)
Configuring package avy...done (0.102s)
Configuring package devil-maps...done (0.107s)
Configuring package devil...done (0.103s)
Configuring package flx...done (0.103s)
Configuring package ivy...done (0.107s)
Configuring package counsel...done (0.104s)
Configuring package savehist...done (0.104s)
Configuring package server...done (0.103s)
Configuring package hl-todo...done (0.103s)
Configuring package hl-line...done (0.104s)
Configuring package recentf...
Loading ~/.emacs.d/.recentf.el (source)...done
Configuring package recentf-ext...done (0.104s)
Configuring package sync-recentf...done (0.103s)
Configuring package recentf...done (15.669s)
Configuring package help-mode...done (0.103s)
Configuring package with-editor...done (0.104s)
Configuring package git-commit...done (0.105s)
Configuring package pdf-tools...done (0.102s)
Configuring package diff...done (0.102s)
Configuring package undo-tree...done (0.105s)
Configuring package ycmd...done (0.102s)
Configuring package flycheck...done (0.103s)
Configuring package flycheck-ycmd...done (0.105s)
Configuring package php-extras...done (0.104s)
Configuring package company...done (0.106s)
Configuring package company-ycmd...done (0.104s)
Configuring package company-flx...done (0.104s)
Configuring package paren...done (0.104s)
Configuring package highlight-escape-sequences...done (0.104s)
Loading ~/.emacs.d/init.el...done (53.348s) [after-init]

Look how as soon as `minibuffer-auto-raise' is set to t, configurations 
of all subsequent packages obviously get delayed by 100 ms each.  This 
is most probably caused by the messages being written to minibuffer.  When

- `x-wait-for-event-timeout' is nil, there are no additional delays at all.

Regards,
Alexander

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Alexander Shukaev]

On 11/09/2017 11:09 PM, Alexander Shukaev wrote:
> - `x-wait-for-event-timeout' is nil, there are no additional delays at all.

Ha, I take this last phrase back.  It's actually getting interesting, in 
fact, when `x-wait-for-event-timeout' is nil:

Configuring package recentf...done (0.365s)

but with `x-wait-for-event-timeout' being 0.1:

Configuring package recentf...done (0.131s)

it's back to lower again.  Whaaat?

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

Alexander Shukaev <emacs@Alexander.Shukaev.name> writes:

> Hi guys,
>
> On 11/09/2017 07:12 PM, martin rudalics wrote:
>> (2) Apparently sometimes the window system / manager does not inform us
>> that a frame has become visible although the frame apparently has become
>> visible.  If I'm not mistaken that's what Alexander sees (or is not able
>> to see).
>
> Apologies for the delay, I was off to another town for a couple of
> days. So let me provide some more details of what's going on and what
> is the use case.  It's actually nothing special, and that's why I'm
> also confused how nobody noticed that before.  All I do is just start
> new Emacs instance.  My (tiling) window manager is BSPWM
> <https://github.com/baskerville/bspwm>.

Do you have the Emacs instance showing up in a different virtual
desktop, or somehow prevent it from becoming visible immediately?  It
could be that this window manager somehow prevents Emacs from getting
the expected events to udpate frame visibility correctly.

> Notice how configuring of package `recentf' suddenly appears to stand
> out and it contains that single 100 ms delay.  Curiously no matter how
> many times I restart Emacs, it's always `recentf' that gets this
> delay. I have no idea why but it's for sure related.

I suppose either recentf and/or your configuration of it are doing
something which takes a lot of time (e.g., reading from disk).

> Look how as soon as `minibuffer-auto-raise' is set to t,
> configurations of all subsequent packages obviously get delayed by 100
> ms each.  This is most probably caused by the messages being written
> to minibuffer.

Right.

> On 11/09/2017 11:09 PM, Alexander Shukaev wrote:
>> - `x-wait-for-event-timeout' is nil, there are no additional delays at all.
>
> Ha, I take this last phrase back.  It's actually getting interesting,
> in fact, when `x-wait-for-event-timeout' is nil:
>
> Configuring package recentf...done (0.365s)
>
> but with `x-wait-for-event-timeout' being 0.1:
>
> Configuring package recentf...done (0.131s)
>
> it's back to lower again.  Whaaat?

Is this consistent, or perhaps just a fluke?

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Noam Postavsky]

close 29095 
quit

Noam Postavsky <npostavs@users.sourceforge.net> writes:

> Do you have the Emacs instance showing up in a different virtual
> desktop, or somehow prevent it from becoming visible immediately?  It
> could be that this window manager somehow prevents Emacs from getting
> the expected events to udpate frame visibility correctly.

>> Ha, I take this last phrase back.  It's actually getting interesting,
>> in fact, when `x-wait-for-event-timeout' is nil:
>>
>> Configuring package recentf...done (0.365s)
>>
>> but with `x-wait-for-event-timeout' being 0.1:
>>
>> Configuring package recentf...done (0.131s)
>>
>> it's back to lower again.  Whaaat?
>
> Is this consistent, or perhaps just a fluke?

Seems we're not going to get any more answers.  Closing.

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 > My (tiling) window manager is BSPWM
 > <https://github.com/baskerville/bspwm>.  Now let's see what happens
 > when
 > - `minibuffer-auto-raise' is nil,
 > - `x-wait-for-event-timeout' is 0.1 (default):
[...]
 > Configuring package minibuffer...done
 > Configuring package minibuffer-line...done

Using a tiling window manager plus ‘minibuffer-auto-raise’ plus
‘minibuffer-line’ is about the worst case scenario I could only imagine.
In practice, it means that all visible windows on your desktop may have
to be resized whenever an Emacs message is shown or the contents of the
modeline of the selected Emacs window changes.

 > Configuring package recentf...
 > Loading ~/.emacs.d/.recentf.el (source)...done
 > Configuring package recentf-ext...done
 > Configuring package sync-recentf...done
 > Configuring package recentf...done (0.135s)
[...]
 >
 > Notice how configuring of package `recentf' suddenly appears to stand
 > out and it contains that single 100 ms delay.  Curiously no matter how
 > many times I restart Emacs, it's always `recentf' that gets this
 > delay. I have no idea why but it's for sure related.  Anyway, let's
 > disregard it for a moment and assume that it is still fine.  Now let's
 > see what happens when

As I never configure any packages I don't understand what you're doing.
For example, I have no idea what configuring packages like "simple" or
"window" does.  But note that recentf.el is the only one of your
"packages" loaded from source and descends into two sub-packages (or
whatever these are) before completing.  And obviously it might look into
the availability of your recent files which could take some time.

 > Configuring package window...done
 > ---------------------------------------------------------
 >  >>> *minibuffer-auto-raise is set to t at this point* <<<
 > ---------------------------------------------------------
 > Configuring package minibuffer-line...done (0.106s)

Who sets that and what happened to the

Configuring package minibuffer...done

line?

 > Look how as soon as `minibuffer-auto-raise' is set to t,
 > configurations of all subsequent packages obviously get delayed by 100
 > ms each.  This is most probably caused by the messages being written
 > to minibuffer.

Sure.  I suppose your window manager is in heavy troubles.  Why can't
you delay setting ‘minibuffer-auto-raise’ at least until after loading
is complete?

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[martin rudalics]

 > It occurs to me that another possibility is simply to disable the
 > timeout when doing the auto-raise.  We have the timeout due some users'
 > configurations accidentally relying on the fact that a frame will be
 > visible after make-frame returns, but it seems unlikely that anyone
 > would manage to rely on the frame being visible after a call to
 > `message' occurs.

But missing a message from an auto-raising frame does not sound like a
good idea either.  That is, if the timeout is supposed to catch a
problem with the Emacs/window manager interaction and to prevent Emacs
from proceeding until some user decision based on something to be shown
in a visible frame has been made.

I wish we would have had the courage to go through with your first
solution - omit such waits completely.  I'm still surprised that we had
so few complaints back then ...

martin

bug#29095: Bug: The '20a09de953f437109a098fa8c4d380663d921481' merge increased my Emacs configuration loading time from 9 s to 60 s

[Eli Zaretskii]

> From: Alexander Shukaev <emacs@Alexander.Shukaev.name>
> Date: Wed, 1 Nov 2017 01:44:50 +0100
> 
> Decided to try pretest of 26.0.90 and immediately discovered that it is 
> slower than, for example, 'e7f65187580342171dd9ad32e570c50c96badb13' 
> which I used before.  In particular, thanks to a couple of hours of 
> bisecting, I found that the '20a09de953f437109a098fa8c4d380663d921481' 
> merge increased my Emacs configuration loading time from 9 s to 60 s, 

By "Emacs configuration loading time" you mean the time it takes Emacs
to start up when you type "emacs" at the shell prompt?  Or do you mean
something else?

> which is unacceptable.  I have no idea how this made it's way to the 
> 'master' branch.  Furthermore, other operations like navigation across 
> windows or performing an incremental search are also noticeably slower, 
> i.e. they stutter annoyingly

Is your build optimized or unoptimized?  If the latter, perhaps your
previous build was optimized?  The difference between them could be a
factor of 2.5 in speed.

> and from what I see is a result of extensive GC spam which did not
> occur in previous versions.

What do you mean by "extensive GC spam"?

Also, in what major mode(s) and what kind of files do you see this
performance degradation?

Thanks.