Actions
Bug #9711
closed'cache' osd crash on ceph 0.86
Status:
Duplicate
Priority:
Normal
Assignee:
-
Category:
OSD
Target version:
-
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
In a tiering setup cache+ EC on KV, one cache OSD has crashed after about 12hours testing with rados bench.
Stacktrace:
-65> 2014-10-09 06:57:53.723685 7f36857ac700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.723536, event: header_read, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -64> 2014-10-09 06:57:53.723702 7f36857ac700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.723541, event: throttled, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -63> 2014-10-09 06:57:53.723716 7f36857ac700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.723603, event: all_read, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -62> 2014-10-09 06:57:53.723730 7f36857ac700 5 -- op tracker -- seq: 2723802, time: 0.000000, event: dispatched, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -61> 2014-10-09 06:57:53.723982 7f3693a80700 5 osd.1 pg_epoch: 112 pg[1.175( v 112'6123 (112'3121,112'6123] local-les=103 n=30 ec=100 les/c 103/103 101/102/100) [1,35] r=0 lpr=102 luod=112'6122 crt=112'6121 lcod 112'6121 mlcod 112'6121 active+clean] agent_choose_mode flush_mode idle -> active -60> 2014-10-09 06:57:53.730082 7f3693a80700 1 -- 10.141.8.180:6805/42710 --> 10.141.8.181:6839/47310 -- osd_op(osd.1.5:945809 benchmark_data_ceph001.cubone.os_56195_object175083 [copy-from ver 6099] 2.4a4ca575 ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e112) v4 -- ?+0 0x10060a00 con 0x6fece60 -59> 2014-10-09 06:57:53.730696 7f3698a8a700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.730696, event: reached_pg, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -58> 2014-10-09 06:57:53.730728 7f3698a8a700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.730728, event: started, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -57> 2014-10-09 06:57:53.730742 7f3698a8a700 5 -- op tracker -- seq: 2723802, time: 2014-10-09 06:57:53.730742, event: done, op: osd_sub_op_reply(osd.1.0:1109992 1.175 e2137575/benchmark_data_ceph001.cubone.os_28148_object522687/head//1 [] ondisk, result = 0) -56> 2014-10-09 06:57:53.736424 7f3683e93700 1 -- 10.141.8.180:6803/42710 <== osd.29 10.141.8.181:6841/47310 2234 ==== osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) v4 ==== 240+0+29 (179429527 0 2022847189) 0x25ab0000 con 0x38c8d800 -55> 2014-10-09 06:57:53.736467 7f3683e93700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.736276, event: header_read, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -54> 2014-10-09 06:57:53.736484 7f3683e93700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.736281, event: throttled, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -53> 2014-10-09 06:57:53.736495 7f3683e93700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.736417, event: all_read, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -52> 2014-10-09 06:57:53.736509 7f3683e93700 5 -- op tracker -- seq: 2723803, time: 0.000000, event: dispatched, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -51> 2014-10-09 06:57:53.736572 7f369b28f700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.736572, event: reached_pg, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -50> 2014-10-09 06:57:53.736610 7f369b28f700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.736609, event: started, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -49> 2014-10-09 06:57:53.736741 7f36abe9e700 5 -- op tracker -- seq: 2723759, time: 2014-10-09 06:57:53.736741, event: journaled_completion_queued, op: osd_op(client.6320.0:178617 benchmark_data_ceph001.cubone.os_56195_object178616 [write 0~4197440] 1.eeb121b8 ack+ondisk+write+known_if_redirected e112) -48> 2014-10-09 06:57:53.736816 7f36ac69f700 5 -- op tracker -- seq: 2723765, time: 2014-10-09 06:57:53.736815, event: write_thread_in_journal_buffer, op: osd_sub_op(osd.17.0:1112917 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6137 snapset=0=[]:[] snapc=0=[]) -47> 2014-10-09 06:57:53.737070 7f36a9699700 5 -- op tracker -- seq: 2723759, time: 2014-10-09 06:57:53.737070, event: op_commit, op: osd_op(client.6320.0:178617 benchmark_data_ceph001.cubone.os_56195_object178616 [write 0~4197440] 1.eeb121b8 ack+ondisk+write+known_if_redirected e112) -46> 2014-10-09 06:57:53.737114 7f36a9699700 1 -- 10.141.8.180:6803/42710 --> 10.141.8.180:0/1056195 -- osd_op_reply(178617 benchmark_data_ceph001.cubone.os_56195_object178616 [write 0~4197440] v112'6219 uv6219 ondisk = 0) v6 -- ?+0 0x1129b9c0 con 0x2e679340 -45> 2014-10-09 06:57:53.737135 7f36a9699700 5 -- op tracker -- seq: 2723759, time: 2014-10-09 06:57:53.737135, event: commit_sent, op: osd_op(client.6320.0:178617 benchmark_data_ceph001.cubone.os_56195_object178616 [write 0~4197440] 1.eeb121b8 ack+ondisk+write+known_if_redirected e112) -44> 2014-10-09 06:57:53.738321 7f36a0299700 1 -- 10.141.8.180:6805/42710 <== osd.23 10.141.8.181:6821/30905 26231 ==== osd_op_reply(945808 benchmark_data_ceph001.cubone.os_56195_object178627 [copy-get max 8388608] v0'0 uv0 ack = -2 ((2) No such file or directory)) v6 ==== 218+0+0 (2219966209 0 0) 0x161fdac0 con 0x8b50840 -43> 2014-10-09 06:57:53.738375 7f36ac69f700 5 -- op tracker -- seq: 2723766, time: 2014-10-09 06:57:53.738375, event: write_thread_in_journal_buffer, op: osd_sub_op(osd.19.0:1012080 1.383 f3d8783/benchmark_data_ceph001.cubone.os_28148_object519293/head//1 [] v 112'5503 snapset=0=[]:[] snapc=0=[]) -42> 2014-10-09 06:57:53.738604 7f36863b8700 1 -- 10.143.8.180:6802/42710 <== osd.33 10.143.8.182:6802/14473 581975 ==== osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (4106323362 0 0) 0x38708dc0 con 0x5b18160 -41> 2014-10-09 06:57:53.738619 7f36863b8700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738543, event: header_read, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -40> 2014-10-09 06:57:53.738627 7f36863b8700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738545, event: throttled, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -39> 2014-10-09 06:57:53.738632 7f36863b8700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738598, event: all_read, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -38> 2014-10-09 06:57:53.738638 7f36863b8700 5 -- op tracker -- seq: 2723804, time: 0.000000, event: dispatched, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -37> 2014-10-09 06:57:53.738685 7f369ca92700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738685, event: reached_pg, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -36> 2014-10-09 06:57:53.738707 7f369ca92700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738706, event: started, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -35> 2014-10-09 06:57:53.738720 7f369ca92700 5 -- op tracker -- seq: 2723804, time: 2014-10-09 06:57:53.738720, event: done, op: osd_sub_op_reply(osd.1.0:1109989 1.3ed 548073ed/benchmark_data_ceph001.cubone.os_56195_object148970/head//1 [] ondisk, result = 0) -34> 2014-10-09 06:57:53.738835 7f3695283700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.182:6802/14473 -- osd_sub_op(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] v 112'6172 snapset=0=[]:[] snapc=0=[]) v11 -- ?+726 0xcb45800 con 0x5b18160 -33> 2014-10-09 06:57:53.739043 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.739043, event: reached_pg, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -32> 2014-10-09 06:57:53.739078 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.739078, event: started, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -31> 2014-10-09 06:57:53.739091 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.739090, event: started, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -30> 2014-10-09 06:57:53.739161 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.739160, event: waiting for subops from 33, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -29> 2014-10-09 06:57:53.739186 7f3698a8a700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.182:6802/14473 -- osd_sub_op(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] v 112'6173 snapset=0=[]:[] snapc=0=[]) v11 -- ?+4198186 0x2cae0000 con 0x5b18160 -28> 2014-10-09 06:57:53.739324 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.739324, event: commit_queued_for_journal_write, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -27> 2014-10-09 06:57:53.742496 7f36ac69f700 5 -- op tracker -- seq: 2723768, time: 2014-10-09 06:57:53.742495, event: write_thread_in_journal_buffer, op: osd_sub_op(osd.33.0:1109759 1.36c a71a576c/benchmark_data_ceph001.cubone.os_28148_object537987/head//1 [] v 112'6155 snapset=0=[]:[] snapc=0=[]) -26> 2014-10-09 06:57:53.742642 7f36863b8700 1 -- 10.143.8.180:6802/42710 <== osd.33 10.143.8.182:6802/14473 581976 ==== osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (2818605695 0 0) 0x3870a100 con 0x5b18160 -25> 2014-10-09 06:57:53.742661 7f36863b8700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742592, event: header_read, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -24> 2014-10-09 06:57:53.742669 7f36863b8700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742594, event: throttled, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -23> 2014-10-09 06:57:53.742674 7f36863b8700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742637, event: all_read, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -22> 2014-10-09 06:57:53.742678 7f36863b8700 5 -- op tracker -- seq: 2723805, time: 0.000000, event: dispatched, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -21> 2014-10-09 06:57:53.742709 7f3698a8a700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742708, event: reached_pg, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -20> 2014-10-09 06:57:53.742721 7f3698a8a700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742721, event: started, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -19> 2014-10-09 06:57:53.742732 7f3698a8a700 5 -- op tracker -- seq: 2723805, time: 2014-10-09 06:57:53.742732, event: done, op: osd_sub_op_reply(osd.1.0:1109993 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -18> 2014-10-09 06:57:53.745183 7f36ac69f700 5 -- op tracker -- seq: 2723767, time: 2014-10-09 06:57:53.745182, event: write_thread_in_journal_buffer, op: osd_sub_op(client.6320.0:178618 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6138 snapset=0=[]:[] snapc=0=[]) -17> 2014-10-09 06:57:53.748167 7f368c418700 1 -- 10.143.8.180:6802/42710 <== osd.17 10.143.8.181:6802/14755 498748 ==== osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (2196699244 0 0) 0x10ae02c0 con 0x547e9e0 -16> 2014-10-09 06:57:53.748199 7f368c418700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748082, event: header_read, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -15> 2014-10-09 06:57:53.748206 7f368c418700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748092, event: throttled, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -14> 2014-10-09 06:57:53.748214 7f368c418700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748158, event: all_read, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -13> 2014-10-09 06:57:53.748220 7f368c418700 5 -- op tracker -- seq: 2723806, time: 0.000000, event: dispatched, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -12> 2014-10-09 06:57:53.748265 7f369a28d700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748265, event: reached_pg, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -11> 2014-10-09 06:57:53.748284 7f369a28d700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748284, event: started, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -10> 2014-10-09 06:57:53.748297 7f369a28d700 5 -- op tracker -- seq: 2723806, time: 2014-10-09 06:57:53.748297, event: done, op: osd_sub_op_reply(osd.1.0:1109984 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -9> 2014-10-09 06:57:53.748295 7f368c418700 1 -- 10.143.8.180:6802/42710 <== osd.17 10.143.8.181:6802/14755 498749 ==== osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (3291642467 0 0) 0x10ae2940 con 0x547e9e0 -8> 2014-10-09 06:57:53.748311 7f368c418700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748255, event: header_read, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -7> 2014-10-09 06:57:53.748319 7f368c418700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748256, event: throttled, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -6> 2014-10-09 06:57:53.748325 7f368c418700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748291, event: all_read, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -5> 2014-10-09 06:57:53.748333 7f368c418700 5 -- op tracker -- seq: 2723807, time: 0.000000, event: dispatched, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -4> 2014-10-09 06:57:53.748372 7f369ca92700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748371, event: reached_pg, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -3> 2014-10-09 06:57:53.748397 7f369ca92700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748397, event: started, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) -2> 2014-10-09 06:57:53.748409 7f369ca92700 5 -- op tracker -- seq: 2723784, time: 2014-10-09 06:57:53.748409, event: sub_op_commit_rec, op: osd_op(client.6320.0:178625 benchmark_data_ceph001.cubone.os_56195_object178624 [write 0~4197440] 1.d5e57922 ack+ondisk+write+known_if_redirected e112) -1> 2014-10-09 06:57:53.748427 7f369ca92700 5 -- op tracker -- seq: 2723807, time: 2014-10-09 06:57:53.748427, event: done, op: osd_sub_op_reply(client.6320.0:178625 1.122 d5e57922/benchmark_data_ceph001.cubone.os_56195_object178624/head//1 [] ondisk, result = 0) 0> 2014-10-09 06:57:53.778840 7f36aae9c700 -1 os/FDCache.h: In function 'void FDCache::clear(const ghobject_t&)' thread 7f36aae9c700 time 2014-10-09 06:57:53.649769 os/FDCache.h: 91: FAILED assert(!registry[registry_id].lookup(hoid)) ceph version 0.86 (97dcc0539dfa7dac3de74852305d51580b7b1f82) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0xb79235] 2: (FDCache::clear(ghobject_t const&)+0x365) [0x904f55] 3: (FileStore::lfn_unlink(coll_t, ghobject_t const&, SequencerPosition const&, bool)+0x42c) [0x8e570c] 4: (FileStore::_remove(coll_t, ghobject_t const&, SequencerPosition const&)+0x9e) [0x8e58fe] 5: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x2929) [0x8f6009] 6: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x8f8524] 7: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x17e) [0x8f86be] 8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa66) [0xb69f46] 9: (ThreadPool::WorkThread::entry()+0x10) [0xb6afd0] 10: (()+0x7df3) [0x7f36b74bfdf3] 11: (clone()+0x6d) [0x7f36b5f863dd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. --- logging levels --- 0/ 5 none 0/ 1 lockdep 0/ 1 context 1/ 1 crush 1/ 5 mds 1/ 5 mds_balancer 1/ 5 mds_locker 1/ 5 mds_log 1/ 5 mds_log_expire 1/ 5 mds_migrator 0/ 1 buffer 0/ 1 timer 0/ 1 filer 0/ 1 striper 0/ 1 objecter 0/ 5 rados 0/ 5 rbd 0/ 5 rbd_replay 0/ 5 journaler 0/ 5 objectcacher 0/ 5 client 0/ 5 osd 0/ 5 optracker 0/ 5 objclass 1/ 3 filestore 1/ 3 keyvaluestore 1/ 3 journal 0/ 5 ms 1/ 5 mon 0/10 monc 1/ 5 paxos 0/ 5 tp 1/ 5 auth 1/ 5 crypto 1/ 1 finisher 1/ 5 heartbeatmap 1/ 5 perfcounter 1/ 5 rgw 1/10 civetweb 1/ 5 javaclient 1/ 5 asok 1/ 1 throttle 0/ 0 refs -2/-2 (syslog threshold) -1/-1 (stderr threshold) max_recent 10000 max_new 1000 log_file /var/log/ceph/ceph-osd.1.log --- end dump of recent events --- 2014-10-09 06:57:53.931184 7f36aae9c700 -1 *** Caught signal (Aborted) ** in thread 7f36aae9c700 ceph version 0.86 (97dcc0539dfa7dac3de74852305d51580b7b1f82) 1: /usr/bin/ceph-osd() [0xa86f92] 2: (()+0xf130) [0x7f36b74c7130] 3: (gsignal()+0x39) [0x7f36b5ec5989] 4: (abort()+0x148) [0x7f36b5ec7098] 5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f36b67d89d5] 6: (()+0x5e946) [0x7f36b67d6946] 7: (()+0x5e973) [0x7f36b67d6973] 8: (()+0x5eb9f) [0x7f36b67d6b9f] 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x27a) [0xb7942a] 10: (FDCache::clear(ghobject_t const&)+0x365) [0x904f55] 11: (FileStore::lfn_unlink(coll_t, ghobject_t const&, SequencerPosition const&, bool)+0x42c) [0x8e570c] 12: (FileStore::_remove(coll_t, ghobject_t const&, SequencerPosition const&)+0x9e) [0x8e58fe] 13: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x2929) [0x8f6009] 14: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x8f8524] 15: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x17e) [0x8f86be] 16: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa66) [0xb69f46] 17: (ThreadPool::WorkThread::entry()+0x10) [0xb6afd0] 18: (()+0x7df3) [0x7f36b74bfdf3] 19: (clone()+0x6d) [0x7f36b5f863dd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. --- begin dump of recent events --- -67> 2014-10-09 06:57:53.779064 7f36863b8700 1 -- 10.143.8.180:6802/42710 <== osd.33 10.143.8.182:6802/14473 581977 ==== osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (622682101 0 0) 0x3870f900 con 0x5b18160 -66> 2014-10-09 06:57:53.779092 7f36863b8700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.778998, event: header_read, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -65> 2014-10-09 06:57:53.779098 7f36863b8700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.779000, event: throttled, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -64> 2014-10-09 06:57:53.779103 7f36863b8700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.779057, event: all_read, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -63> 2014-10-09 06:57:53.779106 7f36863b8700 5 -- op tracker -- seq: 2723808, time: 0.000000, event: dispatched, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -62> 2014-10-09 06:57:53.779143 7f3698a8a700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.779143, event: reached_pg, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -61> 2014-10-09 06:57:53.779153 7f3698a8a700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.779153, event: started, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -60> 2014-10-09 06:57:53.779160 7f3698a8a700 5 -- op tracker -- seq: 2723790, time: 2014-10-09 06:57:53.779160, event: sub_op_commit_rec, op: osd_op(client.6320.0:178628 benchmark_data_ceph001.cubone.os_56195_object178627 [write 0~4197440] 1.3c872e15 ack+ondisk+write+known_if_redirected e112) -59> 2014-10-09 06:57:53.779173 7f3698a8a700 5 -- op tracker -- seq: 2723808, time: 2014-10-09 06:57:53.779173, event: done, op: osd_sub_op_reply(client.6320.0:178628 1.215 3c872e15/benchmark_data_ceph001.cubone.os_56195_object178627/head//1 [] ondisk, result = 0) -58> 2014-10-09 06:57:53.800794 7f369b28f700 1 -- 10.141.8.180:6803/42710 --> 10.141.8.181:6841/47310 -- osd_op_reply(44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] v0'0 uv6099 ondisk = 0) v6 -- ?+0 0x10ae7380 con 0x38c8d800 -57> 2014-10-09 06:57:53.800829 7f369b28f700 5 -- op tracker -- seq: 2723803, time: 2014-10-09 06:57:53.800829, event: done, op: osd_op(osd.29.61:44006 benchmark_data_ceph001.cubone.os_56195_object175083 [assert-version v6099,copy-get max 8390720] 1.4a4ca575 ack+read+ignore_cache+ignore_overlay+flush+map_snap_clone+known_if_redirected e112) -56> 2014-10-09 06:57:53.807924 7f36857ac700 1 -- 10.143.8.180:6802/42710 <== osd.35 10.143.8.182:6806/19867 508005 ==== osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) v11 ==== 1418+0+4198426 (1513685464 0 1087319976) 0x1432ee00 con 0x5b1e880 -55> 2014-10-09 06:57:53.807966 7f36857ac700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.790856, event: header_read, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -54> 2014-10-09 06:57:53.807976 7f36857ac700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.790861, event: throttled, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -53> 2014-10-09 06:57:53.807982 7f36857ac700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.807911, event: all_read, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -52> 2014-10-09 06:57:53.807988 7f36857ac700 5 -- op tracker -- seq: 2723809, time: 0.000000, event: dispatched, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -51> 2014-10-09 06:57:53.808040 7f369a28d700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.808039, event: reached_pg, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -50> 2014-10-09 06:57:53.808076 7f369a28d700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.808075, event: started, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -49> 2014-10-09 06:57:53.808208 7f369a28d700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.808208, event: started, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -48> 2014-10-09 06:57:53.808234 7f369a28d700 5 -- op tracker -- seq: 2723809, time: 2014-10-09 06:57:53.808234, event: commit_queued_for_journal_write, op: osd_sub_op(osd.35.0:1020879 1.343 da990343/benchmark_data_ceph001.cubone.os_28148_object537995/head//1 [] v 112'6305 snapset=0=[]:[] snapc=0=[]) -47> 2014-10-09 06:57:53.811197 7f36a0299700 1 -- 10.141.8.180:6805/42710 <== osd.36 10.141.8.182:6812/22540 31679 ==== osd_op_reply(945771 benchmark_data_ceph001.cubone.os_56195_object174685 [copy-from ver 6226] v112'7406 uv6226 ondisk = 0) v6 ==== 218+0+0 (3965731278 0 0) 0xf2b0dc0 con 0x6fdf900 -46> 2014-10-09 06:57:53.811328 7f3695283700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6802/14755 -- osd_sub_op(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] v 112'6258 snapset=0=[]:[] snapc=0=[]) v11 -- ?+608 0x14329600 con 0x547e9e0 -45> 2014-10-09 06:57:53.811898 7f3695283700 2 filestore(/var/lib/ceph/osd/ceph-1) waiting 51 > 50 ops || 96659760 > 104857600 -44> 2014-10-09 06:57:53.863186 7f36abe9e700 5 -- op tracker -- seq: 2723765, time: 2014-10-09 06:57:53.863185, event: journaled_completion_queued, op: osd_sub_op(osd.17.0:1112917 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6137 snapset=0=[]:[] snapc=0=[]) -43> 2014-10-09 06:57:53.863214 7f36abe9e700 5 -- op tracker -- seq: 2723766, time: 2014-10-09 06:57:53.863214, event: journaled_completion_queued, op: osd_sub_op(osd.19.0:1012080 1.383 f3d8783/benchmark_data_ceph001.cubone.os_28148_object519293/head//1 [] v 112'5503 snapset=0=[]:[] snapc=0=[]) -42> 2014-10-09 06:57:53.863227 7f36abe9e700 5 -- op tracker -- seq: 2723768, time: 2014-10-09 06:57:53.863227, event: journaled_completion_queued, op: osd_sub_op(osd.33.0:1109759 1.36c a71a576c/benchmark_data_ceph001.cubone.os_28148_object537987/head//1 [] v 112'6155 snapset=0=[]:[] snapc=0=[]) -41> 2014-10-09 06:57:53.863237 7f36abe9e700 5 -- op tracker -- seq: 2723767, time: 2014-10-09 06:57:53.863237, event: journaled_completion_queued, op: osd_sub_op(client.6320.0:178618 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6138 snapset=0=[]:[] snapc=0=[]) -40> 2014-10-09 06:57:53.863221 7f36a9699700 5 -- op tracker -- seq: 2723765, time: 2014-10-09 06:57:53.863221, event: commit_sent, op: osd_sub_op(osd.17.0:1112917 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6137 snapset=0=[]:[] snapc=0=[]) -39> 2014-10-09 06:57:53.863262 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6802/14755 -- osd_sub_op_reply(osd.17.0:1112917 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] ondisk, result = 0) v2 -- ?+0 0x1129a100 con 0x547e9e0 -38> 2014-10-09 06:57:53.863294 7f36a9699700 5 -- op tracker -- seq: 2723766, time: 2014-10-09 06:57:53.863294, event: commit_sent, op: osd_sub_op(osd.19.0:1012080 1.383 f3d8783/benchmark_data_ceph001.cubone.os_28148_object519293/head//1 [] v 112'5503 snapset=0=[]:[] snapc=0=[]) -37> 2014-10-09 06:57:53.863304 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6806/20129 -- osd_sub_op_reply(osd.19.0:1012080 1.383 f3d8783/benchmark_data_ceph001.cubone.os_28148_object519293/head//1 [] ondisk, result = 0) v2 -- ?+0 0x1129ca40 con 0x547fd20 -36> 2014-10-09 06:57:53.863318 7f36a9699700 5 -- op tracker -- seq: 2723768, time: 2014-10-09 06:57:53.863318, event: commit_sent, op: osd_sub_op(osd.33.0:1109759 1.36c a71a576c/benchmark_data_ceph001.cubone.os_28148_object537987/head//1 [] v 112'6155 snapset=0=[]:[] snapc=0=[]) -35> 2014-10-09 06:57:53.863329 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.182:6802/14473 -- osd_sub_op_reply(osd.33.0:1109759 1.36c a71a576c/benchmark_data_ceph001.cubone.os_28148_object537987/head//1 [] ondisk, result = 0) v2 -- ?+0 0x387082c0 con 0x5b18160 -34> 2014-10-09 06:57:53.863341 7f36a9699700 5 -- op tracker -- seq: 2723767, time: 2014-10-09 06:57:53.863341, event: commit_sent, op: osd_sub_op(client.6320.0:178618 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] v 112'6138 snapset=0=[]:[] snapc=0=[]) -33> 2014-10-09 06:57:53.864164 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6802/14755 -- osd_sub_op_reply(client.6320.0:178618 1.3a2 cfa553a2/benchmark_data_ceph001.cubone.os_56195_object178617/head//1 [] ondisk, result = 0) v2 -- ?+0 0xa3139c0 con 0x547e9e0 -32> 2014-10-09 06:57:53.865467 7f36ac69f700 5 -- op tracker -- seq: 2723773, time: 2014-10-09 06:57:53.865466, event: write_thread_in_journal_buffer, op: osd_sub_op(osd.35.0:1020877 1.2c1 182fa6c1/benchmark_data_ceph001.cubone.os_28148_object537986/head//1 [] v 112'6315 snapset=0=[]:[] snapc=0=[]) -31> 2014-10-09 06:57:53.865505 7f36ac69f700 5 -- op tracker -- seq: 2723777, time: 2014-10-09 06:57:53.865505, event: write_thread_in_journal_buffer, op: osd_sub_op(osd.17.0:1112923 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6032 snapset=0=[]:[] snapc=0=[]) -30> 2014-10-09 06:57:53.868590 7f36ac69f700 5 -- op tracker -- seq: 2723778, time: 2014-10-09 06:57:53.868589, event: write_thread_in_journal_buffer, op: osd_sub_op(client.6320.0:178621 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6033 snapset=0=[]:[] snapc=0=[]) -29> 2014-10-09 06:57:53.888289 7f368c418700 1 -- 10.143.8.180:6802/42710 <== osd.17 10.143.8.181:6802/14755 498750 ==== osd_sub_op_reply(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] ondisk, result = 0) v2 ==== 189+0+0 (1528745491 0 0) 0xa3139c0 con 0x547e9e0 -28> 2014-10-09 06:57:53.888314 7f368c418700 5 -- op tracker -- seq: 2723810, time: 2014-10-09 06:57:53.888208, event: header_read, op: osd_sub_op_reply(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] ondisk, result = 0) -27> 2014-10-09 06:57:53.888327 7f368c418700 5 -- op tracker -- seq: 2723810, time: 2014-10-09 06:57:53.888212, event: throttled, op: osd_sub_op_reply(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] ondisk, result = 0) -26> 2014-10-09 06:57:53.888332 7f368c418700 5 -- op tracker -- seq: 2723810, time: 2014-10-09 06:57:53.888282, event: all_read, op: osd_sub_op_reply(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] ondisk, result = 0) -25> 2014-10-09 06:57:53.888336 7f368c418700 5 -- op tracker -- seq: 2723810, time: 0.000000, event: dispatched, op: osd_sub_op_reply(osd.1.0:1109995 1.145 17927145/benchmark_data_ceph001.cubone.os_56195_object174685/head//1 [] ondisk, result = 0) -24> 2014-10-09 06:57:53.893861 7f36863b8700 1 -- 10.143.8.180:6802/42710 <== osd.33 10.143.8.182:6802/14473 581978 ==== osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) v11 ==== 1418+0+723 (3974272113 0 4219127927) 0x2cae0000 con 0x5b18160 -23> 2014-10-09 06:57:53.893891 7f36863b8700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.893757, event: header_read, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -22> 2014-10-09 06:57:53.893899 7f36863b8700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.893759, event: throttled, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -21> 2014-10-09 06:57:53.893904 7f36863b8700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.893855, event: all_read, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -20> 2014-10-09 06:57:53.893910 7f36863b8700 5 -- op tracker -- seq: 2723811, time: 0.000000, event: dispatched, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -19> 2014-10-09 06:57:53.893960 7f369928b700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.893959, event: reached_pg, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -18> 2014-10-09 06:57:53.893989 7f369928b700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.893989, event: started, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -17> 2014-10-09 06:57:53.894086 7f369928b700 5 -- op tracker -- seq: 2723811, time: 2014-10-09 06:57:53.894086, event: started, op: osd_sub_op(osd.33.0:1109763 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5923 snapset=0=[]:[] snapc=0=[]) -16> 2014-10-09 06:57:53.894360 7f369928b700 2 filestore(/var/lib/ceph/osd/ceph-1) waiting 51 > 50 ops || 96659978 > 104857600 -15> 2014-10-09 06:57:53.904691 7f36863b8700 1 -- 10.143.8.180:6802/42710 <== osd.33 10.143.8.182:6802/14473 581979 ==== osd_sub_op(client.6320.0:178633 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5924 snapset=0=[]:[] snapc=0=[]) v11 ==== 1418+0+4198183 (2752318958 0 921718436) 0xcb45800 con 0x5b18160 -14> 2014-10-09 06:57:53.904729 7f36863b8700 5 -- op tracker -- seq: 2723812, time: 2014-10-09 06:57:53.895859, event: header_read, op: osd_sub_op(client.6320.0:178633 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5924 snapset=0=[]:[] snapc=0=[]) -13> 2014-10-09 06:57:53.904741 7f36863b8700 5 -- op tracker -- seq: 2723812, time: 2014-10-09 06:57:53.895860, event: throttled, op: osd_sub_op(client.6320.0:178633 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5924 snapset=0=[]:[] snapc=0=[]) -12> 2014-10-09 06:57:53.904750 7f36863b8700 5 -- op tracker -- seq: 2723812, time: 2014-10-09 06:57:53.904681, event: all_read, op: osd_sub_op(client.6320.0:178633 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5924 snapset=0=[]:[] snapc=0=[]) -11> 2014-10-09 06:57:53.904759 7f36863b8700 5 -- op tracker -- seq: 2723812, time: 0.000000, event: dispatched, op: osd_sub_op(client.6320.0:178633 1.a2 3970d4a2/benchmark_data_ceph001.cubone.os_56195_object178632/head//1 [] v 112'5924 snapset=0=[]:[] snapc=0=[]) -10> 2014-10-09 06:57:53.926324 7f36abe9e700 5 -- op tracker -- seq: 2723773, time: 2014-10-09 06:57:53.926323, event: journaled_completion_queued, op: osd_sub_op(osd.35.0:1020877 1.2c1 182fa6c1/benchmark_data_ceph001.cubone.os_28148_object537986/head//1 [] v 112'6315 snapset=0=[]:[] snapc=0=[]) -9> 2014-10-09 06:57:53.926360 7f36abe9e700 5 -- op tracker -- seq: 2723777, time: 2014-10-09 06:57:53.926360, event: journaled_completion_queued, op: osd_sub_op(osd.17.0:1112923 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6032 snapset=0=[]:[] snapc=0=[]) -8> 2014-10-09 06:57:53.926379 7f36abe9e700 5 -- op tracker -- seq: 2723778, time: 2014-10-09 06:57:53.926379, event: journaled_completion_queued, op: osd_sub_op(client.6320.0:178621 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6033 snapset=0=[]:[] snapc=0=[]) -7> 2014-10-09 06:57:53.926373 7f36a9699700 5 -- op tracker -- seq: 2723773, time: 2014-10-09 06:57:53.926373, event: commit_sent, op: osd_sub_op(osd.35.0:1020877 1.2c1 182fa6c1/benchmark_data_ceph001.cubone.os_28148_object537986/head//1 [] v 112'6315 snapset=0=[]:[] snapc=0=[]) -6> 2014-10-09 06:57:53.926405 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.182:6806/19867 -- osd_sub_op_reply(osd.35.0:1020877 1.2c1 182fa6c1/benchmark_data_ceph001.cubone.os_28148_object537986/head//1 [] ondisk, result = 0) v2 -- ?+0 0xa316300 con 0x5b1e880 -5> 2014-10-09 06:57:53.926430 7f36a9699700 5 -- op tracker -- seq: 2723777, time: 2014-10-09 06:57:53.926430, event: commit_sent, op: osd_sub_op(osd.17.0:1112923 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6032 snapset=0=[]:[] snapc=0=[]) -4> 2014-10-09 06:57:53.926444 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6802/14755 -- osd_sub_op_reply(osd.17.0:1112923 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] ondisk, result = 0) v2 -- ?+0 0xa316040 con 0x547e9e0 -3> 2014-10-09 06:57:53.926462 7f36a9699700 5 -- op tracker -- seq: 2723778, time: 2014-10-09 06:57:53.926462, event: commit_sent, op: osd_sub_op(client.6320.0:178621 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] v 112'6033 snapset=0=[]:[] snapc=0=[]) -2> 2014-10-09 06:57:53.926548 7f36a9699700 1 -- 10.143.8.180:6802/42710 --> 10.143.8.181:6802/14755 -- osd_sub_op_reply(client.6320.0:178621 1.248 c2b58248/benchmark_data_ceph001.cubone.os_56195_object178620/head//1 [] ondisk, result = 0) v2 -- ?+0 0xa3123c0 con 0x547e9e0 -1> 2014-10-09 06:57:53.927812 7f36ac69f700 5 -- op tracker -- seq: 2723776, time: 2014-10-09 06:57:53.927812, event: write_thread_in_journal_buffer, op: osd_op(client.6320.0:178622 benchmark_data_ceph001.cubone.os_56195_object178621 [write 0~4197440] 1.1a2234d4 ack+ondisk+write+known_if_redirected e112) 0> 2014-10-09 06:57:53.931184 7f36aae9c700 -1 *** Caught signal (Aborted) ** in thread 7f36aae9c700 ceph version 0.86 (97dcc0539dfa7dac3de74852305d51580b7b1f82) 1: /usr/bin/ceph-osd() [0xa86f92] 2: (()+0xf130) [0x7f36b74c7130] 3: (gsignal()+0x39) [0x7f36b5ec5989] 4: (abort()+0x148) [0x7f36b5ec7098] 5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f36b67d89d5] 6: (()+0x5e946) [0x7f36b67d6946] 7: (()+0x5e973) [0x7f36b67d6973] 8: (()+0x5eb9f) [0x7f36b67d6b9f] 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x27a) [0xb7942a] 10: (FDCache::clear(ghobject_t const&)+0x365) [0x904f55] 11: (FileStore::lfn_unlink(coll_t, ghobject_t const&, SequencerPosition const&, bool)+0x42c) [0x8e570c] 12: (FileStore::_remove(coll_t, ghobject_t const&, SequencerPosition const&)+0x9e) [0x8e58fe] 13: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x2929) [0x8f6009] 14: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x8f8524] 15: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x17e) [0x8f86be] 16: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa66) [0xb69f46] 17: (ThreadPool::WorkThread::entry()+0x10) [0xb6afd0] 18: (()+0x7df3) [0x7f36b74bfdf3] 19: (clone()+0x6d) [0x7f36b5f863dd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
The cluster recovers succesfully after restart of osd
Actions