entering a group is slow

entering a group is slow

[Peter Münster]

Hi,

Entering a group is very slow on my system (several seconds, up to
15 seconds sometimes). Is this a know problem and do you know how to
make it faster?

Or should I do some profiling, for getting more informations? If yes,
what would be the best tool for that please?

TIA for any help,
-- 
           Peter

Re: entering a group is slow

[Igor Sosa Mayor]

Peter Münster <pmlists@free.fr> writes:

> Hi,
>
> Entering a group is very slow on my system (several seconds, up to
> 15 seconds sometimes). Is this a know problem and do you know how to
> make it faster?

how many messages are in the group?

-- 
:: Igor Sosa Mayor     :: joseleopoldo1792@gmail.com ::
:: GnuPG: 0x1C1E2890   :: http://www.gnupg.org/      ::
:: jabberid: rogorido  ::                            ::

Re: entering a group is slow

[Peter Münster]

On Fri, Jun 13 2014, Igor Sosa Mayor wrote:

>> Entering a group is very slow on my system (several seconds, up to
>> 15 seconds sometimes). Is this a know problem and do you know how to
>> make it faster?
>
> how many messages are in the group?

Often some hundreds (700-900) for example.

And I've read http://gnus.org/manual/gnus_403.html#SEC546 :

- gnus-fetch-old-headers is nil
- gc-cons-threshold is 3500000
- gnus-use-correct-string-widths is nil

-- 
           Peter

Re: entering a group is slow

[Peter Münster]

On Fri, Jun 13 2014, Peter Münster wrote:

> On Fri, Jun 13 2014, Igor Sosa Mayor wrote:
>
>>> Entering a group is very slow on my system (several seconds, up to
>>> 15 seconds sometimes). Is this a know problem and do you know how to
>>> make it faster?
>>
>> how many messages are in the group?
>
> Often some hundreds (700-900) for example.
>
> And I've read http://gnus.org/manual/gnus_403.html#SEC546 :
>
> - gnus-fetch-old-headers is nil
> - gc-cons-threshold is 3500000
> - gnus-use-correct-string-widths is nil

My main group is "inbox", there are often only very few messages (< 10)
that are displayed in the summary buffer and it takes about 5 seconds to
enter the group.

After using `elp-instrument-package' I've found, that the sorting
functions are called a lot of times:

gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
gnus-thread-latest-date                 3962     4.6299316569  0.0011685844

Because there are about 300 articles with the expirable-mark. These are
not shown in the summary buffer, but it seems, that they are sorted
nevertheless.

Is it possible to tell gnus, to not sort articles that won't be
displayed in the summary buffer?

TIA for any help,
-- 
           Peter

Re: entering a group is slow

[Eric S Fraga]

On Tuesday, 17 Jun 2014 at 10:02, Peter Münster wrote:

[...]

> My main group is "inbox", there are often only very few messages (< 10)
> that are displayed in the summary buffer and it takes about 5 seconds to
> enter the group.
>
> After using `elp-instrument-package' I've found, that the sorting
> functions are called a lot of times:
>
> gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
> gnus-thread-latest-date                 3962     4.6299316569  0.0011685844
>
> Because there are about 300 articles with the expirable-mark. These are
> not shown in the summary buffer, but it seems, that they are sorted
> nevertheless.
>
> Is it possible to tell gnus, to not sort articles that won't be
> displayed in the summary buffer?
>
> TIA for any help,

What is the backend for this inbox?  I ask because my inbox (on imap) 
has at least an order of magnitude more messages and starting up takes
very little time (<1s generally).

-- 
: Eric S Fraga, GnuPG: 0xFFFCF67D
: in Emacs 24.4.50.2 + Ma Gnus v0.12 + evil evil-git-8a9aeae
: BBDB version 3.1.2 (2014-04-27 15:05:20 -0500)

Re: entering a group is slow

[Peter Münster]

On Tue, Jun 17 2014, Eric S Fraga wrote:

> On Tuesday, 17 Jun 2014 at 10:02, Peter Münster wrote:
>
>> gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
>> gnus-thread-latest-date                 3962     4.6299316569  0.0011685844
>>
>> Because there are about 300 articles with the expirable-mark. These are
>> not shown in the summary buffer, but it seems, that they are sorted
>> nevertheless.
>>
>> Is it possible to tell gnus, to not sort articles that won't be
>> displayed in the summary buffer?
>
> What is the backend for this inbox?

