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