Get doesn't return some keys after flushing a second memtable

[jayaprabhakar]

=== RUN   TestSlateDdModel/path-302195
Calling: db.PutWithOptions("k1", "v0", {AwaitFlush:false})
Calling: db.FlushWal()
Calling: db.PutWithOptions("k0", "v0", {AwaitFlush:false})
Calling: db.FlushMemtableToL0()
Calling: db.FlushWal()
Calling: db.FlushMemtableToL0()
Calling: db.GetWithOptions("k1", {ReadLevel:1})
Iteration Stopped Due To Empty Task Channel
Get k1 Committed  key not found
Iteration Stopped Due To Empty Task Channel
Iteration Stopped Due To Empty Task Channel
Iteration Stopped Due To Empty Task Channel
Iteration Stopped Due To Empty Task Channel
roleref ObjectStore#0 
 map[objects:map[compacted/ulid-0001.sst:map[k1:v0] compacted/ulid-0002.sst:map[k0:v0] wal/0001.sst:map[k1:v0] wal/0002.sst:map[k0:v0]]] 
 map[objects:map[compacted/ulid-0001.sst:map[k1:v0] compacted/ulid-0002.sst:map[k0:v0] wal/0001.sst:map[k1:v0] wal/0002.sst:map[k0:v0]]]
roleref SlateDb#0 
 map[immutable_memtable:map[] immutable_wal:[] l0:[compacted/ulid-0002.sst compacted/ulid-0001.sst] memtable:map[] wal:map[] wal_index:3] 
 map[immutable_memtable:map[] immutable_wal:[] l0:[compacted/ulid-0002.sst compacted/ulid-0001.sst] memtable:map[] wal:map[] wal_index:3]
    mbt_test.go:268: 
        	Error Trace:	/Users/jp/src/slatedb-go/fizztest/mbt_test.go:268
        	            				/Users/jp/src/slatedb-go/fizztest/mbt_test.go:221
        	            				/Users/jp/src/slatedb-go/fizztest/mbt_test.go:131
        	Error:      	Not equal: 
        	            	expected: "\"v0\""
        	            	actual  : "\"notfound\""
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1 +1 @@
        	            	-"v0"
        	            	+"notfound"
        	Test:       	TestSlateDdModel/path-302195
Failed at 0
1 dest:1 name:"SlateDb#0.Put" weight:0.5 req_id:10
2 src:1 dest:4 name:"Any:k=\"k1\"" weight:0.5
3 src:4 dest:10 name:"Any:v=\"v0\"" labels:"put.call" weight:0.3333333333333333
4 src:10 dest:25 name:"SlateDb#0.FlushWal" labels:"freeze_wal.call" weight:0.3333333333333333 req_id:56
5 src:25 dest:57 name:"thread-0" labels:"write_wal.call" labels:"Write.call" weight:0.3333333333333333 messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{name:"name" value:"\"wal/0001.sst\""} values:{name:"content" value:"{\"k1\": \"v0\"}"}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{value:"None"} is_return:true} req_id:56
6 src:57 dest:114 name:"thread-0" labels:"update_memtable.call" weight:0.3333333333333333 req_id:56
7 src:114 dest:227 name:"thread-0" weight:0.25 req_id:56
8 src:227 dest:465 name:"SlateDb#0.Put" weight:0.3333333333333333 req_id:9844
9 src:465 dest:879 name:"Any:k=\"k0\"" weight:0.5
10 src:879 dest:1599 name:"Any:v=\"v0\"" labels:"put.call" weight:0.3333333333333333
11 src:1599 dest:2685 name:"SlateDb#0.FlushMemtable" labels:"freeze_memtable.call" weight:0.25 req_id:18204
12 src:2685 dest:4326 name:"thread-0" labels:"write_l0.call" labels:"Write.call" weight:0.25 messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{name:"name" value:"\"compacted/ulid-0001.sst\""} values:{name:"content" value:"{\"k1\": \"v0\"}"}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{value:"None"} is_return:true} req_id:18204
13 src:4326 dest:6960 name:"thread-0" weight:0.25 req_id:18204
14 src:6960 dest:10546 name:"SlateDb#0.FlushWal" labels:"freeze_wal.call" weight:0.3333333333333333 req_id:80652
15 src:10546 dest:15447 name:"thread-0" labels:"write_wal.call" labels:"Write.call" weight:0.3333333333333333 messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{name:"name" value:"\"wal/0002.sst\""} values:{name:"content" value:"{\"k0\": \"v0\"}"}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{value:"None"} is_return:true} req_id:18203
16 src:15447 dest:22578 name:"thread-0" labels:"update_memtable.call" weight:0.3333333333333333 req_id:18203
17 src:22578 dest:32414 name:"thread-0" weight:0.25 req_id:18203
18 src:32414 dest:45281 name:"SlateDb#0.FlushMemtable" labels:"freeze_memtable.call" weight:0.3333333333333333 req_id:343242
19 src:45281 dest:60843 name:"thread-0" labels:"write_l0.call" labels:"Write.call" weight:0.3333333333333333 messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{name:"content" value:"{\"k0\": \"v0\"}"} values:{name:"name" value:"\"compacted/ulid-0002.sst\""}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Write" values:{value:"None"} is_return:true} req_id:343242
20 src:60843 dest:79756 name:"thread-0" weight:0.3333333333333333 req_id:343242
21 src:79756 dest:101238 name:"SlateDb#0.Get" weight:0.5 req_id:652847
22 src:101238 dest:124264 name:"Any:k=\"k1\"" weight:0.5
23 src:124264 dest:149177 name:"Any:read_level=\"Committed\"" labels:"get.call" labels:"Read.call" labels:"Read.call" weight:0.5 messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Read" values:{name:"name" value:"\"compacted/ulid-0002.sst\""}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Read" values:{value:"{\"k0\": \"v0\"}"} is_return:true} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Read" values:{name:"name" value:"\"compacted/ulid-0001.sst\""}} messages:{sender:"SlateDb#0" receivers:"ObjectStore#0" name:"Read" values:{value:"{\"k1\": \"v0\"}"} is_return:true}
--- FAIL: TestSlateDdModel/path-302195 (0.00s)

Expected :"v0"
Actual   :"notfound"

A simple code snippet to reproduce this bug.

db.PutWithOptions([]byte("k1"), []byte("v0"), slatedb.WriteOptions{AwaitFlush: false})
db.FlushWAL()
db.PutWithOptions([]byte("k0"), []byte("v0"), slatedb.WriteOptions{AwaitFlush: false})
db.FlushMemtableToL0()
db.FlushWAL()
db.FlushMemtableToL0()

data, err := db.GetWithOptions([]byte("k1"), slatedb.ReadOptions{ReadLevel: slatedb.Committed})
fmt.Println("Get:", "k1", string(data), err)
data, err = db.GetWithOptions([]byte("k1"), slatedb.ReadOptions{ReadLevel: slatedb.Uncommitted})
fmt.Println("Get:", "k1", string(data), err)
data, err = db.GetWithOptions([]byte("k0"), slatedb.ReadOptions{ReadLevel: slatedb.Committed})
fmt.Println("Get:", "k0", string(data), err)
data, err = db.GetWithOptions([]byte("k0"), slatedb.ReadOptions{ReadLevel: slatedb.Uncommitted})
fmt.Println("Get:", "k0", string(data), err)

Prints

Get: k1  key not found
Get: k1  key not found
Get: k0 v0 <nil>
Get: k0 v0 <nil>

[naveen246]

@jayaprabhakar this is fixed with #53

[jayaprabhakar]

I reran the tests, and all passed. Thanks.