Project

General

Profile

Bug #9711

'cache' osd crash on ceph 0.86

Added by Kenneth Waegeman over 9 years ago. Updated over 9 years ago.

Status:
Duplicate
Priority:
Normal
Assignee:
-
Category:
OSD
Target version:
-
% Done:

0%

Source:
Community (user)
Tags:
Backport:
Regression:
No
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


Related issues

Duplicates Ceph - Bug #9480: OSD is crashing while object deletion Resolved 09/15/2014

History

#1 Updated by Loïc Dachary over 9 years ago

  • Status changed from New to Duplicate

Also available in: Atom PDF