nnml


> I ask because my inbox (on imap) has at least an order of magnitude
> more messages and starting up takes very little time (<1s generally).

Do you have a similar sorting setup?

Here is mine:

(setq
 gnus-sum-thread-tree-false-root        nil
 gnus-summary-thread-gathering-function 'gnus-gather-threads-by-references
 gnus-thread-operation-ignore-subject   nil
 gnus-thread-sort-functions             '(gnus-thread-sort-by-number
                                          (not gnus-thread-sort-by-most-recent-date)))

And here are my bogomips:

$ grep bogomips /proc/cpuinfo 
bogomips        : 6026.86
bogomips        : 6026.86
bogomips        : 6026.86
bogomips        : 6026.86

-- 
           Peter

Re: entering a group is slow

[Eric S Fraga]

On Tuesday, 17 Jun 2014 at 11:08, Peter Münster wrote:

[...]

> Do you have a similar sorting setup?

Not quite.  

In particular, I only gather threads by subject.  Maybe gathering by
references, as you do, slows things down?  I find that gathering by
subject works well enough in most cases.

-- 
: Eric S Fraga, GnuPG: 0xFFFCF67D
: in Emacs 24.4.50.2 + Ma Gnus v0.12 + evil evil-git-a6a27e0
: BBDB version 3.1.2 (2014-05-06 11:45:08 -0500)

Re: entering a group is slow

[Peter Münster]

On Wed, Jun 18 2014, Eric S Fraga wrote:

> On Tuesday, 17 Jun 2014 at 11:08, Peter Münster wrote:
>
> [...]
>
>> Do you have a similar sorting setup?
>
> Not quite.  
>
> In particular, I only gather threads by subject.  Maybe gathering by
> references, as you do, slows things down?  I find that gathering by
> subject works well enough in most cases.

gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
gnus-thread-latest-date                 3962     4.6299316569  0.0011685844

That means, it's more the sort-by-date function. Just to compare:
- could you try the same sorting setting
- elp-instrument-package with "gnus"
- enter a group
- post the result of elp-results
- post the number of messages in the group and your bogomips

It would be interesting to see, if the result is similar or not.

TIA,
-- 
           Peter

Re: entering a group is slow

[Eric S Fraga]

On Wednesday, 18 Jun 2014 at 11:19, Peter Münster wrote:
> On Wed, Jun 18 2014, Eric S Fraga wrote:
>
>> On Tuesday, 17 Jun 2014 at 11:08, Peter Münster wrote:
>>
>> [...]
>>
>>> Do you have a similar sorting setup?
>>
>> Not quite.  
>>
>> In particular, I only gather threads by subject.  Maybe gathering by
>> references, as you do, slows things down?  I find that gathering by
>> subject works well enough in most cases.
>
> gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
> gnus-thread-latest-date                 3962     4.6299316569  0.0011685844
>
> That means, it's more the sort-by-date function. Just to compare:
> - could you try the same sorting setting
> - elp-instrument-package with "gnus"
> - enter a group
> - post the result of elp-results
> - post the number of messages in the group and your bogomips

Using your settings, on a system with 4788 bogomips power (x8, mind
you), if I enter an imap group that has just over 2200 messages, but
with most of them read, I get the following from elp:

| gnus-topic-select-group          | 1 |   0.1476044 |    0.1476044 |
| gnus-group-select-group          | 1 | 0.147485628 |  0.147485628 |
| gnus-group-read-group            | 1 | 0.147478465 |  0.147478465 |
| gnus-summary-read-group          | 1 | 0.147406824 |  0.147406824 |
| gnus-summary-read-group-1        | 1 | 0.147396391 |  0.147396391 |
| gnus-select-newsgroup            | 1 | 0.127534018 |  0.127534018 |
| gnus-retrieve-headers            | 2 | 0.068619456 |  0.034309728 |
| gnus-fetch-headers               | 1 | 0.056974411 |  0.056974411 |
| gnus-request-group               | 1 |  0.04357731 |   0.04357731 |
| gnus-cache-retrieve-headers      | 1 | 0.034427306 |  0.034427306 |
| gnus-agent-retrieve-headers      | 1 | 0.034103183 |  0.034103183 |
| gnus-get-newsgroup-headers-xover | 1 | 0.022276303 |  0.022276303 |
| gnus-agent-uncached-articles     | 1 | 0.013716601 |  0.013716601 |
| gnus-build-old-threads           | 1 | 0.010798318 |  0.010798318 |
| gnus-build-get-header            | 7 | 0.010754334 | 0.0015363334 |
| gnus-agent-get-undownloaded-list | 1 |  0.00915007 |   0.00915007 |
| gnus-possibly-score-headers      | 1 | 0.008000199 |  0.008000199 |
| gnus-uncompress-range            | 1 | 0.007982589 |  0.007982589 |
| gnus-score-headers               | 1 | 0.006564297 |  0.006564297 |
| gnus-score-string                | 3 | 0.006189354 |  0.002063118 |
| gnus-summary-setup-buffer        | 1 |  0.00525971 |   0.00525971 |
| gnus-summary-prepare             | 1 | 0.004781695 |  0.004781695 |
| gnus-summary-mode                | 1 | 0.004483204 |  0.004483204 |

