wiredtiger/wiredtiger — Issue #175: race in forced page eviction
Author: keithbostic
Created: 2012-02-28 16:53:34+00:00
State: open
Labels: Bug

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
#1 0x000000000041a3aa in __rec_review (session=0x85ce20, page=0x994940,
flags=0, top=1) at ../src/btree/rec_evict.c:359
#2 0x0000000000419c18 in __wt_rec_evict (session=0x85ce20, page=0x994940,
flags=0) at ../src/btree/rec_evict.c:47
#3 0x0000000000410c72 in __evict_request_walk (session=0x85ce20)
at ../src/btree/bt_evict.c:367
#4 0x0000000000410a08 in __evict_worker (session=0x85ce20)
at ../src/btree/bt_evict.c:284
#5 0x00000000004108cd in __wt_cache_evict_server (arg=0x88f5e0)
at ../src/btree/bt_evict.c:242
#6 0x00000030f38077f1 in start_thread () from /lib64/libpthread.so.0
#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

}, 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, "#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, "#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
#1: 0x11921e0 {3} 0x11921e0 {3}
#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
############################################
```