bug#14987: Where is the time spent?

bug#14987: Where is the time spent?

[Sebastien Vauban]

Hello,

With the minimal .emacs file given previously:

--8<---------------cut here---------------start------------->8---
(defconst em/emacs-load-time-start (float-time))

(defadvice message (before leuven-when-was-that activate)
  "Add timestamps to `message' output."
  (ad-set-arg 0 (concat (format-time-string "[%Y-%m-%d %T.")
                        (substring (format-time-string "%N") 0 3)
                        (format-time-string "] ")
                        (ad-get-arg 0))))

(dolist (i '(1 2 3 4 5 6 7 8 9 10))
  (setq org-ellipsis
         (if (char-displayable-p ?\u25B7) ;; white right-pointing triangle
             " \u25B7" ;; string
           'org-ellipsis))
  (message "Call nr %s" i))

(message "Loading Minimal Emacs... Done (in %.2f s)"
         (- (float-time) em/emacs-load-time-start))
--8<---------------cut here---------------end--------------->8---

I have timing information I don't understand in the *Messages* buffer:

--8<---------------cut here---------------start------------->8---
For information about GNU Emacs and the GNU system, type C-h C-a.
[2013-07-29 10:08:14.866] Call nr 1
[2013-07-29 10:08:14.869] Call nr 2
[2013-07-29 10:08:14.870] Call nr 3
[2013-07-29 10:08:14.870] Call nr 4
[2013-07-29 10:08:14.871] Call nr 5
[2013-07-29 10:08:14.872] Call nr 6
[2013-07-29 10:08:14.872] Call nr 7
[2013-07-29 10:08:14.873] Call nr 8
[2013-07-29 10:08:14.873] Call nr 9
[2013-07-29 10:08:14.874] Call nr 10
[2013-07-29 10:08:14.874] Loading Minimal Emacs... Done (in 0.58 s)
--8<---------------cut here---------------end--------------->8---

14.874 (after last call) - 14.866 (after first call) is 0.008 s, not really
0.580 s!???

Something really escapes me here.

I can understand that some time is spent AFTER having read my .emacs file.
But that's NOT the time I report here. So, where is the time spent?  Or do I
have a bug in the way I report timing information?

Best regards,
  Seb

-- 
Sebastien Vauban

bug#14987: Where is the time spent?

[Stefan Monnier]

> Something really escapes me here.

em/emacs-load-time-start is the time at the very beginning of reading
your .emacs.  [2013-07-29 10:08:14.866] is the time at which `message'
is called for the first time.  Between the two,
(char-displayable-p ?\u25B7) was called.


        Stefan

bug#14987: Where is the time spent?

[Nicolas Richard]

Hi,

"Sebastien Vauban" <sva-news-D0wtAvR13HarG/iDocfnWg@public.gmane.org>
writes:
> With the minimal .emacs file given previously:

Based on Stefan's answer, here's the .emacs file I used to do some tests
for myself :

--8<---------------cut here---------------start------------->8---
(defconst em/emacs-load-time-start (float-time))

(message "%s Beginning" (format-time-string "[%Y-%m-%d %T.%3N] "))

(defadvice message (before leuven-when-was-that activate)
  "Add timestamps to `message' output."
  (ad-set-arg 0 (concat (format-time-string "[%Y-%m-%d %T.%3N] ")
                        (ad-get-arg 0))))
(message "Advice set")

(dotimes (i 10)
  (setq org-ellipsis
        (if (char-displayable-p ?\u25B7) ;; white right-pointing triangle
            " \u25B7"                    ;; string
          'org-ellipsis))
  (message "Call nr %s" (1+  i)))

(message "Loading Minimal Emacs... Done (in %.3f s)"
         (- (float-time) em/emacs-load-time-start))
--8<---------------cut here---------------start------------->8---

(I also did some unnecessary modifications.)

Now it seems to match perfectly (defadvice takes some time here, too)

-- 
Nico.

bug#14987: Where is the time spent?

[Glenn Morris]

Nicolas Richard wrote:

> (defconst em/emacs-load-time-start (float-time))

= before-init-time

> (message "Loading Minimal Emacs... Done (in %.3f s)"
>          (- (float-time) em/emacs-load-time-start))

= (emacs-init-time)