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