We've been seeing this issue on all of our dumpling clusters, and I'm wondering what might be the cause of it.
In dump_historic_ops, the time between op_applied and sub_op_commit_rec or the time between commit_sent and sub_op_applied is extremely high. Some of the osd_sub_ops are as long as 100 ms. A sample dump_historic_ops is included at the bottom.
At first, I thought it may have something to do with colocation of MONs on some of the OSD nodes, but ruled that out by moving MONs off.
I also have a cluster of all SSDs, and this is still happening.
The boxes have 64GB RAM (or more), 16 hyperthreaded cores, and are on the Linux 3.8 kernel.
I believe I've ruled out network latency with hping3, and I've tested throughput with iperf.
root@ceph-2001:/home/ceph_deploy# ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok dump_historic_ops
{ "num to keep": 20,
"duration to keep": 600,
"Ops": [
{ "description": "osd_sub_op(client.10860160.0:714612038 4.18d0 c24ab8d0\/rbd_data.7078502ae8944a.0000000000077ad3\/head\/\/4 [] v 7198'104899 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:32:55.227680",
"age": "425.703917",
"duration": "0.067519",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:32:55.228428",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:32:55.228644",
"event": "reached_pg"},
{ "time": "2014-03-13 18:32:55.228785",
"event": "started"},
{ "time": "2014-03-13 18:32:55.229030",
"event": "started"},
{ "time": "2014-03-13 18:32:55.229109",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:32:55.229219",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:32:55.229548",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:32:55.229706",
"event": "commit_sent"},
{ "time": "2014-03-13 18:32:55.295124",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:32:55.295199",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714619302 4.10a 598610a\/rbd_data.7078502ae8944a.00000000000a81a8\/head\/\/4 [] v 7198'159184 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:33:23.868750",
"age": "397.062847",
"duration": "0.074642",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:33:23.869263",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:33:23.869392",
"event": "reached_pg"},
{ "time": "2014-03-13 18:33:23.869437",
"event": "started"},
{ "time": "2014-03-13 18:33:23.869615",
"event": "started"},
{ "time": "2014-03-13 18:33:23.869664",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:33:23.869795",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:33:23.870052",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:33:23.870160",
"event": "commit_sent"},
{ "time": "2014-03-13 18:33:23.943309",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:33:23.943392",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860178.0:106690364 4.4b5 397564b5\/rbd_data.7070772ae8944a.000000000000b793\/head\/\/4 [] v 7198'80545 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:34:35.821056",
"age": "325.110541",
"duration": "0.053297",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:34:35.821479",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:34:35.821587",
"event": "reached_pg"},
{ "time": "2014-03-13 18:34:35.821627",
"event": "started"},
{ "time": "2014-03-13 18:34:35.821816",
"event": "started"},
{ "time": "2014-03-13 18:34:35.821867",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:34:35.822044",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:34:35.822543",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:34:35.822676",
"event": "commit_sent"},
{ "time": "2014-03-13 18:34:35.874162",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:34:35.874353",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860178.0:106690369 4.4b5 397564b5\/rbd_data.7070772ae8944a.000000000000b793\/head\/\/4 [] v 7198'80546 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:34:35.826622",
"age": "325.104975",
"duration": "0.048853",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:34:35.826988",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:34:35.827141",
"event": "reached_pg"},
{ "time": "2014-03-13 18:34:35.827189",
"event": "started"},
{ "time": "2014-03-13 18:34:35.827357",
"event": "started"},
{ "time": "2014-03-13 18:34:35.827404",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:34:35.827541",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:34:35.827790",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:34:35.827937",
"event": "commit_sent"},
{ "time": "2014-03-13 18:34:35.875371",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:34:35.875475",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714665833 4.bcb 6debabcb\/rbd_data.7078502ae8944a.0000000000071d82\/head\/\/4 [] v 7198'71809 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:36:21.297822",
"age": "219.633775",
"duration": "0.049018",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:36:21.298406",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:36:21.298541",
"event": "reached_pg"},
{ "time": "2014-03-13 18:36:21.298622",
"event": "started"},
{ "time": "2014-03-13 18:36:21.298835",
"event": "started"},
{ "time": "2014-03-13 18:36:21.298882",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:36:21.299038",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:36:21.299613",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:36:21.299762",
"event": "commit_sent"},
{ "time": "2014-03-13 18:36:21.346764",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:36:21.346840",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714671894 rbd_data.7078502ae8944a.000000000000e6f4 [sparse-read 2392064~16384] 4.f1750679 e7198)",
"received_at": "2014-03-13 18:36:43.136049",
"age": "197.795548",
"duration": "0.064230",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714671894},
[
{ "time": "2014-03-13 18:36:43.136428",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:36:43.136554",
"event": "reached_pg"},
{ "time": "2014-03-13 18:36:43.195083",
"event": "started"},
{ "time": "2014-03-13 18:36:43.200279",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714673265 rbd_data.7078502ae8944a.000000000000f35b [sparse-read 3162112~16384] 4.c53c5ce6 e7198)",
"received_at": "2014-03-13 18:36:49.162335",
"age": "191.769262",
"duration": "0.063587",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714673265},
[
{ "time": "2014-03-13 18:36:49.162698",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:36:49.162839",
"event": "reached_pg"},
{ "time": "2014-03-13 18:36:49.225742",
"event": "started"},
{ "time": "2014-03-13 18:36:49.225922",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714673392 4.6c1 368946c1\/rbd_data.7078502ae8944a.0000000000057f64\/head\/\/4 [] v 7198'80856 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:36:49.466294",
"age": "191.465303",
"duration": "0.047405",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:36:49.466953",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:36:49.467122",
"event": "reached_pg"},
{ "time": "2014-03-13 18:36:49.467176",
"event": "started"},
{ "time": "2014-03-13 18:36:49.467413",
"event": "started"},
{ "time": "2014-03-13 18:36:49.467479",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:36:49.467601",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:36:49.467854",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:36:49.467942",
"event": "commit_sent"},
{ "time": "2014-03-13 18:36:49.513613",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:36:49.513699",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714677360 4.bcb 56a20bcb\/rbd_data.7078502ae8944a.0000000000054db6\/head\/\/4 [] v 7198'71813 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:37:04.528732",
"age": "176.402865",
"duration": "0.060755",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:37:04.529274",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:37:04.529402",
"event": "reached_pg"},
{ "time": "2014-03-13 18:37:04.529458",
"event": "started"},
{ "time": "2014-03-13 18:37:04.529617",
"event": "started"},
{ "time": "2014-03-13 18:37:04.529667",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:37:04.529835",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:37:04.530129",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:37:04.530319",
"event": "commit_sent"},
{ "time": "2014-03-13 18:37:04.589412",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:37:04.589487",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714691448 rbd_data.7078502ae8944a.0000000000077b5f [sparse-read 1081344~16384] 4.4c4ed357 e7198)",
"received_at": "2014-03-13 18:37:56.306260",
"age": "124.625337",
"duration": "0.061185",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714691448},
[
{ "time": "2014-03-13 18:37:56.306634",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:37:56.306751",
"event": "reached_pg"},
{ "time": "2014-03-13 18:37:56.367205",
"event": "started"},
{ "time": "2014-03-13 18:37:56.367445",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714694290 4.4b5 f33b04b5\/rbd_data.7078502ae8944a.00000000000b30ef\/head\/\/4 [] v 7198'80561 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:38:07.092178",
"age": "113.839419",
"duration": "0.047158",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:38:07.092706",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:38:07.092889",
"event": "reached_pg"},
{ "time": "2014-03-13 18:38:07.092958",
"event": "started"},
{ "time": "2014-03-13 18:38:07.093142",
"event": "started"},
{ "time": "2014-03-13 18:38:07.093195",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:38:07.093317",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:38:07.093569",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:38:07.093661",
"event": "commit_sent"},
{ "time": "2014-03-13 18:38:07.139224",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:38:07.139336",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714694853 rbd_data.7078502ae8944a.0000000000068793 [sparse-read 3489792~16384] 4.7465582b e7198)",
"received_at": "2014-03-13 18:38:09.268594",
"age": "111.663003",
"duration": "0.063490",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714694853},
[
{ "time": "2014-03-13 18:38:09.268926",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:38:09.269085",
"event": "reached_pg"},
{ "time": "2014-03-13 18:38:09.325435",
"event": "started"},
{ "time": "2014-03-13 18:38:09.332084",
"event": "done"}]]},
{ "description": "osd_op(client.10860178.0:106692813 rbd_data.7070772ae8944a.0000000000000001 [write 1183744~4096] 4.fa9322b8 e7198)",
"received_at": "2014-03-13 18:38:21.881596",
"age": "99.050001",
"duration": "0.091794",
"type_data": [
"commit sent; apply or cleanup",
{ "client": "client.10860178",
"tid": 106692813},
[
{ "time": "2014-03-13 18:38:21.882027",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:38:21.882153",
"event": "reached_pg"},
{ "time": "2014-03-13 18:38:21.882658",
"event": "started"},
{ "time": "2014-03-13 18:38:21.882695",
"event": "started"},
{ "time": "2014-03-13 18:38:21.882910",
"event": "waiting for subops from [140]"},
{ "time": "2014-03-13 18:38:21.883212",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:38:21.883425",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:38:21.883832",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:38:21.884061",
"event": "op_commit"},
{ "time": "2014-03-13 18:38:21.885026",
"event": "op_applied"},
{ "time": "2014-03-13 18:38:21.973246",
"event": "sub_op_commit_rec"},
{ "time": "2014-03-13 18:38:21.973340",
"event": "commit_sent"},
{ "time": "2014-03-13 18:38:21.973390",
"event": "done"}]]},
{ "description": "osd_op(client.10860178.0:106692814 rbd_data.7070772ae8944a.0000000000000001 [write 1191936~4096] 4.fa9322b8 e7198)",
"received_at": "2014-03-13 18:38:21.881770",
"age": "99.049827",
"duration": "0.091994",
"type_data": [
"commit sent; apply or cleanup",
{ "client": "client.10860178",
"tid": 106692814},
[
{ "time": "2014-03-13 18:38:21.882431",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:38:21.883413",
"event": "reached_pg"},
{ "time": "2014-03-13 18:38:21.883490",
"event": "started"},
{ "time": "2014-03-13 18:38:21.883521",
"event": "started"},
{ "time": "2014-03-13 18:38:21.883788",
"event": "waiting for subops from [140]"},
{ "time": "2014-03-13 18:38:21.883978",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:38:21.884114",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:38:21.884290",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:38:21.884345",
"event": "op_commit"},
{ "time": "2014-03-13 18:38:21.886064",
"event": "op_applied"},
{ "time": "2014-03-13 18:38:21.973636",
"event": "sub_op_commit_rec"},
{ "time": "2014-03-13 18:38:21.973707",
"event": "commit_sent"},
{ "time": "2014-03-13 18:38:21.973764",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714708118 rbd_data.7078502ae8944a.000000000005c5b3 [sparse-read 32768~16384] 4.c6366678 e7198)",
"received_at": "2014-03-13 18:38:59.209966",
"age": "61.721631",
"duration": "0.032544",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714708118},
[
{ "time": "2014-03-13 18:38:59.210361",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:38:59.210507",
"event": "reached_pg"},
{ "time": "2014-03-13 18:38:59.242156",
"event": "started"},
{ "time": "2014-03-13 18:38:59.242510",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10860160.0:714718480 4.bcb cc254bcb\/rbd_data.7078502ae8944a.00000000000a7ea2\/head\/\/4 [] v 7198'71829 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:39:36.375725",
"age": "24.555872",
"duration": "0.055991",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:39:36.376342",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:39:36.376523",
"event": "reached_pg"},
{ "time": "2014-03-13 18:39:36.376601",
"event": "started"},
{ "time": "2014-03-13 18:39:36.376950",
"event": "started"},
{ "time": "2014-03-13 18:39:36.377031",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:39:36.377150",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:39:36.377549",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:39:36.377669",
"event": "commit_sent"},
{ "time": "2014-03-13 18:39:36.431631",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:39:36.431716",
"event": "done"}]]},
{ "description": "osd_op(client.10860160.0:714719736 rbd_data.7078502ae8944a.000000000008c4a8 [sparse-read 3014656~16384] 4.fbeafe3a e7198)",
"received_at": "2014-03-13 18:39:41.954384",
"age": "18.977213",
"duration": "0.054586",
"type_data": [
"started",
{ "client": "client.10860160",
"tid": 714719736},
[
{ "time": "2014-03-13 18:39:41.954748",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:39:41.954929",
"event": "reached_pg"},
{ "time": "2014-03-13 18:39:41.997870",
"event": "started"},
{ "time": "2014-03-13 18:39:42.008970",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10855810.0:615625702 4.1a01 65e93a01\/rbd_data.3d58122ae8944a.000000000000e83c\/head\/\/4 [] v 7198'90865 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:39:48.167368",
"age": "12.764229",
"duration": "0.055035",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:39:48.167764",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:39:48.167899",
"event": "reached_pg"},
{ "time": "2014-03-13 18:39:48.167957",
"event": "started"},
{ "time": "2014-03-13 18:39:48.168207",
"event": "started"},
{ "time": "2014-03-13 18:39:48.168263",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:39:48.168367",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:39:48.168627",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:39:48.168798",
"event": "commit_sent"},
{ "time": "2014-03-13 18:39:48.222322",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:39:48.222403",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10855810.0:615626699 4.2fe 485e22fe\/rbd_data.3d58122ae8944a.000000000000e7f3\/head\/\/4 [] v 7198'159336 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:39:54.452320",
"age": "6.479277",
"duration": "0.036762",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:39:54.452906",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:39:54.453060",
"event": "reached_pg"},
{ "time": "2014-03-13 18:39:54.453127",
"event": "started"},
{ "time": "2014-03-13 18:39:54.453327",
"event": "started"},
{ "time": "2014-03-13 18:39:54.453383",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:39:54.453639",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:39:54.453931",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:39:54.454094",
"event": "commit_sent"},
{ "time": "2014-03-13 18:39:54.488985",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:39:54.489082",
"event": "done"}]]},
{ "description": "osd_sub_op(client.10855810.0:615626700 4.2fe 485e22fe\/rbd_data.3d58122ae8944a.000000000000e7f3\/head\/\/4 [] v 7198'159337 snapset=0=[]:[] snapc=0=[])",
"received_at": "2014-03-13 18:39:54.457885",
"age": "6.473712",
"duration": "0.032248",
"type_data": [
"commit sent; apply or cleanup",
[
{ "time": "2014-03-13 18:39:54.458299",
"event": "waiting_for_osdmap"},
{ "time": "2014-03-13 18:39:54.458441",
"event": "reached_pg"},
{ "time": "2014-03-13 18:39:54.458491",
"event": "started"},
{ "time": "2014-03-13 18:39:54.458693",
"event": "started"},
{ "time": "2014-03-13 18:39:54.458746",
"event": "commit_queued_for_journal_write"},
{ "time": "2014-03-13 18:39:54.458898",
"event": "write_thread_in_journal_buffer"},
{ "time": "2014-03-13 18:39:54.459152",
"event": "journaled_completion_queued"},
{ "time": "2014-03-13 18:39:54.459312",
"event": "commit_sent"},
{ "time": "2014-03-13 18:39:54.490071",
"event": "sub_op_applied"},
{ "time": "2014-03-13 18:39:54.490133",
"event": "done"}]]}]}
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
