From mboxrd@z Thu Jan 1 00:00:00 1970 From: "Sebastien Vauban" Subject: Re: Huge performance problems to open some Org files Date: Fri, 13 May 2011 00:27:21 +0200 Message-ID: <80aaero8qe.fsf@somewhere.org> References: <8062uswyie.fsf@missioncriticalit.com> <1C972FF9-236E-45EC-9885-EE69656F0769@gmail.com> <8062usv8ck.fsf@missioncriticalit.com> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" Return-path: List-Id: "General discussions about Org-mode." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: emacs-orgmode-bounces+geo-emacs-orgmode=m.gmane.org-mXXj517/zsQ@public.gmane.org Sender: emacs-orgmode-bounces+geo-emacs-orgmode=m.gmane.org-mXXj517/zsQ@public.gmane.org To: emacs-orgmode-mXXj517/zsQ@public.gmane.org --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hi Andrew, Vladimir, Nick, Achim, Carsten & al, Vladimir Alexiev wrote: > S=C3=A9bastien Vauban writes: >> Believe me or not, but C-g has not effect during those 7 seconds. It sim= ply >> does not stop anything > > Sounds like emacs is waiting inside some blocking call, and waits until it > times out. Likely a network call. Do you have any tramp/efs/angeftp stuff > going on? This has gotten worse. But, now, I have some proofs about what I experience: opening the attached Org file (2 KB) consumes me 191 seconds, yes 191 secon= ds, even when done after the agenda view has been launched -- I mean, all agenda files and all Org files have been read... --8<---------------cut here---------------start------------->8--- | find-file | start |c:/home/sva/Public/tags-opening-it-is-sloooooooooow.or= g | ___ | +-> Requiring `org-exp' (already loaded) OVERVIEW in c:/home/sva/Public/tags-opening-it-is-sloooooooooow.org Checking for library `filladapt'... +-> Requiring `filladapt' (already loaded) Checking for library `filladapt'... Found +-> Requiring `outline-mode-easy-bindings' (already loaded) +-> Requiring `bytecomp' (already loaded) Checking for library `filladapt'... +-> Requiring `filladapt' (already loaded) Checking for library `filladapt'... Found | find-file | stop | c:/home/sva/Public/tags-opening-it-is-sloooooooooow.or= g | 191.3 | --8<---------------cut here---------------end--------------->8--- Note that the variance is 0.1 second, over 3 Emacs restarts! Pretty reproducible... To obtain the above trace, I've added the following bits to my .emacs file: #+begin_src emacs-lisp ;; redefine require to leave a trace of packages being loaded (if (not (fboundp 'orig-require)) (fset 'orig-require (symbol-function 'require)) (message "The code to redefine `require' should not be loaded tw= ice")) (defvar my/require-depth 0) (defun require (feature &optional filename noerror) "Leave a trace of packages being loaded." (cond ((member feature features) (message "%sRequiring `%s' (already loaded)" (concat (make-string (* 2 my/require-depth) ? ) "+-> ") feature)) (t (message "%sRequiring `%s'" (concat (make-string (* 2 my/require-depth) ? ) "+-> ") feature) (let ((my/require-depth (+ 1 my/require-depth))) (orig-require feature filename noerror)) (message "%sRequiring `%s'...done" (concat (make-string (* 2 my/require-depth) ? ) "+-> ") feature)))) (defvar missing-packages-list nil "List of packages that `try-require' can't find.") ;; attempt to load a feature/library, failing silently (defun try-require (feature) "Attempt to load a library or module. Return true if the library given as argument is successfully loaded. If not, instead of an error, just add the package to a list of missing packages." (condition-case err ;; protected form (progn (message "Checking for library `%s'..." feature) (if (stringp feature) (load-library feature) (require feature)) (message "Checking for library `%s'... Found" feature)) ;; error handler (file-error ; condition (progn (message "Checking for library `%s'... Missing" feature) (add-to-list 'missing-packages-list feature 'append)) nil))) (defadvice find-file (around my-find-file activate) "Open FILENAME and report time spent." (let* ((my-filename (ad-get-arg 0)) (find-file-time-start (float-time))) (message (concat "| find-file | start |" my-filename " | ___ |")) ad-do-it (message "| find-file | stop | %s | %.1f |" my-filename (- (float-time) find-file-time-start)))) #+end_src Trying to profile: #+begin_src emacs-lisp (elp-instrument-package "org") (elp-instrument-package "outline") (elp-instrument-package "font-lock") (elp-instrument-package "flyspell") (elp-instrument-package "bytecomp") (elp-instrument-package "color-theme") (elp-instrument-package "company") (elp-instrument-package "custom") (elp-instrument-package "files") (elp-instrument-package "filladapt") (elp-instrument-package "help-fns") (elp-instrument-package "ispell") (elp-instrument-package "outline-mode-easy-bindings")) #+end_src did not help finding the culprit: --8<---------------cut here---------------start------------->8--- custom-declare-variable 1733 0.73= 5 0.0004241200 flyspell-mode 51 0.42= 10000000 0.0082549019 flyspell-post-command-hook 10 0.37= 59999999 0.0375999999 custom-initialize-default 33 0.37= 5 0.0113636363 flyspell-word 9 0.36= 09999999 0.0401111111 outline-back-to-heading 5684 0.34= 30000000 6.03...e-005 custom-initialize-reset 1699 0.32= 80000000 0.0001930547 flyspell-mode-on 50 0.28= 1 0.0056200000 ispell-init-process 98 0.26= 5 0.0027040816 flyspell-accept-buffer-local-defs 107 0.25= 1 0.0023457943 ispell-accept-buffer-local-defs 98 0.25= 1 0.0025612244 outline-map-region 47 0.22= 00000000 0.0046808510 custom-declare-face 133 0.21= 90000000 0.0016466165 ispell-accept-output 2 0.20= 19999999 0.1009999999 outline-next-heading 5095 0.17= 20000000 3.37...e-005 font-lock-set-defaults 580 0.12= 5 0.0002155172 font-lock-add-keywords 226 0.12= 5 0.0005530973 font-lock-compile-keywords 180 0.12= 5 0.0006944444 ispell-buffer-local-words 98 0.12= 5 0.0012755102 ispell-buffer-local-parsing 97 0.09= 39999999 0.0009690721 color-theme-install-faces 1 0.07= 79999999 0.0779999999 color-theme-install 1 0.07= 79999999 0.0779999999 color-theme-leuven 1 0.07= 79999999 0.0779999999 font-lock-default-fontify-region 24 0.07= 7 0.0032083333 font-lock-fontify-keywords-region 24 0.07= 7 0.0032083333 font-lock-fontify-region 24 0.07= 7 0.0032083333 ispell-check-version 2 0.04= 7 0.0235 ispell-call-process 2 0.04= 7 0.0235 outline-show-heading 240 0.03= 2 0.0001333333 outline-on-heading-p 5750 0.03= 2 5.56...e-006 flyspell-word-search-forward 2 0.03= 2 0.016 custom-handle-keyword 2611 0.03= 2 1.22...e-005 ispell-buffer-local-dict 98 0.03= 2 0.0003265306 flyspell-check-spell-program 50 0.03= 0.0006 outline-flag-region 1375 0.01= 6 1.16...e-005 flyspell-get-word 12 0.01= 6 0.0013333333 color-theme-filter 3 0.01= 6 0.0053333333 ispell-get-otherchars 12 0.01= 6 0.0013333333 ispell-start-process 2 0.01= 6 0.008 ispell-internal-change-dictionary 98 0.01= 6 0.0001632653 font-lock-default-fontify-buffer 7 0.01= 5 0.0021428571 font-lock-fontify-buffer 7 0.01= 5 0.0021428571 flyspell-check-pre-word-p 10 0.01= 5 0.0015 outline-invisible-p 98 0.0 = 0.0 outline-previous-heading 419 0.0 = 0.0 outline-up-heading 38 0.0 = 0.0 outline-end-of-heading 359 0.0 = 0.0 outline-mode 49 0.0 = 0.0 font-lock-prepend-text-property 59 0.0 = 0.0 font-lock-update-removed-keyword-alist 1 0.0 = 0.0 font-lock-mode-internal 101 0.0 = 0.0 font-lock-extend-region-wholelines 26 0.0 = 0.0 font-lock-extend-jit-lock-region-after-change 12 0.0 = 0.0 font-lock-unfontify-buffer 2 0.0 = 0.0 font-lock-choose-keywords 51 0.0 = 0.0 font-lock-remove-keywords 225 0.0 = 0.0 font-lock-mode 208 0.0 = 0.0 font-lock-unfontify-region 26 0.0 = 0.0 font-lock-after-unfontify-buffer 2 0.0 = 0.0 font-lock-default-function 208 0.0 = 0.0 font-lock-after-fontify-buffer 7 0.0 = 0.0 font-lock-change-mode 51 0.0 = 0.0 font-lock-turn-off-thing-lock 2 0.0 = 0.0 font-lock-extend-region-multiline 26 0.0 = 0.0 font-lock-eval-keywords 102 0.0 = 0.0 font-lock-default-unfontify-buffer 2 0.0 = 0.0 font-lock-compile-keyword 7464 0.0 = 0.0 font-lock-fontify-syntactically-region 7 0.0 = 0.0 font-lock-default-unfontify-region 26 0.0 = 0.0 font-lock-value-in-major-mode 249 0.0 = 0.0 font-lock-turn-on-thing-lock 99 0.0 = 0.0 flyspell-word-search-backward 2 0.0 = 0.0 flyspell-hack-local-variables-hook 48 0.0 = 0.0 flyspell-check-word-p 10 0.0 = 0.0 flyspell-delete-all-overlays 1 0.0 = 0.0 flyspell-kill-ispell-hook 5 0.0 = 0.0 flyspell-highlight-duplicate-region 1 0.0 = 0.0 flyspell-after-change-function 12 0.0 = 0.0 flyspell-delay-commands 49 0.0 = 0.0 flyspell-pre-command-hook 10 0.0 = 0.0 flyspell-get-not-casechars 19 0.0 = 0.0 flyspell-prog-mode 1 0.0 = 0.0 flyspell-highlight-incorrect-region 1 0.0 = 0.0 flyspell-mode-off 1 0.0 = 0.0 flyspell-deplacement-command 196 0.0 = 0.0 flyspell-delay-command 294 0.0 = 0.0 flyspell-generic-progmode-verify 8 0.0 = 0.0 flyspell-deplacement-commands 49 0.0 = 0.0 flyspell-get-casechars 12 0.0 = 0.0 flyspell-delete-region-overlays 38 0.0 = 0.0 flyspell-unhighlight-at 12 0.0 = 0.0 color-theme-frame-params 1 0.0 = 0.0 color-theme-alist 2 0.0 = 0.0 color-theme-spec-compat 448 0.0 = 0.0 color-theme-variables 1 0.0 = 0.0 color-theme-plist-delete 8 0.0 = 0.0 color-theme-install-frame-params 1 0.0 = 0.0 color-theme-install-variables 1 0.0 = 0.0 color-theme-faces 1 0.0 = 0.0 color-theme-alist-reduce 2 0.0 = 0.0 color-theme-spec-filter 1 0.0 = 0.0 color-theme-canonic 1 0.0 = 0.0 custom-handle-all-keywords 82 0.0 = 0.0 custom-add-link 136 0.0 = 0.0 custom-add-to-group 2183 0.0 = 0.0 custom-declare-group 200 0.0 = 0.0 custom-current-group 25 0.0 = 0.0 custom-add-version 237 0.0 = 0.0 custom-initialize-set 1 0.0 = 0.0 custom-set-default 2 0.0 = 0.0 custom-add-option 4 0.0 = 0.0 custom-add-dependencies 2 0.0 = 0.0 ispell-get-casechars 13 0.0 = 0.0 ispell-send-string 208 0.0 = 0.0 ispell-set-spellchecker-params 59 0.0 = 0.0 ispell-process-status 98 0.0 = 0.0 ispell-check-minver 8 0.0 = 0.0 ispell-get-decoded-string 44 0.0 = 0.0 ispell-parse-output 7 0.0 = 0.0 ispell-get-ispell-args 2 0.0 = 0.0 ispell-get-extended-character-mode 99 0.0 = 0.0 ispell-get-not-casechars 19 0.0 = 0.0 ispell-filter 9 0.0 = 0.0 ispell-get-many-otherchars-p 12 0.0 = 0.0 ispell-get-coding-system 90 0.0 = 0.0 ispell-decode-string 43 0.0 = 0.0 ispell-kill-ispell 5 0.0 = 0.0 --8<---------------cut here---------------end--------------->8--- Any idea in which direction to go? Environment: Org-mode version 7.5 (release_7.5.274.gd6aba.dirty) GNU Emacs 23.1.50.1 (i386-mingw-nt5.1.2600) of 2009-10-14 on LENNART-69DE= 564 (patched) on Windows XP SP3 Best regards, Seb --=20 S=C3=A9bastien Vauban --=-=-= Content-Type: text/x-org; charset=utf-8 Content-Disposition: attachment; filename=tags-opening-it-is-sloooooooooow.org Content-Transfer-Encoding: quoted-printable #+TITLE: Tags FIXME #+AUTHOR: Seb Vauban #+EMAIL: no-LMehjL4SQ+Y@public.gmane.org #+DATE: 2011-05-13 #+DESCRIPTION:=20 #+KEYWORDS:=20 #+LANGUAGE: en_US #+STYLE: This page is useless for you. It's only for me, for testing some code. Ce texte est en fran=C3=A7ais. This is in English. * Environments The following are different environments, from the best to the less good... The worse are not even shown ;-) See http://orgmode.org/manual/Literal-examples.html#Literal-examples. ** Src with highlighting #+BEGIN_SRC sh #!/bin/sh #!/bin/sh 123456789 223456789 333456789 444456789 555556789 666666789 77= 7777789 888888889 999999999 000000000 000000000 # script -- What it does # Exits with zero if no error. Looooooonnnng comment... 0123 4567 8901 2= 345 6789 0123 abcd efgh ijkl mnop qrst uvwx yz01 2345 6789 0abc tempfile=3D"/tmp/$(basename $0).tmp" # 80 chars exactly =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D trap "/bin/rm -f $tempfile" EXIT HUP INT QUIT TERM function usage() { cat << EOF >&2 Usage: $(basename $0) flags... Where... EOF exit 1 } if [ $# -eq 0 ]; then usage fi #+END_SRC ** Example #+BEGIN_EXAMPLE #!/bin/sh #!/bin/sh 123456789 223456789 333456789 444456789 555556789 666666789 77= 7777789 888888889 999999999 000000000 000000000 # script -- What it does # Exits with zero if no error. Looooooonnnng comment... 0123 4567 8901 2= 345 6789 0123 abcd efgh ijkl mnop qrst uvwx yz01 2345 6789 0abc tempfile=3D"/tmp/$(basename $0).tmp" # 80 chars exactly =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D trap "/bin/rm -f $tempfile" EXIT HUP INT QUIT TERM function usage() { cat << EOF >&2 Usage: $(basename $0) flags... Where... EOF exit 1 } if [ $# -eq 0 ]; then usage fi #+END_EXAMPLE --=-=-=--