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 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 ? 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
 |