slow saving of scores when leaving a virtual (nnml+) group

slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

Hello all,

recently (past week or two), I've noticed a slow down in leaving some of
my nnml groups.  Using the profiler, I see the outcomes shown below,
capturing cpu and memory when entering a virtual group, that collects 3
different nnml groups, and then immediately leaving that group.  A
significant amount of time is taken saving scores, as far as I can tell.
I use adaptive scoring.  Nothing with respect to scoring has changed in
my configuration in some time (years probably).

The offending function appears to be "lisp--local-defform-body-p" with
large memory and cpu use.

Cpu report (partly expanded):

       10133  79% - command-execute
        8519  66%  - funcall-interactively
        4767  37%   - gnus-summary-exit
        4659  36%    - gnus-score-save
        4655  36%     - gnus-pp
        4655  36%      - pp
        4655  36%       - pp-to-string
        4655  36%        - pp-fill
        4647  36%         - pp--object
        4627  36%          - pp-fill
        4615  36%           - pp-fill
        4555  35%            - pp-fill
        4263  33%             - pp-fill
        4243  33%              - indent-according-to-mode
        4243  33%               - lisp-indent-line
        4163  32%                - calculate-lisp-indent
        4163  32%                 - lisp-indent-function
        4163  32%                    lisp--local-defform-body-p
          48   0%                + lisp-ppss
         240   1%             + indent-according-to-mode
          72   0%    + gnus-run-hooks
          32   0%    + gnus-close-group
           4   0%    + gnus-summary-update-info
        3688  28%   + gnus-topic-select-group
          60   0%   + file-notify-handle-event
           3   0%   + execute-extended-command
        1614  12%  + byte-code
        2260  17%   Automatic GC
         407   3% + timer-event-handler
           0   0%   ...

and memory report, also partly expanded:

    832,940,181  99% - command-execute
    805,535,710  96%  - funcall-interactively
    540,874,166  64%   - gnus-summary-exit
    537,712,423  64%    - gnus-score-save
    536,634,533  64%     - gnus-pp
    535,956,310  64%      - pp
    535,618,670  64%       - pp-to-string
    535,610,465  64%        - pp-fill
    533,695,189  63%         - pp--object
    533,684,957  63%          - pp-fill
    533,683,933  63%           - pp-fill
    533,651,141  63%            - pp-fill
    532,169,752  63%             - pp-fill
    531,888,880  63%              - indent-according-to-mode
    531,888,880  63%               - lisp-indent-line
    484,726,608  58%                - calculate-lisp-indent
    484,661,024  58%                 - lisp-indent-function
    484,661,024  58%                    lisp--local-defform-body-p
        902,445   0%             + indent-according-to-mode
             21   0%       nnheader-set-temp-buffer
      1,609,314   0%    + gnus-summary-update-info
        924,174   0%    + gnus-close-group
        579,308   0%    + gnus-run-hooks
          2,069   0%      gnus-score-adaptive
          1,529   0%    + gnus-configure-windows
             21   0%      gnus-set-global-variables
    263,358,645  31%   + gnus-topic-select-group
        839,207   0%   + execute-extended-command
        463,692   0%   + file-notify-handle-event
     27,404,471   3%  + byte-code
        983,687   0% + timer-event-handler
         53,056   0% + redisplay_internal (C function)
         14,903   0%   Automatic GC
          6,224   0% + hl-line-highlight
             21   0%   gnus-set-global-variables
              0   0%   ...

Any suggestions on how to improve the performance?  Or is it something I
may have done inadvertently?

Thank you,
eric

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-06-29) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric Abrahamsen]

[-- Attachment #1: Type: text/plain, Size: 1897 bytes --]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> Hello all,
>
> recently (past week or two), I've noticed a slow down in leaving some of
> my nnml groups.  Using the profiler, I see the outcomes shown below,
> capturing cpu and memory when entering a virtual group, that collects 3
> different nnml groups, and then immediately leaving that group.  A
> significant amount of time is taken saving scores, as far as I can tell.
> I use adaptive scoring.  Nothing with respect to scoring has changed in
> my configuration in some time (years probably).
>
> The offending function appears to be "lisp--local-defform-body-p" with
> large memory and cpu use.
>
> Cpu report (partly expanded):
>
>        10133  79% - command-execute
>         8519  66%  - funcall-interactively
>         4767  37%   - gnus-summary-exit
>         4659  36%    - gnus-score-save
>         4655  36%     - gnus-pp
>         4655  36%      - pp
>         4655  36%       - pp-to-string
>         4655  36%        - pp-fill
>         4647  36%         - pp--object
>         4627  36%          - pp-fill
>         4615  36%           - pp-fill
>         4555  35%            - pp-fill
>         4263  33%             - pp-fill
>         4243  33%              - indent-according-to-mode
>         4243  33%               - lisp-indent-line
>         4163  32%                - calculate-lisp-indent
>         4163  32%                 - lisp-indent-function
>         4163  32%                    lisp--local-defform-body-p
>           48   0%                + lisp-ppss

A few weeks ago Stefan Monnier made a change to lisp-ppss. It was meant
to improve performance, but the timing looks very suspicious and it may
have had unexpected side effects. The commit is f411cc3a9578eae4ea4549,
I've attached a patch that reverts it, you might give this a try? If it
clearly fixes the problem, I would open a bug report and cc Stefan.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: revert_ppss.diff --]
[-- Type: text/x-patch, Size: 559 bytes --]