If I enter the group with C-u g, asking for 3000 articles (i.e. all of them for sure), I get

| gnus-topic-select-group                                |     1 |  5.071093405 |  5.071093405 |
| gnus-group-select-group                                |     1 |  5.071036504 |  5.071036504 |
| gnus-group-read-group                                  |     1 |  5.071029215 |  5.071029215 |
| gnus-summary-read-group                                |     1 |  5.070994293 |  5.070994293 |
| gnus-summary-read-group-1                              |     1 |  5.070984761 |  5.070984761 |
| gnus-select-newsgroup                                  |     1 |  2.509084108 |  2.509084108 |
| gnus-summary-prepare                                   |     1 |  1.795568169 |  1.795568169 |
| gnus-articles-to-read                                  |     1 |   1.65243982 |   1.65243982 |
| gnus-sort-threads                                      |     1 |  1.136247577 |  1.136247577 |
| gnus-sort-threads-recursive                            |     1 |  1.136086343 |  1.136086343 |
| gnus-thread-sort-by-most-recent-date                   | 23129 | 1.0279419529 | 4.444...e-05 |
| gnus-thread-latest-date                                | 46258 | 0.8665619080 | 1.873...e-05 |
| gnus-possibly-score-headers                            |     1 |  0.758001659 |  0.758001659 |
| gnus-score-headers                                     |     1 |  0.756500616 |  0.756500616 |
| gnus-score-string                                      |     3 | 0.7554036129 | 0.2518012043 |
| gnus-summary-prepare-threads                           |     1 |  0.649919046 |  0.649919046 |
| gnus-fetch-headers                                     |     1 |  0.415423749 |  0.415423749 |
| gnus-get-newsgroup-headers-xover                       |     1 |  0.303366086 |  0.303366086 |
| gnus-request-group                                     |     1 |   0.24331684 |   0.24331684 |
| gnus-retrieve-headers                                  |     2 |  0.223225159 | 0.1116125795 |
| gnus-build-old-threads                                 |     1 |  0.179217222 |  0.179217222 |
| gnus-build-get-header                                  |   162 | 0.1779244090 | 0.0010982988 |
| gnus-cache-retrieve-headers                            |     1 |  0.111749532 |  0.111749532 |
| gnus-agent-retrieve-headers                            |     1 |  0.111384558 |  0.111384558 |
| gnus-user-date                                         |  2297 | 0.0861283389 | 3.749...e-05 |
| gnus-score-string<                                     | 64562 | 0.0808055540 | 1.251...e-06 |
| gnus-uncompress-range                                  |     2 | 0.0750083929 | 0.0375041964 |
| gnus-put-text-property                                 | 11490 | 0.0739330490 | 6.434...e-06 |
| gnus-summary-highlight-line                            |  2297 | 0.0598782789 | 2.606...e-05 |
| gnus-add-text-properties                               |  4601 | 0.0591189480 | 1.284...e-05 |
| gnus-sort-subthreads-recursive                         |   509 | 0.0506805250 | 9.956...e-05 |
| gnus-summary-from-or-to-or-newsgroups                  |  2297 | 0.0407288869 | 1.773...e-05 |
| gnus-agent-uncached-articles                           |     1 |  0.038630534 |  0.038630534 |
| gnus-put-text-property-excluding-characters-with-faces |  2298 | 0.0257365099 | 1.119...e-05 |
| gnus-agent-load-alist                                  |     2 |  0.025423957 | 0.0127119785 |
| gnus-float-time                                        | 83217 | 0.0252736139 | 3.037...e-07 |
| gnus-cache-file-contents                               |     3 |  0.025268561 | 0.0084228536 |
| gnus-agent-read-agentview                              |     1 |  0.025121396 |  0.025121396 |
| gnus-seconds-year                                      |  1829 |  0.024419053 | 1.335...e-05 |
| gnus-user-format-function-j                            |  2297 | 0.0180159340 | 7.843...e-06 |
| gnus-list-range-difference                             |     2 |  0.016108743 | 0.0080543715 |
| gnus-extract-address-components                        |  2297 | 0.0145909759 | 6.352...e-06 |
| gnus-agent-get-undownloaded-list                       |     1 |  0.010274709 |  0.010274709 |
| gnus-seconds-today                                     |  2297 | 0.0080872700 | 3.520...e-06 |
| gnus-gather-threads-by-subject                         |     1 |  0.005732266 |  0.005732266 |
| gnus-summary-setup-buffer                              |     1 |  0.004753846 |  0.004753846 |
| gnus-summary-line-message-size                         |  2297 | 0.0047496790 | 2.067...e-06 |
| gnus-summary-mode                                      |     1 |    0.0039257 |    0.0039257 |

