> -----Original Message----- > From: Somnath Roy [mailto:Somnath.Roy@xxxxxxxxxxx] > Sent: 29 June 2015 23:29 > To: Nick Fisk > Cc: ceph-users@xxxxxxxxxxxxxx > Subject: RE: Old vs New pool on same OSDs - Performance > Difference > > Nick, > I think you are probably hitting the issue of crossing the xattr size limit that > XFS can inline (255 bytes). In your case "_" xattr size is 267 bytes. > Sage talked about that in one of his earlier mails..You can try to apply the > following patch (not backported to hammer yet) and see if it is improving > anything. > > c6cdb4081e366f471b372102905a1192910ab2da Ok I will see if this is something I can apply, I haven't really got the facility to rebuild Ceph at the moment, so I will look into getting a VM set up to build some debs. > > But, I am not sure why this will impact one pool but not other ! > In the slow pool do you have lot of snaps/clones/watchers ? I don't think this is related to particular pools, I think the problem relates to RBD's that haven't been written to in a while. Overwriting the RBD's contents with a fio run seems to restore performance. No, that’s the weird thing. I have a few pools with maybe 8-10 RBD's on them, nothing special is being done. Can there be a case where xattr's can grow larger than 255 bytes if I'm not using any special features? Is there a way to "dump" the xattrs to see why they are taking up so much space? > > > Thanks & Regards > Somnath > > > -----Original Message----- > From: Nick Fisk [mailto:nick@xxxxxxxxxx] > Sent: Monday, June 29, 2015 3:05 PM > To: Somnath Roy > Cc: ceph-users@xxxxxxxxxxxxxx > Subject: RE: Old vs New pool on same OSDs - Performance > Difference > > Sorry, forgot to enable that. Here is another capture with it on and I think you > are spot on as I can see a 100ms delay doing the getattr request. Any ideas > how to debug further? Thanks for the help by the way, really appreciated. > > 2015-06-29 22:48:50.851645 7fd8a2a1e700 15 osd.1 26349 enqueue_op > 0x522bf00 prio 63 cost 0 latency 0.000288 osd_op(client.2796502.0:136 > rb.0.1ba70.238e1f29.000000011477 [read 65536~65536] 0.8b312528 > ack+read+known_if_redirected e26349) v5 > 2015-06-29 22:48:50.851735 7fd8b026e700 10 osd.1 26349 dequeue_op > 0x522bf00 prio 63 cost 0 latency 0.000378 osd_op(client.2796502.0:136 > rb.0.1ba70.238e1f29.000000011477 [read 65536~65536] 0.8b312528 > ack+read+known_if_redirected e26349) v5 pg pg[0.128( v 26335'8141858 > (26331'8138777,26335'8141858] local-les=26276 n=5243 ec=1 les/c > 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 crt=26335'8141855 > lcod 26335'8141857 mlcod 26335'8141857 active+clean] > 2015-06-29 22:48:50.852076 7fd8b026e700 20 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > op_has_sufficient_caps pool=0 (rbd ) owner=0 need_read_cap=1 > need_write_cap=0 need_class_read_cap=0 need_class_write_cap=0 -> yes > 2015-06-29 22:48:50.852252 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > handle_message: 0x522bf00 > 2015-06-29 22:48:50.852471 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > do_op osd_op(client.2796502.0:136 rb.0.1ba70.238e1f29.000000011477 [read > 65536~65536] 0.8b312528 ack+read+known_if_redirected e26349) v5 > may_read -> read-ordered flags ack+read+known_if_redirected > 2015-06-29 22:48:50.852960 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > get_object_context: obc NOT found in cache: > 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 2015-06-29 22:48:50.853016 7fd8b026e700 15 > filestore(/var/lib/ceph/osd/ceph-1) getattr > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 '_' > 2015-06-29 22:48:50.953748 7fd8b026e700 10 > filestore(/var/lib/ceph/osd/ceph-1) getattr > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 '_' = 267 > 2015-06-29 22:48:50.953951 7fd8b026e700 15 > filestore(/var/lib/ceph/osd/ceph-1) getattr > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 'snapset' > 2015-06-29 22:48:50.954148 7fd8b026e700 10 > filestore(/var/lib/ceph/osd/ceph-1) getattr > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 'snapset' > = 31 > 2015-06-29 22:48:50.954379 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > populate_obc_watchers > 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 2015-06-29 22:48:50.954557 7fd8b026e700 20 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > ReplicatedPG::check_blacklisted_obc_watchers for obc > 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 2015-06-29 22:48:50.954581 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > get_object_context: creating obc from disk: 0x5ee4a3c0 > 2015-06-29 22:48:50.954597 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > get_object_context: 0x5ee4a3c0 > 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 rwstate(none n=0 > w=0) oi: 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0(2160'1179595 > osd.1.0:2686580 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest s > 1048576 uv 45452 dd a50a5b00 od ffffffff) ssc: 0xee72780 snapset: > 0=[]:[]+head > 2015-06-29 22:48:50.954735 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > find_object_context 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > @head > oi=8b312528/rb.0.1ba70.238e1f29.000000011477/head//0(2160'1179595 > osd.1.0:2686580 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest s > 1048576 uv 45452 dd a50a5b00 od ffffffff) > 2015-06-29 22:48:50.955142 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > execute_ctx 0x684fd000 > 2015-06-29 22:48:50.955310 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > do_op 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 [read > 65536~65536] ov 2160'1179595 > 2015-06-29 22:48:50.955371 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > taking ondisk_read_lock > 2015-06-29 22:48:50.955475 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > do_osd_op 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 [read > 65536~65536] > 2015-06-29 22:48:50.955493 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > do_osd_op read 65536~65536 > 2015-06-29 22:48:50.955511 7fd8b026e700 15 > filestore(/var/lib/ceph/osd/ceph-1) read > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 65536~65536 > 2015-06-29 22:48:50.965854 7fd8b026e700 10 > filestore(/var/lib/ceph/osd/ceph-1) FileStore::read > 0.128_head/8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 65536~65536/65536 > 2015-06-29 22:48:50.965879 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > read got 65536 / 65536 bytes from obj > 8b312528/rb.0.1ba70.238e1f29.000000011477/head//0 > 2015-06-29 22:48:50.966149 7fd8b026e700 10 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > dropping ondisk_read_lock > 2015-06-29 22:48:50.966285 7fd8b026e700 15 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > do_osd_op_effects client.2796502 con 0x514a5600 > 2015-06-29 22:48:50.966331 7fd8b026e700 15 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > log_op_stats osd_op(client.2796502.0:136 rb.0.1ba70.238e1f29.000000011477 > [read 65536~65536] 0.8b312528 ack+read+known_if_redirected e26349) v5 > inb 0 outb 65536 rlat 0.000000 lat 0.114972 > 2015-06-29 22:48:50.966769 7fd8b026e700 15 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > publish_stats_to_osd 26349:8019961 > 2015-06-29 22:48:50.966961 7fd8b026e700 15 osd.1 pg_epoch: 26349 > pg[0.128( v 26335'8141858 (26331'8138777,26335'8141858] local-les=26276 > n=5243 ec=1 les/c 26276/26305 26264/26272/26272) [1,21,31] r=0 lpr=26272 > crt=26335'8141855 lcod 26335'8141857 mlcod 26335'8141857 active+clean] > requeue_ops > 2015-06-29 22:48:50.967127 7fd8b026e700 10 osd.1 26349 dequeue_op > 0x522bf00 finish > > > > -----Original Message----- > > From: Somnath Roy [mailto:Somnath.Roy@xxxxxxxxxxx] > > Sent: 29 June 2015 17:19 > > To: Nick Fisk > > Cc: ceph-users@xxxxxxxxxxxxxx > > Subject: RE: Old vs New pool on same OSDs - Performance > > Difference > > > > Nick, > > The line " get_object_context: obc NOT found in cache" should be fine, > > it will be rare (even after obc cache implementation) you will have a > > hit during random workload. > > Is the second IO on the pool you are having problem ? I saw huge wait > > time there during getattr completion. In the first case, it is ~64ms > > and in second case ~1 sec !! > > Unfortunately, you didn't enable filestore log level to 20 , that's > > why I couldn't able to say where it is taking time..Please post that.. > > But, I think it is the problem while retrieving xattr '_' and '_snapset'... > > > > Thanks & Regards > > Somnath > > > > -----Original Message----- > > From: Nick Fisk [mailto:nick@xxxxxxxxxx] > > Sent: Monday, June 29, 2015 4:54 AM > > To: Somnath Roy > > Cc: ceph-users@xxxxxxxxxxxxxx > > Subject: RE: Old vs New pool on same OSDs - Performance > > Difference > > > > Hi Somnath, > > > > Sorry for the delay. Release is Hammer, so I can probably drop that > > setting then. > > > > I have hopefully managed to capture a couple of slow IO's on an idle > > cluster, does the below look about right to you? I can see there is a > > delay after this entry " get_object_context: obc NOT found in cache", > > is that indicative of anything? > > > > 2015-06-29 12:35:19.551447 7fd8a7d44700 15 osd.1 26335 enqueue_op > > 0x6b9a4d00 prio 63 cost 0 latency 0.000184 osd_op(client.2808923.0:145 > > rb.0.1ba70.238e1f29.00000000ad7a [read 524288~65536] 0.b974752f > > ack+read+known_if_redirected e26335) v5 > > 2015-06-29 12:35:19.551555 7fd8b1a71700 10 osd.1 26335 dequeue_op > > 0x6b9a4d00 prio 63 cost 0 latency 0.000291 osd_op(client.2808923.0:145 > > rb.0.1ba70.238e1f29.00000000ad7a [read 524288~65536] 0.b974752f > > ack+read+known_if_redirected e26335) v5 pg pg[0.12f( v 26335'1299179 > > (24993'1296145,26335'1299179] local-les=26276 n=5044 ec=1 les/c > > 26276/26309 26264/26270/26270) [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > 2015-06-29 12:35:19.551936 7fd8b1a71700 20 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > op_has_sufficient_caps pool=0 (rbd ) owner=0 need_read_cap=1 > > need_write_cap=0 need_class_read_cap=0 need_class_write_cap=0 -> > yes > > 2015-06-29 12:35:19.552422 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > handle_message: 0x6b9a4d00 > > 2015-06-29 12:35:19.552446 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > do_op osd_op(client.2808923.0:145 rb.0.1ba70.238e1f29.00000000ad7a > > [read 524288~65536] 0.b974752f ack+read+known_if_redirected e26335) > v5 > > may_read -> read-ordered flags ack+read+known_if_redirected > > 2015-06-29 12:35:19.552728 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > get_object_context: obc NOT found in cache: > > b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 > > 2015-06-29 12:35:19.616951 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > populate_obc_watchers > > b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 > > 2015-06-29 12:35:19.617349 7fd8b1a71700 20 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > ReplicatedPG::check_blacklisted_obc_watchers for obc > > b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 > > 2015-06-29 12:35:19.617387 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > get_object_context: creating obc from disk: 0x6863b180 > > 2015-06-29 12:35:19.617409 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > get_object_context: 0x6863b180 > > b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 rwstate(none n=0 > > w=0) oi: b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0(2160'454478 > > osd.1.0:2693729 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest > > s > > 1048576 uv 43100 dd 88ec7921 od ffffffff) ssc: 0x11a8a3a0 snapset: > > 0=[]:[]+head > > 2015-06-29 12:35:19.617516 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > find_object_context b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 > > @head > > oi=b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0(2160'454478 > > osd.1.0:2693729 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest > > s > > 1048576 uv 43100 dd 88ec7921 od ffffffff) > > 2015-06-29 12:35:19.617821 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > execute_ctx 0x5eb34400 > > 2015-06-29 12:35:19.617943 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > do_op b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 [read > > 524288~65536] ov 2160'454478 > > 2015-06-29 12:35:19.617991 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > taking ondisk_read_lock > > 2015-06-29 12:35:19.618003 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > do_osd_op b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 [read > > 524288~65536] > > 2015-06-29 12:35:19.618014 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > do_osd_op read 524288~65536 > > 2015-06-29 12:35:19.618432 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > read got 65536 / 65536 bytes from obj > > b974752f/rb.0.1ba70.238e1f29.00000000ad7a/head//0 > > 2015-06-29 12:35:19.618555 7fd8b1a71700 10 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > dropping ondisk_read_lock > > 2015-06-29 12:35:19.618733 7fd8b1a71700 15 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > do_osd_op_effects client.2808923 con 0x6d9ad760 > > 2015-06-29 12:35:19.618803 7fd8b1a71700 15 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > log_op_stats osd_op(client.2808923.0:145 > > rb.0.1ba70.238e1f29.00000000ad7a [read 524288~65536] 0.b974752f > > ack+read+known_if_redirected e26335) v5 inb 0 outb 65536 rlat 0.000000 > > lat 0.067538 > > 2015-06-29 12:35:19.618983 7fd8b1a71700 15 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > publish_stats_to_osd 26335:1206609 > > 2015-06-29 12:35:19.619143 7fd8b1a71700 15 osd.1 pg_epoch: 26335 > > pg[0.12f( v 26335'1299179 (24993'1296145,26335'1299179] > > local-les=26276 n=5044 ec=1 les/c 26276/26309 26264/26270/26270) > > [1,18,40] r=0 lpr=26270 > > crt=26335'1299176 lcod 26335'1299178 mlcod 26335'1299178 active+clean] > > requeue_ops > > 2015-06-29 12:35:19.619170 7fd8b1a71700 10 osd.1 26335 dequeue_op > > 0x6b9a4d00 finish > > > > > > Second IO > > > > 2015-06-29 12:35:23.928222 7fd8a7d44700 15 osd.1 26335 enqueue_op > > 0x6b9a4900 prio 63 cost 0 latency 0.000381 osd_op(client.2808923.0:188 > > rb.0.1ba70.238e1f29.00000000264a [read 720896~65536] 0.52c31661 > > ack+read+known_if_redirected e26335) v5 > > 2015-06-29 12:35:23.928291 7fd8b3a75700 10 osd.1 26335 dequeue_op > > 0x6b9a4900 prio 63 cost 0 latency 0.000450 osd_op(client.2808923.0:188 > > rb.0.1ba70.238e1f29.00000000264a [read 720896~65536] 0.52c31661 > > ack+read+known_if_redirected e26335) v5 pg pg[0.261( v 26335'1369662 > > (24993'1366661,26335'1369662] local-les=26276 n=5050 ec=1 les/c > > 26276/26311 26264/26270/26270) [1,23,11] r=0 lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > 2015-06-29 12:35:23.928676 7fd8b3a75700 20 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > op_has_sufficient_caps pool=0 (rbd ) owner=0 need_read_cap=1 > > need_write_cap=0 need_class_read_cap=0 need_class_write_cap=0 -> > yes > > 2015-06-29 12:35:23.928910 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > handle_message: 0x6b9a4900 > > 2015-06-29 12:35:23.928929 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > do_op osd_op(client.2808923.0:188 rb.0.1ba70.238e1f29.00000000264a > > [read 720896~65536] 0.52c31661 ack+read+known_if_redirected e26335) > v5 > > may_read -> read-ordered flags ack+read+known_if_redirected > > 2015-06-29 12:35:23.929375 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > get_object_context: obc NOT found in cache: > > 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 > > 2015-06-29 12:35:23.942620 7fd8be28a700 20 osd.1 26335 share_map_peer > > 0x5e5ad180 already has epoch 26335 > > 2015-06-29 12:35:23.942694 7fd8bfa8d700 20 osd.1 26335 share_map_peer > > 0x5e5ad180 already has epoch 26335 > > 2015-06-29 12:35:24.055268 7fd8d7ae5700 5 osd.1 26335 tick > > 2015-06-29 12:35:24.055298 7fd8d7ae5700 20 osd.1 26335 > > scrub_random_backoff lost coin flip, randomly backing off > > 2015-06-29 12:35:24.055301 7fd8d7ae5700 10 osd.1 26335 do_waiters -- > > start > > 2015-06-29 12:35:24.055303 7fd8d7ae5700 10 osd.1 26335 do_waiters -- > > finish > > 2015-06-29 12:35:24.068422 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > populate_obc_watchers > > 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 > > 2015-06-29 12:35:24.068563 7fd8b3a75700 20 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > ReplicatedPG::check_blacklisted_obc_watchers for obc > > 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 > > 2015-06-29 12:35:24.068667 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > get_object_context: creating obc from disk: 0x641a3180 > > 2015-06-29 12:35:24.068693 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > get_object_context: 0x641a3180 > > 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 rwstate(none n=0 > > w=0) oi: 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0(2700'867765 > > osd.1.0:3390976 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest > > s > > 1048576 uv 802272 dd 3b309dc0 od ffffffff) ssc: 0x15842c30 snapset: > > 0=[]:[]+head > > 2015-06-29 12:35:24.068812 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > find_object_context 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 > > @head > > oi=52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0(2700'867765 > > osd.1.0:3390976 wrlock_by=unknown.0.0:0 dirty|data_digest|omap_digest > > s > > 1048576 uv 802272 dd 3b309dc0 od ffffffff) > > 2015-06-29 12:35:24.069048 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > execute_ctx 0x6e47ca00 > > 2015-06-29 12:35:24.069136 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > do_op 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 [read > > 720896~65536] ov 2700'867765 > > 2015-06-29 12:35:24.069275 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > taking ondisk_read_lock > > 2015-06-29 12:35:24.069322 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > do_osd_op 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 [read > > 720896~65536] > > 2015-06-29 12:35:24.069335 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > do_osd_op read 720896~65536 > > 2015-06-29 12:35:24.072584 7fd8be28a700 20 osd.1 26335 share_map_peer > > 0x5e5ac680 already has epoch 26335 > > 2015-06-29 12:35:24.072677 7fd8bfa8d700 20 osd.1 26335 share_map_peer > > 0x5e5ac680 already has epoch 26335 > > 2015-06-29 12:35:24.074427 7fd8be28a700 20 osd.1 26335 share_map_peer > > 0x67792520 already has epoch 26335 > > 2015-06-29 12:35:24.074461 7fd8bfa8d700 20 osd.1 26335 share_map_peer > > 0x67792520 already has epoch 26335 > > 2015-06-29 12:35:24.083945 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > read got 65536 / 65536 bytes from obj > > 52c31661/rb.0.1ba70.238e1f29.00000000264a/head//0 > > 2015-06-29 12:35:24.084056 7fd8b3a75700 10 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > dropping ondisk_read_lock > > 2015-06-29 12:35:24.084094 7fd8b3a75700 15 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > do_osd_op_effects client.2808923 con 0x6d9ad760 > > 2015-06-29 12:35:24.084183 7fd8b3a75700 15 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > log_op_stats osd_op(client.2808923.0:188 > > rb.0.1ba70.238e1f29.00000000264a [read 720896~65536] 0.52c31661 > > ack+read+known_if_redirected e26335) v5 inb 0 outb 65536 rlat 0.000000 > > lat 0.156341 > > 2015-06-29 12:35:24.084499 7fd8b3a75700 15 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > publish_stats_to_osd 26335:1261700 > > 2015-06-29 12:35:24.084660 7fd8b3a75700 15 osd.1 pg_epoch: 26335 > > pg[0.261( v 26335'1369662 (24993'1366661,26335'1369662] > > local-les=26276 > > n=5050 ec=1 les/c 26276/26311 26264/26270/26270) [1,23,11] r=0 > > lpr=26270 > > crt=26335'1369659 lcod 26335'1369661 mlcod 26335'1369661 active+clean] > > requeue_ops > > 2015-06-29 12:35:24.084700 7fd8b3a75700 10 osd.1 26335 dequeue_op > > 0x6b9a4900 finish > > > > > > > > > -----Original Message----- > > > From: ceph-users [mailto:ceph-users-bounces@xxxxxxxxxxxxxx] On > > > Behalf Of Somnath Roy > > > Sent: 21 June 2015 06:03 > > > To: Nick Fisk > > > Cc: ceph-users@xxxxxxxxxxxxxx > > > Subject: Re: Old vs New pool on same OSDs - Performance > > > Difference > > > > > > What release you are using ? > > > filestore_xattr_use_omap is deprecated long back.. > > > > > > Thanks & Regards > > > Somnath > > > > > > > > > > > > > > > ________________________________ > > > > PLEASE NOTE: The information contained in this electronic mail message > > is intended only for the use of the designated recipient(s) named > > above. If the reader of this message is not the intended recipient, > > you are hereby notified that you have received this message in error > > and that any review, dissemination, distribution, or copying of this > > message is strictly prohibited. If you have received this > > communication in error, please notify the sender by telephone or > > e-mail (as shown above) immediately and destroy any and all copies of > > this message in your possession (whether hard copies or electronically > stored copies). > > > > > > > > ________________________________ > > PLEASE NOTE: The information contained in this electronic mail message is > intended only for the use of the designated recipient(s) named above. If the > reader of this message is not the intended recipient, you are hereby notified > that you have received this message in error and that any review, > dissemination, distribution, or copying of this message is strictly prohibited. If > you have received this communication in error, please notify the sender by > telephone or e-mail (as shown above) immediately and destroy any and all > copies of this message in your possession (whether hard copies or > electronically stored copies). _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |