GNU bug report logs - #14987
Where is the time spent?

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 14987 in the body.
You can then email your comments to 14987 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: "Sebastien Vauban" <sva-news <at> mygooglest.com>
To: bug-gnu-emacs <at> gnu.org
Subject: Where is the time spent?
Date: Tue, 30 Jul 2013 17:05:20 +0200

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

Message #8 received at 14987 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: "Sebastien Vauban" <sva-news <at> mygooglest.com>
Cc: 14987 <at> debbugs.gnu.org
Subject: Re: bug#14987: Where is the time spent?
Date: Tue, 30 Jul 2013 11:38:40 -0400

> 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

Message #15 received at 14987 <at> debbugs.gnu.org (full text, mbox):

From: Nicolas Richard <theonewiththeevillook <at> yahoo.fr>
To: "Sebastien Vauban" <public-sva-news-D0wtAvR13HarG/iDocfnWg <at> plane.gmane.org>
Cc: public-14987-ubl+/3LiMTaZdePnXv/OxA <at> plane.gmane.org
Subject: Re: bug#14987: Where is the time spent?
Date: Tue, 30 Jul 2013 18:05:34 +0200

Hi,

"Sebastien Vauban" <sva-news-D0wtAvR13HarG/iDocfnWg <at> 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.

Message #18 received at 14987 <at> debbugs.gnu.org (full text, mbox):

From: Glenn Morris <rgm <at> gnu.org>
To: Nicolas Richard <theonewiththeevillook <at> yahoo.fr>
Cc: 14987 <at> debbugs.gnu.org
Subject: Re: bug#14987: Where is the time spent?
Date: Tue, 30 Jul 2013 12:23:57 -0400

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)

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.