diff --git a/lisp/emacs-lisp/lisp-mode.el b/lisp/emacs-lisp/lisp-mode.el
index 1990630608d..3613c8d88ec 100644
--- a/lisp/emacs-lisp/lisp-mode.el
+++ b/lisp/emacs-lisp/lisp-mode.el
@@ -876,7 +876,7 @@ lisp-ppss
 2 (counting from 0).  This is important for Lisp indentation."
   (unless pos (setq pos (point)))
   (let ((pss (syntax-ppss pos)))
-    (if (and (not (nth 2 pss)) (nth 9 pss))
+    (if (nth 9 pss)
         (let ((sexp-start (car (last (nth 9 pss)))))
           (parse-partial-sexp sexp-start pos nil nil (syntax-ppss sexp-start)))
       pss)))

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Thursday,  6 Jul 2023 at 08:43, Eric Abrahamsen wrote:
> I've attached a patch that reverts it, you might give this a try? If it
> clearly fixes the problem, I would open a bug report and cc Stefan.

Hi Eric,

thank you for this patch.  Unfortunately, it does not seem to have had
any impact in my case.

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-07) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric Abrahamsen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> On Thursday,  6 Jul 2023 at 08:43, Eric Abrahamsen wrote:
>> I've attached a patch that reverts it, you might give this a try? If it
>> clearly fixes the problem, I would open a bug report and cc Stefan.
>
> Hi Eric,
>
> thank you for this patch.  Unfortunately, it does not seem to have had
> any impact in my case.

Bummer. You can always escalate and just open an Emacs bug -- this is a
perfectly normal type of thing to open a bug about.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric Abrahamsen <eric@ericabrahamsen.net> writes:

> > Cpu report (partly expanded):
> >
> >        10133  79% - command-execute
> >         8519  66%  - funcall-interactively
> >         4767  37%   - gnus-summary-exit
> >         4659  36%    - gnus-score-save
> >         4655  36%     - gnus-pp
> >         4655  36%      - pp
> >         4655  36%       - pp-to-string
> >         4655  36%        - pp-fill
> >         4647  36%         - pp--object
> >         4627  36%          - pp-fill
> >         4615  36%           - pp-fill
> >         4555  35%            - pp-fill
> >         4263  33%             - pp-fill
> >         4243  33%              - indent-according-to-mode
> >         4243  33%               - lisp-indent-line
> >         4163  32%                - calculate-lisp-indent
> >         4163  32%                 - lisp-indent-function
> >         4163  32%                    lisp--local-defform-body-p
> >           48   0%                + lisp-ppss
>
> A few weeks ago Stefan Monnier made a change to lisp-ppss.

Hmm - that report doesn't suggest that this is the culprit.

`pp-fill' is also new (this function is used to find good positions for
line breaks, which is the most important aspect of Lisp pretty
printing).  It is the new default behavior of `pp' and maybe slower (in
this use case) than the old implementation.  Maybe it can also be
improved.

Anyway, this can be controlled by binding `pp-default-function'.
Maybe `gnus-pp' or `gnus-score-save' should bind that variable to a
different function?

And - is it worth the time to pretty print this data at all?


Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Saturday,  8 Jul 2023 at 03:22, Michael Heerdegen wrote:
> And - is it worth the time to pretty print this data at all?

This is what I was wondering.  The pretty printing could be saved for
when somebody wishes to edit the scores, at which point a little delay
is not intrusive (or as intrusive).  Most of the time, I just want the
scores updated quickly so I can go on to the next group.

What puzzles me is the very large amount of memory use.  My scores file
is 334 kB in size.  Why does this require half a GB of memory to
process?

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-07) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Friday,  7 Jul 2023 at 08:41, Eric Abrahamsen wrote:
> Bummer. You can always escalate and just open an Emacs bug -- this is a
> perfectly normal type of thing to open a bug about.

