Bug #41145: osd: bad alloc exception - RADOS - Ceph

Actions

Copy link

Bug #41145

closed

osd: bad alloc exception

Added by Patrick Donnelly over 4 years ago. Updated over 4 years ago.

Status:

Duplicate

Priority:

Urgent

Assignee:

Category:

Target version:

Ceph - v15.0.0

% Done:

Source:

Q/A

Tags:

Backport:

nautilus,mimic

Regression:

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

Related issues 1 (0 open — 1 closed)