I tried the mds_cache_memory_limit and it doesn’t work.
But unexpectedly, we found drop_cache can work.
We added a "echo 3 > /proc/sys/vm/drop_caches” cron job.
Let it drop cache every 10 minutes and the problem didn’t occur for a whole night. : )
It seems to work but we can’t understand why. :(
Post by Li,NingI tested the dirty_ratio and dirty_background_ratio setting on ceph storage server side.
It didn’t work.
The problem reproduced just now.
Some process stay in D state for over 10 minitues.
These osd requests is about to take several minutes.
Here are some logs：
[Thu Dec 6 17:59:18 2018] INFO: task java:11477 blocked for more than 120 seconds.
[Thu Dec 6 17:59:18 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Thu Dec 6 17:59:18 2018] java D ffffffff816a4180 0 11477 8391 0x00000180
[Thu Dec 6 17:59:18 2018] ffff8807942bbbd0 0000000000000086 ffff8801f7e79fa0 ffff8807942bbfd8
[Thu Dec 6 17:59:18 2018] ffff8807942bbfd8 ffff8807942bbfd8 ffff8801f7e79fa0 ffff88086de56cc0
[Thu Dec 6 17:59:18 2018] 0000000000000000 7fffffffffffffff ffff88047ffa04e8 ffffffff816a4180
[Thu Dec 6 17:59:18 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Thu Dec 6 17:59:18 2018] [<ffffffff816a6059>] schedule+0x29/0x70
[Thu Dec 6 17:59:18 2018] [<ffffffff816a3b69>] schedule_timeout+0x239/0x2c0
[Thu Dec 6 17:59:18 2018] [<ffffffff81190541>] ? pagevec_lookup_tag+0x21/0x30
[Thu Dec 6 17:59:18 2018] [<ffffffffc081f598>] ? ceph_writepages_start+0x1298/0x1520 [ceph]
[Thu Dec 6 17:59:18 2018] [<ffffffff810e939c>] ? ktime_get_ts64+0x4c/0xf0
[Thu Dec 6 17:59:18 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Thu Dec 6 17:59:18 2018] [<ffffffff816a56dd>] io_schedule_timeout+0xad/0x130
[Thu Dec 6 17:59:18 2018] [<ffffffff816a5778>] io_schedule+0x18/0x20
[Thu Dec 6 17:59:18 2018] [<ffffffff816a4191>] bit_wait_io+0x11/0x50
[Thu Dec 6 17:59:18 2018] [<ffffffff816a3cb5>] __wait_on_bit+0x65/0x90
[Thu Dec 6 17:59:18 2018] [<ffffffff81181cb1>] wait_on_page_bit+0x81/0xa0
[Thu Dec 6 17:59:18 2018] [<ffffffff810b19d0>] ? wake_bit_function+0x40/0x40
[Thu Dec 6 17:59:18 2018] [<ffffffff81181de1>] __filemap_fdatawait_range+0x111/0x190
[Thu Dec 6 17:59:18 2018] [<ffffffff8118f42e>] ? do_writepages+0x1e/0x40
[Thu Dec 6 17:59:18 2018] [<ffffffff81181e74>] filemap_fdatawait_range+0x14/0x30
[Thu Dec 6 17:59:18 2018] [<ffffffff81183db6>] filemap_write_and_wait_range+0x56/0x90
[Thu Dec 6 17:59:18 2018] [<ffffffffc082726c>] ceph_fsync+0x6c/0x510 [ceph]
[Thu Dec 6 17:59:18 2018] [<ffffffff81137273>] ? __secure_computing+0x73/0x240
[Thu Dec 6 17:59:18 2018] [<ffffffff8111f5c6>] ? __audit_syscall_exit+0x1e6/0x280
[Thu Dec 6 17:59:18 2018] [<ffffffff81231d85>] do_fsync+0x65/0xa0
[Thu Dec 6 17:59:18 2018] [<ffffffff81232083>] SyS_fdatasync+0x13/0x20
[Thu Dec 6 17:59:18 2018] [<ffffffff816b1d4e>] tracesys+0xd9/0xde
[Thu Dec 6 18:03:38 2018] libceph: osd3 10.0.30.111:6808 socket closed (con state OPEN)
[Thu Dec 6 18:03:39 2018] libceph: osd7 10.0.30.112:6807 socket closed (con state OPEN)
[Thu Dec 6 18:03:39 2018] libceph: osd6 10.0.30.112:6805 socket closed (con state OPEN)
REQUESTS 1548 homeless 0
124188 osd5 1.7e6c3097 [5,2]/5 [5,2]/5 100004474e2.000006bf 0x400024 1 0'0 write
124191 osd5 1.37d4eeac [5,2]/5 [5,2]/5 100004474e2.000006c2 0x400024 1 0'0 write
124192 osd5 1.2506d82d [5,1]/5 [5,1]/5 100004474e2.000006c3 0x400024 1 0'0 write
124198 osd5 1.5326c49c [5,3]/5 [5,3]/5 100004474e1.00000888 0x400024 1 0'0 write
124219 osd5 1.37203f43 [5,2]/5 [5,2]/5 100004474e2.000006cb 0x400024 1 0'0 write
124236 osd5 1.1318aeb5 [5,0]/5 [5,0]/5 100002adc43.00000000 0x400024 1 0'0 write
124268 osd5 1.b4368bad [5,0]/5 [5,0]/5 100004474e1.000008a2 0x400024 1 0'0 write
124272 osd5 1.a31398ad [5,0]/5 [5,0]/5 100004474e2.000006dc 0x400024 1 0'0 write
124279 osd5 1.f6363aff [5,0]/5 [5,0]/5 100004474e2.000006e3 0x400024 1 0'0 write
124281 osd5 1.e3386fca [5,2]/5 [5,2]/5 100004474e2.000006e5 0x400024 1 0'0 write
124288 osd5 1.a95ff0ac [5,2]/5 [5,2]/5 100004474e1.000008ab 0x400024 1 0'0 write
124290 osd5 1.4e9c48ff [5,0]/5 [5,0]/5 100004474e1.000008ad 0x400024 1 0'0 write
124293 osd5 1.e4721518 [5,2]/5 [5,2]/5 100004474e1.000008b0 0x400024 1 0'0 write
124299 osd5 1.fae2c501 [5,0]/5 [5,0]/5 100004474e2.000006ec 0x400024 1 0'0 write
124303 osd5 1.708289ad [5,0]/5 [5,0]/5 100004474e2.000006f0 0x400024 1 0'0 write
124312 osd5 1.85e93586 [5,0]/5 [5,0]/5 100004474e1.000008b8 0x400024 1 0'0 write
124314 osd5 1.85146f18 [5,2]/5 [5,2]/5 100004474e1.000008ba 0x400024 1 0'0 write
124316 osd5 1.b4c5875a [5,0]/5 [5,0]/5 100004474e2.000006f2 0x400024 1 0'0 write
124336 osd5 1.cc35e38e [5,2]/5 [5,2]/5 100004474e1.000008c5 0x400024 1 0'0 write
124339 osd5 1.c99de197 [5,2]/5 [5,2]/5 100004474e2.000006fe 0x400024 1 0'0 write
124364 osd5 1.21ea6cb7 [5,2]/5 [5,2]/5 100004474e2.0000070c 0x400024 1 0'0 write
124368 osd5 1.411148d8 [5,1]/5 [5,1]/5 100004474e2.00000710 0x400024 1 0'0 write
124370 osd5 1.c56129da [5,1]/5 [5,1]/5 100004474e2.00000712 0x400024 1 0'0 write
124380 osd5 1.dd7b1c12 [5,1]/5 [5,1]/5 100004474e1.000008db 0x400024 1 0'0 write
124384 osd5 1.1878e328 [5,2]/5 [5,2]/5 100004474e2.00000715 0x400024 1 0'0 write
124390 osd5 1.f992feda [5,1]/5 [5,1]/5 100004474e2.0000071b 0x400024 1 0'0 write
124396 osd5 1.84f2e0ff [5,0]/5 [5,0]/5 100004474e1.000008e0 0x400024 1 0'0 write
124398 osd5 1.76e9cbb5 [5,0]/5 [5,0]/5 100004474e1.000008e2 0x400024 1 0'0 write
124405 osd5 1.3a4c5001 [5,0]/5 [5,0]/5 100004474e2.0000071f 0x400024 1 0'0 write
124413 osd5 1.91f47ada [5,1]/5 [5,1]/5 100004474e2.00000727 0x400024 1 0'0 write
124420 osd5 1.da08fa82 [5,1]/5 [5,1]/5 100004474e1.000008ed 0x400024 1 0'0 write
124422 osd5 1.f0dc5efd [5,3]/5 [5,3]/5 100004474e1.000008ef 0x400024 1 0'0 write
124435 osd5 1.28ba590a [5,2]/5 [5,2]/5 100004474e2.00000732 0x400024 1 0'0 write
124442 osd5 1.21439cf [5,1]/5 [5,1]/5 100004474e1.000008f8 0x400024 1 0'0 write
# ceph daemon osd.5 dump_blocked_ops
{
"ops": [],
"complaint_time": 30.000000,
"num_blocked_ops": 0
}
# ceph daemon osd.5 dump_ops_in_flight
{
"ops": [],
"num_ops": 0
}
# ceph daemon osd.5 dump_historic_slow_ops
{
"num to keep": 20,
"threshold to keep": 10,
"Ops": [
{
"description": "osd_op(client.447197.1:71890 1.b7884c19 1:983211ed:::100004342f9.000015e6:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.573307",
"age": 649.893033,
"duration": 13.827240,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71890
},
"events": [
{
"time": "2018-12-06 18:04:10.573307",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.573307",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.573309",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.595225",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.595278",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.595291",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:22.970164",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:22.970227",
"event": "started"
},
{
"time": "2018-12-06 18:04:22.970273",
"event": "waiting for subops from 6"
},
{
"time": "2018-12-06 18:04:23.323234",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.400524",
"event": "sub_op_commit_rec from 6"
},
{
"time": "2018-12-06 18:04:24.400541",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.400547",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71905 1.b5503364 1:26cc0aad:::100004342fb.00000c45:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.620624",
"age": 649.845717,
"duration": 12.702676,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71905
},
"events": [
{
"time": "2018-12-06 18:04:10.620624",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.620624",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.620626",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.635423",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.635476",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.635485",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.057810",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.057896",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.057945",
"event": "waiting for subops from 7"
},
{
"time": "2018-12-06 18:04:23.237036",
"event": "sub_op_commit_rec from 7"
},
{
"time": "2018-12-06 18:04:23.323250",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.323285",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.323300",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71913 1.9b59c75f 1:fae39ad9:::100004342fb.00000c4d:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.649445",
"age": 649.816895,
"duration": 12.762881,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71913
},
"events": [
{
"time": "2018-12-06 18:04:10.649445",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.649445",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.649447",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.667713",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.667783",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.667803",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.059423",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.059494",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.059540",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:23.147873",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:23.412282",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.412312",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.412326",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71924 1.43f2a896 1:69154fc2:::100004342f9.000015f9:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.680689",
"age": 649.785651,
"duration": 12.731666,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71924
},
"events": [
{
"time": "2018-12-06 18:04:10.680689",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.680689",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.680692",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.702583",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.702627",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.702634",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.147879",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.147979",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.148065",
"event": "waiting for subops from 4"
},
{
"time": "2018-12-06 18:04:23.237049",
"event": "sub_op_commit_rec from 4"
},
{
"time": "2018-12-06 18:04:23.412333",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.412349",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.412356",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71935 1.df579f5f 1:faf9eafb:::100004342fb.00000c54:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.751790",
"age": 649.714550,
"duration": 12.747687,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71935
},
"events": [
{
"time": "2018-12-06 18:04:10.751790",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.751790",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.751792",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.764998",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.765049",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.765059",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.149915",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.149990",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.150037",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:23.237059",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:23.499434",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.499466",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.499477",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71948 1.30315755 1:aaea8c0c:::100004342f9.00001602:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.765065",
"age": 649.701276,
"duration": 12.734734,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71948
},
"events": [
{
"time": "2018-12-06 18:04:10.765065",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.765065",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.765067",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.789073",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.789125",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.789136",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.237064",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.237142",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.237187",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:23.323299",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:23.499499",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.499513",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.499799",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71952 1.e0451baf 1:f5d8a207:::100004342f9.00001606:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.789142",
"age": 649.677198,
"duration": 12.809745,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71952
},
"events": [
{
"time": "2018-12-06 18:04:10.789142",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.789142",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.789145",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.802180",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.802240",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.802249",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.238710",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.238776",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.238890",
"event": "waiting for subops from 7"
},
{
"time": "2018-12-06 18:04:23.323284",
"event": "sub_op_commit_rec from 7"
},
{
"time": "2018-12-06 18:04:23.598857",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.598878",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.598888",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:71987 1.87226b4b 1:d2d644e1:::100004342f9.0000161a:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.875449",
"age": 649.590892,
"duration": 12.723466,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 71987
},
"events": [
{
"time": "2018-12-06 18:04:10.875449",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.875449",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.875450",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.889074",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.889109",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.889113",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.323306",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.323402",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.323465",
"event": "waiting for subops from 4"
},
{
"time": "2018-12-06 18:04:23.412387",
"event": "sub_op_commit_rec from 4"
},
{
"time": "2018-12-06 18:04:23.598895",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.598908",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.598915",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72009 1.6e26a0cd 1:b3056476:::100004342f9.00001621:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.951671",
"age": 649.514669,
"duration": 13.559266,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72009
},
"events": [
{
"time": "2018-12-06 18:04:10.951671",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.951671",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.951673",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.971212",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.971265",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.971274",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.325006",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.325073",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.325120",
"event": "waiting for subops from 6"
},
{
"time": "2018-12-06 18:04:23.689393",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.510912",
"event": "sub_op_commit_rec from 6"
},
{
"time": "2018-12-06 18:04:24.510930",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.510937",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72027 1.2675011e 1:7880ae64:::100004342fb.00000c83:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.983790",
"age": 649.482551,
"duration": 13.631767,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72027
},
"events": [
{
"time": "2018-12-06 18:04:10.983790",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.983790",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.983791",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:10.997441",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:10.997486",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:10.997493",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.412425",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.412492",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.412539",
"event": "waiting for subops from 6"
},
{
"time": "2018-12-06 18:04:23.782075",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.615518",
"event": "sub_op_commit_rec from 6"
},
{
"time": "2018-12-06 18:04:24.615545",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.615556",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72047 1.20d53eaf 1:f57cab04:::100004342f9.00001638:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:10.997499",
"age": 649.468842,
"duration": 12.894479,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72047
},
"events": [
{
"time": "2018-12-06 18:04:10.997499",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:10.997499",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:10.997500",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.010879",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.010920",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.010925",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.499523",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.499599",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.499652",
"event": "waiting for subops from 7"
},
{
"time": "2018-12-06 18:04:23.598911",
"event": "sub_op_commit_rec from 7"
},
{
"time": "2018-12-06 18:04:23.891906",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.891960",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.891977",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72114 1.5c7de55 1:aa7be3a0:::100004342fb.00000cad:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.111490",
"age": 649.354851,
"duration": 12.780517,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72114
},
"events": [
{
"time": "2018-12-06 18:04:11.111490",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.111490",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.111492",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.127195",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.127236",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.127242",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.598920",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.598999",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.599048",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:23.688752",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:23.891986",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:23.892001",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:23.892007",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72124 1.59941c4b 1:d238299a:::100004342fb.00000cb7:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.127248",
"age": 649.339093,
"duration": 12.962263,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72124
},
"events": [
{
"time": "2018-12-06 18:04:11.127248",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.127248",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.127250",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.137801",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.137837",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.137842",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.600686",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.600750",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.600795",
"event": "waiting for subops from 4"
},
{
"time": "2018-12-06 18:04:23.688740",
"event": "sub_op_commit_rec from 4"
},
{
"time": "2018-12-06 18:04:24.089450",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.089493",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.089511",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72136 1.4c3df65f 1:fa6fbc32:::100004342f9.00001664:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.161272",
"age": 649.305069,
"duration": 12.928269,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72136
},
"events": [
{
"time": "2018-12-06 18:04:11.161272",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.161272",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.161273",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.176621",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.176665",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.176672",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.688809",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.688878",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.688924",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:23.781472",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:24.089520",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.089534",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.089541",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72202 1.de800dcd 1:b3b0017b:::100004342fb.00000cd8:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.235424",
"age": 649.230917,
"duration": 13.494299,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72202
},
"events": [
{
"time": "2018-12-06 18:04:11.235424",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.235424",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.235425",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.244364",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.244400",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.244406",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.690409",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.690473",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.690519",
"event": "waiting for subops from 6"
},
{
"time": "2018-12-06 18:04:24.175400",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.729691",
"event": "sub_op_commit_rec from 6"
},
{
"time": "2018-12-06 18:04:24.729714",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.729723",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72222 1.bc0cdac3 1:c35b303d:::100004342f9.00001694:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.283182",
"age": 649.183159,
"duration": 12.980151,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72222
},
"events": [
{
"time": "2018-12-06 18:04:11.283182",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.283182",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.283183",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.290043",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.290087",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.290095",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.781478",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.781545",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.781591",
"event": "waiting for subops from 7"
},
{
"time": "2018-12-06 18:04:23.892055",
"event": "sub_op_commit_rec from 7"
},
{
"time": "2018-12-06 18:04:24.263304",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.263325",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.263333",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72237 1.567a0855 1:aa105e6a:::100004342f9.000016a3:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.305424",
"age": 649.160916,
"duration": 13.052176,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72237
},
"events": [
{
"time": "2018-12-06 18:04:11.305424",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.305424",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.305426",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.312298",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.312335",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.312340",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:23.892064",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:23.892156",
"event": "started"
},
{
"time": "2018-12-06 18:04:23.892216",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:24.089563",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:24.357583",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.357594",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.357600",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72249 1.960d9955 1:aa99b069:::100004342f9.000016af:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.319524",
"age": 649.146817,
"duration": 13.038095,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72249
},
"events": [
{
"time": "2018-12-06 18:04:11.319524",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.319524",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.319525",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.327928",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.327967",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.327973",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:24.089569",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:24.089666",
"event": "started"
},
{
"time": "2018-12-06 18:04:24.089730",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:04:24.175469",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:04:24.357605",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.357614",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.357618",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:72256 1.38b4facd 1:b35f2d1c:::100004342f9.000016b6:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:04:11.334694",
"age": 649.131646,
"duration": 13.615766,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 72256
},
"events": [
{
"time": "2018-12-06 18:04:11.334694",
"event": "initiated"
},
{
"time": "2018-12-06 18:04:11.334694",
"event": "header_read"
},
{
"time": "2018-12-06 18:04:11.334696",
"event": "throttled"
},
{
"time": "2018-12-06 18:04:11.340039",
"event": "all_read"
},
{
"time": "2018-12-06 18:04:11.340076",
"event": "dispatched"
},
{
"time": "2018-12-06 18:04:11.340082",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:04:24.091372",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:04:24.091440",
"event": "started"
},
{
"time": "2018-12-06 18:04:24.091490",
"event": "waiting for subops from 6"
},
{
"time": "2018-12-06 18:04:24.359630",
"event": "op_commit"
},
{
"time": "2018-12-06 18:04:24.950426",
"event": "sub_op_commit_rec from 6"
},
{
"time": "2018-12-06 18:04:24.950451",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:04:24.950460",
"event": "done"
}
]
}
},
{
"description": "osd_op(client.447197.1:75635 1.751883c0 1:03c118ae:::100004342f9.00001a19:head [write 0~4194304] snapc 1=[] ondisk+write+known_if_redirected e75)",
"initiated_at": "2018-12-06 18:05:16.411107",
"age": 584.055234,
"duration": 10.290467,
"type_data": {
"flag_point": "commit sent; apply or cleanup",
"client_info": {
"client": "client.447197",
"client_addr": "10.0.30.110:0/3181790720",
"tid": 75635
},
"events": [
{
"time": "2018-12-06 18:05:16.411107",
"event": "initiated"
},
{
"time": "2018-12-06 18:05:16.411107",
"event": "header_read"
},
{
"time": "2018-12-06 18:05:16.411108",
"event": "throttled"
},
{
"time": "2018-12-06 18:05:16.416864",
"event": "all_read"
},
{
"time": "2018-12-06 18:05:16.416903",
"event": "dispatched"
},
{
"time": "2018-12-06 18:05:16.416909",
"event": "queued_for_pg"
},
{
"time": "2018-12-06 18:05:19.383296",
"event": "reached_pg"
},
{
"time": "2018-12-06 18:05:19.383394",
"event": "started"
},
{
"time": "2018-12-06 18:05:19.383443",
"event": "waiting for subops from 5"
},
{
"time": "2018-12-06 18:05:19.957547",
"event": "op_commit"
},
{
"time": "2018-12-06 18:05:26.701524",
"event": "sub_op_commit_rec from 5"
},
{
"time": "2018-12-06 18:05:26.701557",
"event": "commit_sent"
},
{
"time": "2018-12-06 18:05:26.701574",
"event": "done"
}
]
}
}
]
}
—
Best Regards
Li, Ning
Post by Yan, ZhengPost by Li,NingHi,
Overload on the storage nodes that run OSDs is normal during the whole copy.
The memory pressure is on the client side. I think it may not work to turn the dirty_ratio and dirty_background_ratio to small on the ceph storage server side.
Anyway，I will have a try.
—
Best Regards
Li, Ning
Post by Yan, ZhengPost by NingLiHi all,
We found that some process writing cephfs will hang for a long time (> 120s) when uploading(scp/rsync) large files（totally 50G ~ 300G）to the app node's cephfs mountpoint.
This problem is not always reproduciable. But when this problem occurs, the web(nginx) or some other services can’t be access, it’s embarrassing.
Please give some tips.
We are using ceph version 13.2.1 and 3.10.0-693.el7.x86_64 kernel.
When this problem occurs, the memory pressure is a bit high.
# free -h
total used free shared buff/cache available
Mem: 30G 11G 230M 3.3M 18G 18G
Swap: 0B 0B 0B
# mpstat -P ALL
Average: CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
Average: all 3.80 0.04 1.46 55.12 0.00 0.08 0.00 0.00 0.00 39.49
Average: 0 1.52 0.00 0.51 97.98 0.00 0.00 0.00 0.00 0.00 0.00
Average: 1 13.07 0.00 1.51 0.00 0.00 0.00 0.00 0.00 0.00 85.43
Average: 2 3.00 0.00 3.00 0.50 0.00 0.00 0.00 0.00 0.00 93.50
Average: 3 2.50 0.00 2.00 0.00 0.00 0.00 0.00 0.00 0.00 95.50
Average: 4 1.50 0.50 1.50 96.00 0.00 0.50 0.00 0.00 0.00 0.00
Average: 5 0.50 0.00 1.01 32.16 0.00 0.00 0.00 0.00 0.00 66.33
Average: 6 2.49 0.00 2.49 0.00 0.00 0.50 0.00 0.00 0.00 94.53
Average: 7 1.52 0.00 0.51 97.98 0.00 0.00 0.00 0.00 0.00 0.00
Average: 8 1.50 0.00 1.50 97.00 0.00 0.00 0.00 0.00 0.00 0.00
Average: 9 14.07 0.00 2.01 46.23 0.00 0.00 0.00 0.00 0.00 37.69
Average: 10 2.00 0.00 0.50 97.50 0.00 0.00 0.00 0.00 0.00 0.00
Average: 11 2.01 0.00 1.01 96.98 0.00 0.00 0.00 0.00 0.00 0.00
We can see some process in state ‘D’ for a long time. here are 2 fragments in dmesg.
try setting vm.dirty_ration and vm.dirty_background_ration of machines
that run OSDs to smaller value.
Post by NingLi[Fri Nov 30 15:10:43 2018] INFO: task java:11662 blocked for more than 120 seconds.
[Fri Nov 30 15:10:43 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Nov 30 15:10:43 2018] java D ffffffff816a4180 0 11662 10409 0x00000180
[Fri Nov 30 15:10:43 2018] ffff8805f4febbd0 0000000000000082 ffff8807e2edcf10 ffff8805f4febfd8
[Fri Nov 30 15:10:43 2018] ffff8805f4febfd8 ffff8805f4febfd8 ffff8807e2edcf10 ffff88086df56cc0
[Fri Nov 30 15:10:43 2018] 0000000000000000 7fffffffffffffff ffff88087ffc3be8 ffffffff816a4180
[Fri Nov 30 15:10:43 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Fri Nov 30 15:10:43 2018] [<ffffffff816a6059>] schedule+0x29/0x70
[Fri Nov 30 15:10:43 2018] [<ffffffff816a3b69>] schedule_timeout+0x239/0x2c0
[Fri Nov 30 15:10:43 2018] [<ffffffff81190541>] ? pagevec_lookup_tag+0x21/0x30
[Fri Nov 30 15:10:43 2018] [<ffffffffc082b598>] ? ceph_writepages_start+0x1298/0x1520 [ceph]
[Fri Nov 30 15:10:43 2018] [<ffffffff810e939c>] ? ktime_get_ts64+0x4c/0xf0
[Fri Nov 30 15:10:43 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Fri Nov 30 15:10:43 2018] [<ffffffff816a56dd>] io_schedule_timeout+0xad/0x130
[Fri Nov 30 15:10:43 2018] [<ffffffff816a5778>] io_schedule+0x18/0x20
[Fri Nov 30 15:10:43 2018] [<ffffffff816a4191>] bit_wait_io+0x11/0x50
[Fri Nov 30 15:10:43 2018] [<ffffffff816a3cb5>] __wait_on_bit+0x65/0x90
[Fri Nov 30 15:10:43 2018] [<ffffffff81181cb1>] wait_on_page_bit+0x81/0xa0
[Fri Nov 30 15:10:43 2018] [<ffffffff810b19d0>] ? wake_bit_function+0x40/0x40
[Fri Nov 30 15:10:43 2018] [<ffffffff81181de1>] __filemap_fdatawait_range+0x111/0x190
[Fri Nov 30 15:10:43 2018] [<ffffffff811b0d79>] ? do_numa_page+0x159/0x1e0
[Fri Nov 30 15:10:43 2018] [<ffffffff8118f42e>] ? do_writepages+0x1e/0x40
[Fri Nov 30 15:10:43 2018] [<ffffffff81181e74>] filemap_fdatawait_range+0x14/0x30
[Fri Nov 30 15:10:43 2018] [<ffffffff81183db6>] filemap_write_and_wait_range+0x56/0x90
[Fri Nov 30 15:10:43 2018] [<ffffffffc083326c>] ceph_fsync+0x6c/0x510 [ceph]
[Fri Nov 30 15:10:43 2018] [<ffffffff81137273>] ? __secure_computing+0x73/0x240
[Fri Nov 30 15:10:43 2018] [<ffffffff8111f5c6>] ? __audit_syscall_exit+0x1e6/0x280
[Fri Nov 30 15:10:43 2018] [<ffffffff81231d85>] do_fsync+0x65/0xa0
[Fri Nov 30 15:10:43 2018] [<ffffffff81232083>] SyS_fdatasync+0x13/0x20
[Fri Nov 30 15:10:43 2018] [<ffffffff816b1d4e>] tracesys+0xd9/0xde
[Fri Nov 30 15:12:43 2018] INFO: task prometheus:9919 blocked for more than 120 seconds.
[Fri Nov 30 15:12:43 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Nov 30 15:12:43 2018] prometheus D ffff8807e87dbad8 0 9919 9879 0x00000080
[Fri Nov 30 15:12:43 2018] ffff8807e87db970 0000000000000082 ffff8803e273cf10 ffff8807e87dbfd8
[Fri Nov 30 15:12:43 2018] ffff8807e87dbfd8 ffff8807e87dbfd8 ffff8803e273cf10 ffff88046e716cc0
[Fri Nov 30 15:12:43 2018] 0000000000000000 7fffffffffffffff ffffffff816a4180 ffff8807e87dbad8
[Fri Nov 30 15:12:43 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Fri Nov 30 15:12:43 2018] [<ffffffff816a6059>] schedule+0x29/0x70
[Fri Nov 30 15:12:43 2018] [<ffffffff816a3b69>] schedule_timeout+0x239/0x2c0
[Fri Nov 30 15:12:43 2018] [<ffffffff81090007>] ? local_bh_enable+0x17/0x20
[Fri Nov 30 15:12:43 2018] [<ffffffff816a4180>] ? bit_wait+0x50/0x50
[Fri Nov 30 15:12:43 2018] [<ffffffff816a56dd>] io_schedule_timeout+0xad/0x130
[Fri Nov 30 15:12:43 2018] [<ffffffff816a5778>] io_schedule+0x18/0x20
[Fri Nov 30 15:12:43 2018] [<ffffffff816a4191>] bit_wait_io+0x11/0x50
[Fri Nov 30 15:12:43 2018] [<ffffffff816a3eaf>] __wait_on_bit_lock+0x5f/0xc0
[Fri Nov 30 15:12:43 2018] [<ffffffff81182094>] __lock_page+0x74/0x90
[Fri Nov 30 15:12:43 2018] [<ffffffff810b19d0>] ? wake_bit_function+0x40/0x40
[Fri Nov 30 15:12:43 2018] [<ffffffff81182a34>] __find_lock_page+0x54/0x70
[Fri Nov 30 15:12:43 2018] [<ffffffff811836e2>] grab_cache_page_write_begin+0x62/0xd0
[Fri Nov 30 15:12:43 2018] [<ffffffffc082a203>] ceph_write_begin+0x43/0xe0 [ceph]
[Fri Nov 30 15:12:43 2018] [<ffffffff811824ce>] generic_file_buffered_write+0x11e/0x2a0
[Fri Nov 30 15:12:43 2018] [<ffffffffc08259c4>] ceph_aio_write+0xac4/0xc60 [ceph]
[Fri Nov 30 15:12:43 2018] [<ffffffff8160417a>] ? inet_recvmsg+0x7a/0xa0
[Fri Nov 30 15:12:43 2018] [<ffffffff811feb3d>] do_sync_write+0x8d/0xd0
[Fri Nov 30 15:12:43 2018] [<ffffffff811ff5fd>] vfs_write+0xbd/0x1e0
[Fri Nov 30 15:12:43 2018] [<ffffffff8120040f>] SyS_write+0x7f/0xe0
[Fri Nov 30 15:12:43 2018] [<ffffffff816b1b49>] system_call_fastpath+0x16/0x1b
But the cephfs status shows healthy.
# ceph -s
id: b27bc9a3-2e32-4782-b60f-b7901b0b26e5
health: HEALTH_OK
mon: 2 daemons, quorum skyaxe-storage-0,skyaxe-storage-1
mgr: skyaxe-storage-0(active), standbys: skyaxe-storage-1
mds: cephfs-1/1/1 up {0=skyaxe-storage-1=up:active}, 1 up:standby
osd: 8 osds: 8 up, 8 in
pools: 2 pools, 512 pgs
objects: 599.7 k objects, 876 GiB
usage: 2.6 TiB used, 13 TiB / 15 TiB avail
pgs: 512 active+clean
client: 3.7 KiB/s wr, 0 op/s rd, 1 op/s wr
We can see some unfinished requests in osdc.
# cat /sys/kernel/debug/ceph/xxx/osdc
REQUESTS 98 homeless 0
8529 osd1 1.1bfdee5 [1,7]/1 [1,7]/1 100000011be.00000000 0x400024 1 0'0 write
8532 osd1 1.2d81c338 [1,6]/1 [1,6]/1 100000011c0.00000000 0x400024 1 0'0 write
8536 osd1 1.49324f26 [1,4]/1 [1,4]/1 100000011c4.00000000 0x400024 1 0'0 write
8542 osd1 1.1403106f [1,7]/1 [1,7]/1 100000011c8.00000000 0x400024 1 0'0 write
8549 osd1 1.ea273113 [1,4]/1 [1,4]/1 100000011ce.00000000 0x400024 1 0'0 write
8562 osd1 1.f2d68e9a [1,5]/1 [1,5]/1 100000011d8.00000000 0x400024 1 0'0 write
8566 osd1 1.1f212283 [1,4]/1 [1,4]/1 100000011db.00000000 0x400024 1 0'0 write
8568 osd1 1.2e1984e7 [1,5]/1 [1,5]/1 100000011de.00000000 0x400024 1 0'0 write
8576 osd1 1.da7e63d0 [1,5]/1 [1,5]/1 100000011e1.00000000 0x400024 1 0'0 write
8581 osd1 1.3b0d280 [1,4]/1 [1,4]/1 100000011e8.00000000 0x400024 1 0'0 write
8582 osd1 1.80227f0b [1,5]/1 [1,5]/1 100000011ea.00000000 0x400024 1 0'0 write
8593 osd1 1.1efd9391 [1,6]/1 [1,6]/1 100000011ef.00000000 0x400024 1 0'0 write
8594 osd1 1.3db6e880 [1,4]/1 [1,4]/1 100000011f0.00000000 0x400024 1 0'0 write
8611 osd1 1.6d20c41d [1,4]/1 [1,4]/1 1000000028c.00000000 0x400024 1 0'0 write
8612 osd1 1.6d20c41d [1,4]/1 [1,4]/1 1000000028c.00000000 0x400024 1 0'0 write
8616 osd1 1.f4d90a4d [1,7]/1 [1,7]/1 10000001206.00000000 0x400024 1 0'0 write
8619 osd1 1.740514fe [1,5]/1 [1,5]/1 10000001208.00000000 0x400024 1 0'0 write
8630 osd1 1.d5fbabe0 [1,6]/1 [1,6]/1 10000001216.00000000 0x400024 1 0'0 write
8631 osd1 1.daf28f83 [1,4]/1 [1,4]/1 10000001217.00000000 0x400024 1 0'0 write
8635 osd1 1.d29e01a6 [1,5]/1 [1,5]/1 1000000121a.00000000 0x400024 1 0'0 write
8640 osd1 1.2de0ff63 [1,7]/1 [1,7]/1 10000001220.00000000 0x400024 1 0'0 write
8658 osd1 1.2f91206f [1,7]/1 [1,7]/1 1000000122c.00000000 0x400064 1 0'0 write,startsync
...
how long did these osd requests take? If some requests take too long,
use 'ceph daemon osd.x dump dump_blocked_ops/dump_ops_in_flight' to
check
Post by Li,NingPost by Yan, ZhengPost by NingLiHere is our ceph config：
# cat /etc/ceph/ceph.conf
[global]
fsid = b27bc9a3-2e32-4782-b60f-b7901b0b26e5
mon_initial_members = skyaxe-storage-0, skyaxe-storage-1
mon_host = 10.0.30.111,10.0.30.112
auth_cluster_required = cephx
auth_service_required = cephx
auth_client_required = cephx
osd_pool_default_size = 2
public_network = 10.0.30.0/24
cluster_network = 10.0.40.0/24
osd_pool_default_min_size = 1
max_open_files = 131072
[osd]
osd_journal_size = 56320
journal_max_write_bytes = 1073741824
journal_max_write_entries = 10000
journal_queue_max_ops = 50000
journal_queue_max_bytes = 10737418240
osd_mkfs_type = xfs
osd_mkfs_options_xfs = -f
osd_mount_options_xfs = "rw,noexec,nodev,noatime,nodiratime,nobarrier"
osd_max_write_size = 512
osd_client_message_size_cap = 2147483648
osd_deep_scrub_stride = 131072
osd_op_threads = 8
osd_disk_threads = 4
osd_map_cache_size = 1024
osd_map_cache_bl_size = 128
osd_recovery_op_priority = 4
osd_recovery_max_active = 10
osd_max_backfills = 4
—
Best Regards
Li, Ning
_______________________________________________
ceph-users mailing list
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________
ceph-users mailing list
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com