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

race in forced page eviction

    • Type: Icon: Task Task
    • Resolution: Done
    • WT1.2
    • Affects Version/s: None
    • Component/s: None
    • Labels:

      Michael, I saw a free-page race today.

      Here's the gdb run:

         1: read/write ops 12570
      Program received signal SIGSEGV, Segmentation fault.
      [Switching to Thread 0x7ffff7a04700 (LWP 1961)]
      0x000000000041a5df in __hazard_exclusive (session=0x85ce20, ref=0x0)
          at ../src/btree/rec_evict.c:500
      500             if (WT_ATOMIC_CAS(ref->state, WT_REF_EVICTING, WT_REF_LOCKED))
      Missing separate debuginfos, use: debuginfo-install bzip2-libs-1.0.5-7.el6_0.x86
      _64 glibc-2.12-1.47.el6_2.5.x86_64
      (gdb) p ref
      $1 = (WT_REF *) 0x0
      (gdb) where
      #0  0x000000000041a5df in __hazard_exclusive (session=0x85ce20, ref=0x0)
          at ../src/btree/rec_evict.c:500
      WT-1  0x000000000041a3aa in __rec_review (session=0x85ce20, page=0x994940,
          flags=0, top=1) at ../src/btree/rec_evict.c:359
      WT-2  0x0000000000419c18 in __wt_rec_evict (session=0x85ce20, page=0x994940,
          flags=0) at ../src/btree/rec_evict.c:47
      WT-3  0x0000000000410c72 in __evict_request_walk (session=0x85ce20)
          at ../src/btree/bt_evict.c:367
      WT-4  0x0000000000410a08 in __evict_worker (session=0x85ce20)
          at ../src/btree/bt_evict.c:284
      WT-5  0x00000000004108cd in __wt_cache_evict_server (arg=0x88f5e0)
          at ../src/btree/bt_evict.c:242
      WT-6  0x00000030f38077f1 in start_thread () from /lib64/libpthread.so.0
      WT-7  0x00000030f34e592d in clone () from /lib64/libc.so.6
      (gdb) info threads
      * 4 Thread 0x7ffff7a04700 (LWP 1961)  0x000000000041a5df in __hazard_exclusive
          (session=0x85ce20, ref=0x0) at ../src/btree/rec_evict.c:500
        1 Thread 0x7ffff7fed700 (LWP 1946)  0x00000031048098fb in BZ2_decompress ()
         from /lib64/libbz2.so.1
      

      It's not real reliable, but I found a run that reproduces it most of the time.

      evictserver: sleeping
      evictserver: waking
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {0x7fca541173d0}
      evictserver: sleeping
      evictserver: waking
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {0x7fca541173d0}
      evictserver: sleeping
      evictserver: waking
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {0x7fca541173d0}
      evictserver: sleeping
      evictserver: waking
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {0x7fca541173d0}
      evictserver: sleeping
      evictserver: waking
      file:__wt [cursor.insert]: evictserver: ../src/include/cache.i/59: page 0xf3d8a0
       {0x7fca541173d0}
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {0x7fca541173d0}
      file:__wt [cursor.insert]: evictserver: waking, bytes inuse <= max (0MB <= 30MB)
      ,
      file:__wt: evictserver: forcing eviction of page 0xf3d8a0 {(nil)}
      

      Somehow we're evicting a page, discarding it, and then evicting it again, and we go south because WT_PAGE->ref is NULL.

      I changed __wt_page_out() to overwrite the page on discard with 0xab, and the core shows me something more interesting:

      (gdb) p page
      $1 = (WT_PAGE *) 0x9359e0
      (gdb) p *page
      $2 = {parent = 0x983750, ref = 0xabababababababab, u = {intl = {recno = 12370169
      555311111083, t = 0xabababababababab},
          row = {d = 0xabababababababab, ins = 0xabababababababab, upd = 0xabababababa
      babab}, col_fix = {
            recno = 12370169555311111083, bitf = 0xabababababababab <Address 0xabababa
      babababab out of bounds>}, col_var = {
            recno = 12370169555311111083, d = 0xabababababababab, repeats = 0xabababab
      abababab, nrepeats = 2880154539}},
        dsk = 0xabababababababab, modify = 0xabababababababab, read_gen = 123701695553
      11111083, entries = 2880154539,
        memory_footprint = 2880154539, type = 171 '\253', flags = 171 '\253'}
      (gdb)
      

      I'll push that change, we might as well keep it.

      I put a check in __wt_evict_page_request:

              WT_EVICT_REQ_FOREACH(er, er_end, cache)
                      if (er->session != NULL && er->page == page)
                              fprintf(stderr, "WT-1: %p {%d} %p {%d}\n",
                              er->page, er->page->ref->state,
                              page, page->ref->state); 
              if (!WT_ATOMIC_CAS(page->ref->state, WT_REF_MEM, WT_REF_EVICTING))
                      return (0);
              WT_EVICT_REQ_FOREACH(er, er_end, cache)
                      if (er->session != NULL && er->page == page)
                              fprintf(stderr, "WT-2 %p {%d} %p {%d}\n",    
                              er->page, er->page->ref->state,
                              page, page->ref->state);
      

      which gives me:

      ./t -r
      ... reading CONFIG file
      t: process 3060
      WT-1: 0x11921e0 {3} 0x11921e0 {3}
      WT-2 0x11921e0 {1} 0x11921e0 {1}
      Segmentation fault
      

      which translates to both page and er->page being set to WT_REF_MEM, then both set to WT_REF_EVICTING.

      I haven't gotten any further, but if I don't get back to it today, maybe it will be obvious to you?

      The run file is:

      ############################################
      #  RUN PARAMETERS
      ############################################
      # bitcnt not applicable to this run
      bzip=1
      cache=30
      delete_pct=29
      file_type=row-store
      huffman_key=0
      huffman_value=1
      insert_pct=9
      internal_page_max=11
      key_max=121
      key_min=17
      leaf_page_max=9
      ops=20000
      # repeat_data_pct not applicable to this run
      reverse=1
      rows=100
      runs=1
      value_max=1805
      value_min=17
      write_pct=70
      ############################################
      

            Assignee:
            michael.cahill@mongodb.com Michael Cahill (Inactive)
            Reporter:
            keith.bostic@mongodb.com Keith Bostic (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: