Alter logging to help understand performance factors

Change logging of the snapshots to better understand performance

src/leveled_bookie.erl

@@ -644,7 +644,6 @@ bucket_stats(State, Bucket, Tag) ->
         {LedgerSnapshot, LedgerCache},
         _JournalSnapshot} = snapshot_store(State, ledger, no_lookup),
     Folder = fun() ->
-                leveled_log:log("B0004", [cache_size(LedgerCache)]),
                 load_snapshot(LedgerSnapshot, LedgerCache),
                 StartKey = leveled_codec:to_ledgerkey(Bucket, null, Tag),
                 EndKey = leveled_codec:to_ledgerkey(Bucket, null, Tag),
@@ -848,10 +847,12 @@ snapshot_store(State, SnapType) ->
     snapshot_store(State, SnapType, undefined).
 
 snapshot_store(State, SnapType, Query) ->
+    SW = os:timestamp(),
     PCLopts = #penciller_options{start_snapshot=true,
                                     source_penciller=State#state.penciller},
     {ok, LedgerSnapshot} = leveled_penciller:pcl_start(PCLopts),
     LedgerCache = readycache_forsnapshot(State#state.ledger_cache, Query),
+    leveled_log:log_timer("B0004", [cache_size(LedgerCache)], SW),
     case SnapType of
         store ->
             InkerOpts = #inker_options{start_snapshot=true,

src/leveled_log.erl

@@ -35,7 +35,7 @@
     {"B0003",
         {info, "Bookie closing for reason ~w"}},
     {"B0004",
-        {info, "Length of increment in snapshot is ~w"}},
+        {info, "Initialised PCL clone and length of increment in snapshot is ~w"}},
     {"B0005",
         {info, "LedgerSQN=~w at startup"}},
     {"B0006",
@@ -59,9 +59,9 @@
         {info, "Get timing for result ~w is sample ~w total ~w and max ~w"}},
     
     {"P0001",
-        {info, "Ledger snapshot ~w registered"}},
+        {debug, "Ledger snapshot ~w registered"}},
     {"P0003",
-        {info, "Ledger snapshot ~w released"}},
+        {debug, "Ledger snapshot ~w released"}},
     {"P0004",
         {info, "Remaining ledger snapshots are ~w"}},
     {"P0005",
@@ -129,7 +129,9 @@
     {"P0035",
         {info, "Startup with Manifest SQN of ~w"}},
     {"P0036",
-        {info, "Garbage collection on mnaifest removes key for filename ~s"}},
+        {info, "Garbage collection on manifest removes key for filename ~s"}},
+    {"P0037",
+        {info, "Merging of penciller L0 tree to size ~w complete"}},
         
     {"PC001",
         {info, "Penciller's clerk ~w started with owner ~w"}},

src/leveled_penciller.erl

@@ -397,6 +397,7 @@ handle_call({fetch_keys, StartKey, EndKey, AccFun, InitAcc, MaxKeys},
                 _From,
                 State=#state{snapshot_fully_loaded=Ready})
                                                         when Ready == true ->
+    SW = os:timestamp(),
     L0AsList =
         case State#state.levelzero_astree of
             undefined ->
@@ -407,7 +408,9 @@ handle_call({fetch_keys, StartKey, EndKey, AccFun, InitAcc, MaxKeys},
             List ->
                 List
         end,
-    
+    leveled_log:log_timer("P0037",
+                            [length(L0AsList)],
+                            SW),
     SetupFoldFun =
         fun(Level, Acc) ->
             Pointers = leveled_pmanifest:range_lookup(State#state.manifest,

src/leveled_pmanifest.erl

@@ -289,12 +289,12 @@ release_snapshot(Manifest, Pid) ->
     {SnapList0, MinSnapSQN} = lists:foldl(FilterFun,
                                             {[], infinity},
                                             Manifest#manifest.snapshots),
-    leveled_log:log("P0004", [SnapList0]),
     case SnapList0 of
         [] ->
             Manifest#manifest{snapshots = SnapList0,
                                 min_snapshot_sqn = 0};
         _ ->
+            leveled_log:log("P0004", [SnapList0]),
             Manifest#manifest{snapshots = SnapList0,
                                 min_snapshot_sqn = MinSnapSQN}
     end.