Fix put at same second as merge time #34

Merged
merged 3 commits into from Feb 8, 2012

Projects

None yet

2 participants

@jonmeredith
Contributor

Changed put to wrap write file and retry on already_exists.

Resolves issue discovered by bitcask_qc_fsm EQC test. If the merge rewrites keys during the same second as an incoming put, the incoming was failing with already_exists when writing to the keydir.

Now, bitcask will roll over to a new file and reattempt the put once as the put should succeed now the writer process has a greater file_id than the merge process.

jonmeredith added some commits Jan 31, 2012
@jonmeredith jonmeredith Changed the way keys are generated in bitcask_qc_fsm to overlap more.
Have counterexample

32> eqc:check(bitcask_qc_fsm:prop_bitcask(), eqc:current_counterexample()).
Failed!
[{set,{var,1},{call,bitcask_qc_fsm,set_keys,[[<<"\r'Æb¾Û">>]]}},
 {set,{var,3},
      {call,bitcask,open,
            ["/tmp/bitcask.qc",
             [read_write,{open_timeout,0},{sync_strategy,none}]]}},
 {set,{var,28},{call,bitcask,put,[{var,3},<<"\r'Æb¾Û">>,<<>>]}},
 {set,{var,31},{call,bitcask,close,[{var,3}]}},
 {set,{var,32},
      {call,bitcask,open,
            ["/tmp/bitcask.qc",
             [read_write,{open_timeout,0},{sync_strategy,o_sync}]]}},
 {set,{var,46},{call,bitcask,put,[{var,32},<<"k">>,<<>>]}},
 {set,{var,47},{call,bitcask,merge,["/tmp/bitcask.qc"]}},
 {set,{var,48},{call,bitcask,put,[{var,32},<<"\r'Æb¾Û">>,<<>>]}}]
{exception,{'EXIT',{{badmatch,already_exists},
                    [{bitcask,put,3},
                     {eqc_statem,f515_0,5},
                     {eqc_statem,f507_0,5},
                     {eqc_statem,run_commands,2},
                     {eqc_fsm,run_commands,2},
                     {bitcask_qc_fsm,'-prop_bitcask/0-fun-0-',1},
                     {eqc,'-f777_0/2-fun-4-',3},
                     {eqc_gen,'-f321_0/2-fun-0-',5}]}}} /= ok
false
27ad48c
@jonmeredith jonmeredith Changed put to wrap write file and retry on already_exists.
Resolves issue discovered by bitcask_qc_fsm EQC test.  If
the merge rewrites keys during the same second as an incoming
put, the incoming was failing with already_exists when writing
to the keydir.

Now, bitcask will roll over to a new file and reattempt the
put once as the put should succeed now the writer process
has a greater file_id than the merge process.
7706dfb
@rzezeski rzezeski and 1 other commented on an outdated diff Feb 6, 2012
test/bitcask_qc_fsm.erl
closed(_S) ->
[{opened, {call, bitcask, open, [?TEST_DIR, [read_write, {open_timeout, 0}, sync_strategy()]]}},
+ %% {closed, {call, erlang, garbage_collect, []}},
@rzezeski
rzezeski Feb 6, 2012 Contributor

Why was this commented out? Should it just be removed?

@jonmeredith
jonmeredith Feb 6, 2012 Contributor

Yes, it can be removed - it was a misunderstanding on how keydirs were cleaned up.

@rzezeski rzezeski commented on the diff Feb 6, 2012
test/bitcask_qc_fsm.erl
%% Precondition (for state data).
%% Precondition is checked before command is added to the command sequence
+precondition(_From,_To,S,{call,_,get,[_,Key]}) ->
@rzezeski
rzezeski Feb 6, 2012 Contributor

Am I reading these precondition changes correctly? Do we only allow get/put on an existing key? Isn't that limiting the test too much?

@jonmeredith
jonmeredith Feb 6, 2012 Contributor

It isn't testing existing keys - it's to ensure correct shrinking. It restricts the get/puts to be from the universe of keys set up by set_keys.

@rzezeski
rzezeski Feb 6, 2012 Contributor

Yep, I was conflating data and keys.

@rzezeski rzezeski commented on an outdated diff Feb 6, 2012
test/bitcask_qc_fsm.erl
[] = os:cmd("rm -rf " ++ ?TEST_DIR),
{H,{_State, StateData}, Res} = run_commands(?MODULE,Cmds),
- case Res of
- ok ->
- ok;
- _ ->
- io:format(user, "QC result: ~p\n", [Res])
- end,
+ %% case Res of
@rzezeski
rzezeski Feb 6, 2012 Contributor

Looks like you can remove this code

@rzezeski rzezeski commented on the diff Feb 6, 2012
test/bitcask_qc_fsm.erl
weight(_From,_To,{call,_,_,_}) ->
- 1.
+ 100.
+
+set_keys(_Keys) -> %% next_state sets the keys for use by key()
+ ok.
+
+key_gen() ->
+ ?SUCHTHAT(X, binary(), X /= <<>>).
@rzezeski
rzezeski Feb 6, 2012 Contributor

See eqc_gen:non_empty/1.

@jonmeredith
jonmeredith Feb 6, 2012 Contributor

I thought that was just for lists.

@rzezeski
rzezeski Feb 6, 2012 Contributor

Nope, it affects the SIZE which is used by the generator if I recall correctly from QC week.

@rzezeski rzezeski commented on the diff Feb 6, 2012
test/bitcask_qc_fsm.erl
{opened, {call, bitcask, merge, [?TEST_DIR]}}
].
+next_state_data(init, closed, S, _, {call, _, set_keys, [Keys]}) ->
+ S#state{ keys = [<<"k">> | Keys] }; % ensure always one key
@rzezeski
rzezeski Feb 6, 2012 Contributor