Not sure if this helps you or not...

With my own settings, the times are very similar.  Are you asking to see
*all* articles in a large group?  If so, there's not much you can do
about it, I would suggest.

-- 
: Eric S Fraga, GnuPG: 0xFFFCF67D
: in Emacs 24.4.50.2 + Ma Gnus v0.12 + evil evil-git-a6a27e0
: BBDB version 3.1.2 (2014-05-06 11:45:08 -0500)

Re: entering a group is slow

[Peter Münster]

On Wed, Jun 18 2014, Eric S Fraga wrote:

>> gnus-thread-sort-by-most-recent-date    1981     4.8174347399  0.0024318196
>> gnus-thread-latest-date                 3962     4.6299316569  0.0011685844
>
> Using your settings, on a system with 4788 bogomips power (x8, mind
> you), if I enter an imap group that has just over 2200 messages, but
> with most of them read, I get the following from elp:
>
> | gnus-thread-sort-by-most-recent-date                   | 23129 | 1.0279419529 | 4.444...e-05 |
> | gnus-thread-latest-date                                | 46258 | 0.8665619080 | 1.873...e-05 |
>
> Not sure if this helps you or not...

Yes and no. It helps to explore the problem, but I still don't understand...

Your CPU is about 1.26 times slower than mine, but your
gnus-thread-latest-date is about 62 times faster. That means, that your
gnus-thread-latest-date uses about 80 times less CPU cycles than mine !

Now I've tried with nntp+news.gmane.org:gmane.emacs.gnus.general, to see
if the back-end matters: nntp is worse, even 0.0052218751s per call.

What could be the reason for this slowness?

I've used ELP also with the packages "mail" and "message", but there are
no slow functions...

Further information: All these tests are done with emacs started on
June 8, that means 10 days uptime. Now, I've just restarted emacs and
the time per call is 0.0002029752s. Much better, but still worse than
your result.

Why is gnus-thread-latest-date so slow on my system?
Why does the slowness depend on the emacs-uptime?

TIA for any help,
-- 
           Peter

Re: entering a group is slow

[Eric S Fraga]

On Wednesday, 18 Jun 2014 at 23:00, Peter Münster wrote:

[...]

> Your CPU is about 1.26 times slower than mine, but your
> gnus-thread-latest-date is about 62 times faster. That means, that your
> gnus-thread-latest-date uses about 80 times less CPU cycles than mine !

I am not sure if elp reports cpu time or elapsed (wall clock)
time.  Also, remember that my system has 8 cpu cores and large
memory.  Bogomips alone is not a full measure of system
capability.  What storage system are you using?  I.e. do you have a slow
disk?  Etc.

> Further information: All these tests are done with emacs started on
> June 8, that means 10 days uptime. Now, I've just restarted emacs and
> the time per call is 0.0002029752s. Much better, but still worse than
> your result.
>
> Why is gnus-thread-latest-date so slow on my system?
> Why does the slowness depend on the emacs-uptime?

Are you swapping, by any chance?  How much memory does your system have?
Type "free" at the shell.

-- 
: Eric S Fraga, GnuPG: 0xFFFCF67D
: in Emacs 24.3.1 + Ma Gnus v0.12 + evil evil-git-a6a27e0
: BBDB version 3.0.50 (2013-11-16 11:30:49 -0600)

