Measure view build statsarchive/prototype/fdb-layer-view-timing-logsprototype/fdb-layer-view-timing-logs

1 files changed, 71 insertions, 8 deletions

diff --git a/src/couch_views/src/couch_views_indexer.erl b/src/couch_views/src/couch_views_indexer.erl
index 9c8be6fca..9eded8295 100644
--- a/src/couch_views/src/couch_views_indexer.erl
+++ b/src/couch_views/src/couch_views_indexer.erl
@@ -165,13 +165,18 @@ add_error(Error, Reason, Data) ->
 
 
 update(#{} = Db, Mrst0, State0) ->
+    stat_incr(update_loop, 1),
     Limiter = maps:get(limiter, State0),
     case couch_rate:budget(Limiter) of
         0 ->
             couch_rate:wait(Limiter),
             update(Db, Mrst0, State0);
         Limit ->
-            {Mrst1, State1} = do_update(Db, Mrst0, State0#{limit => Limit, limiter => Limiter}),
+            stat_store(rate_limit, Limit),
+
+            {Mrst1, State1} = time_span(do_update, fun() ->
+                do_update(Db, Mrst0, State0#{limit => Limit, limiter => Limiter})
+            end),
             case State1 of
                 finished ->
                     couch_eval:release_map_context(Mrst1#mrst.qserver);
@@ -186,7 +191,9 @@ do_update(Db, Mrst0, State0) ->
     fabric2_fdb:transactional(Db, fun(TxDb) ->
         State1 = get_update_start_state(TxDb, Mrst0, State0),
 
-        {ok, State2} = fold_changes(State1),
+        {ok, State2} = time_span(fold_changes, fun() ->
+            fold_changes(State1)
+        end),
 
         #{
             count := Count,
@@ -198,25 +205,36 @@ do_update(Db, Mrst0, State0) ->
             changes_done := ChangesDone0,
             design_opts := DesignOpts
         } = State2,
-        DocAcc1 = fetch_docs(TxDb, DesignOpts, DocAcc),
+
+        stat_incr(changes_read, length(DocAcc)),
+
+        DocAcc1 = time_span(fetch_docs, fun() ->
+            fetch_docs(TxDb, DesignOpts, DocAcc)
+        end),
+
         couch_rate:in(Limiter, Count),
 
-        {Mrst1, MappedDocs} = map_docs(Mrst0, DocAcc1),
-        WrittenDocs = write_docs(TxDb, Mrst1, MappedDocs, State2),
+        {Mrst1, MappedDocs} = time_span(map_docs, fun() ->
+            map_docs(Mrst0, DocAcc1)
+        end),
 
-        ChangesDone = ChangesDone0 + WrittenDocs,
+        WrittenDocs = time_span(write_docs, fun() ->
+            write_docs(TxDb, Mrst1, MappedDocs, State2)
+        end),
 
+        ChangesDone = ChangesDone0 + WrittenDocs,
         couch_rate:success(Limiter, WrittenDocs),
 
         case Count < Limit of
             true ->
                 maybe_set_build_status(TxDb, Mrst1, ViewVS,
                     ?INDEX_READY),
-                report_progress(State2#{changes_done := ChangesDone},
-                    finished),
+                report_progress(State2#{changes_done := ChangesDone}, finished),
+                stat_dump(),
                 {Mrst1, finished};
             false ->
                 State3 = report_progress(State2, update),
+                stat_dump(),
                 {Mrst1, State3#{
                     tx_db := undefined,
                     count := 0,
@@ -563,6 +581,51 @@ fail_job(Job, Data, Error, Reason) ->
     exit(normal).
 
 
+time_span(Id, Fun) ->
+    Start = erlang:system_time(microsecond),
+    try
+        Fun()
+    after
+        Diff = erlang:system_time(microsecond) - Start,
+        stat_store(Id, Diff / 1000000)
+    end.
+
+
+stat_incr(Id, Count) ->
+    case get('$view_stats') of
+        #{Id := OldCount} ->
+            stat_store(Id, OldCount + Count);
+        _ ->
+            stat_store(Id, Count)
+    end.
+
+
+stat_store(Id, Value) ->
+    NewStats = case get('$view_stats') of
+        #{} = Stats ->
+            maps:put(Id, Value, Stats);
+        undefined ->
+            #{Id => Value}
+    end,
+    put('$view_stats', NewStats).
+
+
+stat_dump() ->
+    case get('$view_stats') of
+        #{} = Stats ->
+            KVs = lists:sort(maps:to_list(Stats)),
+            Strs = lists:foldl(fun({Id, Value}, Acc) ->
+                Str = io_lib:format("~s:~w", [Id, Value]),
+                [Str | Acc]
+            end, [], KVs),
+            Msg = "XKCD VIEW STATS: " ++ string:join(lists:reverse(Strs),  " "),
+            couch_log:error(Msg, []),
+            put('$view_stats', #{});
+        _ ->
+            ok
+    end.
+
+
 retry_limit() ->
     config:get_integer("couch_views", "retry_limit", 3).