-
-
Save slfritchie/442e09035c70c5ab6240 to your computer and use it in GitHub Desktop.
No, I don't know how vector clocks work............
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
* All of the log messages below are from dev3's log, the node that | |
* was joined to the cluster and handoff to dev3 was running when | |
* these new updates run and their logs captured. | |
riak_kv_vnode:do_put(Sender, {Bucket,_Key}=BKey, RObj, ReqID, StartTime, Options, State) -> | |
[...] | |
{PrepPutRes, UpdPutArgs} = prepare_put(State, PutArgs), | |
{Reply, UpdState} = perform_put(PrepPutRes, State, UpdPutArgs), | |
riak_core_vnode:reply(Sender, Reply), | |
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442433 prunetime 63583442433 counter_op undefined | |
riak_kv_vnode:prepare_put(), 2nd clause | |
top of function, Coord=false | |
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1088 prepare_put2: not_found {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
do_get_object() returned {error, not_found, _UpdModState} | |
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1096 prepare_put2: {<<"b">>,<<"k-30">>} | |
riak_kv_vnode:prepare_put(), 2nd clause | |
case GetReply of ok -> | |
2014-11-17 20:20:33.351 [info] <0.574.0>@riak_kv_vnode:prepare_put:1103 prepare_put2: {<<"b">>,<<"k-30">>} | |
riak_kv_vnode:prepare_put(), 2nd clause | |
just before call to prepare_new_put() | |
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:prepare_new_put:1162 prepare_new_put: VId <<157,62,8,202,84,105,217,70>> RObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
riak_kv_vnode:prepare_new_put(false, ...) | |
Return the object as-is (no vclock change) | |
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:prepare_put:1105 prepare_put2: ObjToStore {<<98>>,<<107,45,51,48>>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
immediately before returning {{true, ObjToStore}, ...} | |
2014-11-17 20:20:33.352 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 1 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
--- next req --- | |
2014-11-17 20:20:33.360 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442433 prunetime 63583442433 counter_op undefined | |
riak_kv_vnode:prepare_put(), 2nd clause | |
top of function, Coord=false | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
The object exists locally (sibling count and vclock) | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1108 prepare_put2: OldObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
Immediately before calling put_merge() | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1114 prepare_put2: NewObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the result of put_merge() | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1117 prepare_put2: AMObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the result of enforce_allow_mult() | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1124 prepare_put2: indexspecs {<<"b">>,<<"k-30">>} | |
riak_kv_vnode:prepare_put(), 2nd clause | |
IndexSpecs is [], because we're using Bitcask, and it | |
doesn't support indexes. | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1135 prepare_put2: Prune {<<"b">>,<<"k-30">>} vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the newly-pruned vclock | |
2014-11-17 20:20:33.361 [info] <0.574.0>@riak_kv_vnode:prepare_put:1138 prepare_put2: set_vclock {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the newly-pruned vclock in the new riak_object | |
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:prepare_put:1141 prepare_put2: ObjToStore {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the newly-pruned vclock in the new riak_object | |
called ObjToStore | |
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
After calling handle_counter() | |
2014-11-17 20:20:33.362 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 1 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
--- next req --- | |
2014-11-17 20:20:33.363 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{18,63583442433}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord true lww false starttime 63583442433 prunetime 63583442433 counter_op undefined | |
riak_kv_vnode:prepare_put(), 2nd clause | |
top of function, Coord=**true** | |
Also, notice that this vclock is stale: the last op just | |
finished writing | |
[{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
but the (intentionally broken client) has given us an older vclock. | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
The object exists locally (sibling count and vclock) | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1108 prepare_put2: OldObj {<<"b">>,<<"k-30">>} sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
Immediately before calling put_merge() | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1114 prepare_put2: NewObj {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the result of put_merge(), a newobj flavor | |
FIRST APPEARANCE of the actor <<157,62,8,202,84,105,217,70>> | |
which is this vnode's actor ID. | |
Note that the actor count is 2, interesting, why not 1? | |
The caller uses: | |
case put_merge(Coord, LWW, OldObj, RObj, VId, StartTime) of | |
Hrm, we know the LWW is false, so the 2nd arg to put_merge() | |
is false. We also know that Coord is true. So, that leaves | |
us with: | |
put_merge(Coord=true, LWW=false, CurObj, UpdObj, VId, StartTime) -> | |
UpdObj1 = riak_object:increment_vclock(UpdObj, VId, StartTime), | |
%% SLF: VId doesn't appear in UpdObj's vclock | |
%% before the call, so it must be added here. | |
UpdVC = riak_object:vclock(UpdObj1), | |
CurVC = riak_object:vclock(CurObj), | |
%% Check the coord put will replace the existing object | |
case vclock:get_counter(VId, UpdVC) > vclock:get_counter(VId, CurVC) andalso | |
vclock:descends(CurVC, UpdVC) == false andalso | |
vclock:descends(UpdVC, CurVC) == true of | |
true -> | |
{newobj, UpdObj1}; | |
false -> | |
%% If not, make sure it does | |
%% SLF: here is where we get our | |
%% second actor count *and* the source | |
%% of the 2 siblings. | |
{newobj, riak_object:increment_vclock( | |
riak_object:merge(CurObj, UpdObj1), VId, StartTime)} | |
end. | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1117 prepare_put2: AMObj {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
riak_kv_vnode:prepare_put(), 2nd clause | |
This is the result of enforce_allow_mult() | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1124 prepare_put2: indexspecs {<<"b">>,<<"k-30">>} | |
2014-11-17 20:20:33.364 [info] <0.574.0>@riak_kv_vnode:prepare_put:1135 prepare_put2: Prune {<<"b">>,<<"k-30">>} vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1138 prepare_put2: set_vclock {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1141 prepare_put2: ObjToStore {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
No changes to the object here | |
2014-11-17 20:20:33.365 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 2 Obj [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
2014-11-17 20:20:33.365 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (2) | |
--- next req --- | |
NOTE: The passage of time: we're now into the script's serialized writing phase | |
with only one client. | |
NOTE: The coordinator is *never* true for the next 15 updates. That | |
means that some other vnode (on dev1 or dev2) is the coordinator. | |
NOTE: The incoming vclock never contains dev3's/our vnode actor ID, | |
<<157,62,8,202,84,105,217,70>>. | |
NOTE: But we always find out vnode actor ID, | |
<<157,62,8,202,84,105,217,70>>, in the local store, because of | |
the single time that we were the coordinator. | |
2014-11-17 20:20:41.971 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined | |
2014-11-17 20:20:41.971 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 2 vclock [{<<92,176,215,10,84,105,217,80>>,{2,63583442393}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{19,63583442433}}] | |
2014-11-17 20:20:41.974 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 3 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}] | |
2014-11-17 20:20:41.974 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (3) | |
--- next req --- | |
2014-11-17 20:20:41.979 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined | |
2014-11-17 20:20:41.980 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 3 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{20,63583442441}}] | |
2014-11-17 20:20:41.981 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 4 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}] | |
2014-11-17 20:20:41.981 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (4) | |
--- next req --- | |
2014-11-17 20:20:41.986 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{22,63583442441}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442441 prunetime 63583442441 counter_op undefined | |
2014-11-17 20:20:41.986 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 4 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{21,63583442441}}] | |
2014-11-17 20:20:41.988 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 5 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{22,63583442441}}] | |
2014-11-17 20:20:41.988 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (5) | |
--- next req --- | |
[... time elapses...] | |
--- next req --- | |
2014-11-17 20:20:42.080 [info] <0.574.0>@riak_kv_vnode:prepare_put:1084 prepare_put2: top {<<"b">>,<<"k-30">>} ... original RObj sibs 1 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] bprops [{name,<<98>>},{allow_mult,true},{basic_quorum,false},{big_vclock,50},{chash_keyfun,{riak_core_util,chash_std_keyfun}},{dw,quorum},{last_write_wins,false},{linkfun,{modfun,riak_kv_wm_link_walker,mapreduce_linkfun}},{n_val,3},{notfound_ok,true},{old_vclock,86400},{postcommit,[]},{pr,0},{precommit,[]},{pw,0},{r,quorum},{repl,true},{rw,quorum},{small_vclock,50},{w,quorum},{young_vclock,20}] coord false lww false starttime 63583442442 prunetime 63583442442 counter_op undefined | |
2014-11-17 20:20:42.081 [info] <0.574.0>@riak_kv_vnode:prepare_put:1091 prepare_put2: found {<<"b">>,<<"k-30">>}, TheOldObj sibs 16 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{33,63583442442}}] | |
TheOldObj : [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{33,63583442442}}] | |
: sibs=16 | |
incoming RObj : [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}}, {<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] | |
: sibs=1 | |
Coord=false, LWW=false, local actor ID=<<157,62,8,...>> | |
local vnode put: [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] | |
: sibs=17 | |
2014-11-17 20:20:42.082 [info] <0.574.0>@riak_kv_vnode:prepare_put:1143 prepare_put2: ObjToStore2 {<<"b">>,<<"k-30">>} sibs 17 vclock [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] | |
2014-11-17 20:20:42.083 [info] <0.574.0>@riak_kv_vnode:perform_put:1194 perform_put {<<"b">>,<<"k-30">>} sibs 17 Obj [{<<92,176,215,10,84,105,217,80>>,{4,63583442433}},{<<157,62,8,202,84,105,217,70>>,{2,63583442433}},{<<197,82,177,11,84,105,217,70>>,{34,63583442442}}] | |
2014-11-17 20:20:42.083 [warning] <0.574.0>@riak_kv_vnode:encode_and_put:1838 Too many siblings for object <<"b">>/<<"k-30">> (17) |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
diff --git a/src/riak_kv_vnode.erl b/src/riak_kv_vnode.erl | |
index b86cbbc..093d7bc 100644 | |
--- a/src/riak_kv_vnode.erl | |
+++ b/src/riak_kv_vnode.erl | |
@@ -867,6 +872,10 @@ handoff_finished(_TargetNode, State) -> | |
handle_handoff_data(BinObj, State) -> | |
try | |
{BKey, Val} = decode_binary_object(BinObj), | |
+{B, K} = BKey, | |
+O = riak_object:from_binary(B, K, Val), | |
+VClock = riak_object:vclock(O), | |
+lager:info("handoff receiver ~p sibs ~w vclock ~p\n", [BKey, length(riak_object:get_contents(O)), VClock]), | |
{B, K} = BKey, | |
case do_diffobj_put(BKey, riak_object:from_binary(B, K, Val), | |
State) of | |
@@ -1055,8 +1064,10 @@ prepare_put(State=#state{vnodeid=VId, | |
ObjToStore = | |
case Coord of | |
true -> | |
+lager:info("prepare_put1: increment_vclock ~p\n", [{Bucket, _Key}]), | |
riak_object:increment_vclock(RObj, VId, StartTime); | |
false -> | |
+lager:info("prepare_put1: ~p\n", [{Bucket, _Key}]), | |
RObj | |
end, | |
{{true, ObjToStore}, PutArgs#putargs{is_index = false}}; | |
@@ -1075,47 +1086,66 @@ prepare_put(#state{vnodeid=VId, | |
prunetime=PruneTime, | |
counter_op = CounterOp}, | |
IndexBackend) -> | |
+lager:info("prepare_put2: top ~p ... original RObj sibs ~w vclock ~w bprops ~w coord ~w lww ~w starttime ~w prunetime ~w counter_op ~w\n", [{Bucket, Key}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj), BProps, Coord, LWW, StartTime, PruneTime, CounterOp]), | |
GetReply = | |
case do_get_object(Bucket, Key, Mod, ModState) of | |
{error, not_found, _UpdModState} -> | |
+lager:info("prepare_put2: not_found ~p ... original RObj sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj)]), | |
ok; | |
{ok, TheOldObj, _UpdModState} -> | |
+lager:info("prepare_put2: found ~p, TheOldObj sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(TheOldObj)), riak_object:vclock(TheOldObj)]), | |
{ok, TheOldObj} | |
end, | |
case GetReply of | |
ok -> | |
+lager:info("prepare_put2: ~p\n", [{Bucket, Key}]), | |
case IndexBackend of | |
true -> | |
IndexSpecs = riak_object:index_specs(RObj); | |
false -> | |
IndexSpecs = [] | |
end, | |
+lager:info("prepare_put2: ~p\n", [{Bucket, Key}]), | |
ObjToStore = prepare_new_put(Coord, RObj, VId, StartTime, CounterOp), | |
+lager:info("prepare_put2: ObjToStore ~w sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore)), riak_object:vclock(ObjToStore)]), | |
{{true, ObjToStore}, PutArgs#putargs{index_specs=IndexSpecs, is_index=IndexBackend}}; | |
{ok, OldObj} -> | |
+lager:info("prepare_put2: OldObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj)), riak_object:vclock(OldObj)]), | |
case put_merge(Coord, LWW, OldObj, RObj, VId, StartTime) of | |
{oldobj, OldObj1} -> | |
+lager:info("prepare_put2: OldObj1 ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj1)), riak_object:vclock(OldObj1)]), | |
{{false, OldObj1}, PutArgs}; | |
{newobj, NewObj} -> | |
+lager:info("prepare_put2: NewObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(NewObj)), riak_object:vclock(NewObj)]), | |
VC = riak_object:vclock(NewObj), | |
AMObj = enforce_allow_mult(NewObj, BProps), | |
+lager:info("prepare_put2: AMObj ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(AMObj)), riak_object:vclock(AMObj)]), | |
IndexSpecs = case IndexBackend of | |
true -> | |
+lager:info("prepare_put2: indexspecs ~p\n", [{Bucket, Key}]), | |
riak_object:diff_index_specs(AMObj, | |
OldObj); | |
false -> | |
+lager:info("prepare_put2: indexspecs ~p\n", [{Bucket, Key}]), | |
[] | |
end, | |
ObjToStore = case PruneTime of | |
undefined -> | |
+lager:info("prepare_put2: prune ~p\n", [{Bucket, Key}]), | |
AMObj; | |
_ -> | |
- riak_object:set_vclock(AMObj, | |
- vclock:prune(VC, | |
+ Prune = vclock:prune(VC, | |
PruneTime, | |
- BProps)) | |
+ BProps), | |
+lager:info("prepare_put2: Prune ~p vclock ~w\n", [{Bucket, Key}, Prune]), | |
+ XX = riak_object:set_vclock(AMObj, | |
+ Prune), | |
+lager:info("prepare_put2: set_vclock ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(XX)), riak_object:vclock(XX)]), | |
+ XX | |
end, | |
+lager:info("prepare_put2: ObjToStore ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore)), riak_object:vclock(ObjToStore)]), | |
ObjToStore2 = handle_counter(Coord, CounterOp, VId, ObjToStore), | |
+lager:info("prepare_put2: ObjToStore2 ~p sibs ~w vclock ~w\n", [{Bucket, Key}, length(riak_object:get_contents(ObjToStore2)), riak_object:vclock(ObjToStore2)]), | |
{{true, ObjToStore2}, | |
PutArgs#putargs{index_specs=IndexSpecs, is_index=IndexBackend}} | |
end | |
@@ -1124,13 +1154,17 @@ prepare_put(#state{vnodeid=VId, | |
%% @Doc in the case that this a co-ordinating put, prepare the object. | |
prepare_new_put(true, RObj, VId, StartTime, CounterOp) when is_integer(CounterOp) -> | |
VClockUp = riak_object:increment_vclock(RObj, VId, StartTime), | |
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(RObj)), VClockUp]), | |
%% coordinating a _NEW_ counter operation means | |
%% creating + incrementing the counter. | |
%% Make a new counter, stuff it in the riak_object | |
riak_kv_counter:update(VClockUp, VId, CounterOp); | |
prepare_new_put(true, RObj, VId, StartTime, _CounterOp) -> | |
- riak_object:increment_vclock(RObj, VId, StartTime); | |
+ XX = riak_object:increment_vclock(RObj, VId, StartTime), | |
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(XX)), riak_object:vclock(XX)]), | |
+ XX; | |
prepare_new_put(false, RObj, _VId, _StartTime, _CounterOp) -> | |
+lager:info("prepare_new_put: VId ~p RObj ~p sibs ~w vclock ~w\n", [_VId, {riak_object:bucket(RObj), riak_object:key(RObj)}, length(riak_object:get_contents(RObj)), riak_object:vclock(RObj)]), | |
RObj. | |
handle_counter(true, CounterOp, VId, RObj) when is_integer(CounterOp) -> | |
@@ -1161,6 +1195,8 @@ perform_put({true, Obj}, | |
bkey={Bucket, Key}, | |
reqid=ReqID, | |
index_specs=IndexSpecs}) -> | |
+ObjVClock = riak_object:vclock(Obj), | |
+lager:info("perform_put ~p sibs ~w Obj ~w\n", [{Bucket, Key}, length(riak_object:get_contents(Obj)), ObjVClock]), | |
case encode_and_put(Obj, Mod, Bucket, Key, IndexSpecs, ModState, | |
do_max_check) of | |
{{ok, UpdModState}, _EncodedVal} -> | |
@@ -1504,6 +1540,8 @@ do_diffobj_put({Bucket, Key}, DiffObj, | |
false -> | |
IndexSpecs = [] | |
end, | |
+DiffObjVClock = riak_object:vclock(DiffObj), | |
+lager:info("do_diffobj_put ~p sibs ~w not_found ~p\n", [{Bucket, Key}, length(riak_object:get_contents(DiffObj)), DiffObjVClock]), | |
case encode_and_put(DiffObj, Mod, Bucket, Key, | |
IndexSpecs, ModState, no_max_check) of | |
{{ok, _UpdModState} = InnerRes, _EncodedVal} -> | |
@@ -1515,13 +1553,19 @@ do_diffobj_put({Bucket, Key}, DiffObj, | |
InnerRes | |
end; | |
{ok, OldObj, _UpdModState} -> | |
+OldObjVClock = riak_object:vclock(OldObj), | |
+lager:info("do_diffobj_put ~p sibs ~w OldObj vclock ~p\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj)), OldObjVClock]), | |
%% Merge handoff values with the current - possibly discarding | |
%% if out of date. Ok to set VId/Starttime undefined as | |
%% they are not used for non-coordinating puts. | |
case put_merge(false, false, OldObj, DiffObj, undefined, undefined) of | |
{oldobj, _} -> | |
+OldObjVClock = riak_object:vclock(OldObj), | |
+lager:info("do_diffobj_put ~p sibs ~w put_merge oldobj\n", [{Bucket, Key}, length(riak_object:get_contents(OldObj))]), | |
{ok, ModState}; | |
{newobj, NewObj} -> | |
+NewObjVClock = riak_object:vclock(NewObj), | |
+lager:info("do_diffobj_put ~p sibs ~w OldObj put_merge ~p\n", [{Bucket, Key}, length(riak_object:get_contents(NewObj)), NewObjVClock]), | |
AMObj = enforce_allow_mult(NewObj, riak_core_bucket:get_bucket(Bucket)), | |
case IndexBackend of | |
true -> |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment