GNU bug report logs - #67536
29.1; Calc mode's math-read-preprocess-string conses unnecessarily

Previous Next

Full log

View this message in rfc822 format

From: Raffael Stocker <r.stocker <at> mnet-mail.de>
To: Eli Zaretskii <eliz <at> gnu.org>
Cc: 67536 <at> debbugs.gnu.org
Subject: bug#67536: 29.1; Calc mode's math-read-preprocess-string conses unnecessarily
Date: Thu, 30 Nov 2023 19:28:27 +0100

Eli Zaretskii <eliz <at> gnu.org> writes:

>> ...
>>      60,252,646  96%   - org-ctrl-c-ctrl-c
>>      60,248,166  96%    - org-table-calc-current-TBLFM
>>      60,216,431  96%     - funcall-interactively
>>      60,205,119  96%      - org-table-recalculate
>>      49,094,651  78%       - org-table-eval-formula
>>      32,624,631  52%        - calc-eval
>>      32,624,631  52%         - calc-do-calc-eval
>>      32,620,487  52%          - calc-do-calc-eval
>>      32,611,151  52%           - math-read-exprs
>>      29,388,838  47%            + math-read-preprocess-string
>>       2,343,257   3%            + math-read-expr-list
>
> This is not memory usage, this is CPU usage measured by using
> memory-allocation functions as triggers to probe for the function that
> is being executed.  So its evidence about consing and GC pressure is
> indirect at best.
>
> Can you instead look at the values of gcs-done and gc-elapsed before
> and after running the offending code, and show the delta of each one
> of them, with and without your proposed changes?  Then we will see a
> much more direct evidence about the number of GC cycles and the time
> spent in GC, and could make the decision about how to improve the
> situation.

I defined the following advice:

--8<---------------cut here---------------start------------->8---

(defun my-gc-status (orig-fun &rest args)
  (let* ((done-bf gcs-done)
         (elapsed-bf gc-elapsed)
         (res (apply orig-fun args))
         (done-af gcs-done)
         (elapsed-af gc-elapsed))
    (message "before:\n\tgcs-done: %d, gc-elapsed: %f" done-bf elapsed-bf)
    (message "after:\n\tgcs-done: %d, difference: %d\n\tgc-elapsed: %f, difference: %f"
            done-af (- done-af done-bf)
            elapsed-af (- elapsed-af elapsed-bf))
    res))
(advice-add 'org-table-recalculate :around #'my-gc-status)

--8<---------------cut here---------------end--------------->8---

I had to put it around ‘org-table-recalculate’ instead of
‘math-read-preprocess-string’ as all the functions below
org-table-recalculate are called very often and have small individual
contributions.  With the original ‘math-read-preprocess-string’ I get the
following typical result:

--8<---------------cut here---------------start------------->8---

before:
	gcs-done: 854, gc-elapsed: 170.601313
after:
	gcs-done: 859, difference: 5
	gc-elapsed: 171.671042, difference: 1.069729

--8<---------------cut here---------------end--------------->8---

I ran the command about twenty times and almost always got the
gcs-done difference of 5, with the occasional 4.  The gc-elapsed is
fairly consistent at 1.07 for the 5 GC runs.

The modified version yields this typical output:

--8<---------------cut here---------------start------------->8---

before:
	gcs-done: 906, gc-elapsed: 181.417292
after:
	gcs-done: 908, difference: 2
	gc-elapsed: 181.847972, difference: 0.430679

--8<---------------cut here---------------end--------------->8---

Again, the gcs-done difference is quite stable at 2, with the occasional
3, the gc-elapsed is also fairly consistent at 0.43 for the 2 GC runs.

So we have about a factor of 2.5 between the elapsed GC times for the
two versions.

Regards,
Raffael

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.