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] 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"}},