Reproduced this in another vm environment. Here 2 osds had slow requests, unfortunately only one had debug level set at the time of slow request, hopefully this will be helpful.
Here is the dump_ops_in_flight
sudo ceph --admin-daemon /var/run/ceph/ceph-osd.1.asok dump_ops_in_flight
{ "ops": [
{ "description": "osd_op(client.4440.0:1 default.region [getxattrs,stat] 10.9a566808 RETRY=1 ack+retry+read+known_if_redirected e17)",
"initiated_at": "2015-07-16 11:22:46.304211",
"age": "1412.058120",
"duration": "0.000000",
"type_data": [
"no flag points reached",
{ "client": "client.4440",
"tid": 1},
[
{ "time": "2015-07-16 11:22:46.304211",
"event": "initiated"}]]},
{ "description": "osd_op(client.4516.0:1 default.region [getxattrs,stat] 10.9a566808 RETRY=1 ack+retry+read+known_if_redirected e17)",
"initiated_at": "2015-07-16 11:22:46.304480",
"age": "1412.057851",
"duration": "0.000000",
"type_data": [
"no flag points reached",
{ "client": "client.4516",
"tid": 1},
[
{ "time": "2015-07-16 11:22:46.304480",
"event": "initiated"}]]},
{ "description": "osd_op(client.4767.0:1 default.region [getxattrs,stat] 10.9a566808 RETRY=1 ack+retry+read+known_if_redirected e17)",
"initiated_at": "2015-07-16 11:23:00.126294",
"age": "1398.236037",
"duration": "0.000000",
"type_data": [
"no flag points reached",
{ "client": "client.4767",
"tid": 1},
[
{ "time": "2015-07-16 11:23:00.126294",
"event": "initiated"}]]},
{ "description": "osd_op(client.4839.0:1 default.region [getxattrs,stat] 10.9a566808 ack+read+known_if_redirected e17)",
"initiated_at": "2015-07-16 11:23:16.198332",
"age": "1382.163999",
"duration": "0.000000",
"type_data": [
"no flag points reached",
{ "client": "client.4839",
"tid": 1},
[
{ "time": "2015-07-16 11:23:16.198332",
"event": "initiated"}]]},
{ "description": "osd_op(client.4667.0:1 default.region [getxattrs,stat] 10.9a566808 ack+read+known_if_redirected e18)",
"initiated_at": "2015-07-16 11:23:50.339441",
"age": "1348.022890",
"duration": "0.000000",
"type_data": [
"no flag points reached",
{ "client": "client.4667",
"tid": 1},
[
{ "time": "2015-07-16 11:23:50.339441",
"event": "initiated"}]]}],
"num_ops": 5}
This was the log at that point
2015-07-16 11:22:44.873351 7f68bf7da700 1 -- 10.0.0.54:6800/5734 <== mon.1 10.0.0.57:6789/0 10 ==== mon_check_map_ack(handle=1 version=16) v2 ==== 24+0+0 (3847591702 0 0) 0x4d1fdc0 con 0x4cf0dc0
2015-07-16 11:22:44.873392 7f68b67c8700 10 osd.1 0 _maybe_boot mon has osdmaps 1..16
2015-07-16 11:22:44.873406 7f68b67c8700 10 osd.1 0 _send_boot
2015-07-16 11:22:44.873411 7f68b67c8700 10 osd.1 0 new session (outgoing) 0x4d60780 con=0x4cf0160 addr=10.0.0.54:6801/5734
2015-07-16 11:22:44.873436 7f68b67c8700 10 osd.1 0 client_addr 10.0.0.54:6800/5734, cluster_addr 10.0.0.54:6801/5734, hb_back_addr 10.0.0.54:6802/5734, hb_front_addr 10.0.0.54:6803/5734
2015-07-16 11:22:44.970378 7f68b67c8700 10 osd.1 0 _collect_metadata {arch=x86_64,back_addr=10.0.0.54:6801/5734,ceph_version=ceph version 0.87.2 (87a7cec9ab11c677de2ab23a7668a77d2f5b955e),cpu=Intel Xeon E312xx (Sandy Bridge),distro=Ubuntu,distro_codename=trusty,distro_description=Ubuntu 14.04.2 LTS,distro_version=14.04,filestore_backend=xfs,filestore_f_type=0x58465342,front_addr=10.0.0.54:6800/5734,hb_back_addr=10.0.0.54:6802/5734,hb_front_addr=10.0.0.54:6803/5734,hostname=stmonleader1-testjenkins-puppet-rjil-gate-1802,kernel_description=#74-Ubuntu SMP Tue Jan 13 19:36:28 UTC 2015,kernel_version=3.13.0-45-generic,mem_swap_kb=0,mem_total_kb=3790348,os=Linux,osd_data=/var/lib/ceph/osd/ceph-1,osd_journal=/var/lib/ceph/osd/ceph-1/journal,osd_objectstore=filestore}
2015-07-16 11:22:44.970442 7f68b67c8700 1 -- 10.0.0.54:6800/5734 --> 10.0.0.57:6789/0 -- osd_boot(osd.1 booted 0 v0) v5 -- ?+0 0x4e4a000 con 0x4cf0dc0
2015-07-16 11:22:46.303248 7f68aaeb0700 1 -- 10.0.0.54:6800/5734 >> :/0 pipe(0x4d3b8c0 sd=34 :6800 s=0 pgs=0 cs=0 l=0 c=0x4cf1b80).accept sd=34 10.0.0.57:35811/0
2015-07-16 11:22:46.303358 7f68aafb1700 1 -- 10.0.0.54:6800/5734 >> :/0 pipe(0x4d3b340 sd=33 :6800 s=0 pgs=0 cs=0 l=0 c=0x4cf18c0).accept sd=33 10.0.0.59:33603/0
2015-07-16 11:22:46.303764 7f68aaeb0700 10 osd.1 0 new session 0x4d60c80 con=0x4cf1b80 addr=10.0.0.57:0/1001932
2015-07-16 11:22:46.303833 7f68aaeb0700 10 osd.1 0 session 0x4d60c80 client.radosgw.gateway has caps osdcap[grant(rwx)] 'allow rwx'
2015-07-16 11:22:46.304007 7f68aafb1700 10 osd.1 0 new session 0x4d60f00 con=0x4cf18c0 addr=10.0.0.59:0/1028611
2015-07-16 11:22:46.304048 7f68aafb1700 10 osd.1 0 session 0x4d60f00 client.radosgw.gateway has caps osdcap[grant(rwx)] 'allow rwx'
2015-07-16 11:22:46.304275 7f68aaeb0700 1 -- 10.0.0.54:6800/5734 <== client.4440 10.0.0.57:0/1001932 1 ==== osd_op(client.4440.0:1 default.region [getxattrs,stat] 10.9a566808 RETRY=1 ack+retry+read+known_if_redirected e17) v4 ==== 203+0+0 (928176555 0 0) 0x4d61400 con 0x4cf1b80
2015-07-16 11:22:46.304389 7f68aaeb0700 1 -- 10.0.0.54:6800/5734 --> 10.0.0.57:6789/0 -- mon_subscribe({monmap=4+,osd_pg_creates=0,osdmap=17}) v2 -- ?+0 0x4d643c0 con 0x4cf0dc0
2015-07-16 11:22:46.304513 7f68aafb1700 1 -- 10.0.0.54:6800/5734 <== client.4516 10.0.0.59:0/1028611 1 ==== osd_op(client.4516.0:1 default.region [getxattrs,stat] 10.9a566808 RETRY=1 ack+retry+read+known_if_redirected e17) v4 ==== 203+0+0 (928176555 0 0) 0x4d61900 con 0x4cf18c0
2015-07-16 11:22:46.383313 7f68bf7da700 1 -- 10.0.0.54:6800/5734 <== mon.1 10.0.0.57:6789/0 11 ==== osd_map(16..17 src has 1..17) v3 ==== 1515+0+0 (507967949 0 0) 0x4e46240 con 0x4cf0dc0
2015-07-16 11:22:46.383357 7f68bf7da700 10 osd.1 0 do_waiters -- start
2015-07-16 11:22:46.383362 7f68bf7da700 10 osd.1 0 do_waiters -- finish
2015-07-16 11:22:46.383363 7f68bf7da700 20 osd.1 0 _dispatch 0x4e46240 osd_map(16..17 src has 1..17) v3
2015-07-16 11:22:46.383401 7f68bf7da700 1 -- 10.0.0.54:6800/5734 --> 10.0.0.57:6789/0 -- mon_subscribe({monmap=4+,osd_pg_creates=0,osdmap=0}) v2 -- ?+0 0x4d64780 con 0x4cf0dc0
2015-07-16 11:22:46.383417 7f68bf7da700 3 osd.1 0 handle_osd_map epochs [16,17], i have 0, src has [1,17]
2015-07-16 11:22:46.383421 7f68bf7da700 10 osd.1 0 handle_osd_map message skips epochs 1..15
2015-07-16 11:22:46.383438 7f68bf7da700 1 -- 10.0.0.54:6800/5734 --> 10.0.0.57:6789/0 -- mon_subscribe({monmap=4+,osd_pg_creates=0,osdmap=1}) v2 -- ?+0 0x4d645a0 con 0x4cf0dc0
2015-07-16 11:22:46.383443 7f68bf7da700 10 osd.1 0 do_waiters -- start
2015-07-16 11:22:46.383445 7f68bf7da700 10 osd.1 0 do_waiters -- finish
Attaching the log file in the next comment.. as tracker seems to error out while attaching..