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] 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]