From 299e8e6de3b878214a59d9067d5c9e55d091c4ba Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Tue, 20 Dec 2016 20:55:56 +0000
Subject: [PATCH 01/18] Initial phash test

phash does not appear to be a potential causer of delay
---
 src/leveled_codec.erl | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/src/leveled_codec.erl b/src/leveled_codec.erl
index ffb3f98..5344f53 100644
--- a/src/leveled_codec.erl
+++ b/src/leveled_codec.erl
@@ -469,4 +469,14 @@ stringcheck_test() ->
     ?assertMatch("Bucket", turn_to_string(<<"Bucket">>)),
     ?assertMatch("bucket", turn_to_string(bucket)).
 
+%% Test below proved that the overhead of performing hashes was trivial
+%% Maybe 5 microseconds per hash
+
+hashperf_test() ->
+    OL = lists:map(fun(_X) -> crypto:rand_bytes(8192) end, lists:seq(1, 10000)),
+    SW = os:timestamp(),
+    _HL = lists:map(fun(Obj) -> erlang:phash2(Obj) end, OL),
+    io:format(user, "10000 object hashes in ~w microseconds~n",
+                [timer:now_diff(os:timestamp(), SW)]).
+
 -endif.
\ No newline at end of file

From 060ce2e263e782ab8bb3144977f67c523205de20 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Tue, 20 Dec 2016 23:11:50 +0000
Subject: [PATCH 02/18] Add put timing points

---
 src/leveled_bookie.erl | 25 ++++++++++++++++++++++---
 src/leveled_cdb.erl    | 19 +++++++++++++++++--
 src/leveled_codec.erl  | 12 ++++++------
 src/leveled_inker.erl  | 21 +++++++++++++++++++--
 src/leveled_log.erl    | 11 ++++++++++-
 5 files changed, 74 insertions(+), 14 deletions(-)

diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl
index 35887b8..ee94fac 100644
--- a/src/leveled_bookie.erl
+++ b/src/leveled_bookie.erl
@@ -150,6 +150,7 @@
 -define(CHECKJOURNAL_PROB, 0.2).
 -define(CACHE_SIZE_JITTER, 25).
 -define(JOURNAL_SIZE_JITTER, 20).
+-define(PUT_TIMING_LOGPOINT, 10000).
 
 -record(ledger_cache, {skiplist = leveled_skiplist:empty(true) :: tuple(),
                         min_sqn = infinity :: integer()|infinity,
@@ -160,7 +161,8 @@
                 cache_size :: integer(),
                 ledger_cache = #ledger_cache{},
                 is_snapshot :: boolean(),
-                slow_offer = false :: boolean()}).
+                slow_offer = false :: boolean(),
+                put_timing = {0, {0, 0}, {0, 0}} :: tuple()}).
 
 
 %%%============================================================================
@@ -262,10 +264,12 @@ init([Opts]) ->
 
 handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
     LedgerKey = leveled_codec:to_ledgerkey(Bucket, Key, Tag),
+    SW = os:timestamp(),
     {ok, SQN, ObjSize} = leveled_inker:ink_put(State#state.inker,
                                                 LedgerKey,
                                                 Object,
                                                 {IndexSpecs, TTL}),
+    T0 = timer:now_diff(os:timestamp(), SW),
     Changes = preparefor_ledgercache(no_type_assigned,
                                         LedgerKey,
                                         SQN,
@@ -273,6 +277,8 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
                                         ObjSize,
                                         {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),
     % 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
@@ -286,9 +292,13 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
                                     Cache0,
                                     State#state.penciller) of
         {ok, NewCache} ->
-            {noreply, State#state{ledger_cache=NewCache, slow_offer=false}};
+            {noreply, State#state{ledger_cache=NewCache,
+                                    put_timing=PutTimings,
+                                    slow_offer=false}};
         {returned, NewCache} ->
-            {noreply, State#state{ledger_cache=NewCache, slow_offer=true}}
+            {noreply, State#state{ledger_cache=NewCache,
+                                    put_timing=PutTimings,
+                                    slow_offer=true}}
     end;
 handle_call({get, Bucket, Key, Tag}, _From, State) ->
     LedgerKey = leveled_codec:to_ledgerkey(Bucket, Key, Tag),
@@ -454,6 +464,15 @@ 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)}}.
+
+
 cache_size(LedgerCache) ->
     leveled_skiplist:size(LedgerCache#ledger_cache.skiplist).
 
diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl
index 1c8f9d0..2501098 100644
--- a/src/leveled_cdb.erl
+++ b/src/leveled_cdb.erl
@@ -95,6 +95,7 @@
 -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(),
@@ -108,7 +109,8 @@
                 inker :: pid(),
                 deferred_delete = false :: boolean(),
                 waste_path :: string(),
-                sync_strategy = none}).
+                sync_strategy = none,
+                put_timing = {0, {0, 0}, {0, 0}} :: tuple()}).
 
 
 %%%============================================================================
@@ -256,12 +258,14 @@ writer({key_check, Key}, _From, State) ->
         writer,
         State};
 writer({put_kv, Key, Value}, _From, State) ->
+    SW = os:timestamp(),
     Result = put(State#state.handle,
                     Key,
                     Value,
                     {State#state.last_position, State#state.hashtree},
                     State#state.binary_mode,
                     State#state.max_size),
+    T0 = timer:now_diff(os:timestamp(), SW),
     case Result of
         roll ->
             %% Key and value could not be written
@@ -274,10 +278,13 @@ 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),
             {reply, ok, writer, State#state{handle=UpdHandle,
                                                 last_position=NewPosition,
                                                 last_key=Key,
-                                                hashtree=HashTree}}
+                                                hashtree=HashTree,
+                                                put_timing=Timings}}
     end;
 writer({mput_kv, []}, _From, State) ->
     {reply, ok, writer, State};
@@ -772,6 +779,14 @@ 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".
     
diff --git a/src/leveled_codec.erl b/src/leveled_codec.erl
index 5344f53..b27f5b9 100644
--- a/src/leveled_codec.erl
+++ b/src/leveled_codec.erl
@@ -472,11 +472,11 @@ stringcheck_test() ->
 %% Test below proved that the overhead of performing hashes was trivial
 %% Maybe 5 microseconds per hash
 
-hashperf_test() ->
-    OL = lists:map(fun(_X) -> crypto:rand_bytes(8192) end, lists:seq(1, 10000)),
-    SW = os:timestamp(),
-    _HL = lists:map(fun(Obj) -> erlang:phash2(Obj) end, OL),
-    io:format(user, "10000 object hashes in ~w microseconds~n",
-                [timer:now_diff(os:timestamp(), SW)]).
+%hashperf_test() ->
+%    OL = lists:map(fun(_X) -> crypto:rand_bytes(8192) end, lists:seq(1, 10000)),
+%    SW = os:timestamp(),
+%    _HL = lists:map(fun(Obj) -> erlang:phash2(Obj) end, OL),
+%    io:format(user, "10000 object hashes in ~w microseconds~n",
+%                [timer:now_diff(os:timestamp(), SW)]).
 
 -endif.
\ No newline at end of file
diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl
index 9a37cae..e8fd11e 100644
--- a/src/leveled_inker.erl
+++ b/src/leveled_inker.erl
@@ -126,6 +126,7 @@
 -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(),
@@ -138,7 +139,8 @@
                 clerk :: pid(),
                 compaction_pending = false :: boolean(),
                 is_snapshot = false :: boolean(),
-                source_inker :: pid()}).
+                source_inker :: pid(),
+                put_timing = {0, {0, 0}, {0, 0}} ::tuple()}).
 
 
 %%%============================================================================
@@ -414,15 +416,21 @@ start_from_file(InkOpts) ->
 
 put_object(LedgerKey, Object, KeyChanges, State) ->
     NewSQN = State#state.journal_sqn + 1,
+    SW= os:timestamp(),
     {JournalKey, JournalBin} = leveled_codec:to_inkerkv(LedgerKey,
                                                             NewSQN,
                                                             Object,
                                                             KeyChanges),
+    T0 = timer:now_diff(os:timestamp(), SW),
     case leveled_cdb:cdb_put(State#state.active_journaldb,
                                 JournalKey,
                                 JournalBin) of
         ok ->
-            {ok, State#state{journal_sqn=NewSQN}, byte_size(JournalBin)};
+            T1 = timer:now_diff(os:timestamp(), SW) - T0,
+            UpdPutTimings = update_put_timings(State#state.put_timing, T0, T1),
+            {ok,
+                State#state{journal_sqn=NewSQN, put_timing=UpdPutTimings},
+                byte_size(JournalBin)};
         roll ->
             SW = os:timestamp(),
             CDBopts = State#state.cdb_options,
@@ -742,6 +750,15 @@ 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
 %%%============================================================================
diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 5c36cf7..c4a50bf 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -40,6 +40,9 @@
         {info, "Bucket list finds non-binary Bucket ~w"}},
     {"B0011",
         {warn, "Call to destroy the store and so all files to be removed"}},
+    {"B0012",
+        {info, "After ~w PUTs total inker time is ~w total ledger time is ~w "
+                ++ "and max inker time is ~w and max ledger time is ~w"}},
     
     {"P0001",
         {info, "Ledger snapshot ~w registered"}},
@@ -176,6 +179,9 @@
         {info, "At SQN=~w journal has filename ~s"}},
     {"I0018",
         {warn, "We're doomed - intention recorded to destroy all files"}},
+    {"I0019",
+        {info, "After ~w PUTs total prepare time is ~w total cdb time is ~w "
+                ++ "and max prepare time is ~w and max cdb time is ~w"}},
     
     {"IC001",
         {info, "Closed for reason ~w so maybe leaving garbage"}},
@@ -271,7 +277,10 @@
         {info, "Cycle count of ~w in hashtable search higher than expected"
                 ++ " in search for hash ~w with result ~w"}},
     {"CDB16",
-        {info, "CDB scan from start ~w in file with end ~w and last_key ~w"}}
+        {info, "CDB scan from start ~w in file with end ~w and last_key ~w"}},
+    {"CDB17",
+        {info, "After ~w PUTs total write time is ~w total sync time is ~w "
+                ++ "and max write time is ~w and max sync time is ~w"}}
         ])).
 
 

From c193962c92f10ccc394a601e0ddf28970bcbbb8a Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Tue, 20 Dec 2016 23:16:52 +0000
Subject: [PATCH 03/18] Sort out different timestamps

---
 src/leveled_inker.erl | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl
index e8fd11e..4908351 100644
--- a/src/leveled_inker.erl
+++ b/src/leveled_inker.erl
@@ -432,7 +432,7 @@ put_object(LedgerKey, Object, KeyChanges, State) ->
                 State#state{journal_sqn=NewSQN, put_timing=UpdPutTimings},
                 byte_size(JournalBin)};
         roll ->