The <<"k">> isn't needed, the precondition will catch empty list. Verified by removing and doing 10000 runs.

@jonmeredith
jonmeredith Feb 6, 2012 Contributor

true - it was also so that I got nice counterexamples as it shrunk the list back to empty it just used <<"k">>

@rzezeski
rzezeski Feb 6, 2012 Contributor

It doesn't seem right to put it here then...from what I learned at QC week this should be part of the generator. Don't get me wrong, this works but I don't think the intent is as clear (I know it confused me).

@jonmeredith
jonmeredith Feb 7, 2012 Contributor

the reason for adding the generated list of keys was so that you would get repeats of keys, just using binary() was too random so we very rarely retrieved keys we put. The generation/shrinking could probably be smarter - but time was short.

@rzezeski
rzezeski Feb 7, 2012 Contributor

I understand the reason for having set list of keys, I also understand adding <<"k">> for nice counterexamples. My point was this is the wrong place to do it. E.g. I would change init/1 to do the following:

    [{closed, {call, ?MODULE, set_keys, [[<<"k1">>,<<"k2">>|list(key_gen())]]}}].

I noticed, if you want nice counterexamples you actually need two keys, otherwise a cryptic binary slips in there.

@rzezeski
Contributor
rzezeski commented Feb 6, 2012

According to the comment in the bitcask:do_put code the alread_exists value can be returned, during a put, when a key is written to the keydir with a file_id that comes before the current file_id (caused by a concurrent merge). However, this is not the case if I write an eunit test to verify this fact (shown below). Did you perhaps mean to say timestamp where you said file_id?

The following test fails on the 2nd assertEqual because it returns ok, not the already_exists I expected after reading the comment in bitcask:do_put.

keydir_basic_test() ->
    {ok, Ref} = keydir_new(),
    ok = keydir_put(Ref, <<"abc">>, 1, 1234, 0, 1),

    {1, 3, [{1, 1, 1, 1234, 1234, 1}]} = keydir_info(Ref),

    E = keydir_get(Ref, <<"abc">>),
    1 = E#bitcask_entry.file_id,
    1234 = E#bitcask_entry.total_sz,
    0 = E#bitcask_entry.offset,
    1 = E#bitcask_entry.tstamp,

    ?assertEqual(already_exists, keydir_put(Ref, <<"abc">>, 1, 1234, 0, 0)),
    ?assertEqual(already_exists, keydir_put(Ref, <<"abc">>, 0, 1234, 0, 2)),

    ok = keydir_remove(Ref, <<"abc">>),
    not_found = keydir_get(Ref, <<"abc">>).
@jonmeredith jonmeredith Removed commented out code.
Cleanups from review - thanks Zman.
87974b5
@rzezeski
Contributor
rzezeski commented Feb 6, 2012

I was able to verify the existence of the bug and shrink to essentially the same counterexample as Jon (just different keys). I also verified the fix with 2x10k EQC runs.

@rzezeski
Contributor
rzezeski commented Feb 6, 2012

Is there any concern over choosing to wrap in regards to frequent merges causing the concurrent put+merge to get hit frequently and causing too many prematurely wrapped files?

@jonmeredith
Contributor

I haven't been able to get bitcask to do anything crazy by rewriting the same k/v repeatedly and setting bitcask thresholds low so there is a large amount of merge activity.

application:load(bitcask).
application:set_env(bitcask, dead_bytes_merge_trigger, 1).
application:set_env(bitcask, dead_bytes_threshold,     1).
application:set_env(bitcask, max_file_size, 100).

The merge does not reopen the file, so it should only happen once per merge file which should be a couple of gigabytes at a time so there shouldn't be a lot of files present.

@jonmeredith
Contributor

Heh, no threaded replies

"According to the comment in the bitcask:do_put code the alread_exists value can be returned, during a put, when a key is written to the keydir with a file_id that comes before the current file_id (caused by a concurrent merge). However, this is not the case if I write an eunit test to verify this fact (shown below). Did you perhaps mean to say timestamp where you said file_id?"

Apologies for being confusing - by 'current file id' I meant the one it was written to by the merge, so the merge worker process will be writing to a file_id which is greater than the current writer.

