Re: Intermittent system hangs on 7.2-RELEASE-p1
Linda Messerschmidt wrote: Well, this is interesting. I got really frustrated with the other approach, so I thought I'd thin a machine down absolutely as far as I could, eliminate every possible source of delay, and see what happens. I killed everything... cron, RPC, NFS, devd, gmon, nrpe, everything. The Apache and its exerciser are now the only things running on the machine, and the Apache is only touching an md0 swap device mounted on /mnt. I *still* get the hangs. It hangs for all sorts of different periods, but the duration of the stall is approximately inversely proportional to the chance of seeing it. To get a short delay, you need wait only a little bit. If you want a 2-3 second delay, you may have to wait 15-20 minutes. On what sort of hardware is this hang occurring? Several months ago I was trying to resolve an intermittent hang under FreeBSD 7. I collected a large number of crashdumps I created using the kernel debugger when I caught the machine hanging, but the backtraces were very inconsistent, and the hang was only occurring on Xeons with multithreading (older 2.8GHz and 3.6GHz Xeons). I was able to prevent the hang by setting mach.hyperthreading_enabled=0 in /boot/loader.conf, but I am still not sure why it worked. Guy ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Sat, Sep 12, 2009 at 1:47 AM, Julian Elischer jul...@elischer.org wrote: ok now we need to describe the hang.. if you can predictably get a hang every 7 seconds does this mean that it doesn't respond to keyboard for a moment every 7 seconds? It's possible. or that it doesn't accept packets every 7 seconds? It appears that it accepts responds to at least pings; I was able to do an every-0.1-seconds ping through a bevy of 300-1900ms stalls with: 2323 packets transmitted, 2323 packets received, 0% packet loss round-trip min/avg/max/stddev = 0.120/1.019/5.979/0.288 ms As best as I could tell, schedgraph also showed that the clock interrupt and the em0 interrupt always got serviced on time. Pretty much seems like its userspace that's getting put on hold. Or is it just the apache process that hangs? This is where I started from. In the original post (way long ago now), I described how pretty much every process on the system went into the kernel for something and stalled there, and then when the stall ends, they all unblock at once. I posted some examples via ktrace that I sadly no longer have the source data for. Does the watching process that you refer to below also hang? I don't think I can say for sure. I observe visual stalls from time to time in the output if I have it show every request where there is no stall shown, which could either indicate that a stall occurred outside the request or that my shoddy Internet connection has 100ms latency and consistent 1% packet loss, which it does. I did write a short C program that just select()s on stdin for 100ms over and over and aborts if it takes more than 125ms to go through the loop; it never aborts, even through 1s+ stalls and the loop times it reports are consistently 110ms regardless of what else is going on, which I don't think is unexpected. However, I'm not sure why that differs from the behavior of the master Apache processes, which select() for 1 second all day long, but do appear to be affected. Maybe because they are selecting a network socket instead of a tty? I don't know. Also, if I disable NTP, the system does not appear to lose time during the stalls, which fits with the consistent clock interrupts I saw. would it hang if it tried to access the disk? By using the md device, I believe I have removed the disk from the equation; neither process is accessing it. Even without doing that, if I leave iostat -w 1 running alongside the test, there's no correlation between the tiny amount of disk activity there is and observed stalls. if the watching process is on the same machine, does it only trigger AFTER teh request has taken a ling time or could it time out with a select DURING the delayed response? (another way of asking how hung is 'hung'? It's just a PHP script using libcurl to request the file. I only moved it to the same machine in order to have it be able to write the sysctl to stop the KTR traces I was doing. If you're asking could the check script be modified to time out after, say, 1 second, and if so, would it return during the hang or after it? I don't know. My guess based on the earlier ktrace output is that it would time out, but not return until the hang ended. I'll see if I the curl lib exposes a configurable timeout and try it. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Sat, Sep 12, 2009 at 2:52 AM, Linda Messerschmidt linda.messerschm...@gmail.com wrote: On Sat, Sep 12, 2009 at 1:47 AM, Julian Elischer jul...@elischer.org wrote: ok now we need to describe the hang.. if you can predictably get a hang every 7 seconds does this mean that it doesn't respond to keyboard for a moment every 7 seconds? It's possible. Oops, I meant to explain that my ISP connection and personal sense of time are probably not good enough to say one way or the other for sure. I do see stalls, but I can't say whether they are the same stall or just a dropped packet somewhere along the way. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
OK, first, I figured out the seven second thing. I actually had already found that particular issue earlier in the troubleshooting process, but forgot all about it when I pulled in a second machine to test with. It was simply a case of setting Apache's MaxRequestsPerChild to a very low value (128) in combination with only allowing 1 access at a time. 128 requests * (50ms sleep + 2ms request + overhead) ~= 7s. So that was just noise masking the real problem, which is less frequent and less predictable. Sorry for the red herring. :( On Sat, Sep 12, 2009 at 2:52 AM, Linda Messerschmidt linda.messerschm...@gmail.com wrote: If you're asking could the check script be modified to time out after, say, 1 second, and if so, would it return during the hang or after it? I don't know. My guess based on the earlier ktrace output is that it would time out, but not return until the hang ended. I'll see if I the curl lib exposes a configurable timeout and try it. This proved to be quite easy to do. I ran the script twice, once with the timeout and once without. Without timeout: 1252741492: request 910 101ms 1252741567: request 2133 1429ms 1252741603: request 2722 146ms With 1s timeout: 1252741492: request 1078 106ms 1252741567: request 2302 1010ms (--- Timeout) 1252741567: request 2303 273ms (--- after 50ms sleep, goes back to end of stall) 1252741603: request 2892 136ms As you can see, the two scripts experience stalls in pretty much lockstep, but the script itself does not appear affected, so it's just on the Apache side. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Thursday 10 September 2009 9:34:30 pm Linda Messerschmidt wrote: Just to follow up, I've been doing some testing with masking for KTR_LOCK rather than KTR_SCHED. I'm having trouble with this because I have the KTR buffer size set to 1048576 entries, and with only KTR_LOCK enabled, this isn't enough for even a full second of tracing; the sample I'm working with now is just under 0.9s. It's an average of one entry every 2001 TSC ticks. That *seems* like a lot of locking activity, but some of the lock points are only a couple of lines apart, so maybe it's just incredibly verbose. Since it's so much data and I'm still working on a way to correlate it (lockgraph.py?), all I've got so far is a list of what trace points are coming up the most: 51927 src/sys/kern/kern_lock.c:215 (_lockmgr UNLOCK mtx_unlock() when flags LK_INTERLOCK) 48033 src/sys/kern/vfs_subr.c:2284 (vdropl UNLOCK) 41548 src/sys/kern/vfs_subr.c:2187 (vput VI_LOCK) 29359 src/sys/kern/vfs_subr.c:2067 (vget VI_LOCK) 29358 src/sys/kern/vfs_subr.c:2079 (vget VI_UNLOCK) 23799 src/sys/nfsclient/nfs_subs.c:755 (nfs_getattrcache mtx_lock) 23460 src/sys/nfsclient/nfs_vnops.c:645 (nfs_getattr mtx_unlock) 23460 src/sys/nfsclient/nfs_vnops.c:642 (nfs_getattr mtx_lock) 23460 src/sys/nfsclient/nfs_subs.c:815 (nfs_getattrcache mtx_unlock) 23138 src/sys/kern/vfs_cache.c:345 (cache_lookup CACHE_LOCK) Unfortunately, it kind of sounds like I'm on my way to answering why is this system slow? even though it really isn't slow. (And I rush to point out that the Apache process in question doesn't at any point in its life touch NFS, though some of the other ones on the machine do.) In order to be the cause of my Apache problem, all this goobering around with NFS would have to be relatively infrequent but so intense that it shoves everything else out of the way. I'm skeptical, but I'm sure one of you guys can offer a more informed opinion. The only other thing I can think of is maybe all this is running me out of something I need (vnodes?) so everybody else blocks until it finishes and lets go of whatever finite resource it's using up? But that doesn't make a ton of sense either, because why would a lack of vnodes cause stalls in accept() or select() in unrelated processes? Not sure if I'm going in the right direction here or not. Try turning off KTR_LOCK for spin mutexes (just force LO_QUIET on in mtx_init() if MTX_SPIN is set) and use a schedgraph.py from the latest RELENG_7. It knows how to parse KTR_LOCK events and drop event bars for locks showing when they are held. A more recently schedgraph.py might also fix the bugs you were seeing with the idle threads looking too long (esp. at the start and end of graphs). -- John Baldwin ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
John Baldwin wrote: A more recently schedgraph.py might also fix the bugs you were seeing with the idle threads looking too long (esp. at the start and end of graphs). not unless something has been fixed in the last week or so. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Fri, Sep 11, 2009 at 11:02 AM, John Baldwin j...@freebsd.org wrote: Try turning off KTR_LOCK for spin mutexes (just force LO_QUIET on in mtx_init() if MTX_SPIN is set) I have *no* idea what you just said. :) Which is fine. But more to the point, I have no idea how to do it. :) A more recently schedgraph.py might also fix the bugs you were seeing with the idle threads looking too long (esp. at the start and end of graphs). We are already on RELENG_7 due to the KTR-enabling rebuild, so that'd be the version we're using unless, as Julian observed, it's been fixed in the past week or so. Thanks! ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Friday 11 September 2009 11:35:14 am Julian Elischer wrote: John Baldwin wrote: A more recently schedgraph.py might also fix the bugs you were seeing with the idle threads looking too long (esp. at the start and end of graphs). not unless something has been fixed in the last week or so. Well, I wasn't sure how old of a schedgraph.py is being used. 7.1 would have the bugs, but I think 7.2 should be fine. -- John Baldwin ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Friday 11 September 2009 1:35:00 pm Linda Messerschmidt wrote: On Fri, Sep 11, 2009 at 11:02 AM, John Baldwin j...@freebsd.org wrote: Try turning off KTR_LOCK for spin mutexes (just force LO_QUIET on in mtx_init() if MTX_SPIN is set) I have *no* idea what you just said. :) Which is fine. But more to the point, I have no idea how to do it. :) Something like this: Index: sys/kern/kern_mutex.c === --- sys/kern/kern_mutex.c (.../mirror/FreeBSD/stable/7) (revision 195943) +++ sys/kern/kern_mutex.c (.../stable/7) (revision 195943) @@ -747,6 +747,10 @@ if (opts MTX_NOPROFILE) flags |= LO_NOPROFILE; + /* XXX: Only log for regular mutexes. */ + if (opts MTX_SPIN) + flags |= LO_QUIET; + /* Initialize mutex. */ m-mtx_lock = MTX_UNOWNED; m-mtx_recurse = 0; A more recently schedgraph.py might also fix the bugs you were seeing with the idle threads looking too long (esp. at the start and end of graphs). We are already on RELENG_7 due to the KTR-enabling rebuild, so that'd be the version we're using unless, as Julian observed, it's been fixed in the past week or so. Hmm. It works well for me for doing traces. -- John Baldwin ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Fri, Sep 11, 2009 at 3:06 PM, John Baldwin j...@freebsd.org wrote: Something like this: Ah, I understand now. :) Got up to 17 seconds of trace with that change. Hmm. It works well for me for doing traces. It definitely works, it just always seems to have some-or-another weird artifact. But, with the lock info added, the locks that show big ugly gaping multi-second lock acquire bars are: unp_mtx and so_rcv_sx. I'm not 100% confident in this data yet, so I will try to get more data to confirm, but if that offers any clues about where to look, I'm all ears. I'm also a bit hazy on what the dark grey vs. light grey background is about. Thanks! ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
OK, I have learned that ktrdump looks up the name of the process associated with a particular KSE at the the time of the dump, so if it's changed since tracing stopped, it will blissfully blame the wrong process. I understand why that's the case, but it still sucks for troubleshooting. :( This time, pf task mtx and vnode_free_list are the locks getting the blame. The processes fingered are an httpd ( (the root parent of the one doing the work, which does nothing but select() for 1s and wait to see if its children died), and vnlru. No correlation at all to the previous results, and this machine is now utterly quiescent except for the httpd process and the PHP exerciser. Hard to imagine vnlru has 1s worth of running to do on a machine with 949 total vnodes in use. A third run produced a 997ms lock acquire for buffer daemon lock, a 497ms one for ip6qlock (no, there's no IPv6 in use on this machine), and an 8s (!!!) one on unp_mtx. bufdaemon had a 997s running bar, but according to the raw TSC values, that happened on the same CPU 1.999s *after* the 997ms buffer daemon lock acquire. I really don't know where to go from here. There's so little consistency that I'm just not sure if the data is bad, the tool is bad, the operator is bad, or there's some problem so fundamentally horrible that all I'm seeing is random side effects. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
Linda Messerschmidt wrote: OK, I have learned that ktrdump looks up the name of the process associated with a particular KSE at the the time of the dump, so if it's changed since tracing stopped, it will blissfully blame the wrong process. I understand why that's the case, but it still sucks for troubleshooting. :( This time, pf task mtx and vnode_free_list are the locks getting the blame. The processes fingered are an httpd ( (the root parent of the one doing the work, which does nothing but select() for 1s and wait to see if its children died), and vnlru. No correlation at all to the previous results, and this machine is now utterly quiescent except for the httpd process and the PHP exerciser. Hard to imagine vnlru has 1s worth of running to do on a machine with 949 total vnodes in use. A third run produced a 997ms lock acquire for buffer daemon lock, a 497ms one for ip6qlock (no, there's no IPv6 in use on this machine), and an 8s (!!!) one on unp_mtx. bufdaemon had a 997s running bar, but according to the raw TSC values, that happened on the same CPU 1.999s *after* the 997ms buffer daemon lock acquire. I really don't know where to go from here. There's so little consistency that I'm just not sure if the data is bad, the tool is bad, the operator is bad, or there's some problem so fundamentally horrible that all I'm seeing is random side effects. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org does the system have a serial console? how about a normal console /keyboard? how often deos it hang? and for how long? is there a chance that you could notice when it is hung and hit CTLLATESC and drop it into the debugger IN teh hung state? It is possible if you have a serial port to make a program that sends a char back and forth and when the machine hangs, sends teh magic sequence. (I think it's CRtildeCTL-D for serial debugger break, but I'm sure you can look up the kernel options and the chars in google.) if you can drop the machine into DDB (teh kernel debugger) in teh hung state, then there are lots of comands you can do to find out what is wrong. jhb actually gave a short talk that I videod and put on youtube on the topic. ps will show you what is actually running on which CPU and you an see what locks all the other processes are waiting on. then you can examine those locks and see who owns them. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Sat, Sep 12, 2009 at 12:06 AM, Julian Elischer jul...@elischer.org wrote: does the system have a serial console? how about a normal console /keyboard? It has an IP KVM. how often deos it hang? and for how long? Well, this is interesting. I got really frustrated with the other approach, so I thought I'd thin a machine down absolutely as far as I could, eliminate every possible source of delay, and see what happens. I killed everything... cron, RPC, NFS, devd, gmon, nrpe, everything. The Apache and its exerciser are now the only things running on the machine, and the Apache is only touching an md0 swap device mounted on /mnt. I *still* get the hangs. It hangs for all sorts of different periods, but the duration of the stall is approximately inversely proportional to the chance of seeing it. To get a short delay, you need wait only a little bit. If you want a 2-3 second delay, you may have to wait 15-20 minutes. *However* in order to answer your question, I changed up the test program, which up til now has been cycling requests every 50 ms until it gets one 2s, at which point it sysctls to stop ktr and aborts. Now it prints the timestamp of all too long requests. But I also dropped the threshold for too long from 2s to 100ms, since with everything on RAM disk, there's no longer any reason to expect a request to take more than 1-2ms in the worst case. The results are pretty profound: 1252729876: request 82 131ms 1252729883: request 210 388ms 1252729890: request 338 380ms 1252729897: request 466 388ms 1252729904: request 594 404ms 1252729919: request 849 810ms 1252729926: request 977 386ms 1252729933: request 1105 370ms 1252729940: request 1233 366ms 1252729947: request 1361 400ms 1252729961: request 1617 746ms 1252729968: request 1744 477ms 1252729975: request 1872 388ms 1252729982: request 2000 380ms 1252729989: request 2128 384ms 1252729996: request 2256 395ms It goes on and on like this, I get a 380-400ms stall every seven seconds. I have had a few come back higher, in the 750-850ms range, usually after missing a beat: 1252729897: request 466 388ms 1252729904: request 594 404ms 1252729919: request 849 810ms 1252729926: request 977 386ms 1252730010: request 2512 416ms 1252730017: request 2640 390ms 1252730031: request 2896 774ms 1252730038: request 3023 431ms 1252730454: request 10568 378ms 1252730461: request 10696 397ms 1252730475: request 10952 733ms 1252730482: request 11080 366ms So far, nothing over 1s. So what happens every seven seconds?? ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
Linda Messerschmidt wrote: On Sat, Sep 12, 2009 at 12:06 AM, Julian Elischer jul...@elischer.org wrote: does the system have a serial console? how about a normal console /keyboard? It has an IP KVM. how often deos it hang? and for how long? Well, this is interesting. I got really frustrated with the other approach, so I thought I'd thin a machine down absolutely as far as I could, eliminate every possible source of delay, and see what happens. I killed everything... cron, RPC, NFS, devd, gmon, nrpe, everything. The Apache and its exerciser are now the only things running on the machine, and the Apache is only touching an md0 swap device mounted on /mnt. I *still* get the hangs. ok now we need to describe the hang.. if you can predictably get a hang every 7 seconds does this mean that it doesn't respond to keyboard for a moment every 7 seconds? or that it doesn't accept packets every 7 seconds? if you lean on the A key, do you see echo stop every 7 seconds for a moment? Or is it just the apache process that hangs? Does the watching process that you refer to below also hang? would it hang if it tried to access the disk? if the watching process is on the same machine, does it only trigger AFTER teh request has taken a ling time or could it time out with a select DURING the delayed response? (another way of asking how hung is 'hung'? It hangs for all sorts of different periods, but the duration of the stall is approximately inversely proportional to the chance of seeing it. To get a short delay, you need wait only a little bit. If you want a 2-3 second delay, you may have to wait 15-20 minutes. *However* in order to answer your question, I changed up the test program, which up til now has been cycling requests every 50 ms until it gets one 2s, at which point it sysctls to stop ktr and aborts. Now it prints the timestamp of all too long requests. But I also dropped the threshold for too long from 2s to 100ms, since with everything on RAM disk, there's no longer any reason to expect a request to take more than 1-2ms in the worst case. The results are pretty profound: 1252729876: request 82 131ms 1252729883: request 210 388ms 1252729890: request 338 380ms 1252729897: request 466 388ms 1252729904: request 594 404ms 1252729919: request 849 810ms 1252729926: request 977 386ms 1252729933: request 1105 370ms 1252729940: request 1233 366ms 1252729947: request 1361 400ms 1252729961: request 1617 746ms 1252729968: request 1744 477ms 1252729975: request 1872 388ms 1252729982: request 2000 380ms 1252729989: request 2128 384ms 1252729996: request 2256 395ms It goes on and on like this, I get a 380-400ms stall every seven seconds. I have had a few come back higher, in the 750-850ms range, usually after missing a beat: 1252729897: request 466 388ms 1252729904: request 594 404ms 1252729919: request 849 810ms 1252729926: request 977 386ms 1252730010: request 2512 416ms 1252730017: request 2640 390ms 1252730031: request 2896 774ms 1252730038: request 3023 431ms 1252730454: request 10568 378ms 1252730461: request 10696 397ms 1252730475: request 10952 733ms 1252730482: request 11080 366ms So far, nothing over 1s. So what happens every seven seconds?? ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Thu, Aug 27, 2009 at 5:29 PM, John Baldwinj...@freebsd.org wrote: Ah, cool, what you want to do is use KTR with KTR_SCHED and then use schedgraph.py (src/tools/sched) to get a visual picture of what the box does during a hang. The timestamps in KTR are TSC cycle counts rather than an actual wall time which is why they look off. If you have a lot of events you may want to use a larger KTR_ENTRIES size btw (I use 1048576 (2 ^ 20) here at work to get large (multiple-second) traces). I'm still working on this. I enabled KTR and set it up to log KTR_SCHED events. Then, I wrote a script to exercise the HTTP server that actually ran on that machine, and set it to issue sysctl debug.ktr.cpumask=0 and abort if a request took over 2 seconds. 28,613 requests later, it tripped over one that took 2007ms. (Just a refresher: this is a static file being served by an Apache process that has nothing else to do but serve this file on a relatively unloaded machine.) I don't have access to any machines that can run X, so I did the best I could to examine it from the shell. First, this machine has two CPU's so I split up the KTR results on a per-CPU basis so I could look at each individually. With KTR_ENTRIES set to 1048576, I got about 53 seconds of data with just KTR_SCHED enabled. Since I was interested in a 2.007 second period of time right at the end, I hacked it down to the last 3.795 seconds. In the 3.795 seconds captured in the trace period on CPU 0 that includes the entire 2.007 second stall, CPU 0 was idle for 3.175 seconds. In the same period, CPU 1 was idle for 3.2589 seconds. I did the best I could to manually page through all the scheduling activity on both CPUs during that 3.7 second time, and I didn't see anything really disruptive. Mainly idle, with jumps into the clock and ethernet kernel threads, as well as httpd. If I understand that correctly and have done everything right, that means that whatever happened, it wasn't related to CPU contention or scheduling issues of any sort. So, a couple of follow-up questions: First, what else should I be looking at? I built the kernel with kind of a lot of KTR flags (KTR_LOCK|KTR_SCHED|KTR_PROC|KTR_INTR|KTR_CALLOUT|KTR_UMA|KTR_SYSC) but enabling them all produces enough output that even 1048576 entries doesn't always go back two seconds; the volume of data is all but unmanageable. Second, is there any way to correlate the process address reported by the KTR scheduler entries back to a PID? It'd be nice to be able to view the scheduler activity just for the process I'm interested in, but I can't figure out which one it is. :) Thanks! ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
You should be able to run schedgraph.py on a windows machine with python installed. It works just fine for me on XP. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Thu, Sep 10, 2009 at 12:57 PM, Ryan Stoneryst...@gmail.com wrote: You should be able to run schedgraph.py on a windows machine with python installed. It works just fine for me on XP. Don't have any of those either, but I *did* get it working on a Mac right out of the box. Should have thought of that sooner. :) The output looks pretty straightforward, but there are a couple of things I find odd. First, there's a point right around what I estimate to be the problem time where schedgraph.py indicates gmond (the Ganglia monitor) was running uninterrupted for a period of exactly 1 second. However, it also indicates that both CPU's idle tasks were *also* running almost continuously during that time (subject to clock/net interrupts), and that the run queue on both CPU's was zero for most of that second while gmond was allegedly running. Second, the interval I graphed was about nine seconds. During that time, the PHP command line script made a whole lot of requests: it usleeps 50ms between requests, and non-broken requests average about 1.4ms. So even with the stalled request chopping 2 seconds off the end, there should be somewhere in the neighborhood of 130 requests during the graphed period. But that php process doesn't appear in the schedgraph output at all. So that doesn't make a whole lot of sense to me. I'll try to get another trace and see if that happens the same way again. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
Linda Messerschmidt wrote: On Thu, Sep 10, 2009 at 12:57 PM, Ryan Stoneryst...@gmail.com wrote: You should be able to run schedgraph.py on a windows machine with python installed. It works just fine for me on XP. Don't have any of those either, but I *did* get it working on a Mac right out of the box. Should have thought of that sooner. :) The output looks pretty straightforward, but there are a couple of things I find odd. First, there's a point right around what I estimate to be the problem time where schedgraph.py indicates gmond (the Ganglia monitor) was running uninterrupted for a period of exactly 1 second. However, it also indicates that both CPU's idle tasks were *also* running almost continuously during that time (subject to clock/net interrupts), and that the run queue on both CPU's was zero for most of that second while gmond was allegedly running. I've noticed that schedgraph tends to show the idle threads slightly skewed one way or the other. I think there is a cumulative rounding error in the way they are drawn due to the fact that they are run so often. Check the raw data and I think you will find that you just need to imagine the idle threads slightly to the left or right a bit. The longer the trace and the further to he right you are looking the more out the idle threads appear to be. I saw this on both Linux and Mac python implementations. Second, the interval I graphed was about nine seconds. During that time, the PHP command line script made a whole lot of requests: it usleeps 50ms between requests, and non-broken requests average about 1.4ms. So even with the stalled request chopping 2 seconds off the end, there should be somewhere in the neighborhood of 130 requests during the graphed period. But that php process doesn't appear in the schedgraph output at all. So that doesn't make a whole lot of sense to me. I'll try to get another trace and see if that happens the same way again. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Thu, Sep 10, 2009 at 2:46 PM, Julian Elischerjul...@elischer.org wrote: I've noticed that schedgraph tends to show the idle threads slightly skewed one way or the other. I think there is a cumulative rounding error in the way they are drawn due to the fact that they are run so often. Check the raw data and I think you will find that you just need to imagine the idle threads slightly to the left or right a bit. No, there's no period anywhere in the trace where either idle thread didn't run for an entire second. I'm pretty sure schedgraph is throwing in some nonsense results. I did capture a second, larger, dataset after a 2.1s stall, and schedgraph includes an httpd process that supposedly spent 58 seconds on the run queue. I don't know if it's a dropped record or a parsing error or what. I do think on this second graph I can kind of see the *end* of the stall, because all of a sudden a ton of processes... everything from sshd to httpd to gmond to sh to vnlru to bufdaemon to fdc0... comes off of whatever it's waiting on and hits the run queue. The combined run queues for both processors spike up to 32 tasks at one point and then rapidly tail off as things return to normal. That pretty much matches the behavior shown by ktrace in my initial post, where everything goes to sleep on something-or-other in the kernel, and then at the end of the stall, everything wakes up at the same time. I think this means the problem is somehow related to locking, rather than scheduling. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
Just to follow up, I've been doing some testing with masking for KTR_LOCK rather than KTR_SCHED. I'm having trouble with this because I have the KTR buffer size set to 1048576 entries, and with only KTR_LOCK enabled, this isn't enough for even a full second of tracing; the sample I'm working with now is just under 0.9s. It's an average of one entry every 2001 TSC ticks. That *seems* like a lot of locking activity, but some of the lock points are only a couple of lines apart, so maybe it's just incredibly verbose. Since it's so much data and I'm still working on a way to correlate it (lockgraph.py?), all I've got so far is a list of what trace points are coming up the most: 51927 src/sys/kern/kern_lock.c:215 (_lockmgr UNLOCK mtx_unlock() when flags LK_INTERLOCK) 48033 src/sys/kern/vfs_subr.c:2284 (vdropl UNLOCK) 41548 src/sys/kern/vfs_subr.c:2187 (vput VI_LOCK) 29359 src/sys/kern/vfs_subr.c:2067 (vget VI_LOCK) 29358 src/sys/kern/vfs_subr.c:2079 (vget VI_UNLOCK) 23799 src/sys/nfsclient/nfs_subs.c:755 (nfs_getattrcache mtx_lock) 23460 src/sys/nfsclient/nfs_vnops.c:645 (nfs_getattr mtx_unlock) 23460 src/sys/nfsclient/nfs_vnops.c:642 (nfs_getattr mtx_lock) 23460 src/sys/nfsclient/nfs_subs.c:815 (nfs_getattrcache mtx_unlock) 23138 src/sys/kern/vfs_cache.c:345 (cache_lookup CACHE_LOCK) Unfortunately, it kind of sounds like I'm on my way to answering why is this system slow? even though it really isn't slow. (And I rush to point out that the Apache process in question doesn't at any point in its life touch NFS, though some of the other ones on the machine do.) In order to be the cause of my Apache problem, all this goobering around with NFS would have to be relatively infrequent but so intense that it shoves everything else out of the way. I'm skeptical, but I'm sure one of you guys can offer a more informed opinion. The only other thing I can think of is maybe all this is running me out of something I need (vnodes?) so everybody else blocks until it finishes and lets go of whatever finite resource it's using up? But that doesn't make a ton of sense either, because why would a lack of vnodes cause stalls in accept() or select() in unrelated processes? Not sure if I'm going in the right direction here or not. ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Wed, Aug 26, 2009 at 4:42 PM, John Baldwinj...@freebsd.org wrote: One thing to note is that ktrace only logs voluntary context switches (i.e. call to tsleep or waiting on a condition variable). It specifically does not log preemptions or blocking on a mutex, I was not aware, thanks. so in theory if your machine was livelocked temporarily that might explain this. How would we determine that? We are now able to reproduce this on a test machine, even after slipping in a 7.2-STABLE kernel with KTR enabled. So we have a lot more options now. Unfortunately, I don't really get KTR yet. It looks like it has relevant info, but I was unable to correlate its huge timestamps (e.g. 6795522404430562) to ktrace output times (e.g. 1251387606.225544) showing problem areas. What's my best bet from here? ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Thu, Aug 27, 2009 at 04:14:39PM -0400, Linda Messerschmidt wrote: On Wed, Aug 26, 2009 at 4:42 PM, John Baldwinj...@freebsd.org wrote: One thing to note is that ktrace only logs voluntary context switches (i.e. call to tsleep or waiting on a condition variable). It specifically does not log preemptions or blocking on a mutex, I was not aware, thanks. so in theory if your machine was livelocked temporarily that might explain this. How would we determine that? We are now able to reproduce this on a test machine, even after slipping in a 7.2-STABLE kernel with KTR enabled. So we have a lot more options now. Unfortunately, I don't really get KTR yet. It looks like it has relevant info, but I was unable to correlate its huge timestamps (e.g. 6795522404430562) to ktrace output times (e.g. 1251387606.225544) showing problem areas. What's my best bet from here? How much memory is installed ? pgpXdmsd3YOE6.pgp Description: PGP signature
Intermittent system hangs on 7.2-RELEASE-p1
I'm trying to troubleshoot an intermittent Apache performance problem,
and I've narrowed it down using to what appears to be a brief
whole-system hang that last from 0.5 - 3 seconds. They occur every
few minutes.
I took the rather extreme step of doing ktrace -t cnisuwt -i -d -p 1
and then I waited for the hang.
This is what I got:
54937 httpd1251302859.375313 CALL shutdown(0x3,invalid=1)
54937 httpd1251302859.375333 RET shutdown 0
54937 httpd1251302859.375348 CALL select(0x4,0xbfbfe92c,0,0,0xbfbfe9ac)
54937 httpd1251302859.375363 CSW stop kernel
54937 httpd1251302859.376402 CSW resume kernel
54937 httpd1251302859.376439 RET select 1
54937 httpd1251302859.376453 CALL read(0x3,0xbfbfe9b4,0x200)
54937 httpd1251302859.376470 GIO fd 3 read 0 bytes
54937 httpd1251302859.376482 RET read 0
54937 httpd1251302859.376495 CALL close(0x3)
54937 httpd1251302859.376511 RET close 0
54937 httpd1251302859.376525 CALL sigaction(SIGUSR1,0xbfbfebb0,0xbfbfeb98)
54937 httpd1251302859.376538 RET sigaction 0
54937 httpd1251302859.376552 CALL munmap(0x282ff000,0x11)
54937 httpd1251302859.376607 RET munmap 0
54937 httpd1251302859.376633 CALL accept(0x11,0xbfbfebf0,0xbfbfec10)
54937 httpd1251302859.376649 CSW stop kernel
796 svscan 1251302859.481064 CSW resume kernel
54937 httpd1251302859.489374 CSW resume kernel
54937 httpd1251302859.489391 STRU struct sockaddr { AF_INET,
172.17.0.143:61610 }
98229 httpd1251302859.601850 CSW resume kernel
46517 httpd1251302859.601900 CSW resume kernel
98202 httpd1251302859.611661 CSW resume kernel
837 nrpe21251302859.622681 CSW resume kernel
54454 httpd1251302859.655422 CSW resume kernel
54454 httpd1251302859.655443 STRU struct sockaddr { AF_INET,
172.17.0.131:59011 }
7182 httpd1251302859.722381 CSW resume kernel
98178 httpd1251302859.722438 CSW resume kernel
858 gmond1251302859.794996 CSW resume kernel
858 gmond1251302859.794998 GIO fd 5 wrote 0 bytes
770 ntpd 1251302860.076501 CSW resume kernel
98346 httpd1251302860.086261 CSW resume kernel
65277 httpd1251302860.086300 CSW resume kernel
98514 httpd1251302860.106849 CSW resume kernel
7191 httpd1251302860.106894 CSW resume kernel
796 svscan 1251302861.403335 RET nanosleep 0
796 svscan 1251302861.403370 CALL wait4(0x,0xbfbfee18,WNOHANG,0)
796 svscan 1251302861.403405 RET wait4 0
54454 httpd1251302861.403481 RET accept 3
98229 httpd1251302861.403532 RET select 0
796 svscan 1251302861.403553 CALL stat(0x804a3bb,0xbfbfed6c)
858 gmond1251302861.403601 GIO fd 5 read 20 bytes
54454 httpd1251302861.403619 CSW stop user
46517 httpd1251302861.403647 RET select 0
858 gmond1251302861.403674 RET kevent 1
858 gmond1251302861.403710 CALL socket(PF_INET,SOCK_DGRAM,IPPROTO_IP)
98202 httpd1251302861.403714 RET select 0
858 gmond1251302861.403752 RET socket 9
837 nrpe21251302861.403756 RET select 0
There is a gap between 1251302860.106894 and 1251302861.403335 of over
one second, and the effective gap starts around 1251302859.376649
and thus lasts for about two seconds.
This machine runs Apache and during this sample it was being hit every
0.1 seconds with a test request for a simple static file (in addition
to production traffic). It is a 2-processor machine that is 85-95%
idle; there's nothing in userspace that runs that long without
yielding. According to systat, it handles 5000+ syscalls every
second. But according to ktrace, nothing happens at all during the
hang. This matches user experience. (The static file request, which
usually completes in 0.01s suddenly takes 2 seconds as observed from
the remote machine issuing the requests.)
Here's the relevant snip from the httpd process handling that static
file at the time of the hang:
54937 httpd1251302859.376633 CALL accept(0x11,0xbfbfebf0,0xbfbfec10)
54937 httpd1251302859.376649 CSW stop kernel
54937 httpd1251302859.489374 CSW resume kernel
54937 httpd1251302859.489391 STRU struct sockaddr { AF_INET,
172.17.0.143:61610 }
54937 httpd1251302861.403862 RET accept 3
It's stuck in accept, but does *not* get context-switched away from
during the delay. (The earlier context switch corresponds to the 0.1
seconds between requests; there is an Apache instance configured to
handle just the test requests with one child process; that process has
nothing else to do or block on.)
I'll include some other processes below.
I think it's weird that all these processes get context-switched-into
before/during the hang, and I wonder if it's a clue. The kernel is
obviously still running, since it wakes these processes up, but
nothing is happening. That and the fact that it happens on multiple
machines (though we've only tested this
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Wednesday 26 August 2009 3:03:13 pm Linda Messerschmidt wrote: I'm trying to troubleshoot an intermittent Apache performance problem, and I've narrowed it down using to what appears to be a brief whole-system hang that last from 0.5 - 3 seconds. They occur every few minutes. One thing to note is that ktrace only logs voluntary context switches (i.e. call to tsleep or waiting on a condition variable). It specifically does not log preemptions or blocking on a mutex, so in theory if your machine was livelocked temporarily that might explain this. -- John Baldwin ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
Re: Intermittent system hangs on 7.2-RELEASE-p1
On Wed, 26 Aug 2009, Linda Messerschmidt wrote: I'm trying to troubleshoot an intermittent Apache performance problem, and I've narrowed it down using to what appears to be a brief whole-system hang that last from 0.5 - 3 seconds. They occur every few minutes. One thought would be to use ps to try to determine which process, if any, is charged with CPU time during the hang. If you could afford a little downtime, it would be worth seeing if the hang occurs in single-user mode (perhaps with a simple program that loops calling gettimeofday() and warns when the time between successive iterations is large). I once had a problem like this that I eventually traced to a power management problem. (Specifically, the machine had a modem, and would hang for a few seconds whenever the line would ring. It was apparently related to the Wake-On-Ring feature.) If I remember correctly, disabling ACPI made it go away. So that might be something to try, if rebooting is an option. What are the similarities and differences in hardware and software among the affected machines (you mentioned there were several)? -- Nate Eldredge neldre...@math.ucsd.edu ___ freebsd-hackers@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-hackers To unsubscribe, send any mail to freebsd-hackers-unsubscr...@freebsd.org
