Subject: [sup-talk] Sup is hanging

From: [email-masked] (Edward Z. Yang)
Date: Wed, 03 Jun 2009 13:39:40 -0400

Hey all,

Somehow, I messed something up really bad, and now, whenever Sup
attempts to poll for new messages, it hang completely, spinning the
CPU.  I've let it run for an appreciable amount of time, and haven't
seen any change.  I was wondering how I could fix this, or go about
debugging it.  There also seems to be a single mail source at fault,
but I can't remove it without having Sup complain at me.  Right now,
I'm running sup as -no.

Thanks,
Edward

---

From: [email-masked] (William Morgan)
Date: Wed, 03 Jun 2009 11:11:28 -0700

Reformatted excerpts from Edward Z. Yang's message of 2009-06-03:
> debugging it.

Is the curses interface hung? If not, can you see if there's activity in
the poll mode or the log mode buffers? (Hit ; if you're running from
git, or B if you're running 0.7.) It might be that you've somehow reset
the recorded offset for a very large source, so Sup is polling a lot of
stuff in the background.

If it's completely hung (which would be weird), try first disabling your
hooks (move them from ~/.sup/hooks to another directory) and see if that
helps. If not, please describe the behavior of running sup-sync.

-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 03 Jun 2009 14:21:35 -0400

The current working theory (based on strace'ing and lsof) is that Sup
is hanging on a select() call that doesn't have any timeout.  The reason
why this is hanging is because between opening the connection and
closing it, Sup does some ridiculously slow message parsing code (that
really thrashes the CPU) and by the time it's done the server has
closed the connection (but we don't know about it).  The fix would probably
be to always set a timeout, but I don't know what code needs to be fixed
for that.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 3 Jun 2009 14:26:44 -0400 (EDT)

On Wed, 3 Jun 2009, William Morgan wrote:
> Is the curses interface hung?>

Yep.

> helps. If not, please describe the behavior of running sup-sync.

I can try that. I've described the behavior of sup-sync in my other
email.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 3 Jun 2009 14:45:59 -0400 (EDT)

Also, if it helps, here's the backtrace for when it's hanging on the
select:

     /usr/lib/ruby/1.8/monitor.rb:102:in `stop': Interrupt
     from /usr/lib/ruby/1.8/monitor.rb:102:in `wait'
     from /usr/lib/ruby/1.8/net/imap.rb:972:in `get_tagged_response'
     from /usr/lib/ruby/1.8/net/imap.rb:1032:in `send_command'
     from /usr/lib/ruby/1.8/monitor.rb:242:in `synchronize'
     from /usr/lib/ruby/1.8/net/imap.rb:1017:in `send_command'
     from /usr/lib/ruby/1.8/net/imap.rb:409:in `examine'
     from /usr/lib/ruby/1.8/monitor.rb:242:in `synchronize'
     from /usr/lib/ruby/1.8/net/imap.rb:407:in `examine'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:145:in `unsynchronized_scan_mailbox'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:322:in `safely'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:144:in `unsynchronized_scan_mailbox'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:192:in `unsynchronized_start_offset'
     from (eval):3:in `start_offset'
     from (eval):3:in `synchronize'
     from (eval):3:in `start_offset'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:544:in `send'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:544:in `__pass'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:531:in `method_missing'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup-sync:147
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/poll.rb:160:in `add_messages_from'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:187:in `each'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:175:in `upto'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/imap.rb:175:in `each'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:544:in `send'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:544:in `__pass'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:531:in `method_missing'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/poll.rb:141:in `add_messages_from'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:505:in `send'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/util.rb:505:in `method_missing'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup-sync:140
     from /usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup-sync:135:in `each'
     from /usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup-sync:135
     from /var/lib/gems/1.8/bin/sup-sync:19:in `load'
     from /var/lib/gems/1.8/bin/sup-sync:19

Cheers,
Edward

---

From: [email-masked] (William Morgan)
Date: Wed, 03 Jun 2009 14:36:15 -0700

Reformatted excerpts from Edward Z. Yang's message of 2009-06-03:
> is hanging on a select() call that doesn't have any timeout.  The
> reason why this is hanging is because between opening the connection
> and closing it, Sup does some ridiculously slow message parsing code
> (that really thrashes the CPU) and by the time it's done the server
> has closed the connection (but we don't know about it).

That may all be true, but I'd be surprised if a) Sup didn't know that
the server had closed the connection, and b) that this would cause the
whole thing to hang.

When you don't use -n, does Sup still lock up?
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 3 Jun 2009 17:48:56 -0400 (EDT)

On Wed, 3 Jun 2009, William Morgan wrote:
> the server had closed the connection, and

It doesn't have anything to do with Sup: the system select() call is
hanging; Sup (and Ruby for that matter) is out of the equation. This
might be IMAP server weirdness, but that shouldn't cause Sup to
freeze.

> b) that this would cause the
> whole thing to hang.

That's what I find surprising, since Sup is multithreaded. I suppose
all of the threads are blocking on the select.

Sup hangs without -n. (it always hangs after it's "done fetching IMAP
headers"). "done fetching IMAP headers" is the last message we get.

The behavior seems to be:

1. Log reports "done fetching IMAP headers"

2. Sup begins malloc'ing like crazy. sup-sync still is able to catch
    signals and if you kill it you find that it's somewhere in
    lib/sup/message.rb, message_to_chunks. sup doesn't respond to Ctrl+C

3. After some minutes, CPU usage dies off, but Sup doesn't unfreeze.
    strace indicates that sup/sup-sync is waiting on a select(), and that
    the descriptors are TCP connections to the IMAP server.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 3 Jun 2009 18:00:06 -0400 (EDT)

Oh hey, I managed to kill Sup:

ezyang at javelin:~$ sup
[Wed Jun 03 17:42:43 -0400 2009] using character set encoding "UTF-8"
[Wed Jun 03 17:42:44 -0400 2009] dynamically loading setlocale() from
libc.so.6
[Wed Jun 03 17:42:44 -0400 2009] setting locale...
[Wed Jun 03 17:42:44 -0400 2009] locking /home/ezyang/.sup/lock...
[Wed Jun 03 17:42:44 -0400 2009] crypto: detected gpg binary in
/usr/bin/gpg
[Wed Jun 03 17:42:44 -0400 2009] loading index...
[Wed Jun 03 17:42:44 -0400 2009] loaded index of 20188 messages
[Wed Jun 03 17:42:44 -0400 2009] starting curses
[Wed Jun 03 17:54:47 -0400 2009] stopped cursing
[Wed Jun 03 17:54:47 -0400 2009] oh crap, an exception
[Wed Jun 03 17:54:47 -0400 2009] unlocking /home/ezyang/.sup/lock...
----------------------------------------------------------------
I'm very sorry. It seems that an error occurred in Sup. Please
accept my sincere apologies. If you don't mind, please send the
contents of ~/.sup/exception-log.txt and a brief report of the
circumstances to sup-talk at rubyforge dot orgs so that I might
address this problem. Thank you!

Sincerely,
William
----------------------------------------------------------------
--- Interrupt from thread: main

/usr/lib/ruby/gems/1.8/gems/ncurses-0.9.1/lib/ncurses.rb:71:in
`method_missing'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/buffer.rb:109:in `write'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/scroll-mode.rb:245:in
`draw_line_from_string'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/scroll-mode.rb:182:in
`draw_line'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/scroll-mode.rb:48:in
`draw'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/scroll-mode.rb:48:in
`each'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/scroll-mode.rb:48:in
`draw'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/buffer.rb:99:in `draw'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/buffer.rb:303:in
`draw_screen'
/usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup:308
/var/lib/gems/1.8/bin/sup:19:in `load'
/var/lib/gems/1.8/bin/sup:19

This seems... unrelated.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 03 Jun 2009 21:26:01 -0400

Ok, after a bit of fiddling, I've managed to figure out that this is
two problems, not one.

The first is related to a naughty IMAP server which simply stops responding
after a certain number of seconds.  Unfortunately, this is my workplace's
IMAP server, so I can't give you a test environment.  Furthermore, the code
that would be appropriate to change is in Net::Imap, and thus is not
easily accessible by Sup.  I've worked around this by making it an unusual
source.

The second is a large amount of CPU thrashing as Sup parses messages. This
is something we can fix, and I hope to do some more poking to help make
Sup run faster in this respect. The basic behavior is Sup repeatedly
allocates some amount of memory, reallocates it twice (quadrupling it
in size to about 4MB), deallocates, and then does it again. I'm running
ruby-prof in hopes of tickling this again.  Unlike the hung IMAP server,
this eventually finishes, but it is extremely obnoxious when it happens
and blocks everything else. It commonly occurs when I open an email message.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Wed, 3 Jun 2009 21:53:12 -0400 (EDT)

> and blocks everything else. It commonly occurs when I open an email message.

Here we go:

http://web.mit.edu/~ezyang/Public/sup-performance.png

Look at String::=~. Definitely not acceptable.

Cheers,
Edward

---

From: [email-masked] (William Morgan)
Date: Wed, 03 Jun 2009 19:11:31 -0700

[resent to list]

> all of the threads are blocking on the select.

It's possible... Ruby does use green threads and a GIL, so there's
always the possibility that something in C land will block all Ruby
threads, but my impression was that that was an issue mainly with
third-party libraries. I believe that Net::IMAP is pure Ruby, thus using
the core Ruby IO mechanisms, and I thought those were pretty good about
being preemptible. Curious!
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (William Morgan)
Date: Wed, 03 Jun 2009 19:12:25 -0700

---

From: [email-masked] (William Morgan)
Date: Wed, 03 Jun 2009 19:13:58 -0700

[sorry about that last one. really not doing too well with the ol' email
today.]

Reformatted excerpts from Edward Z. Yang's message of 2009-06-03:
> /usr/lib/ruby/gems/1.8/gems/ncurses-0.9.1/lib/ncurses.rb:71:in `method_missing'
[snip]
> This seems... unrelated.

This looks like a ctrl-c that got caught by an ncurses thread. I agree,
seems unrelated.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (William Morgan)
Date: Thu, 04 Jun 2009 09:09:40 -0700

> Look at String::=~. Definitely not acceptable.

Doing some profiling on my end, it looks like the majority of IMAP
syncing time is spent in these five methods:

Redwood::Index#load_entry_for_id (22%)
Redwood::IMAP#load_message (25%)
Redwood::Message#message_to_chunks (16.5%)
Redwood::IMAP#load_header (14%)
Redwood::Index#sync_message (13%)

Four of those are essentially wrappers around IMAP or Ferret methods.
The Sup-specific one is Message#message_to_chunks. But message_to_chunks
and its callee text_to_chunks doesn't seem to have a major culprits.
String#=~ only takes 2.3% of the CPU time, and a chunk of that is coming
from RubyMail.

Just for good measure, I "manually" measured the individual regexen in
text_to_chunks. After parsing 100 messages from an IMAP server, which
took 1m27s for me, I got:

           time (s)   calls
     bqp = 0.00854 /  1789 = 209411.2 calls/second
      n1 = 0.00218 /   313 = 143709.8 calls/second
     qsp = 0.03212 /  1923 =  59873.0 calls/second
      n2 = 0.00202 /   312 = 154226.4 calls/second
   empty = 0.00061 /    90 = 146341.5 calls/second
      sp = 0.02570 /  1927 =  74995.1 calls/second
      qp = 0.03392 /  4459 = 131452.5 calls/second

The names are abbreviations for the various regexen in that method. You
can see that the cumulative time spent on any one regex is at most .034
seconds (qp, which is QUERY_PATTERN), and that the slowest one is qsp,
QUERY_START_PATTERN.

Incidentally, I can parse IMAP mailboxes at a little over 1 message/s,
and mbox files at ~50 messages/second, which also suggests that the IMAP
libraries are the biggest time sink here.

This is all with ruby 1.8.7 (2008-08-11 patchlevel 72) [x86_64-linux]), Sup
git next.

Now that's all CPU stuff. There might be memory blowup issues. If
nothing else, Sup leaks memory over time, but fixing that involves the
getting into the hellish world of Ruby<->C land or the even more hellish
internals of MRI, so I've been loathe to start down that path.

You might be able to speed up sup-sync runs on IMAP by threading the
network access and the parsing. But the IMAP connection seems pretty
CPU-heavy so who knows.

None of this answers the original question of why all Ruby threads block
when Sup waits for a response from IMAP. Since I'm pretty sure the IMAP
libraries are all Ruby (why they're so slow!), and that core Ruby IO
should be nonblocking, this might be an interpreter bug. Are you able to
pinpoint what part of MRI is blocking?
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Edward Z. Yang)
Date: Fri, 05 Jun 2009 01:08:10 -0400

Hi William,

I tickled the bug and took a more careful look at the message that had
triggered it, and noticed that it was an auto-generated commit message
that was really long.  So one possible stop-gap would be just to detect
if a message is long and disable quoting if that was the case (a long
message would be, say, one over 100KB).  There is also a possibility
that the commit message had some pathological backtracking built into
it.

> Redwood::Index#sync_message (13%)

Ok, so this isn't the same spread as when I managed to make Sup hang,
so this isn't quite the same.

> internals of MRI, so I've been loathe to start down that path.

Sup memory leakage has not been a problem; Sup will hang on a poll
asynchronously (as in, UI is still responsive, but I get no more
new messages) often enough that I have to quit and start sup up again.

> pinpoint what part of MRI is blocking?

Not yet. I don't know Ruby threads well enough to know how to get more
fine-grained information on thread mutex/blocking interaction.

To summarize:

1. If I thrash message_to_chunks() with a very long message, I cause
   sup to hang.

   * If this case is only caused by long messages, implement a hueristic
     to prevent quoting from happening to long messages.

   * If there is something specific about the message that causes massive
     back-tracking, fix the regex.

   In either case, message_to_chunks() should not block the rest of the
   interface (although if we fix either or the two sub-points, this
   may not be a noticeable problem).

2. If an IMAP connection hangs, it occasionally causes all of Sup to
   block (this is rare, and comes from a pathological IMAP server. I
   think the ops administering the naughty IMAP server fixed it, so
   I am no longer seeing this hang).

3. Under less pathological cases, an IMAP connection can hang, and
   asynchronously blocks any further polling from taking place, resulting
   in no new messages.  This happens commonly for me.

Cheers,
Edward

---

From: [email-masked] (William Morgan)
Date: Fri, 05 Jun 2009 06:23:50 -0700

Reformatted excerpts from Edward Z. Yang's message of 2009-06-04:
> triggered it

This is good stuff. I think we're getting somewhere. I was hoping to
have this this fixed by 0.8 but I think it's going to have to wait till
0.9.

> and noticed that it was an auto-generated commit message that was
> really long. So one possible stop-gap would be just to detect if a
> message is long and disable quoting if that was the case (a long
> message would be, say, one over 100KB).

Yep, I bet that's the problem.

Not parsing long messages would be fine as far as I'm concerned. Heck
even 25k might be a reasonable limit (per MIME part).

> There is also a possibility that the commit message had some
> pathological backtracking built into it.

It's possible... but I'm willing to bet that it's the sheer size. If
we're still seeing this performance on smaller messages (e.g.  when you
start sending me emails carefully constructed to induce worst-case
performance in Sup's regexen) we can wrap a timeout around the whole
parse as well.

> so this isn't quite the same.

That makes sense.

> 1. If I thrash message_to_chunks() with a very long message, I cause

This is still weird. It only makes sense if Ruby regexen block the whole
interpreter when evaluating. I guess that might be the case if they're
they haven't taken the (what I imagine must be trivial) step of allowing
preemption during the DFA execution (or however the hell they're
implemented). I guess an experiment would show this.

>    I am no longer seeing this hang).

This is also still weird, and I wonder if it's not just problems 1 and 3
combining. If it comes back we will have to do some more investigation.

> in no new messages.  This happens commonly for me.

This one we can fix. (Though it's something the IMAP libraries should've
done for us.) If we put a timeout block around that #examine call, we
should be able to reset the connection if it hangs.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Edward Z. Yang)
Date: Fri, 05 Jun 2009 17:47:00 -0400

Excerpts from Marc Hartstein's message of Fri Jun 05 14:43:59 -0400 2009:
> I noticed that one feature of the messages was that they contained one
> extremely long line.  Not sure if this information will in any way help
> figure out what's going on there.

Now that you mention it, the messages that tickle this bug on my side also
have one extremely long line.  That's very interesting.

Cheers,
Edward

---

From: [email-masked] (Edward Z. Yang)
Date: Sat, 06 Jun 2009 02:20:25 -0400

> have one extremely long line.  That's very interesting.

Here is the culprit, laid out to bear its full shame:

    /\w.*:$/

I thought this was a suspicious looking regexen; a simple test confirmed my
belief:

    line = ":a" * 10000
    line =~ /\w.*:$/

Ba boom ba boom ba boom.  This is a textbook case of catastrophic backtracking.

I have two possible fixes, they end up being about the same time for regular
cases, but the second one is more optimal for really long strings:

First, the simple one:

diff --git a/lib/sup/message.rb b/lib/sup/message.rb
index 5993729..0ddd3af 100644
--- a/lib/sup/message.rb
+++ b/lib/sup/message.rb
@@ -26,7 +26,7 @@ class Message
 
   QUOTE_PATTERN = /^\s{0,4}[>|\}]/
   BLOCK_QUOTE_PATTERN = /^-----\s*Original Message\s*----+$/
-  QUOTE_START_PATTERN = /\w.*:$/
+  QUOTE_START_PATTERN = /\w\W*:$/
   SIG_PATTERN = /(^-- ?$)|(^\s*----------+\s*$)|(^\s*_________+\s*$)|(^\s*--~--~-)|(^\s*--\+\+\*\*==)/
 
   MAX_SIG_DISTANCE = 15 # lines from the end

And the slightly more complicated one (but optimal for large n):

diff --git a/lib/sup/message.rb b/lib/sup/message.rb
index 5993729..c5481a6 100644
--- a/lib/sup/message.rb
+++ b/lib/sup/message.rb
@@ -26,7 +26,6 @@ class Message
 
   QUOTE_PATTERN = /^\s{0,4}[>|\}]/
   BLOCK_QUOTE_PATTERN = /^-----\s*Original Message\s*----+$/
-  QUOTE_START_PATTERN = /\w.*:$/
   SIG_PATTERN = /(^-- ?$)|(^\s*----------+\s*$)|(^\s*_________+\s*$)|(^\s*--~--~-)|
 
   MAX_SIG_DISTANCE = 15 # lines from the end
@@ -449,7 +448,7 @@ private
       when :text
         newstate = nil
 
-        if line =~ QUOTE_PATTERN || (line =~ QUOTE_START_PATTERN && nextline =~ QUO
+        if line =~ QUOTE_PATTERN || (line =~ /:$/ && line =~ /\w/ && nextline =~ QU
           newstate = :quote
         elsif line =~ SIG_PATTERN && (lines.length - i) < MAX_SIG_DISTANCE
           newstate = :sig

There are number of micro-optimizations that could be made to message
parsing, but this will basically fix the egregious problem.

Cheers,
Edward

---

From: [email-masked] (William Morgan)
Date: Mon, 08 Jun 2009 11:09:52 -0700

> +        if line =~ QUOTE_PATTERN || (line =~ /:$/ && line =~ /\w/ && nextline =~ QU

Seems fine to me. I've applied that change directly to master. Not only
are there millions of optimiziations for this stuff, there are millions
of tweaks to improve detection precision and recall.

Thanks for your help with this, Edward!
-- 
William <wmorgan-sup at masanjin.net>