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

test/format stress assertion failure: state == WT_CHILD_MODIFIED

    • Type: Icon: Task Task
    • Resolution: Done
    • WT2.5.1
    • Affects Version/s: None
    • Component/s: None
    • Labels:

      http://build.wiredtiger.com:8080/job/wiredtiger-test-format-stress/6045

      On tinderbox, I unpacked the tarball in ~jenkins/stress.6045.

        50: file, variable-length column-store
      [1420229849:916566][30371:0x7f6d8ffff700], t, file:wt, session.checkpoint: ../src/reconcile/rec_write.c, 3202: state == WT_CHILD_MODIFIED
      

      The stack and other useful structures:

      WT-3  0x0000000000465684 in __wt_assert (session=0x101d600, error=0, file_name=0x678833 "../src/reconcile/rec_write.c", line_number=3202, fmt=0x67868a "%s")
          at ../src/support/err.c:447
      WT-4  0x000000000044f50b in __rec_col_int (session=0x101d600, r=0x7f6cf438c6e0, page=0x105b710) at ../src/reconcile/rec_write.c:3202
      WT-5  0x0000000000449fa1 in __wt_reconcile (session=0x101d600, ref=0x105b6d0, salvage=0x0, flags=0) at ../src/reconcile/rec_write.c:400
      WT-6  0x000000000048f57d in __sync_file (session=0x101d600, syncop=1) at ../src/btree/bt_sync.c:135
      WT-7  0x000000000048f79d in __wt_cache_op (session=0x101d600, ckptbase=0x7f6cf43035f0, op=1) at ../src/btree/bt_sync.c:222
      WT-8  0x000000000046ed3a in __checkpoint_worker (session=0x101d600, cfg=0x7f6d8fffed80, is_checkpoint=1) at ../src/txn/txn_ckpt.c:886
      WT-9  0x000000000046efb2 in __wt_checkpoint (session=0x101d600, cfg=0x7f6d8fffed80) at ../src/txn/txn_ckpt.c:951
      WT-10 0x000000000046cfd2 in __checkpoint_apply (session=0x101d600, cfg=0x7f6d8fffed80, op=0x46ef0b <__wt_checkpoint>) at ../src/txn/txn_ckpt.c:183
      WT-11 0x000000000046db47 in __wt_txn_checkpoint (session=0x101d600, cfg=0x7f6d8fffed80) at ../src/txn/txn_ckpt.c:403
      WT-12 0x0000000000462346 in __session_checkpoint (wt_session=0x101d600, config=0x7f6d8fffede0 "name=thread-3") at ../src/session/session_api.c:895
      WT-13 0x000000000040ff96 in ops (arg=0x1085d90) at ../../../test/format/ops.c:341
      WT-14 0x0000003f17e07ee5 in start_thread (arg=0x7f6d8ffff700) at pthread_create.c:309
      WT-3  0x0000000000465684 in __wt_assert (session=0x101d600, error=0, file_name=0x678833 "../src/reconcile/rec_write.c", line_number=3202, fmt=0x67868a "%s")
          at ../src/support/err.c:447
      WT-4  0x000000000044f50b in __rec_col_int (session=0x101d600, r=0x7f6cf438c6e0, page=0x105b710) at ../src/reconcile/rec_write.c:3202
      WT-5  0x0000000000449fa1 in __wt_reconcile (session=0x101d600, ref=0x105b6d0, salvage=0x0, flags=0) at ../src/reconcile/rec_write.c:400
      WT-6  0x000000000048f57d in __sync_file (session=0x101d600, syncop=1) at ../src/btree/bt_sync.c:135
      WT-7  0x000000000048f79d in __wt_cache_op (session=0x101d600, ckptbase=0x7f6cf43035f0, op=1) at ../src/btree/bt_sync.c:222
      WT-8  0x000000000046ed3a in __checkpoint_worker (session=0x101d600, cfg=0x7f6d8fffed80, is_checkpoint=1) at ../src/txn/txn_ckpt.c:886
      WT-9  0x000000000046efb2 in __wt_checkpoint (session=0x101d600, cfg=0x7f6d8fffed80) at ../src/txn/txn_ckpt.c:951
      WT-10 0x000000000046cfd2 in __checkpoint_apply (session=0x101d600, cfg=0x7f6d8fffed80, op=0x46ef0b <__wt_checkpoint>) at ../src/txn/txn_ckpt.c:183
      WT-11 0x000000000046db47 in __wt_txn_checkpoint (session=0x101d600, cfg=0x7f6d8fffed80) at ../src/txn/txn_ckpt.c:403
      WT-12 0x0000000000462346 in __session_checkpoint (wt_session=0x101d600, config=0x7f6d8fffede0 "name=thread-3") at ../src/session/session_api.c:895
      WT-13 0x000000000040ff96 in ops (arg=0x1085d90) at ../../../test/format/ops.c:341
      WT-14 0x0000003f17e07ee5 in start_thread (arg=0x7f6d8ffff700) at pthread_create.c:309
      
      (gdb) p state
      $2 = 1
      [WT_CHILD_IGNORE]
      (gdb) p *ref
      $3 = {page = 0x7f6d2c14e4d0, home = 0x105b710, ref_hint = 2235, state = WT_REF_MEM, addr = 0x0, key = {recno = 120921, ikey = 0x1d859}, page_del = 0x0}
      (gdb) p *page
      $4 = {u = {intl = {recno = 91014, parent_ref = 0x105b6d0, __index = 0x7f6d2c3b0810}, row = {d = 0x16386, ins = 0x105b6d0, upd = 0x7f6d2c3b0810, entries = 0}, 
          col_fix = {recno = 91014, bitf = 0x105b6d0 "\020\267\005\001", entries = 742066192}, col_var = {recno = 91014, d = 0x105b6d0, repeats = 0x7f6d2c3b0810, 
            nrepeats = 0, entries = 0}}, dsk = 0x105b800, modify = 0x7f6d0c368d90, read_gen = 202, memory_footprint = 237213, type = 3 '\003', flags_atomic = 18 '\022'}
      (gdb) p *child
      $5 = {u = {intl = {recno = 120921, parent_ref = 0x7f6d2c14e518, __index = 0x7f6d2c14e590}, row = {d = 0x1d859, ins = 0x7f6d2c14e518, upd = 0x7f6d2c14e590, 
            entries = 4}, col_fix = {recno = 120921, bitf = 0x7f6d2c14e518 "(", entries = 739566992}, col_var = {recno = 120921, d = 0x7f6d2c14e518, 
            repeats = 0x7f6d2c14e590, nrepeats = 4, entries = 25}}, dsk = 0x7f6d2c39ffe0, modify = 0x7f6d2c14e660, read_gen = 291, memory_footprint = 1589, 
        type = 4 '\004', flags_atomic = 2 '\002'}
      (gdb) p *r
      $7 = {ref = 0x105b6d0, page = 0x105b710, flags = 0, dsk = {data = 0x7f6cf40d8c00, size = 0, flags = 1, mem = 0x7f6cf40d8c00, memsize = 33280}, max_txn = 177851, 
        skipped_txn = 177859, orig_write_gen = 350, leave_dirty = 0, raw_compression = 0, raw_max_slots = 0, raw_entries = 0x0, raw_offsets = 0x0, raw_recnos = 0x0, 
        raw_destination = {data = 0x0, size = 0, flags = 1, mem = 0x0, memsize = 0}, ovfl_items = 0, all_empty_value = 1, any_empty_value = 0, page_size = 32768, 
        page_size_orig = 32768, split_size = 15360, bnd = 0x7f6cf4050170, bnd_next = 3, bnd_next_max = 541, bnd_entries = 640, bnd_allocated = 81920, 
        total_entries = 2096, bnd_state = SPLIT_TRACKING_OFF, recno = 120921, entries = 277, first_free = 0x7f6cf40d9c70 "\343\001U", space_avail = 11152, skip = 0x0, 
        skip_next = 0, skip_allocated = 0, cell_zero = 0, dictionary = 0x0, dictionary_next = 0, dictionary_slots = 0, dictionary_head = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 
          0x0, 0x0, 0x0, 0x0}, k = {buf = {data = 0x0, size = 0, flags = 0, mem = 0x0, memsize = 0}, cell = {__chunk = '\000' <repeats 15 times>}, cell_len = 0, 
          len = 0}, v = {buf = {data = 0x7f6d2c14e470, size = 9, flags = 0, mem = 0x7f6cf41043a0, memsize = 11}, cell = {
            __chunk = "$\343\001\270\003\211\000\000\000\000\000\000\000\000\000"}, cell_len = 6, len = 15}, cur = 0x7f6cf438c8f8, _cur = {data = 0x0, size = 0, 
          flags = 0, mem = 0x0, memsize = 0}, last = 0x7f6cf438c928, _last = {data = 0x7f6d181789ef, size = 17, flags = 0, mem = 0x0, memsize = 0}, 
        key_pfx_compress = 0, key_pfx_compress_conf = 0, key_sfx_compress = 0, key_sfx_compress_conf = 0, is_bulk_load = 0, salvage = 0x0, tested_ref_state = 3}
      (gdb) p/x r->flags
      $8 = 0x0
      (gdb) p *ref->page->modify
      $9 = {disk_snap_min = 0, rec_max_txn = 0, first_dirty_txn = 177812, update_txn = 0, inmem_split_txn = 0, bytes_dirty = 1589, u1 = {replace = {addr = 0x0, 
            size = 0 '\000', type = 0 '\000', reuse = 0 '\000'}, m = {multi = 0x0, multi_entries = 0}}, u2 = {intl = {root_split = 0x0, split_txn = 140106867730128}, 
          leaf = {append = 0x0, update = 0x7f6d2c14e6d0}}, ovfl_track = 0x0, write_gen = 1, page_lock = 3 '\003', flags = 0 '\000'}
      

      I'm not sure if the comment above the assertion (frame 4) about all other non-zero states are row-only is still correct because it is the exact state we're in. We appear to have a child page set up as described in the comment in __rec_child_modify:1156:

               * but, if we're forced to instantiate
               * a deleted child page and it's never modified, we end up here with
               * a page that has a modify structure, no modifications, and no disk
               * address.  Ignore those pages, they're not modified and there is no
               * reason to write the cell.
      

      The CONFIG:

      ############################################
      #  RUN PARAMETERS
      ############################################
      abort=0
      auto_throttle=1
      firstfit=0
      bitcnt=1
      bloom=1
      bloom_bit_count=57
      bloom_hash_count=12
      bloom_oldest=0
      cache=73
      checkpoints=1
      checksum=uncompressed
      chunk_size=7
      compaction=0
      compression=none
      data_extend=0
      data_source=file
      delete_pct=45
      dictionary=0
      evict_max=5
      file_type=variable-length column-store
      backups=0
      huffman_key=0
      huffman_value=0
      insert_pct=10
      internal_key_truncation=1
      internal_page_max=15
      isolation=read-uncommitted
      key_gap=18
      key_max=49
      key_min=13
      leak_memory=0
      leaf_page_max=9
      logging=0
      logging_archive=0
      logging_prealloc=0
      logging=0
      lsm_worker_threads=4
      merge_max=9
      mmap=1
      ops=100000
      prefix_compression=1
      prefix_compression_min=2
      repeat_data_pct=20
      reverse=0
      rows=100000
      runs=100
      split_pct=46
      statistics=0
      threads=7
      timer=0
      value_max=2694
      value_min=14
      wiredtiger_config=
      write_pct=42
      ############################################
      

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

              Created:
              Updated:
              Resolved: