Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-5117

truncate can race with a truncate being aborted

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Labels:
      None
    • Storage Engines 2019-11-18

      Chasing WT-5078, and saw a failure twice that I think is different.

      Here's the failing stacks:

      Sun Sep  8 16:03:17 UTC 2019: -c CONFIG.5078 iteration 4
[1567959072:302857][54295:0x7f7b2effd700], t, file:wt.wt, WT_SESSION.truncate: __wt_delete_page, 113: ref->page_del->txnid == WT_TXN_ABORTED
[1567959072:302888][54295:0x7f7b2effd700], t, file:wt.wt, WT_SESSION.truncate: __wt_abort, 22: process ID 54295: waiting for debugger...
[1567959072:376507][54295:0x7f7b2a7f4700], t, file:wt.wt, WT_SESSION.truncate: __wt_delete_page, 113: ref->page_del->txnid == WT_TXN_ABORTED
[1567959072:376536][54295:0x7f7b2a7f4700], t, file:wt.wt, WT_SESSION.truncate: __wt_abort, 22: process ID 54295: waiting for debugger...

Thread 22 (Thread 0x7f7b2a7f4700 (LWP 56739)):
#0  0x00007f7b4781c03f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0,
    timeout=0x7f7b2a7f3a60) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x000055880fa2720e in __wt_sleep (seconds=100, micro_seconds=0) at src/os_posix/os_sleep.c:30
#2  0x000055880fa1de21 in __wt_abort (session=0x7f7b48963540) at src/os_common/os_abort.c:26
#3  0x000055880fabdeab in __wt_delete_page (session=0x7f7b48963540, ref=0x558816989ac0,
    skipp=0x7f7b2a7f3b51) at src/btree/bt_delete.c:113
#4  0x000055880fafe208 in __tree_walk_internal (session=0x7f7b48963540, refp=0x7f7a880d0508,
    walkcntp=0x0, skip_func=0x0, func_cookie=0x0, flags=6274) at src/btree/bt_walk.c:486
#5  0x000055880fafe568 in __wt_tree_walk (session=0x7f7b48963540, refp=0x7f7a880d0508, flags=6272)
    at src/btree/bt_walk.c:572
#6  0x000055880fba001a in __wt_btcur_next (cbt=0x7f7a880d0390, truncating=true)
    at src/btree/bt_curnext.c:689
#7  0x000055880fabb3c5 in __cursor_truncate (session=0x7f7b48963540, start=0x7f7a880d0390,
    stop=0x7f7a895d6410, rmfunc=0x55880fab7880 <__cursor_row_modify>) at src/btree/bt_cursor.c:1676
#8  0x000055880fabb73d in __wt_btcur_range_truncate (start=0x7f7a880d0390, stop=0x7f7a895d6410)
    at src/btree/bt_cursor.c:1795
#9  0x000055880fb956dd in __wt_schema_range_truncate (session=0x7f7b48963540,
    start=0x7f7a880d0390, stop=0x7f7a895d6410) at src/schema/schema_truncate.c:141
#10 0x000055880fa59a42 in __wt_session_range_truncate (session=0x7f7b48963540, uri=0x0,
    start=0x7f7a880d0390, stop=0x7f7a895d6410) at src/session/session_api.c:1417
#11 0x000055880fa5a415 in __session_truncate (wt_session=0x7f7b48963540, uri=0x0,
    start=0x7f7a880d0390, stop=0x7f7a895d6410, config=0x0) at src/session/session_api.c:1488
#12 0x000055880f9b6428 in row_truncate (tinfo=0x55881ab231a0, cursor=0x7f7a880d0390) at ops.c:1443
#13 0x000055880f9b4376 in ops (arg=0x55881ab231a0) at ops.c:879
#14 0x00007f7b481556db in start_thread (arg=0x7f7b2a7f4700) at pthread_create.c:463
#15 0x00007f7b4782688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 13 (Thread 0x7f7b2effd700 (LWP 56730)):
#0  0x00007f7b4781c03f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0,
    timeout=0x7f7b2effca60) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x000055880fa2720e in __wt_sleep (seconds=100, micro_seconds=0) at src/os_posix/os_sleep.c:30
#2  0x000055880fa1de21 in __wt_abort (session=0x7f7b48968040) at src/os_common/os_abort.c:26
#3  0x000055880fabdeab in __wt_delete_page (session=0x7f7b48968040, ref=0x558817229730,
    skipp=0x7f7b2effcb51) at src/btree/bt_delete.c:113