-            SW = os:timestamp(),
+            SWroll = os:timestamp(),
             CDBopts = State#state.cdb_options,
             ManEntry = start_new_activejournal(NewSQN,
                                                 State#state.root_path,
@@ -445,7 +445,7 @@ put_object(LedgerKey, Object, KeyChanges, State) ->
             ok = leveled_cdb:cdb_put(NewJournalP,
                                         JournalKey,
                                         JournalBin),
-            leveled_log:log_timer("I0008", [], SW),
+            leveled_log:log_timer("I0008", [], SWroll),
             {rolling,
                 State#state{journal_sqn=NewSQN,
                                 manifest=NewManifest,

From f3e16dcd10be4e57cdd26e4dc79a7108c3960678 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 01:56:12 +0000
Subject: [PATCH 04/18] Add long-running logs

---
 src/leveled_bookie.erl | 15 +++++++++++++++
 src/leveled_log.erl    |  2 ++
 2 files changed, 17 insertions(+)

diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl
index ee94fac..e058c5b 100644
--- a/src/leveled_bookie.erl
+++ b/src/leveled_bookie.erl
@@ -288,6 +288,7 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
         false ->
             gen_server:reply(From, ok)
     end,
+    maybe_longrunning(SW, overall_put),
     case maybepush_ledgercache(State#state.cache_size,
                                     Cache0,
                                     State#state.penciller) of
@@ -472,6 +473,14 @@ update_put_timings({?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}},
 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 ->
+            leveled_log:log("B0013", [N, Aspect]);
+        _ ->
+            ok
+    end.
+
 
 cache_size(LedgerCache) ->
     leveled_skiplist:size(LedgerCache#ledger_cache.skiplist).
@@ -747,6 +756,7 @@ startup(InkerOpts, PencillerOpts) ->
 
 
 fetch_head(Key, Penciller, LedgerCache) ->
+    SW = os:timestamp(),
     Hash = leveled_codec:magic_hash(Key),
     if
         Hash /= no_lookup ->
@@ -755,20 +765,25 @@ fetch_head(Key, Penciller, LedgerCache) ->
                                             LedgerCache#ledger_cache.skiplist),
             case L0R of
                 {value, Head} ->
+                    maybe_longrunning(SW, local_head),
                     Head;
                 none ->
                     case leveled_penciller:pcl_fetch(Penciller, Key, Hash) of
                         {Key, Head} ->
+                            maybe_longrunning(SW, pcl_head),
                             Head;
                         not_present ->
+                            maybe_longrunning(SW, pcl_head),
                             not_present
                     end
             end
     end.
 
 fetch_value(Key, SQN, Inker) ->
+    SW = os:timestamp(),
     case leveled_inker:ink_fetch(Inker, Key, SQN) of
         {ok, Value} ->
+            maybe_longrunning(SW, inker_fetch),
             Value;
         not_present ->
             not_present
diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index c4a50bf..e37552d 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -43,6 +43,8 @@
     {"B0012",
         {info, "After ~w PUTs total inker time is ~w total ledger time is ~w "
                 ++ "and max inker time is ~w and max ledger time is ~w"}},
+    {"B0013",
+        {warn, "Long running task took ~w microseconds with task of type ~w"}},
     
     {"P0001",
         {info, "Ledger snapshot ~w registered"}},

From be775127e847fe67355a484b36c914269084f1d6 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 12:45:27 +0000
Subject: [PATCH 05/18] Improve logging of merge activity and slow GETs

Look into speculation that collisions between fetch_rnage and fetch may
be an issue
---
 src/leveled_log.erl       |  5 ++++-
 src/leveled_penciller.erl | 20 ++++++++++++++++++--
 src/leveled_sft.erl       |  2 ++
 3 files changed, 24 insertions(+), 3 deletions(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index e37552d..225c113 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -142,6 +142,8 @@
         {info, "Empty file ~s to be cleared"}},
     {"PC015",
         {info, "File created"}},
+    {"PC016",
+        {info, "Slow fetch from SFT ~w of ~w microseconds with result ~w"}},
     
     {"I0001",
         {info, "Unexpected failure to fetch value for Key=~w SQN=~w "
@@ -243,7 +245,8 @@
         {error, "Segment filter failed due to CRC check ~w did not match ~w"}},
     {"SFT13",
         {error, "Segment filter failed due to ~s"}},
-    
+    {"SFT14",
+        {info, "Range fetch from SFT PID ~w"}},
     
     {"CDB01",
         {info, "Opening file for writing with filename ~s"}},
diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl
index 82dc432..f338076 100644
--- a/src/leveled_penciller.erl
+++ b/src/leveled_penciller.erl
@@ -202,6 +202,7 @@
 -define(PROMPT_WAIT_ONL0, 5).
 -define(WORKQUEUE_BACKLOG_TOLERANCE, 4).
 -define(COIN_SIDECOUNT, 5).
+-define(SLOW_FETCH, 10000).
 
 -record(state, {manifest = [] :: list(),
 				manifest_sqn = 0 :: integer(),
@@ -736,7 +737,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, none) ->
     L0Check = leveled_pmem:check_levelzero(Key, Hash, L0Cache),
     case L0Check of
         {false, not_found} ->
-            fetch(Key, Hash, Manifest, 0, fun leveled_sft:sft_get/3);
+            fetch(Key, Hash, Manifest, 0, fun timed_sft_get/3);
         {true, KV} ->
             KV
     end;
@@ -745,7 +746,7 @@ fetch_mem(Key, Hash, Manifest, L0Cache, L0Index) ->
         true ->
             fetch_mem(Key, Hash, Manifest, L0Cache, none);
         false ->
-            fetch(Key, Hash, Manifest, 0, fun leveled_sft:sft_get/3)
+            fetch(Key, Hash, Manifest, 0, fun timed_sft_get/3)
     end.
 
 fetch(_Key, _Hash, _Manifest, ?MAX_LEVELS + 1, _FetchFun) ->
@@ -774,6 +775,21 @@ fetch(Key, Hash, Manifest, Level, FetchFun) ->
             end
     end.
     
+timed_sft_get(PID, Key, Hash) ->
+    SW = os:timestamp(),
+    R = leveled_sft:sft_get(PID, Key, Hash),
+    T0 = timer:now_diff(os:timestamp(), SW),
+    case {T0, R} of
+        {T, R} when T < ?SLOW_FETCH ->
+            R;
+        {T, not_present} ->
+            leveled_log:log("PC016", [PID, T, not_present]),
+            not_present;
+        {T, R} ->
+            leveled_log:log("PC016", [PID, T, found]),
+            R
+    end.
+    
 
 compare_to_sqn(Obj, SQN) ->
     case Obj of
diff --git a/src/leveled_sft.erl b/src/leveled_sft.erl
index 7cffdd7..d66dfaf 100644
--- a/src/leveled_sft.erl
+++ b/src/leveled_sft.erl
@@ -1100,7 +1100,9 @@ maybe_expand_pointer([H|Tail]) ->
     case H of
         {next, SFTPid, StartKey} ->
             %% io:format("Scanning further on PID ~w ~w~n", [SFTPid, StartKey]),
+            SW = os:timestamp(),
             Acc = sft_getkvrange(SFTPid, StartKey, all, ?MERGE_SCANWIDTH),
+            leveled_log:log_timer("SFT14", [SFTPid], SW),
             lists:append(Acc, Tail);
         _ ->
             [H|Tail]

From b2835aeaeca48d2bceac9e079a88c3da67b1df1a Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 18:28:14 +0000
Subject: [PATCH 06/18] Improve fetching efficiency

Experiment to see if parsing all keys in block can be avoided - and if
so does this make the range scan more efficient.

Unproven change.
---
 src/leveled_penciller.erl |  2 +-
 src/leveled_sft.erl       | 31 ++++++++++++++++++++++++++++++-
 2 files changed, 31 insertions(+), 2 deletions(-)

diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl
index f338076..ad13bfc 100644
--- a/src/leveled_penciller.erl
+++ b/src/leveled_penciller.erl
@@ -202,7 +202,7 @@
 -define(PROMPT_WAIT_ONL0, 5).
 -define(WORKQUEUE_BACKLOG_TOLERANCE, 4).
 -define(COIN_SIDECOUNT, 5).
--define(SLOW_FETCH, 10000).
+-define(SLOW_FETCH, 20000).
 
 -record(state, {manifest = [] :: list(),
 				manifest_sqn = 0 :: integer(),
diff --git a/src/leveled_sft.erl b/src/leveled_sft.erl
index d66dfaf..8c42d23 100644
--- a/src/leveled_sft.erl
+++ b/src/leveled_sft.erl
@@ -644,6 +644,8 @@ acc_list_keysonly(null, empty) ->
     [];
 acc_list_keysonly(null, RList) ->
     RList;
+acc_list_keysonly(R, RList) when is_list(R) ->
+    lists:foldl(fun acc_list_keysonly/2, RList, R);
 acc_list_keysonly(R, RList) ->
     lists:append(RList, [leveled_codec:strip_to_keyseqstatusonly(R)]).
 
@@ -651,6 +653,8 @@ acc_list_kv(null, empty) ->
     [];
 acc_list_kv(null, RList) ->
     RList;
+acc_list_kv(R, RList) when is_list(R) ->
+    RList ++ R;
 acc_list_kv(R, RList) ->
     lists:append(RList, [R]).
 
@@ -713,7 +717,13 @@ fetch_range(Handle, FileMD, StartKey, NearestKey, EndKey,
                         Pointer,
                         Acc) ->
     Block = fetch_block(Handle, LengthList, BlockNumber, Pointer),
-    Results = scan_block(Block, StartKey, EndKey, AccFun, Acc),
+    Results = 
+        case maybe_scan_entire_block(Block, StartKey, EndKey) of
+            true ->
+                {partial, AccFun(Block, Acc), StartKey};
+            false ->
+                scan_block(Block, StartKey, EndKey, AccFun, Acc)
+        end,
     case Results of
         {partial, Acc1, StartKey} ->
             %% Move on to the next block
@@ -741,6 +751,25 @@ scan_block([HeadKV|T], StartKey, EndKey, AccFun, Acc) ->
     end.
 
 
+maybe_scan_entire_block([], _, _) ->
+    true;
+maybe_scan_entire_block(_Block, all, all) ->
+    true;
+maybe_scan_entire_block(Block, StartKey, all) ->
+    [FirstKey|_Tail] = Block,
+    leveled_codec:strip_to_keyonly(FirstKey) >= StartKey;
+maybe_scan_entire_block(Block, StartKey, EndKey) ->
+    [FirstKey|_Tail] = Block,
+    LastKey = leveled_codec:strip_to_keyonly(lists:last(Block)),
+    FromStart = leveled_codec:strip_to_keyonly(FirstKey) >= StartKey,
+    ToEnd = leveled_codec:endkey_passed(EndKey, LastKey),
+    case {FromStart, ToEnd} of
+        {true, true} ->
+            true;
+        _ ->
+            false
+    end.
+
 fetch_keyvalue_fromblock([], _Key, _LengthList, _Handle, _StartOfSlot) ->
     not_present;
 fetch_keyvalue_fromblock([BlockNmb|T], Key, LengthList, Handle, StartOfSlot) ->

From 3de146043bcd1e33add0bfd6aa241405f613175a Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 21:41:54 +0000
Subject: [PATCH 07/18] Its not like there's more than two hard things

D'oh
---
 src/leveled_sft.erl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/leveled_sft.erl b/src/leveled_sft.erl
index 8c42d23..46703c8 100644
--- a/src/leveled_sft.erl
+++ b/src/leveled_sft.erl
@@ -761,7 +761,7 @@ maybe_scan_entire_block(Block, StartKey, all) ->
 maybe_scan_entire_block(Block, StartKey, EndKey) ->
     [FirstKey|_Tail] = Block,
     LastKey = leveled_codec:strip_to_keyonly(lists:last(Block)),
-    FromStart = leveled_codec:strip_to_keyonly(FirstKey) >= StartKey,
+    FromStart = leveled_codec:strip_to_keyonly(FirstKey) > StartKey,
     ToEnd = leveled_codec:endkey_passed(EndKey, LastKey),
     case {FromStart, ToEnd} of
         {true, true} ->

From 39d634c95bba221e1fc91ece5def9ea2a22c7acd Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 21:49:08 +0000
Subject: [PATCH 08/18] And again

---
 src/leveled_sft.erl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/leveled_sft.erl b/src/leveled_sft.erl
index 46703c8..2660cf5 100644
--- a/src/leveled_sft.erl
+++ b/src/leveled_sft.erl
@@ -757,7 +757,7 @@ maybe_scan_entire_block(_Block, all, all) ->
     true;
 maybe_scan_entire_block(Block, StartKey, all) ->
     [FirstKey|_Tail] = Block,
-    leveled_codec:strip_to_keyonly(FirstKey) >= StartKey;
+    leveled_codec:strip_to_keyonly(FirstKey) > StartKey;
 maybe_scan_entire_block(Block, StartKey, EndKey) ->
     [FirstKey|_Tail] = Block,
     LastKey = leveled_codec:strip_to_keyonly(lists:last(Block)),

From ea20fc07f4d587e6313045e1fa127a5faadebba0 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Wed, 21 Dec 2016 21:56:33 +0000
Subject: [PATCH 09/18] Maybe not

---
 src/leveled_sft.erl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/leveled_sft.erl b/src/leveled_sft.erl
index 2660cf5..e736a47 100644
--- a/src/leveled_sft.erl
+++ b/src/leveled_sft.erl
@@ -764,7 +764,7 @@ maybe_scan_entire_block(Block, StartKey, EndKey) ->
     FromStart = leveled_codec:strip_to_keyonly(FirstKey) > StartKey,
     ToEnd = leveled_codec:endkey_passed(EndKey, LastKey),
     case {FromStart, ToEnd} of
-        {true, true} ->
+        {true, false} ->
             true;
         _ ->
             false

From 130fb36ddd428ccc33c3ad21796f5660427a4bde Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 14:03:31 +0000
Subject: [PATCH 10/18] Add head timings

Include log breaking down timings of HEAD requests by result and level
---
 src/leveled_bookie.erl    | 19 ++++--------
 src/leveled_cdb.erl       | 13 ++------
 src/leveled_inker.erl     | 15 +++------
 src/leveled_log.erl       | 65 +++++++++++++++++++++++++++++++++++++--
 src/leveled_penciller.erl | 48 +++++++++++++++++++----------
 5 files changed, 108 insertions(+), 52 deletions(-)

diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl
index e058c5b..cdc39ff 100644
--- a/src/leveled_bookie.erl
+++ b/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).
 
diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl
index 2501098..66c528c 100644
--- a/src/leveled_cdb.erl
+++ b/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".
     
diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl
index 4908351..df3c33a 100644
--- a/src/leveled_inker.erl
+++ b/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
diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 225c113..1c6d5ad 100644
--- a/src/leveled_log.erl
+++ b/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
diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl
index ad13bfc..689a701 100644
--- a/src/leveled_penciller.erl
+++ b/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,
-        fetch_mem(Key,
-                    Hash,
-                    State#state.manifest,
-                    State#state.levelzero_cache,
-                    State#state.levelzero_index),
-        State};
+    {R, HeadTimer} = timed_fetch_mem(Key,
+                                        Hash,
+                                        State#state.manifest,
+                                        State#state.levelzero_cache,
+                                        State#state.levelzero_index,
+                                        State#state.head_timing),
+    {reply, R, State#state{head_timing=HeadTimer}};
 handle_call({check_sqn, Key, Hash, SQN}, _From, State) ->
     {reply,
-        compare_to_sqn(fetch_mem(Key,
-                                    Hash,
-                                    State#state.manifest,
-                                    State#state.levelzero_cache,
-                                    State#state.levelzero_index),
+        compare_to_sqn(plain_fetch_mem(Key,
+                                        Hash,
+                                        State#state.manifest,
+                                        State#state.levelzero_cache,
+                                        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.
     

From df350e1e6f83b4ba306b0e6dd6bd9e9993628718 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 14:09:17 +0000
Subject: [PATCH 11/18] Add unit test for head timing

---
 src/leveled_log.erl | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 1c6d5ad..3154ab6 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -395,4 +395,14 @@ log_test() ->
     log("D0001", []),
     log_timer("D0001", [], os:timestamp()).
 
+head_timing_test() ->
+    SW = os:timestamp(),
+    HeadTimer0 = head_timings(undefined, SW, 2, found),
+    HeadTimer1 = head_timings(HeadTimer0, SW, 2, found),
+    HeadTimer2 = head_timings(HeadTimer1, SW, 3, found),
+    {N, D} = HeadTimer2,
+    ?assertMatch(3, N),
+    ?assertMatch(2, lists:nth(1, dict:fetch(found_2, D))),
+    ?assertMatch(1, lists:nth(1, dict:fetch(found_lower, D))).
+
 -endif.
\ No newline at end of file

From e9e0a7b323aec003f216d66e80c01493f0a31b25 Mon Sep 17 00:00:00 2001
From: Martin Sumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 14:36:57 +0000
Subject: [PATCH 12/18] Set higher logpoint

Expectation is for many HEAD requests - so only log every 100K
---
 src/leveled_log.erl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 3154ab6..50163f3 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -13,7 +13,7 @@
             head_timings/4]).         
 
 -define(PUT_TIMING_LOGPOINT, 10000).
--define(HEAD_TIMING_LOGPOINT, 10000).
+-define(HEAD_TIMING_LOGPOINT, 100000).
 -define(LOG_LEVEL, [info, warn, error, critical]).
 
 -define(LOGBASE, dict:from_list([

From 7a0cf22909df1130c7fc9564efa4fd5f40ca721f Mon Sep 17 00:00:00 2001
From: Martin Sumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 14:41:43 +0000
Subject: [PATCH 13/18] put-timing default

Remove need for individual actors to know the defaults for put_timing
tuple
---
 src/leveled_bookie.erl | 2 +-
 src/leveled_cdb.erl    | 2 +-
 src/leveled_inker.erl  | 2 +-
 src/leveled_log.erl    | 4 +++-
 4 files changed, 6 insertions(+), 4 deletions(-)

diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl
index cdc39ff..af0f102 100644
--- a/src/leveled_bookie.erl
+++ b/src/leveled_bookie.erl
@@ -162,7 +162,7 @@
                 ledger_cache = #ledger_cache{},
                 is_snapshot :: boolean(),
                 slow_offer = false :: boolean(),
-                put_timing = {0, {0, 0}, {0, 0}} :: tuple()}).
+                put_timing :: tuple()}).
 
 
 %%%============================================================================
diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl
index 66c528c..816e43c 100644
--- a/src/leveled_cdb.erl
+++ b/src/leveled_cdb.erl
@@ -109,7 +109,7 @@
                 deferred_delete = false :: boolean(),
                 waste_path :: string(),
                 sync_strategy = none,
-                put_timing = {0, {0, 0}, {0, 0}} :: tuple()}).
+                put_timing :: tuple()}).
 
 
 %%%============================================================================
diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl
index df3c33a..7fa7a25 100644
--- a/src/leveled_inker.erl
+++ b/src/leveled_inker.erl
@@ -139,7 +139,7 @@
                 compaction_pending = false :: boolean(),
                 is_snapshot = false :: boolean(),
                 source_inker :: pid(),
-                put_timing = {0, {0, 0}, {0, 0}} ::tuple()}).
+                put_timing :: tuple()}).
 
 
 %%%============================================================================
diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 50163f3..67151cc 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -328,6 +328,8 @@ log_timer(LogReference, Subs, StartTime) ->
 %% Make a log of put timings split out by actor - one log for every
 %% PUT_TIMING_LOGPOINT puts
 
+put_timings(_Actor, undefined, T0, T1) ->
+    {1, {T0, T1}, {T0, T1}};
 put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
     LogRef =
         case Actor of
@@ -336,7 +338,7 @@ put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T
             journal -> "CDB17"
         end,
     log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
-    {1, {T0, T1}, {T0, T1}};
+    put_timings(Actor, undefined, T0, T1);
 put_timings(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
     {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.
 

From 676e8fa4949b294d55d14ee5261a6de1c2e91763 Mon Sep 17 00:00:00 2001
From: Martin Sumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 15:45:38 +0000
Subject: [PATCH 14/18] Add Get Timing

---
 src/leveled_bookie.erl    | 26 +++++++++++-----
 src/leveled_cdb.erl       |  2 +-
 src/leveled_inker.erl     |  2 +-
 src/leveled_log.erl       | 65 +++++++++++++++++++++++++++++----------
 src/leveled_penciller.erl |  4 +--
 5 files changed, 71 insertions(+), 28 deletions(-)

diff --git a/src/leveled_bookie.erl b/src/leveled_bookie.erl
index af0f102..90a0b2a 100644
--- a/src/leveled_bookie.erl
+++ b/src/leveled_bookie.erl
@@ -162,7 +162,8 @@
                 ledger_cache = #ledger_cache{},
                 is_snapshot :: boolean(),
                 slow_offer = false :: boolean(),
-                put_timing :: tuple()}).
+                put_timing :: tuple(),
+                get_timing :: tuple()}).
 
 
 %%%============================================================================
@@ -278,7 +279,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,
-    PutTimes = leveled_log:put_timings(bookie, State#state.put_timing, T0, T1),
+    PutTimes = leveled_log:put_timing(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
@@ -303,26 +304,35 @@ handle_call({put, Bucket, Key, Object, IndexSpecs, Tag, TTL}, From, State) ->
     end;
 handle_call({get, Bucket, Key, Tag}, _From, State) ->
     LedgerKey = leveled_codec:to_ledgerkey(Bucket, Key, Tag),
+    SWh = os:timestamp(),
     case fetch_head(LedgerKey,
                     State#state.penciller,
                     State#state.ledger_cache) of
         not_present ->
-            {reply, not_found, State};
+            GT0 = leveled_log:get_timing(State#state.get_timing, 
+                                            SWh,
+                                            head_not_present),
+            {reply, not_found, State#state{get_timing=GT0}};
         Head ->
+            GT0 = leveled_log:get_timing(State#state.get_timing, 
+                                            SWh,
+                                            head_found),
+            SWg = os:timestamp(),
             {Seqn, Status, _MH, _MD} = leveled_codec:striphead_to_details(Head),
             case Status of
                 tomb ->
                     {reply, not_found, State};
                 {active, TS} ->
                     Active = TS >= leveled_codec:integer_now(),
-                    case {Active,
-                            fetch_value(LedgerKey, Seqn, State#state.inker)} of
+                    Object = fetch_value(LedgerKey, Seqn, State#state.inker),
+                    GT1 = leveled_log:get_timing(GT0, SWg, fetch),
+                    case {Active, Object} of
                         {_, not_present} ->
-                            {reply, not_found, State};
+                            {reply, not_found, State#state{get_timing=GT1}};
                         {true, Object} ->
-                            {reply, {ok, Object}, State};
+                            {reply, {ok, Object}, State#state{get_timing=GT1}};
                         _ ->
-                            {reply, not_found, State}
+                            {reply, not_found, State#state{get_timing=GT1}}
                     end
             end
     end;
diff --git a/src/leveled_cdb.erl b/src/leveled_cdb.erl
index 816e43c..0c0f745 100644
--- a/src/leveled_cdb.erl
+++ b/src/leveled_cdb.erl
@@ -278,7 +278,7 @@ writer({put_kv, Key, Value}, _From, State) ->
                         ok
                 end,
             T1 = timer:now_diff(os:timestamp(), SW) - T0,
-            Timings = leveled_log:put_timings(journal,
+            Timings = leveled_log:put_timing(journal,
                                                 State#state.put_timing,
                                                 T0, T1),
             {reply, ok, writer, State#state{handle=UpdHandle,
diff --git a/src/leveled_inker.erl b/src/leveled_inker.erl
index 7fa7a25..f56ea20 100644
--- a/src/leveled_inker.erl
+++ b/src/leveled_inker.erl
@@ -426,7 +426,7 @@ put_object(LedgerKey, Object, KeyChanges, State) ->
                                 JournalBin) of
         ok ->
             T1 = timer:now_diff(os:timestamp(), SW) - T0,
-            UpdPutTimes = leveled_log:put_timings(inker,
+            UpdPutTimes = leveled_log:put_timing(inker,
                                                     State#state.put_timing,
                                                     T0, T1),
             {ok,
diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 67151cc..4b87108 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -9,11 +9,13 @@
 
 -export([log/2,
             log_timer/3,
-            put_timings/4,
-            head_timings/4]).         
+            put_timing/4,
+            head_timing/4,
+            get_timing/3]).         
 
--define(PUT_TIMING_LOGPOINT, 10000).
+-define(PUT_TIMING_LOGPOINT, 20000).
 -define(HEAD_TIMING_LOGPOINT, 100000).
+-define(GET_TIMING_LOGPOINT, 50000).
 -define(LOG_LEVEL, [info, warn, error, critical]).
 
 -define(LOGBASE, dict:from_list([
@@ -50,6 +52,8 @@
                 ++ "and max inker time is ~w and max ledger time is ~w"}},
     {"B0013",
         {warn, "Long running task took ~w microseconds with task of type ~w"}},
+    {"B0014",
+        {info, "Get timing for result ~w is count ~w total ~w and max ~w"}},
     
     {"P0001",
         {info, "Ledger snapshot ~w registered"}},
@@ -328,9 +332,9 @@ log_timer(LogReference, Subs, StartTime) ->
 %% Make a log of put timings split out by actor - one log for every
 %% PUT_TIMING_LOGPOINT puts
 
-put_timings(_Actor, undefined, T0, T1) ->
+put_timing(_Actor, undefined, T0, T1) ->
     {1, {T0, T1}, {T0, T1}};
-put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
+put_timing(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
     LogRef =
         case Actor of
             bookie -> "B0012";
@@ -338,19 +342,19 @@ put_timings(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}}, T0, T
             journal -> "CDB17"
         end,
     log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
-    put_timings(Actor, undefined, T0, T1);
-put_timings(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
+    put_timing(Actor, undefined, T0, T1);
+put_timing(_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) ->
+head_timing(HeadTimer, SW, Level, R) ->
     T0 = timer:now_diff(os:timestamp(), SW),
-    head_timings_int(HeadTimer, T0, Level, R).
+    head_timing_int(HeadTimer, T0, Level, R).
 
-head_timings_int(undefined, T0, Level, R) -> 
+head_timing_int(undefined, T0, Level, R) -> 
     Key = head_key(R, Level),
     NewDFun = fun(K, Acc) ->
                 case K of
@@ -360,11 +364,11 @@ head_timings_int(undefined, T0, Level, R) ->
                         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) ->
+head_timing_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) ->
+    head_timing_int(undefined, T0, Level, R);
+head_timing_int({N, HeadTimingD}, T0, Level, R) ->
     Key = head_key(R, Level),
     [Count0, Total0, Max0] = dict:fetch(Key, HeadTimingD),
     {N + 1,
@@ -385,6 +389,35 @@ head_key(found, Level) when Level > 2 ->
 head_keylist() ->
     [not_present, found_lower, found_0, found_1, found_2].
 
+get_timing(GetTimer, SW, TimerType) ->
+    T0 = timer:now_diff(os:timestamp(), SW),
+    get_timing_int(GetTimer, T0, TimerType).
+
+get_timing_int(undefined, T0, TimerType) ->
+    NewDFun = fun(K, Acc) ->
+                case K of
+                    TimerType ->
+                        dict:store(K, [1, T0, T0], Acc);
+                    _ ->
+                        dict:store(K, [0, 0, 0], Acc)
+                end end,
+    {1, lists:foldl(NewDFun, dict:new(), get_keylist())};
+get_timing_int({?GET_TIMING_LOGPOINT, GetTimerD}, T0, TimerType) ->
+    LogFun  = fun(K) -> log("B0014", [K|dict:fetch(K, GetTimerD)]) end,
+    lists:foreach(LogFun, get_keylist()),
+    get_timing_int(undefined, T0, TimerType);
+get_timing_int({N, GetTimerD}, T0, TimerType) ->
+    [Count0, Total0, Max0] = dict:fetch(TimerType, GetTimerD),
+    {N + 1, 
+        dict:store(TimerType, 
+                    [Count0 + 1, Total0 + T0, max(Max0, T0)], 
+                    GetTimerD)}.
+
+
+
+get_keylist() ->
+    [head_not_present, head_found, fetch].
+
 %%%============================================================================
 %%% Test
 %%%============================================================================
@@ -399,9 +432,9 @@ log_test() ->
 
 head_timing_test() ->
     SW = os:timestamp(),
-    HeadTimer0 = head_timings(undefined, SW, 2, found),
-    HeadTimer1 = head_timings(HeadTimer0, SW, 2, found),
-    HeadTimer2 = head_timings(HeadTimer1, SW, 3, found),
+    HeadTimer0 = head_timing(undefined, SW, 2, found),
+    HeadTimer1 = head_timing(HeadTimer0, SW, 2, found),
+    HeadTimer2 = head_timing(HeadTimer1, SW, 3, found),
     {N, D} = HeadTimer2,
     ?assertMatch(3, N),
     ?assertMatch(2, lists:nth(1, dict:fetch(found_2, D))),
diff --git a/src/leveled_penciller.erl b/src/leveled_penciller.erl
index 689a701..0de9b2b 100644
--- a/src/leveled_penciller.erl
+++ b/src/leveled_penciller.erl
@@ -739,9 +739,9 @@ timed_fetch_mem(Key, Hash, Manifest, L0Cache, L0Index, HeadTimer) ->
     UpdHeadTimer =
         case R of
             not_present ->
-                leveled_log:head_timings(HeadTimer, SW, Level, not_present);
+                leveled_log:head_timing(HeadTimer, SW, Level, not_present);
             _ ->
-                leveled_log:head_timings(HeadTimer, SW, Level, found)
+                leveled_log:head_timing(HeadTimer, SW, Level, found)
         end,
     {R, UpdHeadTimer}.
 

From 151dd3ab7036ce716ab0d595946b8425faddb910 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 16:47:36 +0000
Subject: [PATCH 15/18] Sample only for HEAD/GET response times

Report regularly but only on a sample
---
 src/leveled_log.erl | 47 ++++++++++++++++++++++++++++++++-------------
 1 file changed, 34 insertions(+), 13 deletions(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 4b87108..0848e0b 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -17,6 +17,7 @@
 -define(HEAD_TIMING_LOGPOINT, 100000).
 -define(GET_TIMING_LOGPOINT, 50000).
 -define(LOG_LEVEL, [info, warn, error, critical]).
+-define(SAMPLE_RATE, 16#F).
 
 -define(LOGBASE, dict:from_list([
 
@@ -53,7 +54,7 @@
     {"B0013",
         {warn, "Long running task took ~w microseconds with task of type ~w"}},
     {"B0014",
-        {info, "Get timing for result ~w is count ~w total ~w and max ~w"}},
+        {info, "Get timing for result ~w is sample ~w total ~w and max ~w"}},
     
     {"P0001",
         {info, "Ledger snapshot ~w registered"}},
@@ -121,7 +122,7 @@
     {"P0031",
         {info, "Completion of update to levelzero"}},
     {"P0032",
-        {info, "Head timing for result ~w is count ~w total ~w and max ~w"}},
+        {info, "Head timing for result ~w is sample ~w total ~w and max ~w"}},
     
     {"PC001",
         {info, "Penciller's clerk ~w started with owner ~w"}},
@@ -349,10 +350,18 @@ put_timing(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, 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_timing(HeadTimer, SW, Level, R) ->
+head_timing(undefined, SW, Level, R) ->
     T0 = timer:now_diff(os:timestamp(), SW),
-    head_timing_int(HeadTimer, T0, Level, R).
+    head_timing_int(undefined, T0, Level, R);
+head_timing({N, HeadTimingD}, SW, Level, R) ->
+    case N band ?SAMPLE_RATE of
+        0 ->
+            T0 = timer:now_diff(os:timestamp(), SW),
+            head_timing_int({N, HeadTimingD}, T0, Level, R);
+        _ ->
+            % Not to be sampled this time
+            {N + 1, HeadTimingD}
+    end.
 
 head_timing_int(undefined, T0, Level, R) -> 
     Key = head_key(R, Level),
@@ -389,9 +398,20 @@ head_key(found, Level) when Level > 2 ->
 head_keylist() ->
     [not_present, found_lower, found_0, found_1, found_2].
 
-get_timing(GetTimer, SW, TimerType) ->
+
+
+get_timing(undefined, SW, TimerType) ->
     T0 = timer:now_diff(os:timestamp(), SW),
-    get_timing_int(GetTimer, T0, TimerType).
+    get_timing_int(undefined, T0, TimerType);
+get_timing({N, GetTimerD}, SW, TimerType) ->
+    case N band ?SAMPLE_RATE of
+        0 ->
+            T0 = timer:now_diff(os:timestamp(), SW),
+            get_timing_int({N, GetTimerD}, T0, TimerType);
+        _ ->
+            % Not to be sampled this time
+            {N + 1, GetTimerD}
+    end.
 
 get_timing_int(undefined, T0, TimerType) ->
     NewDFun = fun(K, Acc) ->
@@ -432,12 +452,13 @@ log_test() ->
 
 head_timing_test() ->
     SW = os:timestamp(),
-    HeadTimer0 = head_timing(undefined, SW, 2, found),
-    HeadTimer1 = head_timing(HeadTimer0, SW, 2, found),
-    HeadTimer2 = head_timing(HeadTimer1, SW, 3, found),
-    {N, D} = HeadTimer2,
-    ?assertMatch(3, N),
-    ?assertMatch(2, lists:nth(1, dict:fetch(found_2, D))),
+    HeadTimer0 = lists:foldl(fun(_X, Acc) -> head_timing(Acc, SW, 2, found) end,
+                                undefined,
+                                lists:seq(0, 47)),
+    HeadTimer1 = head_timing(HeadTimer0, SW, 3, found),
+    {N, D} = HeadTimer1,
+    ?assertMatch(49, N),
+    ?assertMatch(3, lists:nth(1, dict:fetch(found_2, D))),
     ?assertMatch(1, lists:nth(1, dict:fetch(found_lower, D))).
 
 -endif.
\ No newline at end of file

From ee534081c336a1ceb52bbd92b25491838b8572e4 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 17:15:42 +0000
Subject: [PATCH 16/18] Reduce log levels

Remove some log noise to debug level
---
 src/leveled_log.erl | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 0848e0b..b7a7a22 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -114,7 +114,7 @@
     {"P0027",
         {info, "Rename of manifest from ~s ~w to ~s ~w"}},
     {"P0028",
-        {info, "Adding cleared file ~s to deletion list"}},
+        {debug, "Adding cleared file ~s to deletion list"}},
     {"P0029",
         {info, "L0 completion confirmed and will transition to not pending"}},
     {"P0030",
@@ -258,7 +258,7 @@
     {"SFT13",
         {error, "Segment filter failed due to ~s"}},
     {"SFT14",
-        {info, "Range fetch from SFT PID ~w"}},
+        {debug, "Range fetch from SFT PID ~w"}},
     
     {"CDB01",
         {info, "Opening file for writing with filename ~s"}},

From 353fb08e217e102da98d72b974f7443466df2262 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 17:28:41 +0000
Subject: [PATCH 17/18] Randomise logging of GET/HEAD samples

---
 src/leveled_log.erl | 34 ++++++++++++++++++++++++++--------
 1 file changed, 26 insertions(+), 8 deletions(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index b7a7a22..4943289 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -14,8 +14,8 @@
             get_timing/3]).         
 
 -define(PUT_TIMING_LOGPOINT, 20000).
--define(HEAD_TIMING_LOGPOINT, 100000).
--define(GET_TIMING_LOGPOINT, 50000).
+-define(HEAD_TIMING_LOGPOINT, 160000).
+-define(GET_TIMING_LOGPOINT, 160000).
 -define(LOG_LEVEL, [info, warn, error, critical]).
 -define(SAMPLE_RATE, 16#F).
 
@@ -374,9 +374,18 @@ head_timing_int(undefined, T0, Level, R) ->
                 end end,
     {1, lists:foldl(NewDFun, dict:new(), head_keylist())};
 head_timing_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_timing_int(undefined, T0, Level, R);
+    RN = random:uniform(?HEAD_TIMING_LOGPOINT),
+    case RN > ?HEAD_TIMING_LOGPOINT div 2 of
+        true ->
+            % log at the timing point less than half the time
+            LogFun  = fun(K) -> log("P0032", [K|dict:fetch(K, HeadTimingD)]) end,
+            lists:foreach(LogFun, head_keylist()),
+            head_timing_int(undefined, T0, Level, R);
+        false ->
+            % Log some other time - reset to RN not 0 to stagger logs out over
+            % time between the vnodes
+            head_timing_int({RN, HeadTimingD}, T0, Level, R)
+    end;
 head_timing_int({N, HeadTimingD}, T0, Level, R) ->
     Key = head_key(R, Level),
     [Count0, Total0, Max0] = dict:fetch(Key, HeadTimingD),
@@ -423,9 +432,18 @@ get_timing_int(undefined, T0, TimerType) ->
                 end end,
     {1, lists:foldl(NewDFun, dict:new(), get_keylist())};
 get_timing_int({?GET_TIMING_LOGPOINT, GetTimerD}, T0, TimerType) ->
-    LogFun  = fun(K) -> log("B0014", [K|dict:fetch(K, GetTimerD)]) end,
-    lists:foreach(LogFun, get_keylist()),
-    get_timing_int(undefined, T0, TimerType);
+    RN = random:uniform(?GET_TIMING_LOGPOINT),
+    case RN > ?GET_TIMING_LOGPOINT div 2 of
+        true ->
+            % log at the timing point less than half the time
+            LogFun  = fun(K) -> log("B0014", [K|dict:fetch(K, GetTimerD)]) end,
+            lists:foreach(LogFun, get_keylist()),
+            get_timing_int(undefined, T0, TimerType);
+        false ->
+            % Log some other time - reset to RN not 0 to stagger logs out over
+            % time between the vnodes
+            get_timing_int({RN, GetTimerD}, T0, TimerType)
+    end;
 get_timing_int({N, GetTimerD}, T0, TimerType) ->
     [Count0, Total0, Max0] = dict:fetch(TimerType, GetTimerD),
     {N + 1, 

From a131b99082625bde1db5d0c53f1ab6d058e1b7e8 Mon Sep 17 00:00:00 2001
From: martinsumner <martin.sumner@adaptip.co.uk>
Date: Thu, 22 Dec 2016 17:33:14 +0000
Subject: [PATCH 18/18] Randomising logging of PUT timings

---
 src/leveled_log.erl | 27 ++++++++++++++++++---------
 1 file changed, 18 insertions(+), 9 deletions(-)

diff --git a/src/leveled_log.erl b/src/leveled_log.erl
index 4943289..3d7cba3 100644
--- a/src/leveled_log.erl
+++ b/src/leveled_log.erl
@@ -335,15 +335,24 @@ log_timer(LogReference, Subs, StartTime) ->
 
 put_timing(_Actor, undefined, T0, T1) ->
     {1, {T0, T1}, {T0, T1}};
-put_timing(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]),
-    put_timing(Actor, undefined, T0, T1);
+put_timing(Actor, {?PUT_TIMING_LOGPOINT, {Total0, Total1}, {Max0, Max1}},
+                                                                    T0, T1) ->
+    RN = random:uniform(?HEAD_TIMING_LOGPOINT),
+    case RN > ?HEAD_TIMING_LOGPOINT div 2 of
+        true ->
+            % log at the timing point less than half the time
+            LogRef =
+                case Actor of
+                    bookie -> "B0012";
+                    inker -> "I0019";
+                    journal -> "CDB17"
+                end,
+            log(LogRef, [?PUT_TIMING_LOGPOINT, Total0, Total1, Max0, Max1]),
+            put_timing(Actor, undefined, T0, T1);
+        false ->
+            % Log some other random time
+            put_timing(Actor, {RN, {Total0, Total1}, {Max0, Max1}}, T0, T1)
+    end;
 put_timing(_Actor, {N, {Total0, Total1}, {Max0, Max1}}, T0, T1) ->
     {N + 1, {Total0 + T0, Total1 + T1}, {max(Max0, T0), max(Max1, T1)}}.