The logic for a keydir put to succeed is below

        if ((old_entry->tstamp < entry.tstamp) ||

            ((old_entry->tstamp == entry.tstamp) &&
             (old_entry->file_id < entry.file_id)) ||

            ((old_entry->tstamp == entry.tstamp) &&
             ((old_entry->file_id == entry.file_id) &&
              (old_entry->offset < entry.offset))))

If that doesn't match (which it shouldn't for equal timestamps and (writer) old_entry->file_id < (merge) entry.file_id) it will return already_exists

@rzezeski
Contributor
rzezeski commented Feb 7, 2012

I see, so the file_id of the incoming put must be lower AND the tstamps must be equal. I don't think that second part was clear in the comment.

Also, in the original comment for the PR you say the put/merge must happen in the same second. Did you literally mean a second? I would imagine the resolution is finer than that? I noticed if a put timer:sleep(500) into the postcondition for merge I still can generate the failure which would verify your comment.

EDIT: Nevermind, just read the tstamp code. It is a second.

@rzezeski
Contributor
rzezeski commented Feb 7, 2012

Alright, I think I beat this up enough. I'd like to see the small QC changes made but otherwise this patch looks good.

+1 to merge.

@jonmeredith
Contributor

You're spot on on both eqc issues - it would have been clearer to add the keys in the command generator and non_empty(binary()) would be better than SUCHTHAT. Given how close we are to the release and the hintfile CRC branch depends on this one those improvements can wait until next time we make changes to the tests.

Thanks for the review.

@jonmeredith jonmeredith merged commit 87974b5 into master Feb 8, 2012
@slfritchie slfritchie added a commit that referenced this pull request Nov 27, 2013
@slfritchie slfritchie Work-around model limitation/bug in PULSE test, bitcask_eqc.erl
In the C65 counterexample below, the {var,2} worker proc tries to
get key #19 and allegedly fails.  The last step of the main proc is
a put loop of keys #1 - #34.  The {var,2} worker is racing with
both the main proc and also with the {var,7} worker that is
doing a fold.  The fold happens first, which freezes the keydir
when the next put happens.  Then the {var,2} worker does its get
and finds (correctly) `not_found` ... but the model is buggy and
can't predict the correct answer.

I'm not good enough at the temporal logic to fix the model
The Correct Way.  So I've patched it up so that any 'bad' thing
detected by the main/1st proc is truly bad.  But if a 'bad' thing
happens in a forked worker, then if we know that there's a fold
happening at the same time, we assume that the model's predicted
answer is bad and thus we *ignore* the 'bad' thing.

    191> C65 = binary_to_term(element(2,file:read_file("zzz.c65@develop@commit=a2d75.bin"))).
    [[{set,{var,2},
           {call,bitcask_eqc,fork,
                 [[{init,{state,undefined,false,false,[]}},
                   {set,{not_var,8},{not_call,bitcask_eqc,bc_open,[false]}}]]}},
      {set,{var,4},
           {call,bitcask_eqc,fork,
                 [[{init,{state,undefined,false,false,[]}},
                   {set,{not_var,2},{not_call,bitcask_eqc,bc_open,[false]}},
                   {set,{not_var,3},
                        {not_call,bitcask_eqc,bc_close,[{not_var,2}]}},
                   {set,{not_var,9},{not_call,bitcask_eqc,bc_open,[false]}},
                   {set,{not_var,10},
                        {not_call,bitcask_eqc,get,[{not_var,9},19]}}]]}},
      {set,{var,6},
           {call,bitcask_eqc,fork,
                 [[{init,{state,undefined,false,false,[]}},
                   {set,{not_var,3},{not_call,bitcask_eqc,bc_open,[false]}}]]}},
      {set,{var,7},
           {call,bitcask_eqc,fork,
                 [[{init,{state,undefined,false,false,[]}},
                   {set,{not_var,5},{not_call,bitcask_eqc,bc_open,[false]}},
                   {set,{not_var,7},
                        {not_call,bitcask_eqc,fold,[{not_var,5}]}}]]}},
      {set,{var,12},
           {call,bitcask_eqc,fork,
                 [[{init,{state,undefined,false,false,[]}},
                   {set,{not_var,3},{not_call,bitcask_eqc,bc_open,[false]}},
                   {set,{not_var,8},
                        {not_call,bitcask_eqc,fold,[{not_var,3}]}}]]}},
      {set,{var,17},{call,bitcask_eqc,bc_open,[true]}},
      {set,{var,28},{call,bitcask_eqc,put,[{var,17},1,<<>>]}},
      {set,{var,29},{call,bitcask_eqc,needs_merge,[{var,17}]}},
      {set,{var,30},{call,bitcask_eqc,fork_merge,[{var,17}]}},
      {set,{var,32},
           {call,bitcask_eqc,puts,[{var,17},{1,34},<<>>]}}],
     {77863,46676,48146},
     [{events,[]}]]
3b70204
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment