On Fri, 3 Feb 2012, Jim Schutt 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.: > > 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....
Oh... they are separate thread. In the OSD's case two different messengers (the public and cluster ones) are wired up to the same dispatcher (OSD::ms_dispatch). MOSDOps come in on the public thread, MOSDSubOps on the cluster one, but they're both fed to the same function. That's why there's some funkiness going on in, say, handle_osd_map(). But like Greg said, I don't think we've seen any significant latencies there except from map processing. If you have a log, that would be interesting to look at! sage > > > > > > > > > > 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 > > -- 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
