Re: [O] elp-instrument-package does not return anything

[Sebastien Vauban]

Hello,

(I did not see my previous answer to this, so redoing it)

"Sebastien Vauban" wrote:
> For the sake of finding potential bottlenecks in my config, I'm looking back
> at elp.
>
> I've the following minimal Emacs config file for the current work: [...]
>
> Though, for whatever unknown reason, when calling elp-results, I just get info
> about font-lock.
>
> Nothing about Org!?
>
> I'm really out of ideas about what to do to get those Org profiling results?
> Any idea of what I'm doing wrong (I guess)?

As found out by Bastien, one needs to require the packages first, before
instrumenting them. Not automatic!

OK, so, with the new Emacs *minimal config*:

--8<---------------cut here---------------start------------->8---
;; activate debugging
(setq debug-on-error t)
(setq debug-on-quit t)

;; change the pathnames appropriately!
(add-to-list 'load-path (expand-file-name "~/src/org-mode/lisp"))
(add-to-list 'load-path (expand-file-name "~/src/org-mode/contrib/lisp"))

(require 'org)
(require 'org-agenda)
(require 'outline)
(require 'font-lock)
(require 'flyspell)
(require 'ispell)
(require 'calendar)
(require 'cal-iso)
(require 'diary-lib)

;; profile some times... CAUTION: require the packages first (to get results)!
(when (require 'elp)
  ;; the most important ones
  (elp-instrument-package "org")
  (elp-instrument-package "org-agenda")
  (elp-instrument-package "outline")
  (elp-instrument-package "font-lock")
  (elp-instrument-package "flyspell")
  (elp-instrument-package "ispell")
  (elp-instrument-package "emacs-leuven")
  (elp-instrument-package "calendar")
  (elp-instrument-package "cal-iso")
  (elp-instrument-package "diary-lib")

  (global-set-key "\C-ce" 'elp-results))

;; improve readability of profile results, give milliseconds
(defun elp-pack-number (number width)
  (format (concat "%" (number-to-string (- width 3)) ".2f")
          (* 100 (string-to-number number))))

(setq org-agenda-files
      (append
       ;; org-directory
       (file-expand-wildcards "~/Personal/*.org")
       (file-expand-wildcards "~/Projects/*.org")))

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

Generating the agenda for 43 files, and more or less 75 entries to display,
takes between 17 and 20 seconds, in this case 19 seconds:

--8<---------------cut here---------------start------------->8---
org-agenda-list                                               1           
19.156        19.156
org-agenda-prepare                                            1           
11.141        11.141
org-agenda-prepare-buffers                                    1           
11.078        11.078
org-get-agenda-file-buffer                                    344         
11.064000000  0.0321627906
org-agenda-get-day-entries                                    301         
7.5179999999  0.0249767441
org-agenda-get-scheduled                                      301         
4.5180000000  0.0150099667
org-mode                                                      43          
3.7710000000  0.0876976744
org-entry-get                                                 2601        
2.0339999999  0.0007820069
org-back-to-heading                                           11116       
1.9679999999  0.0001770421
org-get-property-block                                        2601        
1.9089999999  0.0007339484
outline-back-to-heading                                       11116       
1.7799999999  0.0001601295
org-set-startup-visibility                                    43          1.391 
        0.0323488372
org-agenda-get-deadlines                                      301         1.36  
        0.0045182724
org-get-todo-state                                            3782        
1.3399999999  0.0003543098
org-agenda-files                                              46          
0.8050000000  0.0175000000
org-cycle-internal-global                                     43          
0.7810000000  0.0181627906
org-cycle                                                     43          
0.7810000000  0.0181627906
org-install-agenda-files-menu                                 43          
0.7740000000  0.0180000000
org-agenda-skip                                               4636        
0.7170000000  0.0001546591
org-agenda-get-sexps                                          301         
0.7020000000  0.0023322259
outline-next-heading                                          7764        
0.6780000000  8.73...e-005
org-overview                                                  43          
0.6720000000  0.0156279069
outline-map-region                                            43          
0.6090000000  0.0141627906
org-load-modules-maybe                                        86          0.594 
        0.0069069767
org-time-string-to-absolute                                   3759        
0.5170000000  0.0001375365
org-parse-time-string                                         4088        0.5   
        0.0001223091
org-set-regexps-and-options                                   43          
0.4970000000  0.0115581395
org-cycle-hide-drawers                                        86          
0.4050000000  0.0047093023
org-find-base-buffer-visiting                                 344         
0.4040000000  0.0011744186
org-agenda-get-timestamps                                     301         
0.3590000000  0.0011926910
org-agenda-get-blocks                                         301         
0.3470000000  0.0011528239
org-diary-sexp-entry                                          714         
0.3280000000  0.0004593837
org-flag-drawer                                               1396        
0.2970000000  0.0002127507
org-before-first-heading-p                                    2602        
0.2820000000  0.0001083781
org-outline-level                                             4313        0.265 
        6.14...e-005
org-cycle-show-empty-lines                                    86          
0.2050000000  0.0023837209
org-agenda-finalize-entries                                   4           0.203 
        0.05075
org-macro-initialize-templates                                43          
0.1730000000  0.0040232558
org-get-tags-at                                               84          
0.1710000000  0.0020357142
org-up-heading-safe                                           225         0.14  
        0.0006222222
org-entries-lessp                                             372         0.14  
        0.0003763440
org-all-targets                                               43          0.138 
        0.0032093023
org-update-radio-target-regexp                                43          0.138 
        0.0032093023
org-babel-hide-all-hashes                                     43          0.127 
        0.0029534883
org-time-string-to-time                                       168         0.125 
        0.0007440476
org-closest-date                                              161         0.11  
        0.0006832298
org-agenda-format-item                                        84          0.109 
        0.0012976190
org-in-src-block-p                                            4636        0.093 
        2.00...e-005
org-file-contents                                             16          0.093 
        0.0058125
org-agenda-align-tags                                         1           0.093 
        0.093
org-agenda-finalize                                           1           0.093 
        0.093
org-refresh-category-properties                               43          0.092 
        0.0021395348
org-set-visibility-according-to-property                      43          0.078 
        0.0018139534
org-fit-window-to-buffer                                      1           0.078 
        0.078
org-agenda-skip-eval                                          9124        0.078 
        8.54...e-006
org-agenda-fit-window-to-buffer                               1           0.078 
        0.078
outline-flag-region                                           1672        0.078 
        4.66...e-005
org-agenda-highlight-todo                                     84          0.063 
        0.00075
org-agenda-todayp                                             609         0.062 
        0.0001018062
...
--8<---------------cut here---------------end--------------->8---

Is this normal?  For a 6-year old laptop?

In particular, when looking at the top entries:

--8<---------------cut here---------------start------------->8---
org-agenda-list                                               1           
19.156        19.156
org-agenda-prepare                                            1           
11.141        11.141
org-agenda-prepare-buffers                                    1           
11.078        11.078
org-get-agenda-file-buffer                                    344         
11.064000000  0.0321627906
org-agenda-get-day-entries                                    301         
7.5179999999  0.0249767441
org-agenda-get-scheduled                                      301         
4.5180000000  0.0150099667
org-mode                                                      43          
3.7710000000  0.0876976744
--8<---------------cut here---------------end--------------->8---

I'm amazed by:

- the difference between the 3 seconds for the 43 calls to `org-mode' and the
  final 19 seconds for the list to be displayed

- the difference as well between the top 2 functions: `org-agenda-prepare'
  "only" takes 11 seconds, while `org-agenda-list' consumes another
  8 seconds...

Any comment on this?

Best regards,
Seb

-- 
Sebastien Vauban