From 4024793334c0edb6debf761a1c050a977534f012 Mon Sep 17 00:00:00 2001
From: Scott Lystig Fritchie <slfritchie@snookles.com>
Date: Thu, 29 Oct 2015 14:18:37 +0900
Subject: [PATCH] More timing, and a bit more understanding about timing

    f().
    exit(self(), bye).
    {ok, T} = machi_merkle_tree_mgr:start_link(a, "/tmp/a", []).
    Leaves = [{{Pos*65,65}, begin {A,B,C} = now(), crypto:hash(sha, <<A:32, B:32, C:32>>) end} || Pos <- lists:seq(1,10*1000)].  length(Leaves).
    timer:tc(fun() -> [machi_merkle_tree_mgr:update(a, "yofile-3", Off, Sz, CSum) || {{Off,Sz},CSum} <- Leaves] end).
    timer:tc(fun() -> machi_merkle_tree_mgr:fetch(a, "yofile-3") end).

All of the update() calls are quick, but they are gen_server:cast()
calls!  So, when we send the fetch(), we see that the gen_server proc
doesn't get the {fetch,...} tuple for 7 seconds.  All of the update
stuff is taking lots of time. The tree building itself is a tiny
fraction of the total time.

    7> timer:tc(fun() -> machi_merkle_tree_mgr:fetch(a, "yofile-3") end).
    build_tree LINE 136 at {1446,95570,34679}
    build_tree LINE 152 at {1446,95577,180438}
    build_tree LINE 306 at {1446,95577,180770}
    build_tree LINE 308 at {1446,95577,181340}
    build_tree LINE 311 at {1446,95577,185524}
    build_tree LINE 315 at {1446,95577,185572}
    build_tree LINE 319 at {1446,95577,185589}
    build_tree LINE 322 at {1446,95577,185608}
    Root: <<95,199,42,232,84,255,228,36,2,174,24,5,20,56,69,109,109,26,92,220>>
    {7151003,
     {ok,[<<95,199,42,232,84,255,228,36,2,174,24,5,20,56,69,
    [...]
---
 src/machi_merkle_tree_mgr.erl | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/src/machi_merkle_tree_mgr.erl b/src/machi_merkle_tree_mgr.erl
index 2964c42..dc1d974 100644
--- a/src/machi_merkle_tree_mgr.erl
+++ b/src/machi_merkle_tree_mgr.erl
@@ -82,7 +82,7 @@
 -define(LEVEL_SIZE, 10).
 -define(H, sha).
 
--define(TIMEOUT, (10*1000)).
+-define(TIMEOUT, infinity).
 
 %% public API
 
@@ -133,6 +133,7 @@ fetch(FluName, Filename) ->
 %% checksum of the tree.  If `all' is specified, returns a list
 %% with all levels.
 fetch(FluName, Filename, Level) ->
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     gen_server:call(make_merkle_tree_mgr_name(FluName),
                     {fetch, Filename, Level}, ?TIMEOUT).
 
@@ -148,6 +149,7 @@ init({FluName, DataDir, Options}) ->
     {ok, #state{fluname=FluName, datadir=DataDir, tid = Tid}}.
 
 handle_call({fetch, Filename, Level}, _From, S = #state{ tid = Tid }) ->
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     Res = handle_fetch(Tid, Filename, Level),
     {reply, {ok, Res}, S};
 handle_call(Req, _From, State) ->
@@ -301,17 +303,23 @@ find(Tid, Filename) ->
     end.
 
 build_tree(Tid, MT = #mt{ leaves = D }) ->
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     Leaves = lists:map(fun map_dict/1, orddict:to_list(D)),
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     %io:format(user, "Leaves: ~p~n", [Leaves]),
     Lvl1s = build_level_1(?CHUNK_SIZE, Leaves, 1, [ crypto:hash_init(?H) ]),
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     %io:format(user, "Lvl1: ~p~n", [Lvl1s]),
     Mod2 = length(Lvl1s) div ?LEVEL_SIZE,
     Lvl2s = build_int_level(Mod2, Lvl1s, 1, [ crypto:hash_init(?H) ]),
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     %io:format(user, "Lvl2: ~p~n", [Lvl2s]),
     Mod3 = length(Lvl2s) div 2,
     Lvl3s = build_int_level(Mod3, Lvl2s, 1, [ crypto:hash_init(?H) ]),
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     %io:format(user, "Lvl3: ~p~n", [Lvl3s]),
     Root = build_root(Lvl3s, crypto:hash_init(?H)),
+    io:format(user, "build_tree LINE ~p at ~p\n", [?LINE, now()]),
     io:format(user, "Root: ~p~n", [Root]),
     %%% ets:insert(Tid, MT#mt{ root = Root, lvl1 = Lvl1s, lvl2 = Lvl2s, lvl3 = Lvl3s, recalc = false }),
     [Root, Lvl3s, Lvl2s, Lvl1s].