Getting detailed per-request timing in Riak

gistfile1.erl

([email protected])1> {ok, C} = riak:local_client().
{ok,{riak_client,'[email protected]',undefined}}
([email protected])2> Object = riak_object:new(<<"testbucket">>, <<"testkey">>, <<"testvalue">>).
{r_object,<<"testbucket">>,<<"testkey">>,
          [{r_content,{dict,0,16,16,8,80,48,
                            {[],[],[],[],[],[],[],[],[],[],[],[],[],[],...},
                            {{[],[],[],[],[],[],[],[],[],[],[],[],...}}},
                      <<"testvalue">>}],
          [],
          {dict,1,16,16,8,80,48,
                {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],...},
                {{[],[],[],[],[],[],[],[],[],[],[],[],[],...}}},
          undefined}
([email protected])3> C:put(Object, [{details, [timing]}]).
{ok,[{response_usecs,5079},
     {stages,[{prepare,201},   
              {validate,134},
              {precommit,92},
              {execute_local,94},
              {waiting_local_vnode,2456},
              {execute_remote,102},
              {waiting_remote_vnode,2000}]}]}
([email protected])4> 

Explanation of timing values:

response_usecs:  total time to complete the request in microseconds.
stages:  breakdown of various request processing stages (all in microseconds)

    prepare:              retrieve list of replicas using consistent hashing, forward to primary if needed
    validate:             verify that the request is well-formed and we can meet the r/w/pr/pw values
    precommit:            run any precommit hooks
    execute_local:        dispatch request to local vnode 
    waiting_local_vnode:  wait for write to local disk
    execute_remote:       dispatch request to remote N-1 replicas
    waiting_remote_vnode: wait for write to remote replicas