I'll keep this as my fallback position, once any discussion here has
petered out.  Thank you.

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-07) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> > And - is it worth the time to pretty print this data at all?
>
> This is what I was wondering.  The pretty printing could be saved for
> when somebody wishes to edit the scores, at which point a little delay
> is not intrusive (or as intrusive).  Most of the time, I just want the
> scores updated quickly so I can go on to the next group.

And you did not just turn on `gnus-adaptive-pretty-print' by accident?

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Sunday,  9 Jul 2023 at 07:23, Michael Heerdegen wrote:
> And you did not just turn on `gnus-adaptive-pretty-print' by accident?

Well, I've had this variable set to t for years now.

In any case, I have set it to nil and it's made no difference
unfortunately.  Which seems strange.  Could there be another variable
that affects this as I really don't need the score files prettified?
I've looked at the parameter settings for individual groups (G p) but
seen nothing strange in the nnml groups I'm dealing with.

thank you,
eric

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-10) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> On Sunday,  9 Jul 2023 at 07:23, Michael Heerdegen wrote:
> > And you did not just turn on `gnus-adaptive-pretty-print' by accident?
>
> Well, I've had this variable set to t for years now.
>
> In any case, I have set it to nil and it's made no difference
> unfortunately.  Which seems strange.  Could there be another variable
> that affects this as I really don't need the score files prettified?

Seems the variable is only respected for adaptive score files.  For all
others pretty-printing is always used.  I guess your score file is not
an adaptive one?

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Tuesday, 11 Jul 2023 at 04:56, Michael Heerdegen wrote:
> Seems the variable is only respected for adaptive score files.  For all
> others pretty-printing is always used.  I guess your score file is not
> an adaptive one?

I use both adaptive and permanent scores.  I have:

((score-file . "/.../work.scores")
 (adapt-file . "/.../work.adaptive.scores"))

for my "work" topic which includes a few nnml groups.

The score-file is small (600 bytes!) but the adaptive scores file is
around 350 kB in size.  Pretty printing the score file should be
instantaneous, I would have thought.  Puzzled I be!

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-06-19) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> > Seems the variable is only respected for adaptive score files.  For all
> > others pretty-printing is always used.  I guess your score file is not
> > an adaptive one?
>
> I use both adaptive and permanent scores.  I have:
>
> ((score-file . "/.../work.scores")
>  (adapt-file . "/.../work.adaptive.scores"))
>
> for my "work" topic which includes a few nnml groups.
>
> The score-file is small (600 bytes!) but the adaptive scores file is
> around 350 kB in size.  Pretty printing the score file should be
> instantaneous, I would have thought.  Puzzled I be!

I guess the new `pp-fill' code is not working well in your case.  I'm
sorry, I don't use score files, I just read some of the source code, so
my insights are limited.

The slowness, is it only happening for that 600 Bytes file?  How do the
contents of that file look like - can you share some of the contents so
that we can maybe find a recipe (you can replace any private
information of course)?

Of course you can just use an advice if you just want to get rid of this
problem.  But maybe we can find out why the code is working that slowly.

And...you are using a master built (from when)?

TIA,

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Wednesday, 12 Jul 2023 at 02:48, Michael Heerdegen wrote:
> The slowness, is it only happening for that 600 Bytes file?  

I have no idea but I would assume not as I cannot believe that pretty
printing a file (see below) with 12 lines would take 0.5 GB of data to
process.

> How do the contents of that file look like -can you share some of the
> contents so that we can maybe find a recipe (you can replace any
> private information of course)?

--8<---------------cut here---------------start------------->8---
(("subject"
  ("^xxx .*" 100 nil r))
 ("from"
  ("\"name\" <email>" 10000 nil e)
  [... elided ...]
  ("name <email>" -1000 nil e)))
--8<---------------cut here---------------end--------------->8---

where the elided are lines that look like the one before or the one
after.

> And...you are using a master built (from when)?

On this computer, yes, master built two days ago.

I hope some of the above helps.  But, to be clear, this is not a
critical issue, just a minor annoyance. :-)

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-10) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> I have no idea but I would assume not as I cannot believe that pretty
> printing a file (see below) with 12 lines would take 0.5 GB of data to
> process.

From what source of information do you have the 0.5 GB?

> > How do the contents of that file look like -can you share some of the
> > contents so that we can maybe find a recipe (you can replace any
> > private information of course)?
>
> (("subject"
>   ("^xxx .*" 100 nil r))
>  ("from"
>   ("\"name\" <email>" 10000 nil e)
>   [... elided ...]
>   ("name <email>" -1000 nil e)))

Thanks.  I tried the following: I inserted this expression into a buffer
(*scratch* and a buffer in fundamental mode):

#+begin_src emacs-lisp
(("subject" ("^xxx .*" 100 nil r))
 ("from" ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("\"name\" <email>" 10000 nil e)
  ("\"name\" <email>" 10000 nil e) ("name <email>" -1000 nil e)))
#+end_src

then I replaced all line breaks with spaces and called M-:
(pp-fill (point-min) (point-max)).  But that succeeds almost
immediately...   Not sure what the important different aspect in your
scenario is.

Have you tried to change the value of `pp-default-function' btw?

Thx,

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Thursday, 13 Jul 2023 at 02:18, Michael Heerdegen wrote:
> From what source of information do you have the 0.5 GB?

From the original post I made which included mem profiler results:

--8<---------------cut here---------------start------------->8---
and memory report, also partly expanded:

    832,940,181  99% - command-execute
    805,535,710  96%  - funcall-interactively
    540,874,166  64%   - gnus-summary-exit
    537,712,423  64%    - gnus-score-save
    536,634,533  64%     - gnus-pp
    [...]
--8<---------------cut here---------------end--------------->8---

It could be that I am misinterpreting those profiler results.

> Thanks.  I tried the following: I inserted this expression into a buffer
> (*scratch* and a buffer in fundamental mode):

[...]

> then I replaced all line breaks with spaces and called M-:
> (pp-fill (point-min) (point-max)).  But that succeeds almost
> immediately...   Not sure what the important different aspect in your
> scenario is.

I tried this as well and also get results immediately.

> Have you tried to change the value of `pp-default-function' btw?

No, it's set to pp-fill.

Thank you,
eric

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-10) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

>     832,940,181  99% - command-execute
>     805,535,710  96%  - funcall-interactively
>     540,874,166  64%   - gnus-summary-exit
>     537,712,423  64%    - gnus-score-save
>     536,634,533  64%     - gnus-pp
>     [...]
>
> It could be that I am misinterpreting those profiler results.

I think so, yes.  These numbers cannot be interpreted directly as used
memory.  It's more like "time spent inside the function, measured
memory-usage wise.

> I tried this as well and also get results immediately.

Hmm.  Ok.  We could try with M-x trace-function pp-to-string RET
directly before `gnus-summary-exit'.  A popup buffer should appear, and
it would be helpful if you could again post the output (with any private
data obfuscated; we are interested in the argument(s) of the function
call(s)).  But before that please M-x untrace-all RET.

> > Have you tried to change the value of `pp-default-function' btw?
>
> No, it's set to pp-fill.

Are things significantly faster when setting this to pp-28?


Thx,

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Friday, 14 Jul 2023 at 01:56, Michael Heerdegen wrote:
> I think so, yes.  These numbers cannot be interpreted directly as used
> memory.  It's more like "time spent inside the function, measured
> memory-usage wise.

Ah, okay.  Total misunderstanding on my part!

> Hmm.  Ok.  We could try with M-x trace-function pp-to-string RET
> directly before `gnus-summary-exit'.  A popup buffer should appear, and
> it would be helpful if you could again post the output (with any private
> data obfuscated; we are interested in the argument(s) of the function
> call(s)).  But before that please M-x untrace-all RET.

The trace output is difficult to obfuscate so I won't include it here
but what it shows is that the function is passed the full contents of
the adaptive scoring file, not the static score file.

> Are things significantly faster when setting this to pp-28?

Very much so!  Group exists almost immediately, back to what I used to
see.  With pp-28, I'm happy!  Problem solved. :-)

Thank you,
eric

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-10) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> > Are things significantly faster when setting this to pp-28?
>
> Very much so!  Group exists almost immediately, back to what I used to
> see.  With pp-28, I'm happy!  Problem solved. :-)

At least avoided.  Ok, good.

We should nonetheless create a bug report (M-x report-emacs-bug).  Could
you please do that?  I think we still need somebody to provide the (more
or less complete) data that shows the slowdown - with other words, a
recipe that doesn't involve setting up Gnus + scoring, to ease the work
of the developers.


TIA,

Michael.

Re: slow saving of scores when leaving a virtual (nnml+) group

[Eric S Fraga]

On Sunday, 16 Jul 2023 at 04:55, Michael Heerdegen wrote:
> At least avoided.  Ok, good.

Yes, that's a better description!

> We should nonetheless create a bug report (M-x report-emacs-bug).  Could
> you please do that?  I think we still need somebody to provide the (more
> or less complete) data that shows the slowdown - with other words, a
> recipe that doesn't involve setting up Gnus + scoring, to ease the work
> of the developers.

I will create a bug report.

Thank you,
eric

-- 
Eric S Fraga via gnus (Emacs 30.0.50 2023-07-10) on Debian 12.0

Re: slow saving of scores when leaving a virtual (nnml+) group

[Michael Heerdegen]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> I will create a bug report.

Thanks Eric.

Michael.