Showing posts with label Erlang. Show all posts
Showing posts with label Erlang. Show all posts

Tuesday, December 24, 2013

Get statistics from Riak

Riak uses folsom_metrics to gather stats. For instance, to obtain GET and PUT operations speed
erl -name tst -remsh dev1@127.0.0.1 -setcookie riak

(dev1@127.0.0.1)1> folsom_metrics:get_histogram_statistics({riak_kv,node_get_fsm_time}).
[{min,4717},
{max,8996},
{arithmetic_mean,7383.6},
{geometric_mean,7212.3111343349},
{harmonic_mean,7027.752380931542},
{median,7322},
{variance,2550850.2666666666},
{standard_deviation,1597.1381488984184},
{skewness,-0.4278090078808716},
{kurtosis,-1.5957932734122735},
{percentile,[{75,8726},{95,8996},{99,8996},{999,8996}]},
{histogram,[{7317,4},{10717,6},{12717,0}]}]

(dev1@127.0.0.1)2> folsom_metrics:get_histogram_statistics({riak_kv,node_put_fsm_time}).
[{min,6377},
{max,15908},
{arithmetic_mean,11016.857142857143},
{geometric_mean,10642.075761157581},
{harmonic_mean,10268.560398236386},
{median,10245},
{variance,8786965.516483517},
{standard_deviation,2964.281618956525},
{skewness,0.1986125638310398},
{kurtosis,-1.3191900349579302},
{percentile,[{75,14016},{95,14995},{99,15908},{999,15908}]},
{histogram,[{11377,9},{15377,4},{19377,1}]}]
Note
  • all values are in microseconds;
  • stats are stored for last minute only;
  • data is stored in memory (in ets tables), minimal impact on performance.
There was a task to gather stats about backend speed (leveldb and bitcask). Unfortunately Riak doesn't have such stats. To add them use patch below
diff --git a/src/riak_kv_stat.erl b/src/riak_kv_stat.erl
index 6cd5240..cf06de8 100644
--- a/src/riak_kv_stat.erl
+++ b/src/riak_kv_stat.erl
@@ -250,6 +250,8 @@ update1({get_fsm, Bucket, Microsecs, undefined, undefined, PerBucket}) ->
     folsom_metrics:notify_existing_metric({?APP, node_gets}, 1, spiral),
     folsom_metrics:notify_existing_metric({?APP, node_get_fsm_time}, Microsecs, histogram),
     do_get_bucket(PerBucket, {Bucket, Microsecs, undefined, undefined});
+update1({get_vnode, Microsecs}) ->
+    folsom_metrics:notify_existing_metric({?APP, vnode_get_time}, Microsecs, histogram);
 update1({get_fsm, Bucket, Microsecs, NumSiblings, ObjSize, PerBucket}) ->
     folsom_metrics:notify_existing_metric({?APP, node_gets}, 1, spiral),
     folsom_metrics:notify_existing_metric({?APP, node_get_fsm_time}, Microsecs, histogram),
@@ -260,6 +262,8 @@ update1({put_fsm_time, Bucket,  Microsecs, PerBucket}) ->
     folsom_metrics:notify_existing_metric({?APP, node_puts}, 1, spiral),
     folsom_metrics:notify_existing_metric({?APP, node_put_fsm_time}, Microsecs, histogram),
     do_put_bucket(PerBucket, {Bucket, Microsecs});
+update1({put_vnode, Microsecs}) ->
+    folsom_metrics:notify_existing_metric({?APP, vnode_put_time}, Microsecs, histogram);
 update1(read_repairs) ->
     folsom_metrics:notify_existing_metric({?APP, read_repairs}, 1, spiral);
 update1(coord_redir) ->
@@ -370,8 +374,10 @@ stats() ->
      {node_get_fsm_siblings, histogram},
      {node_get_fsm_objsize, histogram},
      {node_get_fsm_time, histogram},
+     {vnode_get_time, histogram},
      {node_puts, spiral},
      {node_put_fsm_time, histogram},
+     {vnode_put_time, histogram},
      {read_repairs, spiral},
      {coord_redirs_total, counter},
      {mapper_count, counter},
diff --git a/src/riak_kv_vnode.erl b/src/riak_kv_vnode.erl
index 0c1d761..8482548 100644
--- a/src/riak_kv_vnode.erl
+++ b/src/riak_kv_vnode.erl
@@ -760,8 +760,12 @@ perform_put({true, Obj},
                      reqid=ReqID,
                      index_specs=IndexSpecs}) ->
     Val = term_to_binary(Obj),
+    StartNow = now(),
     case Mod:put(Bucket, Key, IndexSpecs, Val, ModState) of
         {ok, UpdModState} ->
