* [sup-talk] Sup is hanging @ 2009-06-03 17:39 Edward Z. Yang 2009-06-03 18:11 ` William Morgan 2009-06-03 18:21 ` Edward Z. Yang 0 siblings, 2 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 17:39 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 17:39 [sup-talk] Sup is hanging Edward Z. Yang @ 2009-06-03 18:11 ` William Morgan 2009-06-03 18:26 ` Edward Z. Yang 2009-06-03 18:21 ` Edward Z. Yang 1 sibling, 1 reply; 19+ messages in thread From: William Morgan @ 2009-06-03 18:11 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: > 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. 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 18:11 ` William Morgan @ 2009-06-03 18:26 ` Edward Z. Yang 0 siblings, 0 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 18:26 UTC (permalink / raw) On Wed, 3 Jun 2009, William Morgan wrote: > Is the curses interface hung?> Yep. > 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. I can try that. I've described the behavior of sup-sync in my other email. Cheers, Edward ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 17:39 [sup-talk] Sup is hanging Edward Z. Yang 2009-06-03 18:11 ` William Morgan @ 2009-06-03 18:21 ` Edward Z. Yang 2009-06-03 18:45 ` Edward Z. Yang 2009-06-03 21:36 ` William Morgan 1 sibling, 2 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 18:21 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 18:21 ` Edward Z. Yang @ 2009-06-03 18:45 ` Edward Z. Yang 2009-06-03 21:36 ` William Morgan 1 sibling, 0 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 18:45 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 18:21 ` Edward Z. Yang 2009-06-03 18:45 ` Edward Z. Yang @ 2009-06-03 21:36 ` William Morgan 2009-06-03 21:48 ` Edward Z. Yang 2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang 1 sibling, 2 replies; 19+ messages in thread From: William Morgan @ 2009-06-03 21:36 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: > 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). 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 21:36 ` William Morgan @ 2009-06-03 21:48 ` Edward Z. Yang 2009-06-04 2:11 ` William Morgan 2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang 1 sibling, 1 reply; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 21:48 UTC (permalink / raw) On Wed, 3 Jun 2009, William Morgan wrote: > Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: >> 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). > > That may all be true, but I'd be surprised if a) Sup didn't know that > 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-03 21:48 ` Edward Z. Yang @ 2009-06-04 2:11 ` William Morgan 0 siblings, 0 replies; 19+ messages in thread From: William Morgan @ 2009-06-04 2:11 UTC (permalink / raw) [resent to list] Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: > That's what I find surprising, since Sup is multithreaded. I suppose > 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hangingy 2009-06-03 21:36 ` William Morgan 2009-06-03 21:48 ` Edward Z. Yang @ 2009-06-03 22:00 ` Edward Z. Yang 2009-06-04 1:26 ` Edward Z. Yang ` (2 more replies) 1 sibling, 3 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-03 22:00 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hangingy 2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang @ 2009-06-04 1:26 ` Edward Z. Yang 2009-06-04 1:53 ` [sup-talk] Sup is hangingyy Edward Z. Yang 2009-06-04 2:12 ` [sup-talk] Sup is hangingy William Morgan 2009-06-04 2:13 ` William Morgan 2 siblings, 1 reply; 19+ messages in thread From: Edward Z. Yang @ 2009-06-04 1:26 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hangingyy 2009-06-04 1:26 ` Edward Z. Yang @ 2009-06-04 1:53 ` Edward Z. Yang 2009-06-04 16:09 ` [sup-talk] Sup is hanging William Morgan 0 siblings, 1 reply; 19+ messages in thread From: Edward Z. Yang @ 2009-06-04 1:53 UTC (permalink / raw) On Wed, 3 Jun 2009, Edward Z. Yang wrote: > 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. Here we go: http://web.mit.edu/~ezyang/Public/sup-performance.png Look at String::=~. Definitely not acceptable. Cheers, Edward ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-04 1:53 ` [sup-talk] Sup is hangingyy Edward Z. Yang @ 2009-06-04 16:09 ` William Morgan 2009-06-05 5:08 ` Edward Z. Yang 0 siblings, 1 reply; 19+ messages in thread From: William Morgan @ 2009-06-04 16:09 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: > http://web.mit.edu/~ezyang/Public/sup-performance.png > > 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-04 16:09 ` [sup-talk] Sup is hanging William Morgan @ 2009-06-05 5:08 ` Edward Z. Yang 2009-06-05 13:23 ` William Morgan [not found] ` <1244227108-sup-3123@cabinet> 0 siblings, 2 replies; 19+ messages in thread From: Edward Z. Yang @ 2009-06-05 5:08 UTC (permalink / raw) 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. Excerpts from William Morgan's message of Thu Jun 04 12:09:40 -0400 2009: > 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%) Ok, so this isn't the same spread as when I managed to make Sup hang, so this isn't quite the same. > 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. 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. > 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? 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-05 5:08 ` Edward Z. Yang @ 2009-06-05 13:23 ` William Morgan [not found] ` <1244227108-sup-3123@cabinet> 1 sibling, 0 replies; 19+ messages in thread From: William Morgan @ 2009-06-05 13:23 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-04: > I tickled the bug and took a more careful look at the message that had > 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. > Excerpts from William Morgan's message of Thu Jun 04 12:09:40 -0400 2009: > > 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%) > > Ok, so this isn't the same spread as when I managed to make Sup hang, > so this isn't quite the same. That makes sense. > 1. If I thrash message_to_chunks() with a very long message, I cause > sup to hang. 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. > 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). 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. > 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. 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
[parent not found: <1244227108-sup-3123@cabinet>]
* [sup-talk] Sup is hanging [not found] ` <1244227108-sup-3123@cabinet> @ 2009-06-05 21:47 ` Edward Z. Yang 2009-06-06 6:20 ` Edward Z. Yang 0 siblings, 1 reply; 19+ messages in thread From: Edward Z. Yang @ 2009-06-05 21:47 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-05 21:47 ` Edward Z. Yang @ 2009-06-06 6:20 ` Edward Z. Yang 2009-06-08 18:09 ` William Morgan 0 siblings, 1 reply; 19+ messages in thread From: Edward Z. Yang @ 2009-06-06 6:20 UTC (permalink / raw) Excerpts from Edward Z. Yang's message of Fri Jun 05 17:47:00 -0400 2009: > Now that you mention it, the messages that tickle this bug on my side also > 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 ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hanging 2009-06-06 6:20 ` Edward Z. Yang @ 2009-06-08 18:09 ` William Morgan 0 siblings, 0 replies; 19+ messages in thread From: William Morgan @ 2009-06-08 18:09 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-05: > - if line =~ QUOTE_PATTERN || (line =~ QUOTE_START_PATTERN && nextline =~ QUO > + 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> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hangingy 2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang 2009-06-04 1:26 ` Edward Z. Yang @ 2009-06-04 2:12 ` William Morgan 2009-06-04 2:13 ` William Morgan 2 siblings, 0 replies; 19+ messages in thread From: William Morgan @ 2009-06-04 2:12 UTC (permalink / raw) Reformatted excerpts from Edward Z. Yang's message of 2009-06-03: > 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 -- William <wmorgan-sup at masanjin.net> ^ permalink raw reply [flat|nested] 19+ messages in thread
* [sup-talk] Sup is hangingy 2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang 2009-06-04 1:26 ` Edward Z. Yang 2009-06-04 2:12 ` [sup-talk] Sup is hangingy William Morgan @ 2009-06-04 2:13 ` William Morgan 2 siblings, 0 replies; 19+ messages in thread From: William Morgan @ 2009-06-04 2:13 UTC (permalink / raw) [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: > --- Interrupt from thread: main > > /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> ^ permalink raw reply [flat|nested] 19+ messages in thread
end of thread, other threads:[~2009-06-08 18:09 UTC | newest]
Thread overview: 19+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-06-03 17:39 [sup-talk] Sup is hanging Edward Z. Yang
2009-06-03 18:11 ` William Morgan
2009-06-03 18:26 ` Edward Z. Yang
2009-06-03 18:21 ` Edward Z. Yang
2009-06-03 18:45 ` Edward Z. Yang
2009-06-03 21:36 ` William Morgan
2009-06-03 21:48 ` Edward Z. Yang
2009-06-04 2:11 ` William Morgan
2009-06-03 22:00 ` [sup-talk] Sup is hangingy Edward Z. Yang
2009-06-04 1:26 ` Edward Z. Yang
2009-06-04 1:53 ` [sup-talk] Sup is hangingyy Edward Z. Yang
2009-06-04 16:09 ` [sup-talk] Sup is hanging William Morgan
2009-06-05 5:08 ` Edward Z. Yang
2009-06-05 13:23 ` William Morgan
[not found] ` <1244227108-sup-3123@cabinet>
2009-06-05 21:47 ` Edward Z. Yang
2009-06-06 6:20 ` Edward Z. Yang
2009-06-08 18:09 ` William Morgan
2009-06-04 2:12 ` [sup-talk] Sup is hangingy William Morgan
2009-06-04 2:13 ` William Morgan
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox