Possible cache problems

Possible cache problems

[Suvayu Ali]

Hi,

I have been noticing a strange heisenbug.  From time to time, Org starts
eating CPU for certain specific tasks: org-end-of-line, fill-paragraph,
folding or unfolding trees, or adding/changing properties with
org-set-property.  However these happen only after I have been using Org
for a while.  

I think I also see similar CPU eating symptoms when I have buffers
editing version controlled files.  I have auto-revert-mode enabled for
files under version control, I think that is related.  I'm not entirely
sure though, I don't know how to narrow it down either.

I say it is cache related since all this magically goes away, once I go
to the top of my current tree, and call org-element-cache-reset.
However, once the symptoms start showing, it happens more frequently
despite my cache resets.

It's very hard to reproduce this though.  I see it when I have been
using the same Emacs session over several days.  I always run emacs as a
daemon, so sessions lasting a week or more is quite common.  To see the
symptoms I have to wait about half a week to a whole week, hence the
hard to reproduce comment.  However, once the symptoms show, it gets bad
rather fast.  I end up restarting when the need to reset the cache gets
too frequent.

Any thoughts?

Thanks,

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Nicolas Goaziou]

Hello,

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I have been noticing a strange heisenbug.  From time to time, Org starts
> eating CPU for certain specific tasks: org-end-of-line, fill-paragraph,
> folding or unfolding trees, or adding/changing properties with
> org-set-property.  However these happen only after I have been using Org
> for a while.

This is typical for cache breakage.

> I think I also see similar CPU eating symptoms when I have buffers
> editing version controlled files.  I have auto-revert-mode enabled for
> files under version control, I think that is related.  I'm not entirely
> sure though, I don't know how to narrow it down either.
>
> I say it is cache related since all this magically goes away, once I go
> to the top of my current tree, and call org-element-cache-reset.
> However, once the symptoms start showing, it happens more frequently
> despite my cache resets.

Usually, a cache breakage is a specific action applied to some specific
document structure that induces an incorrect computation of the parts of
the cache to clear and to update.

If you encountered the problem, it means the problematic document
structure is already in the current buffer. So, the chances are high
that you will repeat the problematic editing action on it again, even
after resetting the cache. IOW, all the ingredients are there for the
problem to repeat again and again.

Finding the problematic action is not easy. I wrote a basic minor mode
(element-debug-mode) for that: after each change to the buffer, it
checks if the cache and pending updates match the parse tree. It sends
a message anytime they differ, which happens as soon as a problematic
action was triggered.

Obviously, it is unusable if the buffer is not small. You may want to
try it on small parts of your document, repeating your usual editing
actions.

