* bug#14987: Where is the time spent?
@ 2013-07-30 15:05 Sebastien Vauban
2013-07-30 15:38 ` Stefan Monnier
2013-07-30 16:05 ` Nicolas Richard
0 siblings, 2 replies; 4+ messages in thread
From: Sebastien Vauban @ 2013-07-30 15:05 UTC (permalink / raw)
To: 14987-ubl+/3LiMTaZdePnXv/OxA
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
^ permalink raw reply [flat|nested] 4+ messages in thread
* bug#14987: Where is the time spent?
2013-07-30 15:05 bug#14987: Where is the time spent? Sebastien Vauban
@ 2013-07-30 15:38 ` Stefan Monnier
2013-07-30 16:05 ` Nicolas Richard
1 sibling, 0 replies; 4+ messages in thread
From: Stefan Monnier @ 2013-07-30 15:38 UTC (permalink / raw)
To: Sebastien Vauban; +Cc: 14987
> 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
^ permalink raw reply [flat|nested] 4+ messages in thread
* bug#14987: Where is the time spent?
2013-07-30 15:05 bug#14987: Where is the time spent? Sebastien Vauban
2013-07-30 15:38 ` Stefan Monnier
@ 2013-07-30 16:05 ` Nicolas Richard
2013-07-30 16:23 ` Glenn Morris
1 sibling, 1 reply; 4+ messages in thread
From: Nicolas Richard @ 2013-07-30 16:05 UTC (permalink / raw)
To: Sebastien Vauban; +Cc: public-14987-ubl+/3LiMTaZdePnXv/OxA
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.
^ permalink raw reply [flat|nested] 4+ messages in thread
* bug#14987: Where is the time spent?
2013-07-30 16:05 ` Nicolas Richard
@ 2013-07-30 16:23 ` Glenn Morris
0 siblings, 0 replies; 4+ messages in thread
From: Glenn Morris @ 2013-07-30 16:23 UTC (permalink / raw)
To: Nicolas Richard; +Cc: 14987
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)
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2013-07-30 16:23 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-07-30 15:05 bug#14987: Where is the time spent? Sebastien Vauban
2013-07-30 15:38 ` Stefan Monnier
2013-07-30 16:05 ` Nicolas Richard
2013-07-30 16:23 ` Glenn Morris
Code repositories for project(s) associated with this external index
https://git.savannah.gnu.org/cgit/emacs.git
https://git.savannah.gnu.org/cgit/emacs/org-mode.git
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.