Re: font-lock-after-change function unbearably slow; Ben change?

Stephen J. Turnbull writes: > >>>>> "Ben" == Ben Wing <ben(a)666.com&gt; writes: > > Ben> indeed i did change this and i can't see why those calls to > Ben> make-extent should have such a slowdown effect. > > I was afraid of that. > > Ben> [b] someone broke the redisplay extent optimization code. > > Can you give me some function names or other ways to localize > dangerous changes for `cvs annotate'? I consider this a priority item > for the release. Slow font-lock sucks badly for too many people. > > Ben> but even more to the point, redisplay should not even be > Ben> getting called at all. > > The only thing I can think of off-hand is that Andy has done several > "set-yet-another-dirty-flag" fixes for the widget code. Andy? > > Chris, do you have the progress bar enabled? It may not matter if > it's invisible, depending on where those flags are getting set. (NB: > Matt Tucker's password buffer bug is a background font-lock problem.) > Okay. I've got some more information. If I use beta32, which is an interesting data point because it's the first xemacs that has the progress bar (or at least a visible progress bar in my environment) it looks like the options.el file is being loaded several times. However, the time to save the customization file is still pretty fast. I'm afraid I don't even have the menubar enabled, let alone the progress bar. Also, it doesn't seem like the font-lock-after-change-function is getting called any more now than before. Both weigh in at 7934 calls. Oh, and font-lock-always-fontify-immediately is definitely nil. I couldn't imagine having that variable set to t. :-) In fact, I even commented out the check in font-lock-after-change-function to make sure. Here's my methodology: (define-key global-map [(control c) (control f)] (function (lambda () (interactive) (if (profiling-active-p) (progn (stop-profiling) (message "...Finished profiling")) (message "Profiling...") (clear-profiling-info) (start-profiling))))) I used the above function to control start/stop of profile. The experiment entailed going to a customization buffer with lazy-shot, changing something, and profiling the save of the customization file. Although the profile includes me hitting "C-c C-f" a couple of times, plus a C-g, they're way in the noise. Here's my results: ; Trial #1: Out-of-the-box font-lock.el version b43. Stopped save before ; completion. font-lock-after-change-function looks like this: (defun font-lock-after-change-function (beg end old-len) (when font-lock-mode (let ((ex (make-extent beg end))) (set-extent-property ex 'detachable nil) (set-extent-property ex 'end-open nil) (let ((exs (gethash (current-buffer) font-lock-pending-extent-table))) (push ex exs) (puthash (current-buffer) exs font-lock-pending-extent-table))) (if font-lock-always-fontify-immediately (font-lock-fontify-pending-extents)))) ))) (profile-results) Function Name Ticks %/Total Call Count =============================== ===== ======= ========== prin1 2788 74.987 427 princ 868 23.346 674 (in garbage collection) 24 0.646 #<compiled-function (symbol) "...(119)" [spec now requests comment symbol #theme-value custom-requests standard-value boundp force-value rogue saved-variable-comment user set princ '( prin1 saved-value t nil )] 6> 5 0.134 14798 make-extent 4 0.108 3038 car-safe 3 0.081 15871 read 3 0.081 7 font-lock-after-change-function 2 0.054 3038 #<compiled-function (ex) "...(52)" [extent-live-p ex extent-detached-p #extent-start-position beg extent-end-position end 0 1 detach-extent #put-range-table t font-lock-range-table] 5> 2 0.054 3038 car 2 0.054 15871 get 2 0.054 15873 quote 1 0.027 31969 not 1 0.027 15871 #<subr when> 1 0.027 15871 itimer-restart 1 0.027 2 memq 1 0.027 15875 let 1 0.027 15871 run-hook-with-args 1 0.027 9 mapc-internal 1 0.027 2 syntactically-sectionize 1 0.027 1 gethash 1 0.027 3038 and 1 0.027 15874 when 1 0.027 15871 boundp 1 0.027 14141 set-extent-property 1 0.027 6077 mapatoms 1 0.027 2 ---------------------------------------------------------------- Total 3718 100.00 One tick = 1 ms nil ; Trial #2: Comment out everything but the extent stuff. Stopped save before ; completion. New font-lock-after-change-function: (defun font-lock-after-change-function (beg end old-len) (when font-lock-mode (let ((ex (make-extent beg end))) (set-extent-property ex 'detachable nil) (set-extent-property ex 'end-open nil) ; (let ((exs (gethash (current-buffer) ; font-lock-pending-extent-table))) ; (push ex exs) ; (puthash (current-buffer) exs font-lock-pending-extent-table))) ; (if font-lock-always-fontify-immediately ; (font-lock-fontify-pending-extents)))) ))) (profile-results) Function Name Ticks %/Total Call Count =============================== ===== ======= ========== prin1 2902 75.357 427 princ 875 22.721 673 (in garbage collection) 26 0.675 #<compiled-function (symbol) "...(119)" [spec now requests comment symbol #theme-value custom-requests standard-value boundp force-value rogue saved-variable-comment user set princ '( prin1 saved-value t nil )] 6> 5 0.130 15663 make-extent 5 0.130 3117 set-extent-property 5 0.130 6207 quote 3 0.078 39995 car-safe 3 0.078 16781 (in redisplay) 3 0.078 #<subr when> 3 0.078 19884 read 3 0.078 16 let 3 0.078 19885 eq 2 0.052 17002 font-lock-after-change-function 2 0.052 3103 get 2 0.052 16783 insert-file-contents-internal 1 0.026 1 car 1 0.026 16781 lazy-shot-after-change-function 1 0.026 3103 when 1 0.026 19884 redisplay-echo-area 1 0.026 12 (lambda (object) (let ((spec (car-safe (get object (quote theme-value))))) (when (and (not (memq object ignored-special)) (eq (car spec) (quote user)) (eq (second spec) (quote reset))) (unless started-writing (setq started-writing t) (unless (bolp) (princ )) (princ () (princ (quote custom-reset-variables)) (princ '() (prin1 object) (princ ) (prin1 (third spec)) (princ )))))) 1 0.026 16781 boundp 1 0.026 15014 put-char-table 1 0.026 17 mapatoms 1 0.026 2 ---------------------------------------------------------------- Total 3851 100.00 One tick = 1 ms nil ; Trial #3: Comment out everything but the actual make-extent. This time, ; the save did run to completion. (defun font-lock-after-change-function (beg end old-len) (when font-lock-mode (let ((ex (make-extent beg end))) ; (set-extent-property ex 'detachable nil) ; (set-extent-property ex 'end-open nil) ; (let ((exs (gethash (current-buffer) ; font-lock-pending-extent-table))) ; (push ex exs) ; (puthash (current-buffer) exs font-lock-pending-extent-table))) ; (if font-lock-always-fontify-immediately ; (font-lock-fontify-pending-extents)))) ))) (profile-results) Function Name Ticks %/Total Call Count =============================== ===== ======= ========== prin1 177 53.636 659 princ 49 14.848 1054 (in garbage collection) 43 13.030 get 6 1.818 33565 custom-save-face-internal 5 1.515 16782 #<compiled-function (symbol) "...(119)" [spec now requests comment symbol #theme-value custom-requests standard-value boundp force-value rogue saved-variable-comment user set princ '( prin1 saved-value t nil )] 6> 4 1.212 16781 eq 3 0.909 33889 #<subr when> 3 0.909 41968 read 3 0.909 28 when 3 0.909 41968 find-face 3 0.909 16738 scan-sexps 2 0.606 2 quote 2 0.606 67458 car 2 0.606 33888 car-safe 2 0.606 33563 memq 2 0.606 33567 let 2 0.606 41969 if 2 0.606 41970 make-extent 2 0.606 8422 mapatoms 2 0.606 4 not 1 0.303 33563 font-lock-after-change-function 1 0.303 8405 widget-default-create 1 0.303 6 (in redisplay) 1 0.303 check-menu-syntax 1 0.303 278 byte-compile-constant 1 0.303 324 load-average 1 0.303 2 next-command-event 1 0.303 1 (lambda (object) (let ((spec (car-safe (get object (quote theme-value))))) (when (and (not (memq object ignored-special)) (eq (car spec) (quote user)) (eq (second spec) (quote reset))) (unless started-writing (setq started-writing t) (unless (bolp) (princ )) (princ () (princ (quote custom-reset-variables)) (princ '() (prin1 object) (princ ) (prin1 (third spec)) (princ )))))) 1 0.303 16781 second 1 0.303 324 and 1 0.303 33566 redisplay-echo-area 1 0.303 21 boundp 1 0.303 16114 ---------------------------------------------------------------- Total 330 100.00 One tick = 1 ms nil ; Trial #4: Used the old version of font-lock-after-change-function. This ; one also ran to completion (obviously). (profile-results) Function Name Ticks %/Total Call Count =============================== ===== ======= ========== (in garbage collection) 41 27.703 prin1 27 18.243 659 #<compiled-function (symbol) "...(119)" [spec now requests comment symbol #theme-value custom-requests standard-value boundp force-value rogue saved-variable-comment user set princ '( prin1 saved-value t nil )] 6> 7 4.730 16786 read 7 4.730 28 custom-save-face-internal 7 4.730 16787 quote 5 3.378 67478 memq 4 2.703 33577 let 4 2.703 33574 get 4 2.703 33575 princ 4 2.703 1054 (in redisplay) 3 2.027 boundp 3 2.027 16118 mapatoms 3 2.027 4 eq 2 1.351 33899 car 2 1.351 33898 car-safe 2 1.351 33573 if 2 1.351 33575 when 2 1.351 33573 re-search-forward 2 1.351 438 put-nonduplicable-text-property 2 1.351 714 byte-compile-out-toplevel 1 0.676 1 font-lock-after-change-function 1 0.676 8405 key-binding 1 0.676 1 #<subr when> 1 0.676 33573 lazy-shot-after-change-function 1 0.676 8405 set-marker-insertion-type 1 0.676 21 crypt-write-file-hook 1 0.676 1 insert-string 1 0.676 19 kill-all-local-variables 1 0.676 2 (lambda (object) (let ((spec (car-safe (get object (quote theme-face))))) (when (and (not (memq object ignored-special)) (eq (car spec) (quote user)) (eq (second spec) (quote reset))) (unless started-writing (setq started-writing t) (unless (bolp) (princ )) (princ () (princ (quote custom-reset-faces)) (princ '() (prin1 object) (princ ) (prin1 (third spec)) (princ )))))) 1 0.676 16787 and 1 0.676 33576 redisplay-echo-area 1 0.676 19 extent-start-position 1 0.676 8412 put-text-property 1 0.676 379 next-single-property-change 1 0.676 376 ---------------------------------------------------------------- Total 148 100.00 One tick = 1 ms nil Analysis -------- Well, I'm not an xemacs expert, but it looks to this layman that the print functions don't get along well with extents, for whatever reason. The number of calls to prin1 and princ (and whatever anonymous compiled function that called them) in the last two trials were exactly the same, and higher than in the first two, but the time spent in them was far less, especially in Trial 4. Hmmm... Hope this helps, Chris