#4  0x000055880fafe208 in __tree_walk_internal (session=0x7f7b48968040, refp=0x7f7ab04086b8,
    walkcntp=0x0, skip_func=0x0, func_cookie=0x0, flags=6274) at src/btree/bt_walk.c:486
#5  0x000055880fafe568 in __wt_tree_walk (session=0x7f7b48968040, refp=0x7f7ab04086b8, flags=6272)
    at src/btree/bt_walk.c:572
#6  0x000055880fba001a in __wt_btcur_next (cbt=0x7f7ab0408540, truncating=true)
    at src/btree/bt_curnext.c:689
#7  0x000055880fabb3c5 in __cursor_truncate (session=0x7f7b48968040, start=0x7f7ab0408540,
    stop=0x7f7ab015ba50, rmfunc=0x55880fab7880 <__cursor_row_modify>) at src/btree/bt_cursor.c:1676
#8  0x000055880fabb73d in __wt_btcur_range_truncate (start=0x7f7ab0408540, stop=0x7f7ab015ba50)
    at src/btree/bt_cursor.c:1795
#9  0x000055880fb956dd in __wt_schema_range_truncate (session=0x7f7b48968040,
    start=0x7f7ab0408540, stop=0x7f7ab015ba50) at src/schema/schema_truncate.c:141
#10 0x000055880fa59a42 in __wt_session_range_truncate (session=0x7f7b48968040, uri=0x0,
    start=0x7f7ab0408540, stop=0x7f7ab015ba50) at src/session/session_api.c:1417
#11 0x000055880fa5a415 in __session_truncate (wt_session=0x7f7b48968040, uri=0x0,
    start=0x7f7ab0408540, stop=0x7f7ab015ba50, config=0x0) at src/session/session_api.c:1488
#12 0x000055880f9b6428 in row_truncate (tinfo=0x558813d42fd0, cursor=0x7f7ab0408540) at ops.c:1443
#13 0x000055880f9b4376 in ops (arg=0x558813d42fd0) at ops.c:879
#14 0x00007f7b481556db in start_thread (arg=0x7f7b2effd700) at pthread_create.c:463
#15 0x00007f7b4782688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

      I think the two stacks occurred independently, I don't see any relationship between them, they're different WT_REFs, truncating ranges that are disjoint. They are both, however, failing in the aftermath of txnID=18446744073709551615, that is, they're seeing problems with objects deleted by the same transaction.

      (gdb) thread 13
[Switching to thread 13 (Thread 0x7f7b2effd700 (LWP 56730))]
#0  0x00007f7b4781c03f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, 
    timeout=0x7f7b2effca60) at ../sysdeps/unix/sysv/linux/select.c:41
41	in ../sysdeps/unix/sysv/linux/select.c
(gdb) frame 3
#3  0x000055880fabdeab in __wt_delete_page (session=0x7f7b48968040, ref=0x558817229730, 
    skipp=0x7f7b2effcb51) at src/btree/bt_delete.c:113
113	        WT_ASSERT(session, ref->page_del->txnid == WT_TXN_ABORTED);
(gdb) p *ref
$14 = {
  page = 0x0, 
  home = 0x558812c2b390, 
  pindex_hint = 4, 
  state = 3, 
  addr = 0x5588172298a5, 
  key = {
    recno = 64424509741, 
    ikey = 0xf0000012d
  }, 
  page_del = 0x7f7af80acb90, 
  page_las = 0x0, 
  hist = {{
      session = 0x7f7b48968040, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4290 <__func__.36683> "__wt_delete_page", 
      time_sec = 1567959072, 
      line = 101, 
      state = 3
    }, {
      session = 0x7f7b48961dd0, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4390 <__func__.36703> "__wt_delete_page_rollback", 
      time_sec = 1567959072, 
      line = 189, 
      state = 0
    }, {
      session = 0x7f7b48961dd0, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4290 <__func__.36683> "__wt_delete_page", 
      time_sec = 1567959072, 
      line = 155, 
      state = 1
    }}, 
  histoff = 2
}
(gdb) p *ref.page_del
$15 = {
  txnid = 18446744073709551615, 
  timestamp = 0, 
  durable_timestamp = 0, 
  prepare_state = 0 '\000', 
  previous_state = 0, 
  update_list = 0x0
}

