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

[Raffael Stocker]

Eli Zaretskii <eliz@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