Subject: Pine slowdown since 4.60

From: Steve Huston <[email-masked]>
Date: Mon, 1 Nov 2004 15:03:56 -0500 (EST)

We use Pine extensively in our department, and I've noticed a bit of a
slowdown in recent versions.  Up to and including 4.55, I could take a series
of messages that were selected (even over 2000), and save them all to another
folder within a matter of a few seconds.  Since version 4.60 (and just tried
4.61), performing the same operation takes many seconds, sometimes minutes
depending on the number of messages.  I've tried older machines in the
building that still run 4.55 and the symptom disappears.

All machines running Linux - older ones running RedHat 7.2 or 8.0, newer ones
that show the problem running Fedora Core 2.  IMAP server is Cyrus IMAPD, and
all message moves are between IMAP folders.

Any hints appreciated!  If you need more information, let me know.  Thanks!

-- 
Steve Huston - W2SRH - Unix Sysadmin, Dept. of Astrophysical Sciences
  Princeton University  |    ICBM Address: 40.346525   -74.651285
    126 Peyton Hall     |"On my ship, the Rocinante, wheeling through
  Princeton, NJ   08544 | the galaxies; headed for the heart of Cygnus,
    (609) 258-7375      | headlong into mystery."  -Rush, 'Cygnus X-1'
-- 
-----------------------------------------------------------------
 For information about this mailing list, and its archives, see: 
 http://www.washington.edu/pine/pine-info/
-----------------------------------------------------------------

---

From: Eduardo Chappa <[email-masked]>
Date: Mon, 1 Nov 2004 12:18:06 -0800 (PST)

*** Steve Huston ([email-masked]) wrote in the pine-info...:

:) We use Pine extensively in our department, and I've noticed a bit of a 
:) slowdown in recent versions.  Up to and including 4.55, I could take a 
:) series of messages that were selected (even over 2000), and save them 
:) all to another folder within a matter of a few seconds.  Since version 
:) 4.60 (and just tried 4.61), performing the same operation takes many 
:) seconds, sometimes minutes depending on the number of messages. 

Hello Steve,

  The first thing I would suggest in order to investigate this problem is 
to see the debug information. In this case, you need to reproduce the 
problem, then press "M J", then select the debug level "9" and press "T" 
for time stamps, once there you will be able to see what happened during 
the session. Since this is happening by imap, you want to take a look at 
the lines "IMAP DEBUG" and look for big gap times. In case you can not do 
this directly because Pine was not compiled with DEBUGJOURNAL on, you will 
want to run the command

  pine -d verbose=9,imap=4

and take a look at the output in the file ~/.pine-debug1. Finally if Pine 
was built without debug support, then you will have to build your own 
version from scratch (which builds with debug and debugjournal by 
default).

-- 
Eduardo
Patches/Help: http://www.math.washington.edu/~chappa/pine/
XML/RSS feed: http://www.math.washington.edu/~chappa/pine/pine.xml

---

From: Steve Huston <[email-masked]>
Date: Mon, 1 Nov 2004 16:51:35 -0500 (EST)

On Mon, 1 Nov 2004, Eduardo Chappa wrote:
> to see the debug information.

Well, on 4.61, there doesn't seem to be an IMAP delay anywhere.  Looks like it
went through all that fine... what's interesting is:

   16:32:09.808255: Folder "archives.sent-mail" opened with 9,641 messages
   16:32:16.046280: Select matched 2,000 messages!
   16:33:28.043875: IMAP DEBUG 16:33:28 11/1: * 1421 FETCH (FLAGS (\Deleted \Seen NotJunk))

I basically picked the first 2000 mails, told it to save them to a new folder.
In the debug information, it has no information about mails 1-1420, though
later when I undeleted them the IMAP DEBUG lines are there.  Shortly after the
lines setting the messages as deleted (at TS 16:33:28.144893) is reported
"2,000 messages saved and deleted".  I double checked, and on a RH7.2 machine
with Pine 4.44, the same operation took 3 seconds, though it's not compiled
with debugging information so I didn't get the whole lines.

If you want the whole debug log from the 4.61 copy, let me know and I'll gzip
and send it.  Don't want to spam the list otherwise.

---

From: Eduardo Chappa <[email-masked]>
Date: Mon, 1 Nov 2004 15:20:39 -0800 (PST)

:) If you want the whole debug log from the 4.61 copy, let me know and 
:) I'll gzip and send it.  Don't want to spam the list otherwise.

Thank you Steve for the debug (sent outside the list). Here's what's going 
on:

You copy 2000 messages, Pine copies each message, one by one, executing 
a loop "for i=1 to 2000", this is the loop with "i=46": (my comments 
preceeded with a ">")

10000039 COPY 46 INBOX.tmp
10000039 OK [COPYUID 1099346072 9688 46] Completed
2000008d NOOP
* 46 EXISTS
* 46 RECENT
2000008d OK Completed
2000008e SEARCH HEADER Message-ID <Pine.GSO.4.03.1010816112331$16:54:34.552004: * SEARCH 46
> I don't see why it it needed. Once Pine has run out of cached 
> Message-Ids it will request for more of them, but I don't see why it is
> searching for them. Maybe someone would like to explain this?
2000008e OK Completed (1 msgs in 0.000 secs)
2000008f STORE 46 +Flags (NotJunk)
* 46 FETCH (FLAGS (\Recent \Seen NotJunk))
2000008f OK Completed

Ok, so your delay is due to the fact that the copy and store commands are 
doing this process on a one by one message basis. Pine could perfectly do 
a

TAG COPY 1:2000 INBOX.tmp

to copy those messages, but it does not, and a couple of STORE commands 
would also take care of this (the sequence numbers are complicated to 
compute, but Pine has that information fetched already for each message, 
so it should be fast). This would not take very long, at least not the 1 
minute as you are waiting for.

I have not read the code to try to find why this is done so, but it seems 
that IMAP has a good way of doing this, that is not being used.

---

From: Steve Hubert <[email-masked]>
Date: Mon, 1 Nov 2004 16:12:51 -0800 (PST)

If what Eduardo talks about is the problem, take a look at the hidden pine 
feature "save-aggregates-copy-sequence" and its help text.

Steve