Add head timings

Include log breaking down timings of HEAD requests by result and level

src/leveled_bookie.erl

@@ -150,7 +150,7 @@
 -define(CHECKJOURNAL_PROB, 0.2).
 -define(CACHE_SIZE_JITTER, 25).
 -define(JOURNAL_SIZE_JITTER, 20).
--define(PUT_TIMING_LOGPOINT, 10000).
+-define(LONG_RUNNING, 80000).
 
 -record(ledger_cache, {skiplist = leveled_skiplist:empty(true) :: tuple(),
                         min_sqn = infinity :: integer()|infinity,
@@ -278,7 +278,7 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
                                         {IndexSpecs, TTL}),
     Cache0 = addto_ledgercache(Changes, State#state.ledger_cache),
     T1 = timer:now_diff(os:timestamp(), SW) - T0,
-    PutTimings = update_put_timings(State#state.put_timing, T0, T1),
+    PutTimes = leveled_log:put_timings(bookie, State#state.put_timing, T0, T1),
     % If the previous push to memory was returned then punish this PUT with a
     % delay.  If the back-pressure in the Penciller continues, these delays
     % will beocme more frequent
@@ -294,11 +294,11 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
                                     State#state.penciller) of
         {ok, NewCache} ->
             {noreply, State#state{ledger_cache=NewCache,
-                                    put_timing=PutTimings,
+                                    put_timing=PutTimes,
                                     slow_offer=false}};
         {returned, NewCache} ->
             {noreply, State#state{ledger_cache=NewCache,
-                                    put_timing=PutTimings,
+                                    put_timing=PutTimes,
                                     slow_offer=true}}
     end;
 handle_call({get, Bucket, Key, Tag}, _From, State) ->
@@ -465,23 +465,16 @@ push_ledgercache(Penciller, Cache) ->
 %%% Internal functions
 %%%============================================================================
 
-update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}},
+
-                                                                    T0, T1) ->
-    leveled_log:log("B0012",
-                    [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
-    {1, {T0, T1}, {T0, T1}};
-update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
-    {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.
 
 maybe_longrunning(SW, Aspect) ->
     case timer:now_diff(os:timestamp(), SW) of
-        N when N > 80000 ->
+        N when N > ?LONG_RUNNING ->
             leveled_log:log("B0013", [N, Aspect]);
         _ ->
             ok
     end.
 
-
 cache_size(LedgerCache) ->
     leveled_skiplist:size(LedgerCache#ledger_cache.skiplist).
 

src/leveled_cdb.erl

@@ -95,7 +95,6 @@
 -define(WRITE_OPS, [binary, raw, read, write]).
 -define(PENDING_ROLL_WAIT, 30).
 -define(DELETE_TIMEOUT, 10000).
--define(PUT_TIMING_LOGPOINT, 10000).
 
 -record(state, {hashtree,
                 last_position :: integer(),
@@ -279,7 +278,9 @@ writer({put_kv, Key, Value}, _From, State) ->
                         ok
                 end,
             T1 = timer:now_diff(os:timestamp(), SW) - T0,
-            Timings = update_put_timings(State#state.put_timing, T0, T1),
+            Timings = leveled_log:put_timings(journal,
+                                                State#state.put_timing,
+                                                T0, T1),
             {reply, ok, writer, State#state{handle=UpdHandle,
                                                 last_position=NewPosition,
                                                 last_key=Key,
@@ -779,14 +780,6 @@ hashtable_calc(HashTree, StartPos) ->
 %% Internal functions
 %%%%%%%%%%%%%%%%%%%%
 
-update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}},
-                                                                    T0, T1) ->
-    leveled_log:log("CDB17",
-                    [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
-    {1, {T0, T1}, {T0, T1}};
-update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
-    {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.
-
 determine_new_filename(Filename) ->
     filename:rootname(Filename, ".pnd") ++ ".cdb".
     

src/leveled_inker.erl

@@ -126,7 +126,6 @@
 -define(PENDING_FILEX, "pnd").
 -define(LOADING_PAUSE, 1000).
 -define(LOADING_BATCH, 1000).
--define(PUT_TIMING_LOGPOINT, 10000).
 
 -record(state, {manifest = [] :: list(),
 				manifest_sqn = 0 :: integer(),
@@ -427,9 +426,11 @@ put_object(LedgerKey, Object, KeyChanges, State) ->
                                 JournalBin) of
         ok ->
             T1 = timer:now_diff(os:timestamp(), SW) - T0,
-            UpdPutTimings = update_put_timings(State#state.put_timing, T0, T1),
+            UpdPutTimes = leveled_log:put_timings(inker,
+                                                    State#state.put_timing,
+                                                    T0, T1),
             {ok,
-                State#state{journal_sqn=NewSQN, put_timing=UpdPutTimings},
+                State#state{journal_sqn=NewSQN, put_timing=UpdPutTimes},
                 byte_size(JournalBin)};
         roll ->
             SWroll = os:timestamp(),
@@ -750,14 +751,6 @@ initiate_penciller_snapshot(Bookie) ->
     MaxSQN = leveled_penciller:pcl_getstartupsequencenumber(LedgerSnap),
     {LedgerSnap, MaxSQN}.
 
-update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}},
-                                                                    T0, T1) ->
-    leveled_log:log("I0019",
-                    [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
-    {1, {T0, T1}, {T0, T1}};
-update_put_timings({N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
-    {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.
-
 
 %%%============================================================================
 %%% Test

src/leveled_log.erl

@@ -8,9 +8,14 @@
 -include_lib("eunit/include/eunit.hrl").
 
 -export([log/2,
-            log_timer/3]).         
+            log_timer/3,
+            put_timings/4,
+            head_timings/4]).         
 
+-define(PUT_TIMING_LOGPOINT, 10000).
+-define(HEAD_TIMING_LOGPOINT, 10000).
 -define(LOG_LEVEL, [info, warn, error, critical]).
+
 -define(LOGBASE, dict:from_list([
 
     {"G0001",
@@ -111,6 +116,8 @@
         {warn, "We're doomed - intention recorded to destroy all files"}},
     {"P0031",
         {info, "Completion of update to levelzero"}},
+    {"P0032",
+        {info, "Head timing for result ~w is count ~w total ~w and max ~w"}},
     
     {"PC001",
         {info, "Penciller's clerk ~w started with owner ~w"}},
@@ -226,7 +233,7 @@
     {"SFT03",
         {info, "File creation of L0 file ~s"}},
     {"SFT04",
-        {info, "File ~s prompting for delete status check"}},
+        {debug, "File ~s prompting for delete status check"}},
     {"SFT05",
         {info, "Exit called for reason ~w on filename ~s"}},
     {"SFT06",
@@ -318,9 +325,63 @@ log_timer(LogReference, Subs, StartTime) ->
             ok
     end.
 
+%% Make a log of put timings split out by actor - one log for every
+%% PUT_TIMING_LOGPOINT puts
 
+put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
+    LogRef =
+        case Actor of
+            bookie -> "B0012";
+            inker -> "I0019";
+            journal -> "CDB17"
+        end,
+    log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
+    {1, {T0, T1}, {T0, T1}};
+put_timings(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
+    {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.
 
+%% Make a log of penciller head timings split out by level and result - one
+%% log for every HEAD_TIMING_LOGPOINT puts
+%% Returns a tuple of {Count, TimingDict} to be stored on the process state
 
+head_timings(HeadTimer, SW, Level, R) ->
+    T0 = timer:now_diff(os:timestamp(), SW),
+    head_timings_int(HeadTimer, T0, Level, R).
+
+head_timings_int(undefined, T0, Level, R) -> 
+    Key = head_key(R, Level),
+    NewDFun = fun(K, Acc) ->
+                case K of
+                    Key ->
+                        dict:store(K, [1, T0, T0], Acc);
+                    _ ->
+                        dict:store(K, [0, 0, 0], Acc)
+                end end,
+    {1, lists:foldl(NewDFun, dict:new(), head_keylist())};
+head_timings_int({?HEAD_TIMING_LOGPOINT, HeadTimingD}, T0, Level, R) ->
+    LogFun  = fun(K) -> log("P0032", [K|dict:fetch(K, HeadTimingD)]) end,
+    lists:foreach(LogFun, head_keylist()),
+    head_timings_int(undefined, T0, Level, R);
+head_timings_int({N, HeadTimingD}, T0, Level, R) ->
+    Key = head_key(R, Level),
+    [Count0, Total0, Max0] = dict:fetch(Key, HeadTimingD),
+    {N + 1,
+        dict:store(Key, [Count0 + 1, Total0 + T0, max(Max0, T0)],
+        HeadTimingD)}.
+                                    
+head_key(not_present, _Level) ->
+    not_present;
+head_key(found, 0) ->
+    found_0;
+head_key(found, 1) ->
+    found_1;
+head_key(found, 2) ->
+    found_2;
+head_key(found, Level) when Level > 2 ->
+    found_lower.
+
+head_keylist() ->
+    [not_present, found_lower, found_0, found_1, found_2].
 
 %%%============================================================================
 %%% Test

src/leveled_penciller.erl

@@ -228,7 +228,9 @@
                 levelzero_astree :: list(),
                 
                 ongoing_work = [] :: list(),
-                work_backlog = false :: boolean()}).
+                work_backlog = false :: boolean(),
+                
+                head_timing :: tuple()}).
 
 
 %%%============================================================================
@@ -367,20 +369,20 @@ handle_call({push_mem, {PushedTree, MinSQN, MaxSQN}},
                                         State)}
     end;
 handle_call({fetch, Key, Hash}, _From, State) ->
-    {reply,
+    {R, HeadTimer} = timed_fetch_mem(Key,
-        fetch_mem(Key,
+                                        Hash,
-                    Hash,
+                                        State#state.manifest,
-                    State#state.manifest,
+                                        State#state.levelzero_cache,
-                    State#state.levelzero_cache,
+                                        State#state.levelzero_index,
-                    State#state.levelzero_index),
+                                        State#state.head_timing),
-        State};
+    {reply, R, State#state{head_timing=HeadTimer}};
 handle_call({check_sqn, Key, Hash, SQN}, _From, State) ->
     {reply,
-        compare_to_sqn(fetch_mem(Key,
+        compare_to_sqn(plain_fetch_mem(Key,
-                                    Hash,
+                                        Hash,
-                                    State#state.manifest,
+                                        State#state.manifest,
-                                    State#state.levelzero_cache,
+                                        State#state.levelzero_cache,
-                                    State#state.levelzero_index),
+                                        State#state.levelzero_index),
                         SQN),
         State};
 handle_call({fetch_keys, StartKey, EndKey, AccFun, InitAcc, MaxKeys},
@@ -731,7 +733,21 @@ levelzero_filename(State) ->
                 ++ integer_to_list(MSN) ++ "_0_0",
     FileName.
 
+timed_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index, HeadTimer) ->
+    SW = os:timestamp(),
+    {R, Level} = fetch_mem(Key, Hash, Manifest, L0Cache, L0Index),
+    UpdHeadTimer =
+        case R of
+            not_present ->
+                leveled_log:head_timings(HeadTimer, SW, Level, not_present);
+            _ ->
+                leveled_log:head_timings(HeadTimer, SW, Level, found)
+        end,
+    {R, UpdHeadTimer}.
 
+plain_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) ->
+    R = fetch_mem(Key, Hash, Manifest, L0Cache, L0Index),
+    element(1, R).
 
 fetch_mem(Key, Hash, Manifest, L0Cache, none) ->
     L0Check = leveled_pmem:check_levelzero(Key, Hash, L0Cache),
@@ -739,7 +755,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, none) ->
         {false, not_found} ->
             fetch(Key, Hash, Manifest, 0, fun timed_sft_get/3);
         {true, KV} ->
-            KV
+            {KV, 0}
     end;
 fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) ->
     case leveled_pmem:check_index(Hash, L0Index) of
@@ -750,7 +766,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) ->
     end.
 
 fetch(_Key, _Hash, _Manifest, ?MAX_LEVELS + 1, _FetchFun) ->
-    not_present;
+    {not_present, basement};
 fetch(Key, Hash, Manifest, Level, FetchFun) ->
     LevelManifest = get_item(Level, Manifest, []),
     case lists:foldl(fun(File, Acc) ->
@@ -771,7 +787,7 @@ fetch(Key, Hash, Manifest, Level, FetchFun) ->
                 not_present ->
                     fetch(Key, Hash, Manifest, Level + 1, FetchFun);
                 ObjectFound ->
-                    ObjectFound
+                    {ObjectFound, Level}
             end
     end.