--8<---------------cut here---------------start------------->8---
(defun element-check-cache (&rest ignore)
  (when (org-element--cache-active-p)
    (save-match-data
      (let ((cache (copy-tree org-element--cache t))
            (requests (copy-tree org-element--cache-sync-requests t))
            (buffer-contents (org-with-wide-buffer (buffer-string)))
            (translations (make-hash-table :test #'eq))
            (structures (make-hash-table :test #'eq))
            (keys (make-hash-table :test #'eq)))
        ;; Fix parents.
        (loop for key in (avl-tree-flatten org-element--cache)
              for value in (avl-tree-flatten cache)
              do (let ((struct (and (memq (org-element-type key)
                                          '(plain-list item))
                                    (gethash (org-element-property :structure key)
                                             structures 'missing))))
                   (progn
                     (puthash key value translations)
                     (let ((k (gethash key org-element--cache-sync-keys)))
                       (when k (puthash value k keys)))
                     (puthash
                      key
                      (org-element-put-property
                       value :parent
                       (gethash (org-element-property :parent key)
                                translations))
                      translations)
                     (when (eq struct 'missing)
                       (setq struct
                             (puthash (org-element-property :structure key)
                                      (org-element-property :structure value)
                                      structures)))
                     (when struct
                       (puthash
                        key
                        (org-element-put-property value :structure struct)
                        translations)))))
        ;; Fix requests.
        (loop for original in org-element--cache-sync-requests
              for copy in requests
              do (progn (aset copy 4 (gethash (aref original 4) translations))
                        (aset copy 5 (gethash (aref original 5) translations))))
        (with-temp-buffer
          (let ((org-element-use-cache nil)) (insert buffer-contents))
          (let ((org-inhibit-startup t)) (org-mode))
          (setq org-element--cache cache
                org-element--cache-sync-requests requests
                org-element--cache-sync-keys keys)
          (org-element--cache-sync (current-buffer) (point-max))
          (let ((seen '()))
            (avl-tree-mapc
             (lambda (element)
               (let ((beg (org-element-property :begin element))
                     (type (org-element-type element)))
                 (let ((real (let (org-element-use-cache)
                               (goto-char
                                (if (memq type '(item table-row)) (1+ beg)
                                  beg))
                               (org-element-at-point))))
                   (cond
                    ((member real seen)
                     (message
                      "======\nWARNING. Two entries for the same element\n\n %s"
                      element))
                    ((not (equal real element))
                     (message
                      "======\nWARNING. Corrupted element (%s) at %d\n\nReal: %s\n\nCached: %s\nLast request: %s"
                      (org-element-type element) beg real element (car requests)))
                    (t (push real seen))))))
             org-element--cache)))))))

(define-minor-mode element-debug-mode
  "Minor mode to debug Org Element cache."
  nil " OrgCacheD" nil
  (if ngz-debug-mode
      (progn (setq org-element-cache-sync-idle-time 3600)
             (add-hook 'after-change-functions 'element-check-cache t t))
    (setq org-element-cache-sync-idle-time 0.6)
    (remove-hook 'after-change-functions 'element-check-cache t)))
--8<---------------cut here---------------end--------------->8---


Regards,

-- 
Nicolas Goaziou

Re: Possible cache problems

[Suvayu Ali]

Hi Nicolas,

On Tue, Jun 02, 2015 at 10:26:54PM +0200, Nicolas Goaziou wrote:
> Hello,
> 
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I have been noticing a strange heisenbug.  From time to time, Org starts
> > eating CPU for certain specific tasks: org-end-of-line, fill-paragraph,
> > folding or unfolding trees, or adding/changing properties with
> > org-set-property.  However these happen only after I have been using Org
> > for a while.
> 
> This is typical for cache breakage.

Okay, good that it is not as mysterious as I was thinking :).

> > I think I also see similar CPU eating symptoms when I have buffers
> > editing version controlled files.  I have auto-revert-mode enabled for
> > files under version control, I think that is related.  I'm not entirely
> > sure though, I don't know how to narrow it down either.
> >
> > I say it is cache related since all this magically goes away, once I go
> > to the top of my current tree, and call org-element-cache-reset.
> > However, once the symptoms start showing, it happens more frequently
> > despite my cache resets.
> 
> Usually, a cache breakage is a specific action applied to some specific
> document structure that induces an incorrect computation of the parts of
> the cache to clear and to update.
> 
> If you encountered the problem, it means the problematic document
> structure is already in the current buffer. So, the chances are high
> that you will repeat the problematic editing action on it again, even
> after resetting the cache. IOW, all the ingredients are there for the
> problem to repeat again and again.
> 
> Finding the problematic action is not easy. I wrote a basic minor mode
> (element-debug-mode) for that: after each change to the buffer, it
> checks if the cache and pending updates match the parse tree. It sends
> a message anytime they differ, which happens as soon as a problematic
> action was triggered.

I have enabled the mode on my document.  Let's see how this goes.  Btw,
since you warn against large documents, would it help if I narrowed a
large document before enabling the mode?

Thanks a lot :).

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Nicolas Goaziou]

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I have enabled the mode on my document.  Let's see how this goes.

OK. You have to keep an eye on the *Messages* buffer so that warning
don't go unnoticed.

> Btw, since you warn against large documents, would it help if
> I narrowed a large document before enabling the mode?

It wouldn't: cache ignores narrowing anyway.

Regards,

Re: Possible cache problems

[Suvayu Ali]

On Tue, Jun 02, 2015 at 11:27:55PM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > Btw, since you warn against large documents, would it help if
> > I narrowed a large document before enabling the mode?
> 
> It wouldn't: cache ignores narrowing anyway.

Okay thanks :)

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Suvayu Ali]

Hi Nicolas,

On Tue, Jun 02, 2015 at 11:27:55PM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I have enabled the mode on my document.  Let's see how this goes.
> 
> OK. You have to keep an eye on the *Messages* buffer so that warning
> don't go unnoticed.

I do not see anything happening.  In the modeline I see OrgCacheD, so
the mode is definitely enabled.  However to enable it, I had to do one
of these two:

  (setq ngz-debug-mode nil)
  (setq ngz-debug-mode t)

I do not see any messages with either.  Here is a sample of messages
with nil,

  Wrote /home/user/org/LHCb-Bs2Dsh/gamma/cpv.org
  Saving file /home/user/org/LHCb-Bs2Dsh/gamma/WIN2015/cpv_flavour_suvayu.tex...
  Wrote /home/user/org/LHCb-Bs2Dsh/gamma/WIN2015/cpv_flavour_suvayu.tex
  Searched 1 buffer; 11 matches for `em]'
  Mark saved where search started
  Saving file /home/user/org/LHCb-Bs2Dsh/gamma/cpv.org...
  Wrote /home/user/org/LHCb-Bs2Dsh/gamma/cpv.org
  Saving file /home/user/org/LHCb-Bs2Dsh/gamma/WIN2015/cpv_flavour_suvayu.tex...
  Wrote /home/user/org/LHCb-Bs2Dsh/gamma/WIN2015/cpv_flavour_suvayu.tex

I'm exporting to LaTeX and compiling from a shell.  Everytime I export,
Emacs starts eating CPU after export.  This is apart from the random
hangs during editing.  I usually keep doing C-g several times to get
back a responsive interface; the last few times I waited for it to
finish though, and it does finish but no messages (as you see above).

Am I missing something?

I also see some folding anomalies:

After 1 <tab>:

  **** asl & phi                                                        :BMCOL:
       :PROPERTIES:...
  ***** φ_{s} measurements                                            :B_boldH:...
  
After 2 <tab>s:

  **** asl & phi                                                        :BMCOL:
       :PROPERTIES:...
        :PROPERTIES:...
  - B⁰ → D^{\ast}Xlν (\BaBar) ::  PRL 111 101802 (2013)
  - B → X_{s}ll (\BaBar) :: PRL 112 211802
  - B → X_{s}γ (\BaBar) :: PRD 90 092001
  
  ***** φ_{s} measurements                                            :B_boldH:
        :PROPERTIES:
        :BEAMER_env: boldH
        :END:
  - B_{s} → J/ψKK,ππ (LHCb) :: PRD 87 (2013) 112010

And this is the Org source:

  **** asl & phi                                                        :BMCOL:
       :PROPERTIES:
       :BEAMER_col: 0.33
       :END:
  ***** a_{sl}/A_{\CP} measurements                                   :B_boldH:
        :PROPERTIES:
        :BEAMER_env: boldH
        :END:
  #+attr_LaTeX: :options [style=nextline]
  - B⁰ → D^{\ast}Xlν (\BaBar) ::  PRL 111 101802 (2013)
  - B → X_{s}ll (\BaBar) :: PRL 112 211802
  - B → X_{s}γ (\BaBar) :: PRD 90 092001
  
  ***** φ_{s} measurements                                            :B_boldH:
        :PROPERTIES:
        :BEAMER_env: boldH
        :END:
  - B_{s} → J/ψKK,ππ (LHCb) :: PRD 87 (2013) 112010

I have to go unfold the property drawer for "asl & phi", go to the end
of the :END: line, and hit tab to reveal the next headline.  I don't
think this one is cache related, maybe I should start different thread
for this.

Any thoughts?

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Nicolas Goaziou]

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I do not see anything happening.  In the modeline I see OrgCacheD, so
> the mode is definitely enabled.  However to enable it, I had to do one
> of these two:
>
>   (setq ngz-debug-mode nil)
>   (setq ngz-debug-mode t)

My bad, it should be

(define-minor-mode element-debug-mode
  "Minor mode to debug Org Element cache."
  nil " OrgCacheD" nil
  (if element-debug-mode
      (progn (setq org-element-cache-sync-idle-time 3600)
             (add-hook 'after-change-functions 'element-check-cache t t))
    (setq org-element-cache-sync-idle-time 0.6)
    (remove-hook 'after-change-functions 'element-check-cache t)))

Then, you can just ignore `ngz-debug-mode'.

> I have to go unfold the property drawer for "asl & phi", go to the end
> of the :END: line, and hit tab to reveal the next headline.  I don't
> think this one is cache related, maybe I should start different thread
> for this.

It is probably cache related. Anyway, could you check again with
definition above?

Thank you.


Regards,

Re: Possible cache problems

[Suvayu Ali]

On Sun, Jun 07, 2015 at 01:29:04AM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I do not see anything happening.  In the modeline I see OrgCacheD, so
> > the mode is definitely enabled.  However to enable it, I had to do one
> > of these two:
> >
> >   (setq ngz-debug-mode nil)
> >   (setq ngz-debug-mode t)
> 
> My bad, it should be
> 
> (define-minor-mode element-debug-mode
>   "Minor mode to debug Org Element cache."
>   nil " OrgCacheD" nil
>   (if element-debug-mode
>       (progn (setq org-element-cache-sync-idle-time 3600)
>              (add-hook 'after-change-functions 'element-check-cache t t))
>     (setq org-element-cache-sync-idle-time 0.6)
>     (remove-hook 'after-change-functions 'element-check-cache t)))

I should have caught that!  I guess I'm too distracted from everything
else at the moment :-p.  Thanks a lot.  Let's see how this goes ...

Cheers,

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Suvayu Ali]

Hi Nicolas,

On Sun, Jun 07, 2015 at 01:29:04AM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I do not see anything happening.  In the modeline I see OrgCacheD, so
> > the mode is definitely enabled.  However to enable it, I had to do one
> > of these two:
> >
> >   (setq ngz-debug-mode nil)
> >   (setq ngz-debug-mode t)
> 
> My bad, it should be
> 
> (define-minor-mode element-debug-mode
>   "Minor mode to debug Org Element cache."
>   nil " OrgCacheD" nil
>   (if element-debug-mode
>       (progn (setq org-element-cache-sync-idle-time 3600)
>              (add-hook 'after-change-functions 'element-check-cache t t))
>     (setq org-element-cache-sync-idle-time 0.6)
>     (remove-hook 'after-change-functions 'element-check-cache t)))

I got a message like the following one quite a few times.

  Partially completed
  ======
  WARNING. Corrupted element (table-row) at 34386
  
  Real: (table-row (:type standard :begin 34386 :end 34430 :contents-begin 34387 :contents-end 34429 :post-blank 0 :post-affiliated 34386 :parent (table (:begin 34327 :end 34431 :type org :tblfm nil :contents-begin 34342 :contents-end 34430 :value nil :post-blank 1 :post-affiliated 34342 :attr_latex () :parent nil))))
  
  Cached: (table-row (:type standard :begin 34386 :end 34430 :contents-begin 34387 :contents-end 34429 :post-blank 0 :post-affiliated 34386 :parent (table (:begin 34328 :end 34417 :type org :tblfm nil :contents-begin 34328 :contents-end 34416 :value nil :post-blank 1 :post-affiliated 34328 :parent nil))))
  Last request: [34926 34372 34328 14 (property-drawer (:begin 34276 :end 34328 :contents-begin 34294 :contents-end 34316 :post-blank 1 :post-affiliated 34276 :parent nil)) (table (:begin 34327 :end 34431 :type org :tblfm nil :contents-begin 34342 :contents-end 34430 :value nil :post-blank 1 :post-affiliated 34342 :attr_latex () :parent nil)) 2]

I was trying to edit the attr_latex line for the following table:

  #+attr_latex: 
  | year | 2012 | 2018 | 2022 | 2028 | 2035 |
  | γ(°) |    7 |    4 |  1.3 |  0.9 |  0.6 |

Right now I'm not working with Org for a few days, but next week I'll
start again.  So maybe I'll get a few other data points soon.

Cheers,

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Rasmus]

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I got a message like the following one quite a few times.
>
>   Partially completed
>   ======
>   WARNING. Corrupted element (table-row) at 34386
   
I wonder if this is the same bug that I've been seeing:

  http://thread.gmane.org/gmane.emacs.orgmode/92883/focus=92884

Rasmus

-- 
However beautiful the theory, you should occasionally look at the evidence

Re: Possible cache problems

[Nicolas Goaziou]

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I got a message like the following one quite a few times.
>
>   Partially completed
>   ======
>   WARNING. Corrupted element (table-row) at 34386
>   
>   Real: (table-row (:type standard :begin 34386 :end
> 34430 :contents-begin 34387 :contents-end 34429 :post-blank
> 0 :post-affiliated 34386 :parent (table (:begin 34327 :end 34431 :type
> org :tblfm nil :contents-begin 34342 :contents-end 34430 :value
> nil :post-blank 1 :post-affiliated 34342 :attr_latex () :parent
> nil))))
>   
>   Cached: (table-row (:type standard :begin 34386 :end
> 34430 :contents-begin 34387 :contents-end 34429 :post-blank
> 0 :post-affiliated 34386 :parent (table (:begin 34328 :end 34417 :type
> org :tblfm nil :contents-begin 34328 :contents-end 34416 :value
> nil :post-blank 1 :post-affiliated 34328 :parent nil))))
>   Last request: [34926 34372 34328 14 (property-drawer (:begin
> 34276 :end 34328 :contents-begin 34294 :contents-end 34316 :post-blank
> 1 :post-affiliated 34276 :parent nil)) (table (:begin 34327 :end
> 34431 :type org :tblfm nil :contents-begin 34342 :contents-end
> 34430 :value nil :post-blank 1 :post-affiliated 34342 :attr_latex
> () :parent nil)) 2]
>
> I was trying to edit the attr_latex line for the following table:
>
>   #+attr_latex: 
>   | year | 2012 | 2018 | 2022 | 2028 | 2035 |
>   | γ(°) |    7 |    4 |  1.3 |  0.9 |  0.6 |

I can reproduce it. I will look into it before the end of the week.

Thank you.


Regards,

Re: Possible cache problems

[Suvayu Ali]

On Thu, Jun 11, 2015 at 09:00:39AM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I was trying to edit the attr_latex line for the following table:
> >
> >   #+attr_latex: 
> >   | year | 2012 | 2018 | 2022 | 2028 | 2035 |
> >   | γ(°) |    7 |    4 |  1.3 |  0.9 |  0.6 |
> 
> I can reproduce it. I will look into it before the end of the week.

Great, I wasn't expecting to get a reproducible case so soon!

Cheers,

-- 
Suvayu

Open source is the future. It sets us free.

Re: Possible cache problems

[Nicolas Goaziou]

Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:

> I was trying to edit the attr_latex line for the following table:
>
>   #+attr_latex: 
>   | year | 2012 | 2018 | 2022 | 2028 | 2035 |
>   | γ(°) |    7 |    4 |  1.3 |  0.9 |  0.6 |

Fixed in 182ff104b77d1c4cd03a2749472d9da0c7733116. Thank you.

This change requires a modification to `element-check-cache' function
I sent you earlier, if you plan to use it again:

--8<---------------cut here---------------start------------->8---
(defun element-check-cache (&rest ignore)
  (when (org-element--cache-active-p)
    (save-match-data
      (let ((cache (copy-tree org-element--cache t))
            (requests (copy-tree org-element--cache-sync-requests t))
            (buffer-contents (org-with-wide-buffer (buffer-string)))
            (translations (make-hash-table :test #'eq))
            (structures (make-hash-table :test #'eq))
            (keys (make-hash-table :test #'eq)))
        ;; Fix parents.
        (loop for key in (avl-tree-flatten org-element--cache)
              for value in (avl-tree-flatten cache)
              do (let ((struct (and (memq (org-element-type key)
                                          '(plain-list item))
                                    (gethash (org-element-property :structure key)
                                             structures 'missing))))
                   (progn
                     (puthash key value translations)
                     (let ((k (gethash key org-element--cache-sync-keys)))
                       (when k (puthash value k keys)))
                     (puthash
                      key
                      (org-element-put-property
                       value :parent
                       (gethash (org-element-property :parent key)
                                translations))
                      translations)
                     (when (eq struct 'missing)
                       (setq struct
                             (puthash (org-element-property :structure key)
                                      (org-element-property :structure value)
                                      structures)))
                     (when struct
                       (puthash
                        key
                        (org-element-put-property value :structure struct)
                        translations)))))
        ;; Fix requests.
        (loop for original in org-element--cache-sync-requests
              for copy in requests
              do (aset copy 4 (gethash (aref original 4) translations)))
        (with-temp-buffer
          (let ((org-element-use-cache nil)) (insert buffer-contents))
          (let ((org-inhibit-startup t)) (org-mode))
          (setq org-element--cache cache
                org-element--cache-sync-requests requests
                org-element--cache-sync-keys keys)
          (org-element--cache-sync (current-buffer) (point-max))
          (let ((seen '()))
            (avl-tree-mapc
             (lambda (element)
               (let ((beg (org-element-property :begin element))
                     (type (org-element-type element)))
                 (let ((real (let (org-element-use-cache)
                               (goto-char
                                (if (memq type '(item table-row)) (1+ beg)
                                  beg))
                               (org-element-at-point))))
                   (cond
                    ((member real seen)
                     (message
                      "======\nWARNING. Two entries for the same element\n\n %s"
                      element))
                    ((not (equal real element))
                     (message
                      "======\nWARNING. Corrupted element (%s) at %d\n\nReal:\
 %s\n\nCached: %s\n\nLast request: %s"
                      (org-element-type element) beg real element (car requests)))
                    (t (push real seen))))))
             org-element--cache)))))))--8<---------------cut here---------------end--------------->8---

Regards,

Re: Possible cache problems

[Suvayu Ali]

On Sun, Jun 14, 2015 at 02:58:25PM +0200, Nicolas Goaziou wrote:
> Suvayu Ali <fatkasuvayu+linux@gmail.com> writes:
> 
> > I was trying to edit the attr_latex line for the following table:
> >
> >   #+attr_latex: 
> >   | year | 2012 | 2018 | 2022 | 2028 | 2035 |
> >   | γ(°) |    7 |    4 |  1.3 |  0.9 |  0.6 |
> 
> Fixed in 182ff104b77d1c4cd03a2749472d9da0c7733116. Thank you.

Thanks a lot!

> This change requires a modification to `element-check-cache' function
> I sent you earlier, if you plan to use it again:

Thank you.  I'll most definitely use it to debug problems :).

Cheers,

-- 
Suvayu

Open source is the future. It sets us free.