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). _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |