[couchdb] branch prototype/fdb-layer-view-timing-logs created (now 0063dcc)

[da...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

davisp pushed a change to branch prototype/fdb-layer-view-timing-logs
in repository https://gitbox.apache.org/repos/asf/couchdb.git.


      at 0063dcc  Measure view build stats

This branch includes the following new commits:

     new 0063dcc  Measure view build stats

The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails.  The revisions
listed as "add" were already present in the repository and have only
been added to this reference.

[couchdb] 01/01: Measure view build stats

[da...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

davisp pushed a commit to branch prototype/fdb-layer-view-timing-logs
in repository https://gitbox.apache.org/repos/asf/couchdb.git

commit 0063dcc7ce748fe8043b185378fd647cb5f440a5
Author: Paul J. Davis <pa...@gmail.com>
AuthorDate: Thu Aug 13 11:58:45 2020 -0500

    Measure view build stats
---
 src/couch_views/src/couch_views_indexer.erl | 79 ++++++++++++++++++++++++++---
 1 file 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 9c8be6f..9eded82 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).