(gdb) thread 22
[Switching to thread 22 (Thread 0x7f7b2a7f4700 (LWP 56739))]
#0  0x00007f7b4781c03f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, 
    timeout=0x7f7b2a7f3a60) at ../sysdeps/unix/sysv/linux/select.c:41
41	in ../sysdeps/unix/sysv/linux/select.c
(gdb) frame 3
#3  0x000055880fabdeab in __wt_delete_page (session=0x7f7b48963540, ref=0x558816989ac0, 
    skipp=0x7f7b2a7f3b51) at src/btree/bt_delete.c:113
113	        WT_ASSERT(session, ref->page_del->txnid == WT_TXN_ABORTED);
(gdb) p *ref
$16 = {
  page = 0x0, 
  home = 0x558818098770, 
  pindex_hint = 18, 
  state = 3, 
  addr = 0x55881800866d, 
  key = {
    recno = 81604379829, 
    ikey = 0x13000004b5
  }, 
  page_del = 0x7f7acc0e96c0, 
  page_las = 0x0, 
  hist = {{
      session = 0x7f7b48963540, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4290 <__func__.36683> "__wt_delete_page", 
      time_sec = 1567959072, 
      line = 101, 
      state = 3
    }, {
      session = 0x7f7b48965f70, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4390 <__func__.36703> "__wt_delete_page_rollback", 
      time_sec = 1567959072, 
      line = 189, 
      state = 0
    }, {
      session = 0x7f7b48965f70, 
      name = 0x55880fbc50dc "WT_SESSION.truncate", 
      func = 0x55880fbd4290 <__func__.36683> "__wt_delete_page", 
      time_sec = 1567959072, 
      line = 155, 
      state = 1
    }}, 
  histoff = 2
}
(gdb) p *ref.page_del
$17 = {
  txnid = 18446744073709551615, 
  timestamp = 0, 
  durable_timestamp = 0, 
  prepare_state = 0 '\000', 
  previous_state = 0, 
  update_list = 0x0
}

      Here's the CONFIG (copied from WT-5078).

      ############################################
#  RUN PARAMETERS
############################################
abort=0
alter=0
assert_commit_timestamp=1
assert_read_timestamp=0
auto_throttle=1
backups=1
bitcnt=7
bloom=1
bloom_bit_count=5
bloom_hash_count=28
bloom_oldest=0
cache=620
cache_minimum=20
checkpoints=wiredtiger
checkpoint_log_size=71
checkpoint_wait=59
checksum=on
chunk_size=10
compaction=0
compression=none
data_extend=0
data_source=table
delete_pct=33
dictionary=0
direct_io=0
encryption=none
evict_max=2
file_type=row-store
firstfit=0
huffman_key=0
huffman_value=0
independent_thread_rng=0
in_memory=0
insert_pct=25
internal_key_truncation=1
internal_page_max=12
isolation=snapshot
key_gap=5
key_max=28
key_min=14
leaf_page_max=10
leak_memory=0
logging=0
logging_archive=0
logging_compression=none
logging_file_max=436785
logging_prealloc=1
long_running_txn=0
lsm_worker_threads=3
memory_page_max=10
merge_max=15
mmap=1
modify_pct=22
ops=0
prefix_compression=0
prefix_compression_min=1
prepare=0
quiet=1
read_pct=16
rebalance=1
repeat_data_pct=27
reverse=1
rows=1000000
runs=1
salvage=1
split_pct=98
statistics=0
statistics_server=0
threads=31
timer=4
timing_stress_aggressive_sweep=0
timing_stress_checkpoint=0
timing_stress_lookaside_sweep=0
timing_stress_split_1=0
timing_stress_split_2=0
timing_stress_split_3=0
timing_stress_split_4=0
timing_stress_split_5=0
timing_stress_split_6=0
timing_stress_split_7=0
timing_stress_split_8=0
transaction_timestamps=1
transaction-frequency=100
truncate=1
value_max=883
value_min=2
verify=1
wiredtiger_config=
write_pct=4
############################################

        1. wt.5117.diff
          3 kB

            Assignee:
            keith.bostic@mongodb.com Keith Bostic (Inactive)
            Reporter:
            keith.bostic@mongodb.com Keith Bostic (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: