Actions
Bug #41145
closedosd: bad alloc exception
% Done:
0%
Source:
Q/A
Tags:
Backport:
nautilus,mimic
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
OSD
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
-106> 2019-08-06T15:57:35.909+0000 7f81dea85700 1 -- [v2:172.21.15.133:6814/11501,v1:172.21.15.133:6817/11501] <== mds.0 v2:172.21.15.174:6832/3226542569 53 ==== osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8 ==== 229+0+0 (crc 0 0 0) 0x560165fe2900 con 0x560168bc9180 -105> 2019-08-06T15:57:35.909+0000 7f81dea85700 15 osd.6 190 enqueue_op 0x560176848520 prio 63 cost 0 latency 0.000019 epoch 190 osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8 -104> 2019-08-06T15:57:35.909+0000 7f81dea85700 20 osd.6 op_wq(1) _enqueue OpQueueItem(3.1 PGOpItem(op=osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8) prio 63 cost 0 e190) -103> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 op_wq(1) _process 3.1 to_process <> waiting <> waiting_peering {} -102> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 op_wq(1) _process OpQueueItem(3.1 PGOpItem(op=osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8) prio 63 cost 0 e190) queued -101> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 op_wq(1) _process 3.1 to_process <OpQueueItem(3.1 PGOpItem(op=osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8) prio 63 cost 0 e190)> waiting <> waiting_peering {} -100> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 op_wq(1) _process OpQueueItem(3.1 PGOpItem(op=osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8) prio 63 cost 0 e190) pg 0x5601647fe000 -99> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 190 dequeue_op 0x560176848520 prio 63 cost 0 latency 0.000063 osd_op(mds.0.648:12333 3.1 3.54a88471 (undecoded) ondisk+write+known_if_redirected+full_force e190) v8 pg pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] -98> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] _handle_message: 0x560176848520 -97> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_op: op osd_op(mds.0.648:12333 3.1 3:8e21152a:::1000000e7e6.00000000:head [delete] snapc 27d=[] ondisk+write+known_if_redirected+full_force e190) v8 -96> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] op_has_sufficient_caps session=0x56016d3ab640 pool=3 (cephfs_data ) pool_app_metadata={cephfs={data=cephfs}} need_read_cap=0 need_write_cap=1 classes=[] -> yes -95> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_op osd_op(mds.0.648:12333 3.1 3:8e21152a:::1000000e7e6.00000000:head [delete] snapc 27d=[] ondisk+write+known_if_redirected+full_force e190) v8 may_write -> write-ordered flags ondisk+write+known_if_redirected+full_force -94> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] get_object_context: obc NOT found in cache: 3:8e21152a:::1000000e7e6.00000000:head -93> 2019-08-06T15:57:35.909+0000 7f81bdfca700 15 bluestore(/var/lib/ceph/osd/ceph-6) getattr 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# _ -92> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) getattr 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# _ = 0 -91> 2019-08-06T15:57:35.909+0000 7f81bdfca700 15 bluestore(/var/lib/ceph/osd/ceph-6) getattr 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# snapset -90> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) getattr 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# snapset = 0 -89> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] populate_obc_watchers 3:8e21152a:::1000000e7e6.00000000:head -88> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] PrimaryLogPG::check_blacklisted_obc_watchers for obc 3:8e21152a:::1000000e7e6.00000000:head -87> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] get_object_context: creating obc from disk: 0x560178ac3080 -86> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] get_object_context: 0x560178ac3080 3:8e21152a:::1000000e7e6.00000000:head rwstate(none n=0 w=0) oi: 3:8e21152a:::1000000e7e6.00000000:head(180'26113 mds.0.601:1371 dirty|data_digest s 11427 uv 26113 dd e0b53614 alloc_hint [0 0 0]) exists: 1 ssc: 0x560176f3af20 snapset: 27c=[]:{} -85> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] find_object_context 3:8e21152a:::1000000e7e6.00000000:head @head oi=3:8e21152a:::1000000e7e6.00000000:head(180'26113 mds.0.601:1371 dirty|data_digest s 11427 uv 26113 dd e0b53614 alloc_hint [0 0 0]) -84> 2019-08-06T15:57:35.909+0000 7f81bdfca700 25 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_op oi 3:8e21152a:::1000000e7e6.00000000:head(180'26113 mds.0.601:1371 dirty|data_digest s 11427 uv 26113 dd e0b53614 alloc_hint [0 0 0]) -83> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_op obc obc(3:8e21152a:::1000000e7e6.00000000:head rwstate(write n=1 w=0)) -82> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] execute_ctx 0x5601795a2900 -81> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] execute_ctx 3:8e21152a:::1000000e7e6.00000000:head [delete] ov 180'26113 av 190'40294 snapc 27d=[] snapset 27c=[]:{} -80> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_osd_op 3:8e21152a:::1000000e7e6.00000000:head [delete] -79> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] do_osd_op delete -78> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] _delete_oid 3:8e21152a:::1000000e7e6.00000000:head whiteout=0 no_whiteout=0 try_no_whiteout=0 -77> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] make_writeable 3:8e21152a:::1000000e7e6.00000000:head snapset=27c=[]:{} snapc=27d=[] -76> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] deletion, decrementing num_dirty and clearing flag -75> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] make_writeable 3:8e21152a:::1000000e7e6.00000000:head done, snapset=27d=[]:{} -74> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] finish_ctx 3:8e21152a:::1000000e7e6.00000000:head 0x5601795a2900 op delete -73> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] finish_ctx object 3:8e21152a:::1000000e7e6.00000000:head marks clean_regions clean_offsets: [11427~18446744073709540188], clean_omap: 0, object_new: 0 -72> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] zeroing write result code 0 -71> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] calc_trim_to_aggressive limit = 190'40293 -70> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] calc_trim_to_aggressive approx pg log length = 3029 -69> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] calc_trim_to_aggressive num_to_trim = 29 -68> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] new_repop rep_tid 61126 on osd_op(mds.0.648:12333 3.1 3:8e21152a:::1000000e7e6.00000000:head [delete] snapc 27d=[] ondisk+write+known_if_redirected+full_force e190) v8 -67> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] new_repop: repgather(0x5601781e3680 0'0 rep_tid=61126 committed?=0 r=0) -66> 2019-08-06T15:57:35.909+0000 7f81bdfca700 7 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=139 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] issue_repop rep_tid 61126 o 3:8e21152a:::1000000e7e6.00000000:head -65> 2019-08-06T15:57:35.909+0000 7f81bdfca700 1 -- [v2:172.21.15.133:6820/11501,v1:172.21.15.133:6821/11501] --> [v2:172.21.15.174:6808/11232,v1:172.21.15.174:6810/11232] -- osd_repop(mds.0.648:12333 3.1 e190/20 3:8e21152a:::1000000e7e6.00000000:head v 190'40294) v2 -- 0x560176a83800 con 0x5601646a0880 -64> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 earliest_dup_version = 37295 -63> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 trim 190'40294 (180'26113) delete 3:8e21152a:::1000000e7e6.00000000:head by mds.0.648:12333 2019-08-06T15:57:35.912072+0000 0 ObjectCleanRegions clean_offsets: [11427~18446744073709540188], clean_omap: 0, object_new: 0 -62> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 trim dup log_dup(reqid=mds.0.624:5315 v=186'37294 uv=37294 rc=0) -61> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40293 (186'37264,190'40293] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] append_log log((186'37264,190'40293], crt=190'40293) [190'40294 (180'26113) delete 3:8e21152a:::1000000e7e6.00000000:head by mds.0.648:12333 2019-08-06T15:57:35.912072+0000 0 ObjectCleanRegions clean_offsets: [11427~18446744073709540188], clean_omap: 0, object_new: 0] -60> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 lua=190'40293 crt=190'40293 lcod 190'40291 mlcod 190'40291 active+clean] add_log_entry 190'40294 (180'26113) delete 3:8e21152a:::1000000e7e6.00000000:head by mds.0.648:12333 2019-08-06T15:57:35.912072+0000 0 ObjectCleanRegions clean_offsets: [11427~18446744073709540188], clean_omap: 0, object_new: 0 -59> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 lua=190'40293 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] rollforward: entry=190'40294 (180'26113) delete 3:8e21152a:::1000000e7e6.00000000:head by mds.0.648:12333 2019-08-06T15:57:35.912072+0000 0 ObjectCleanRegions clean_offsets: [11427~18446744073709540188], clean_omap: 0, object_new: 0 -58> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 lua=190'40293 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] append_log approx pg log length = 3030 -57> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 lua=190'40293 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] append_log transaction_applied = 1 -56> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 trim proposed trim_to = 186'37264 -55> 2019-08-06T15:57:35.909+0000 7f81bdfca700 6 write_log_and_missing with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, writeout_from: 190'40294, trimmed: , trimmed_dups: , clear_divergent_priors: 0 -54> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) queue_transactions ch 0x5601647cab40 3.1_head -53> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _txc_create osr 0x56016480c000 = 0x5601649e7500 seq 31330 -52> 2019-08-06T15:57:35.909+0000 7f81bdfca700 15 bluestore(/var/lib/ceph/osd/ceph-6) _remove 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# onode 0x56017bf23e40 txc 0x5601649e7500 -51> 2019-08-06T15:57:35.909+0000 7f81bdfca700 15 bluestore(/var/lib/ceph/osd/ceph-6) _do_truncate 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# 0x0 -50> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.blob(0x56017d154c30) put_ref 0x0~2ca3 Blob(0x56017d154c30 blob([0x20cc0000~4000] csum+has_unused crc32c/0x1000 unused=0xf000) use_tracker(0x4000 0x2ca3) SharedBlob(0x56017d154ca0 sbid 0x0)) -49> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.extentmap(0x56017bf23f90) dirty_range mark inline shard dirty -48> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _wctx_finish lex_old 0x0~2ca3: 0x0~2ca3 Blob(0x56017d154c30 blob([!~4000] csum+has_unused crc32c/0x1000 unused=0xf000) use_tracker(0x4000 0x0) SharedBlob(0x56017d154ca0 sbid 0x0)) -47> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _wctx_finish blob release [0x20cc0000~4000] -46> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.blob(0x56017d154c30) discard_unallocated 0x0~4000 -45> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.BufferSpace(0x56017d154cb8 in 0x56016131ac40) _discard 0x0~4000 -44> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _wctx_finish release 0x20cc0000~4000 -43> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.sharedblob(0x56017d154ca0) put 0x56017d154ca0 removing self from set 0x5601647cac10 -42> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore.BufferSpace(0x56017d154cb8 in 0x56016131ac40) _clear -41> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) _remove 3.1_head #3:8e21152a:::1000000e7e6.00000000:head# = 0 -40> 2019-08-06T15:57:35.909+0000 7f81bdfca700 15 bluestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 3.1_head #3:80000000::::head# -39> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 0x0000000000000432'.0000000190.00000000000000040294' <- 0000000190.00000000000000040294 -38> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 0x0000000000000432'._fastinfo' <- _fastinfo -37> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 3.1_head #3:80000000::::head# = 0 -36> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) _txc_calc_cost 0x5601649e7500 cost 4778 (1 ios * 4000 + 778 bytes) -35> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _txc_write_nodes txc 0x5601649e7500 onodes shared_blobs -34> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _txc_finalize_kv txc 0x5601649e7500 allocated 0x[] released 0x[20cc0000~4000] -33> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _txc_finalize_kv release 0x20cc0000~4000 -32> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 freelist release 0x20cc0000~4000 -31> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 freelist _xor first_key 0x20c00000 last_key 0x20c00000 -30> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) _txc_state_proc txc 0x5601649e7500 prepare -29> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 bluestore(/var/lib/ceph/osd/ceph-6) _txc_finish_io 0x5601649e7500 -28> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 bluestore(/var/lib/ceph/osd/ceph-6) _txc_state_proc txc 0x5601649e7500 io_done -27> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 lua=190'40293 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] op_applied version 190'40294 -26> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] eval_repop repgather(0x5601781e3680 190'40294 rep_tid=61126 committed?=0 r=0) -25> 2019-08-06T15:57:35.909+0000 7f81bdfca700 10 osd.6 190 dequeue_op 0x560176848520 finish -24> 2019-08-06T15:57:35.909+0000 7f81bdfca700 20 osd.6 op_wq(1) _process empty q, waiting -23> 2019-08-06T15:57:35.909+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -22> 2019-08-06T15:57:35.909+0000 7f81dea85700 1 -- [v2:172.21.15.133:6820/11501,v1:172.21.15.133:6821/11501] <== osd.2 v2:172.21.15.174:6808/11232 62024 ==== osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2 ==== 111+0+0 (crc 0 0 0) 0x560165a641c0 con 0x5601646a0880 -21> 2019-08-06T15:57:35.909+0000 7f81dea85700 15 osd.6 190 enqueue_op 0x560178d54d60 prio 196 cost 0 latency 0.000060 epoch 190 osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2 -20> 2019-08-06T15:57:35.909+0000 7f81dea85700 20 osd.6 op_wq(1) _enqueue OpQueueItem(3.1 PGOpItem(op=osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2) prio 196 cost 0 e190) -19> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 20 osd.6 op_wq(1) _process 3.1 to_process <> waiting <> waiting_peering {} -18> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 20 osd.6 op_wq(1) _process OpQueueItem(3.1 PGOpItem(op=osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2) prio 196 cost 0 e190) queued -17> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 20 osd.6 op_wq(1) _process 3.1 to_process <OpQueueItem(3.1 PGOpItem(op=osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2) prio 196 cost 0 e190)> waiting <> waiting_peering {} -16> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 20 osd.6 op_wq(1) _process OpQueueItem(3.1 PGOpItem(op=osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2) prio 196 cost 0 e190) pg 0x5601647fe000 -15> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 10 osd.6 190 dequeue_op 0x560178d54d60 prio 196 cost 0 latency 0.000114 osd_repop_reply(mds.0.648:12333 3.1 e190/20) v2 pg pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] -14> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 10 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] _handle_message: 0x560178d54d60 -13> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 7 osd.6 pg_epoch: 190 pg[3.1( v 190'40294 (186'37264,190'40294] local-lis/les=20/21 n=138 ec=20/20 lis/c=20/20 les/c/f=21/21/0 sis=20) [6,2] r=0 lpr=20 luod=190'40292 crt=190'40294 lcod 190'40291 mlcod 190'40291 active+clean] do_repop_reply: tid 61126 op ack_type 4 from 2 -12> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 10 osd.6 190 dequeue_op 0x560178d54d60 finish -11> 2019-08-06T15:57:35.909+0000 7f81c1fd2700 20 osd.6 op_wq(1) _process empty q, waiting -10> 2019-08-06T15:57:35.961+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -9> 2019-08-06T15:57:36.009+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -8> 2019-08-06T15:57:36.061+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -7> 2019-08-06T15:57:36.109+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -6> 2019-08-06T15:57:36.161+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -5> 2019-08-06T15:57:36.209+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -4> 2019-08-06T15:57:36.261+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -3> 2019-08-06T15:57:36.309+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -2> 2019-08-06T15:57:36.361+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 -1> 2019-08-06T15:57:36.409+0000 7f81d27f3700 20 bluestore.MempoolThread(0x56016139cb58) _resize_shards cache_size: 2845415832 kv_alloc: 1056964608 kv_used: 10275392 meta_alloc: 1107296256 meta_used: 58895075 data_alloc: 654311424 data_used: 0 0> 2019-08-06T15:57:36.417+0000 7f81d37f5700 -1 *** Caught signal (Aborted) ** in thread 7f81d37f5700 thread_name:bstore_kv_sync ceph version 15.0.0-3536-g313cd11 (313cd11e28c5578822a5fc1eca9edf6c5ef2aafe) octopus (dev) 1: (()+0x12890) [0x7f81e130d890] 2: (gsignal()+0xc7) [0x7f81dffbfe97] 3: (abort()+0x141) [0x7f81dffc1801] 4: (()+0x8c957) [0x7f81e09b4957] 5: (()+0x92ab6) [0x7f81e09baab6] 6: (()+0x92af1) [0x7f81e09baaf1] 7: (()+0x92d24) [0x7f81e09bad24] 8: (()+0x1424b) [0x7f81e1e1824b] 9: (tc_new()+0x283) [0x7f81e1e39943] 10: (rocksdb::Arena::AllocateNewBlock(unsigned long)+0x4e) [0x560156c57586] 11: (rocksdb::Arena::AllocateFallback(unsigned long, bool)+0xcb) [0x560156c57173] 12: (rocksdb::Arena::AllocateAligned(unsigned long, unsigned long, rocksdb::Logger*)+0x1c2) [0x560156c574fe] 13: (rocksdb::ConcurrentArena::AllocateAligned(unsigned long, unsigned long, rocksdb::Logger*)::{lambda()#1}::operator()() const+0x37) [0x560156aef6ad] 14: (char* rocksdb::ConcurrentArena::AllocateImpl<rocksdb::ConcurrentArena::AllocateAligned(unsigned long, unsigned long, rocksdb::Logger*)::{lambda()#1}>(unsigned long, bool, rocksdb::ConcurrentArena::AllocateAligned(unsigned long, unsigned long, rocksdb::Logger*)::{lambda()#1} const&)+0x14c) [0x560156af1774] 15: (rocksdb::ConcurrentArena::AllocateAligned(unsigned long, unsigned long, rocksdb::Logger*)+0xbd) [0x560156aef76d] 16: (rocksdb::InlineSkipList<rocksdb::MemTableRep::KeyComparator const&>::AllocateNode(unsigned long, int)+0x58) [0x560156b99632] 17: (rocksdb::InlineSkipList<rocksdb::MemTableRep::KeyComparator const&>::AllocateKey(unsigned long)+0x31) [0x560156b98f7b] 18: (()+0x1587e85) [0x560156b97e85] 19: (rocksdb::MemTable::Add(unsigned long, rocksdb::ValueType, rocksdb::Slice const&, rocksdb::Slice const&, bool, rocksdb::MemTablePostProcessInfo*)+0x126) [0x560156aebec4] 20: (rocksdb::MemTableInserter::PutCFImpl(unsigned int, rocksdb::Slice const&, rocksdb::Slice const&, rocksdb::ValueType)+0x314) [0x560156b84968] 21: (rocksdb::MemTableInserter::PutCF(unsigned int, rocksdb::Slice const&, rocksdb::Slice const&)+0x4e) [0x560156b850fa] 22: (rocksdb::WriteBatch::Iterate(rocksdb::WriteBatch::Handler*) const+0x44c) [0x560156b7eba6] 23: (rocksdb::WriteBatchInternal::InsertInto(rocksdb::WriteThread::WriteGroup&, unsigned long, rocksdb::ColumnFamilyMemTables*, rocksdb::FlushScheduler*, bool, unsigned long, rocksdb::DB*, bool, bool, bool)+0x21b) [0x560156b81efb] 24: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool, unsigned long*, unsigned long, rocksdb::PreReleaseCallback*)+0x14a5) [0x560156a3813b] 25: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x59) [0x560156a36bfb] 26: (RocksDBStore::submit_common(rocksdb::WriteOptions&, std::shared_ptr<KeyValueDB::TransactionImpl>)+0x81) [0x5601569b6061] 27: (RocksDBStore::submit_transaction(std::shared_ptr<KeyValueDB::TransactionImpl>)+0x8e) [0x5601569b689e] 28: (BlueStore::_kv_sync_thread()+0x101c) [0x5601564ed37c] 29: (BlueStore::KVSyncThread::entry()+0xd) [0x56015651216d] 30: (()+0x76db) [0x7f81e13026db] 31: (clone()+0x3f) [0x7f81e00a288f] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
From: /ceph/teuthology-archive/pdonnell-2019-08-06_02:42:23-fs-wip-pdonnell-testing-20190805.224801-distro-basic-smithi/4187159/remote/smithi133/log/ceph-osd.6.log.gz
corresponding MDS log:
2019-08-06T15:57:35.907+0000 7f1583a22700 20 mds.0.purge_queue _consume: decoding entry 2019-08-06T15:57:35.907+0000 7f1583a22700 20 mds.0.purge_queue _consume: executing item (0x1000000e7e6) 2019-08-06T15:57:35.907+0000 7f1583a22700 10 mds.0.purge_queue _execute_item: 0~11427 objects 0~1 snapc 27d=[] on 0x1000000e7e6 2019-08-06T15:57:35.907+0000 7f1583a22700 1 -- [v2:172.21.15.174:6832/3226542569,v1:172.21.15.174:6833/3226542569] --> [v2:172.21.15.133:6814/11501,v1:172.21.15.133:6817/11501] -- osd_op(unknown.0.648:12333 3.1 3:8e21152a:::1000000e7e6.00000000:head [delete] snapc 27d=[] ondisk+write+known_if_redirected+full_force e190) v8 -- 0x5580f6bf3800 con 0x5580f68c8480
From: /ceph/teuthology-archive/pdonnell-2019-08-06_02:42:23-fs-wip-pdonnell-testing-20190805.224801-distro-basic-smithi/4187159/remote/smithi174/log/ceph-mds.a.log.gz
Actions