+            EndNow = now(),
+            Microsecs = timer:now_diff(EndNow, StartNow),
+            riak_kv_stat:update({put_vnode, Microsecs}),
             case RB of
                 true ->
                     Reply = {dw, Idx, Obj, ReqID};
@@ -866,7 +870,12 @@ do_get_term(BKey, Mod, ModState) ->
     end.
 
 do_get_binary({Bucket, Key}, Mod, ModState) ->
-    Mod:get(Bucket, Key, ModState).
+    StartNow = now(),
+    Res = Mod:get(Bucket, Key, ModState),
+    EndNow = now(),
+    Microsecs = timer:now_diff(EndNow, StartNow),
+    riak_kv_stat:update({get_vnode, Microsecs}),
+    Res.
 
 %% @private
 %% @doc This is a generic function for operations that involve
And now
(dev1@127.0.0.1)1> folsom_metrics:get_histogram_statistics({riak_kv,vnode_get_time}).
[{min,1516},
{max,5511},
{arithmetic_mean,3751.9},
{geometric_mean,3486.0111678580415},
{harmonic_mean,3190.229915515953},
{median,3892},
{variance,1879300.7666666668},
{standard_deviation,1370.8759122060126},
{skewness,-0.2710851221084366},
{kurtosis,-1.6493136210655186},
{percentile,[{75,4760},{95,5511},{99,5511},{999,5511}]},
{histogram,[{3816,4},{6516,6},{8516,0}]}]

(dev1@127.0.0.1)2> folsom_metrics:get_histogram_statistics({riak_kv,vnode_put_time}).
[{min,507},
{max,1776},
{arithmetic_mean,952.6428571428571},
{geometric_mean,818.2293396377823},
{harmonic_mean,722.2652885738648},
{median,561},
{variance,317468.09340659337},
{standard_deviation,563.4430702445397},
{skewness,0.5582974538827159},
{kurtosis,-1.7588827239013622},
{percentile,[{75,1615},{95,1759},{99,1776},{999,1776}]},
{histogram,[{1407,9},{2207,5},{3007,0}]}]
Also note that with n_val=3 1 PUT for Riak equals to (1 GET + 1 PUT) * 3 nodes for leveldb/bitcask. And 1 GET for Riak equals to 1 GET * 3 nodes for leveldb/bitcask.

Monday, December 23, 2013

Debug and profile erlang linked in driver

OTP tools like fprof refuse to profile your .so (for a good reason). So how to do this?
erl is like any other executable loads linked in driver as a shared library and one can intorspect this shared library like any other. During compilation one need to add debug info to .so file (-ggdb flag for gcc) then attach to running erlang virtual machine from gdb or kdbg or similar.
> ps ax | grep erlang
 9801 pts/1    Sl+    0:00 /usr/lib64/erlang/erts-5.8.1/bin/beam.smp -K true -- -root /usr/lib64/erlang -progname erl -- -home /home/adolgarev --
11208 pts/0    S+     0:00 grep erlang
> kdbg -p 9801 /usr/lib64/erlang/erts-5.8.1/bin/beam.smp
Now breakpoints can be added and program state inspected
To profile do the following
valgrind --tool=callgrind --trace-children=yes /usr/bin/erl
Run tests, grab callgrind.out.PID, open it in kcachegrind
In this particular example you can see cons (|) for list creation is really slow (procedure ei_x_encode_list_header). Knowing list size beforehand decreases caller relative execution time from 34.45% to 23.25%.
Note that profiling is not a sign of premature optimization but also a sanity check that you do not do some insane things.

Friday, December 20, 2013

Erlang, how to change backlog in http inets server

Moving my very old posts from old engine I've found interesting problem on increasing backlog from 128 that is inappropriate for loaded system to something more suitable. Long time ago (in 2010) an only way I found to do this was to apply the following patch
> diff -u /usr/lib64/erlang/lib/inets-5.5/src/http_lib/http_transport.erl http_transport.erl 
--- /usr/lib64/erlang/lib/inets-5.5/src/http_lib/http_transport.erl     2010-09-28 12:45:42.000000000 +0300
+++ http_transport.erl  2010-12-08 17:57:42.759407719 +0200
@@ -218,7 +218,7 @@
 
 get_socket_info(Addr, Port) ->
     Key  = list_to_atom("httpd_" ++ integer_to_list(Port)),
-    BaseOpts =  [{backlog, 128}, {reuseaddr, true}], 
+    BaseOpts =  [{backlog, 10000}, {reuseaddr, true}], 
     IpFamilyDefault = ipfamily_default(Addr, Port), 
     case init:get_argument(Key) of
        {ok, [[Value]]} ->
I wonder whether this is still true.