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,

[Igor Sosa Mayor]

Post by 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?

how many messages are in the group?

[Peter Münster]

Post by Igor Sosa Mayor

Post by Peter Münster
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 Münster]

Post by Peter Münster

Post by Igor Sosa Mayor

Post by Peter Münster
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.
- 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,

[Eric S Fraga]

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

[...]

Post by Peter Münster
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
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).

[Peter Münster]

Post by Eric S Fraga

Post by Peter Münster
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

Post by Eric S Fraga
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

[Eric S Fraga]

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

[...]

Post by Peter Münster
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.

[Peter Münster]

Post by Eric S Fraga
[...]

Post by Peter Münster
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,

[Eric S Fraga]

Post by Peter Münster

Post by Eric S Fraga
[...]

Post by Peter Münster
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
- 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.

[Peter Münster]

Post by Eric S Fraga

Post by Peter Münster
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
| 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,

[Eric S Fraga]

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

[...]

Post by Peter Münster
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.

Post by Peter Münster
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.

[Peter Münster]

Post by Eric S Fraga
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.

Post by Eric S Fraga
Also, remember that my system has 8 cpu cores and large memory.

But emacs can only use one core.

Post by Eric S Fraga
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...?

[Eric S Fraga]

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

[...]

Post by Peter Münster
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.

Post by Peter Münster

Post by Eric S Fraga
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.

Post by Peter Münster
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!

[Peter Münster]

Post by Eric S Fraga
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.

Post by Eric S Fraga
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.)

Post by Eric S Fraga

Post by Peter Münster
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.

Post by Eric S Fraga
otherwise, I am out of ideas and maybe somebody else can jump in!

That would be really appreciated!

Thanks for your efforts,

[lee]

Post by Peter Münster

Post by Eric S Fraga
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?

[Peter Münster]

Post by lee
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,