On Feb 3, 2012, at 8:18 AM, Jim Schutt <jasc...@sandia.gov> wrote: > On 02/02/2012 05:28 PM, Gregory Farnum wrote: >> On Thu, Feb 2, 2012 at 12:22 PM, Jim Schutt<jasc...@sandia.gov> wrote: >>> I found 0 instances of "waiting for commit" in all my OSD logs for my last >>> run. >>> >>> So I never waited on the journal? >> >> Looks like it. Interesting. >> >> >>>>> So far I'm looking at two behaviours I've noticed that seem anomalous to >>>>> me. >>>>> >>>>> One is that I instrumented ms_dispatch(), and I see it take >>>>> a half-second or more several hundred times, out of several >>>>> thousand messages. Is that expected? >>>> >>>> >>>> How did you instrument it? If you wrapped the whole function it's >>>> possible that those longer runs are actually chewing through several >>>> messages that had to get waitlisted for some reason previously. >>>> (That's the call to do_waiters().) >>> >>> >>> Yep, I wrapped the whole function, and also instrumented taking osd_lock >>> while I was there. About half the time that ms_dispatch() takes more than >>> 0.5 seconds, taking osd_lock is responsible for the delay. There's two >>> dispatch threads, one for ops and one for rep_ops, right? So one's >>> waiting on the other? >> >> There's just one main dispatcher; no split for the ops and rep_ops . >> The reason for that "dispatch_running" is that if there are requests >> waiting then the tick() function will run through them if the >> messenger dispatch thread is currently idle. >> But it is possible for the Messenger to try and dispatch, and for that >> to be blocked while some amount of (usually trivial) work is being >> done by a different thread, yes. I don't think we've ever observed it >> being a problem for anything other than updating OSD maps, though... > > Ah, OK. > > I guess I was confused by my log output, e.g.:
D'oh. Sorry, you confused me with your reference to repops, which aren't special-cased or anything. But there are two messengers on the OSD, each with their own dispatch thread. One of those messengers is for clients and one is for other OSDs. And now that you point that out, I wonder if the problem is lack of Cond signaling in ms_dispatch. I'm on my phone right now but I believe there's a chunk of commented-out code (why commented instead of deleted? I don't know) that we want to uncomment for reasons that will become clear when you look at it. :) Try that and see how many of your problems disappear? > > osd.0.log:2277569:2012-02-02 09:23:41.666420 7fe5fe65e700 osd.0 31 > ms_dispatch ET 0.990204 osd_lock ET 0.001438 msg 0xbe19400 > osd.0.log:2277697:2012-02-02 09:23:41.669949 7fe5fee5f700 osd.0 31 > ms_dispatch ET 0.993136 osd_lock ET 0.992708 msg 0x13afd680 > > I thought 7fe5fe65e700 and 7fe5fee5f700 identified the threads. > > I need to go study that code some more.... > >> >> >>>>> Another is that once a message receive starts, I see ~50 messages >>>>> that take tens of seconds to receive, when the nominal receive time is >>>>> a half-second or less. I'm in the process of tooling up to collect >>>>> tcpdump data on all my clients to try to catch what is going on with >>>>> that. >>>> >>>> >>>> Again, how are you instrumenting that? >>> >>> >>> I post-process the logs, looking at the time difference between >>> "reader got .* policy throttler" and "reader got .* osd_op(client". >> >> I guess the logging output must have changed a bit at some pointer (or >> was that one of your patches?). master has "reader wants" not "reader >> got" for the policy throttler. (Just got a little confused when >> checking the code.) > > Yep, I added an extra message to make post-processing logs easier, sorry. > >> >>> When I find a candidate message, I grep the log for just that reader thread, >>> and see, e.g., this: >>> >>> osd.0.log:1280693:2012-02-02 09:17:57.704508 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader got 2670720 from policy throttler 48809510/50000000 >>> seq 828/828 waiters 157/149 for src client.4301 tid=247 >>> osd.0.log:1280694:2012-02-02 09:17:57.704525 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader wants 2670720 from dispatch throttler >>> 41944358/66666666 >>> osd.0.log:1280701:2012-02-02 09:17:57.704654 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader got front 128 >>> osd.0.log:1280705:2012-02-02 09:17:57.704752 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader allocating new rx buffer at offset 0 >>> osd.0.log:1280710:2012-02-02 09:17:57.704873 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader reading nonblocking into 0x11922000 len 2670592 >>> osd.0.log:1559767:2012-02-02 09:19:40.726589 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader reading nonblocking into 0x11a6a5cc len 1325620 >>> osd.0.log:1561092:2012-02-02 09:19:40.927559 7fe5c9099700 -- >>> 172.17.131.32:6800/14974>> 172.17.135.85:0/1283168808 pipe(0xbdc9680 sd=215 >>> pgs=49 cs=1 l=1).reader reading nonblocking into 0x11a6ab74 len 1324172 >>> >>> Note the ~2 minute delay (and ~300,000 lines of logging) between the first >>> and second reads. >>> >>> During that time 129 sockets were processed - what makes sd=215 special? >> >> Hrm. Well, you can try turning up the messenger debugging to 30 and >> taking advantage of the "reader reading" "reader read" pair right >> around tcp_read_nonblocking. > > OK, I'll give that a try as well, thanks. >> >>> I've added tracepoints in my client kernel try_write(), and nothing seems >>> unusual (that's with running the patch to ceph_write_space() I posted >>> earlier): >>> >>> kworker/0:2-1790 [000] 1543.200887: ceph_try_write_msg_done: peer osd0 >>> tid 179 seq 3 sent 4194304 >>> kworker/0:2-1790 [000] 1543.200901: ceph_prepare_write_msg: peer osd0 >>> tid 207 seq 4 sent 0 >> *snip* >>> kworker/0:2-1790 [000] 1569.078614: ceph_try_write_msg_done: peer osd0 >>> tid 207 seq 4 sent 4194304 >>> >>> There's a 25 second gap at 1543.236256, but nothing like the >>> 100 second gap in the reader. >>> >>> Hence, tcpdump seems like a good idea? >> >> You do bring us interesting problems! Let us know what info you come up with. >> >> Oh, and I keep forgetting to ask: what does the write workload look >> like? At first I assumed this was a CephFS workload, but given that >> you're changing max message sizes and have half-second writes you're >> probably doing something else? > > I'm just using "pdsh -f <number of clients> -w <client list>" > to start up a "dd conv=fdatasync" on each client, roughly > simultaneously. > > I think the short messages are coming from writeback control. > I've got the writeback tracepoints enabled, and most of the time > I see things like this: > > tc85.trace.log:166469: flush-ceph-1-11910 [000] 1787.028175: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296424688 age=30 index=513024 to_write=1024 wrote=1024 > tc85.trace.log:166474: flush-ceph-1-11910 [000] 1787.028889: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296424688 age=30 index=514048 to_write=1024 wrote=1024 > > But occasionally I see this sort of thing: > > tc85.trace.log:22410: flush-ceph-1-11910 [001] 1546.957999: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=0 index=295936 to_write=11264 wrote=11264 > tc85.trace.log:29383: flush-ceph-1-11910 [001] 1547.327652: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=0 index=307200 to_write=11264 wrote=11264 > tc85.trace.log:37048: flush-ceph-1-11910 [001] 1548.861577: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=2 index=316416 to_write=9216 wrote=9216 > tc85.trace.log:42864: flush-ceph-1-11910 [000] 1550.023496: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=3 index=323584 to_write=7168 wrote=7168 > tc85.trace.log:47626: flush-ceph-1-11910 [000] 1550.976374: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=4 index=329728 to_write=6144 wrote=6144 > tc85.trace.log:51607: flush-ceph-1-11910 [001] 1551.781108: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=5 index=334848 to_write=5120 wrote=5120 > tc85.trace.log:51998: flush-ceph-1-11910 [001] 1551.860104: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=5 index=339968 to_write=5120 wrote=5120 > tc85.trace.log:52018: flush-ceph-1-11910 [001] 1551.863599: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=5 index=345088 to_write=5120 wrote=5120 > tc85.trace.log:52034: flush-ceph-1-11910 [001] 1551.866372: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=5 index=350208 to_write=5120 wrote=5120 > tc85.trace.log:52044: flush-ceph-1-11910 [001] 1551.866767: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=5 index=0 to_write=5120 wrote=648 > tc85.trace.log:69705: flush-ceph-1-11910 [000] 1576.878034: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296214116 age=30 index=352256 to_write=1024 wrote=1400 > tc85.trace.log:69830: flush-ceph-1-11910 [000] 1576.892907: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state= > dirtied_when=4296214116 age=30 index=0 to_write=1024 wrote=576 > tc85.trace.log:81609: flush-ceph-1-11910 [001] 1606.907407: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296244466 age=30 index=378880 to_write=1024 wrote=1472 > tc85.trace.log:81678: flush-ceph-1-11910 [001] 1606.916107: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state= > dirtied_when=4296244466 age=30 index=0 to_write=1024 wrote=831 > tc85.trace.log:96729: flush-ceph-1-11910 [000] 1636.918264: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296274503 age=30 index=393216 to_write=1024 wrote=1217 > tc85.trace.log:96839: flush-ceph-1-11910 [000] 1636.931363: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state= > dirtied_when=4296274503 age=30 index=0 to_write=1024 wrote=933 > tc85.trace.log:111179: flush-ceph-1-11910 [001] 1666.932329: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state=I_DIRTY_PAGES > dirtied_when=4296304541 age=30 index=415744 to_write=1024 wrote=1115 > tc85.trace.log:111298: flush-ceph-1-11910 [001] 1666.945162: > writeback_single_inode: bdi ceph-1: ino=1099511712863 state= > dirtied_when=4296304541 age=30 index=0 to_write=1024 wrote=941 > > I eventually want to understand what is happening here..... > > BTW, should I post my ceph client tracepoint patches? I ask because > it's not clear to me they would be useful to anyone but me. > > -- Jim > >> -Greg >> >> > > -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