Re: entering a group is slow

[Peter Münster]

On Thu, Jun 19 2014, Eric S Fraga wrote:

> On Wednesday, 18 Jun 2014 at 23:00, Peter Münster wrote:
>
> I am not sure if elp reports cpu time or elapsed (wall clock)
> time.

I guess elapsed time. But it doesn't matter, because when I do the test,
emacs uses 100% CPU time.


> Also, remember that my system has 8 cpu cores and large memory.

But emacs can only use one core.


> Bogomips alone is not a full measure of system capability. What
> storage system are you using? I.e. do you have a slow disk? Etc.

When I do the test, everything is in memory, no disk reading involved.
I have 4GB memory, and the swap area is almost never needed.

You are right, bogomips is perhaps not the only parameter for speed.
Perhaps the CPU cache is also important here.

The speed is acceptable now, with gnus-large-newsgroup = 500, but it
would be interesting to know, why emacs becomes slower after some days
of uptime... ?
Or perhaps I've done something particular, that has made emacs slow?
What could it be...?

-- 
           Peter

Re: entering a group is slow

[Eric S Fraga]

On Thursday, 19 Jun 2014 at 11:45, Peter Münster wrote:

[...]

> I guess elapsed time. But it doesn't matter, because when I do the test,
> emacs uses 100% CPU time.

Wow!  Mine does not, or not noticeably so.  The delay, if any, is
network latency and the email server, in my case.

>> Also, remember that my system has 8 cpu cores and large memory.
>
> But emacs can only use one core.

Sure but if emacs is competing for cpu with anything else, this matters.

> Or perhaps I've done something particular, that has made emacs slow?
> What could it be...?

What about the summary line?  Do you have a highly customised one?  In
my case, the user date function actually contributes non-negligibly to
the time gnus takes in preparing the summary buffer...  otherwise, I am
out of ideas and maybe somebody else can jump in!

-- 
: Eric S Fraga, GnuPG: 0xFFFCF67D
: in Emacs 24.4.50.2 + Ma Gnus v0.12 + evil evil-git-a6a27e0
: BBDB version 3.1.2 (2014-04-27 15:05:20 -0500)

Re: entering a group is slow

[Peter Münster]

On Thu, Jun 19 2014, Eric S Fraga wrote:

> Wow!  Mine does not, or not noticeably so.  The delay, if any, is
> network latency and the email server, in my case.

Oh, then I would really like to know, where emacs spends the cpu-time on
my system...   And why it can become much slower suddenly.


> Sure but if emacs is competing for cpu with anything else, this matters.

Right. But it was not the case on my system. (I use xosview for monitoring
the CPUs: 3 were idle, and the fourth was at 100% because of emacs.)


>> Or perhaps I've done something particular, that has made emacs slow?
>> What could it be...?
>
> What about the summary line?  Do you have a highly customised one?  In
> my case, the user date function actually contributes non-negligibly to
> the time gnus takes in preparing the summary buffer...

I've tested with the default line, there is no difference.


> otherwise, I am out of ideas and maybe somebody else can jump in!

That would be really appreciated!

Thanks for your efforts,
-- 
           Peter

Re: entering a group is slow

[lee]

Peter Münster <pmlists@free.fr> writes:

> On Thu, Jun 19 2014, Eric S Fraga wrote:
>
>> Wow!  Mine does not, or not noticeably so.  The delay, if any, is
>> network latency and the email server, in my case.
>
> Oh, then I would really like to know, where emacs spends the cpu-time on
> my system...   And why it can become much slower suddenly.

You might be experiencing some latency from your storage system.  Does
top show a lot of waitstates when you're entering a group, or when disk
activity is going on?


-- 
Knowledge is volatile and fluid.  Software is power.

Re: entering a group is slow

[Peter Münster]

On Mon, Sep 08 2014, lee wrote:

> You might be experiencing some latency from your storage system.  Does
> top show a lot of waitstates when you're entering a group, or when disk
> activity is going on?

No, there is no disk reading. Everything is in RAM.

ELP shows, that the mapcar function called from gnus-thread-latest-date
takes a lot of time (uptime of emacs is 10 days):

mapcar                  20250       5.3743043500  0.0002653977

After restarting emacs:

mapcar                  21468       0.1387124370  6.461...e-06

About 40 times faster now!!


Thanks in advance for any help or hints how to debug further,
-- 
           Peter