This is an automated email from the ASF dual-hosted git repository.
vatamane pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/couchdb.git
The following commit(s) were added to refs/heads/main by this push:
new 0a58f4e24 Add extra timing stats for couch_js engine commands
0a58f4e24 is described below
commit 0a58f4e24a18d8b906be02f3192c4b847ad70787
Author: Nick Vatamaniuc <[email protected]>
AuthorDate: Fri Sep 29 15:54:23 2023 -0400
Add extra timing stats for couch_js engine commands
When evaluating various JS engine versions it's useful to track not just
error
metrics, but also how fast commands execute. To avoid creating a large
number
of histograms, and keep the metrics count reasonable, keep track of the
total
accumulated time spent on these commands from the point of view of CouchDB's
Erlang side.
To reduce counting json serialization into the JS processing time, move the
writejson/2 and writeline/2 logic into the `prompt` callback. The time
delta,
is then taken after the data is serialized, and after it's deserialized from
readjson/1. The reason for the asymmetry is that response data could be
streamed back byte-by-byte, so in that case to keep it simpler, opt to
record
the times after json had already been parsed.
Take advantage of updating couch_js_module and switch it to use the more
common
?TDEF macro. Also, take the opportinity to expand the coverage of the
couch_js_module so it also tests reduces, add_lib and some ddoc operations
like
vdu, filter, and updates.
---
src/couch/priv/stats_descriptions.cfg | 40 +++++++
src/couch/src/couch_os_process.erl | 58 +++++++---
src/couch/test/eunit/couch_js_tests.erl | 195 ++++++++++++++++++++++++--------
3 files changed, 230 insertions(+), 63 deletions(-)
diff --git a/src/couch/priv/stats_descriptions.cfg
b/src/couch/priv/stats_descriptions.cfg
index 1983eed9b..578b4c65b 100644
--- a/src/couch/priv/stats_descriptions.cfg
+++ b/src/couch/priv/stats_descriptions.cfg
@@ -330,6 +330,46 @@
{type, counter},
{desc, <<"number of OS process prompt errors">>}
]}.
+{[couchdb, query_server, time, spawn_proc], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent spawning os query
processes">>}
+]}.
+{[couchdb, query_server, time, map], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing map_doc
requests">>}
+]}.
+{[couchdb, query_server, time, reduce], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing reduce
requests">>}
+]}.
+{[couchdb, query_server, time, reset], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing reset
requests">>}
+]}.
+{[couchdb, query_server, time, add_fun], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing add_fun
requests">>}
+]}.
+{[couchdb, query_server, time, ddoc_new], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing ddoc new
requests">>}
+]}.
+{[couchdb, query_server, time, ddoc_vdu], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing vdu
requests">>}
+]}.
+{[couchdb, query_server, time, ddoc_filter], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing filter
requests">>}
+]}.
+{[couchdb, query_server, time, ddoc_other], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing other ddoc
requests">>}
+]}.
+{[couchdb, query_server, time, other], [
+ {type, counter},
+ {desc, <<"accumulated number of microseconds spent processing other
requests">>}
+]}.
{[couchdb, legacy_checksums], [
{type, counter},
{desc, <<"number of legacy checksums found in couch_file instances">>}
diff --git a/src/couch/src/couch_os_process.erl
b/src/couch/src/couch_os_process.erl
index d133a2d96..0302cb01d 100644
--- a/src/couch/src/couch_os_process.erl
+++ b/src/couch/src/couch_os_process.erl
@@ -47,12 +47,8 @@ prompt(Pid, Data) ->
throw(Error)
end.
-% Utility functions for reading and writing lines
+% Utility functions for reading lines and parsing json
%
-writeline(OsProc, Data) when is_record(OsProc, os_proc) ->
- Res = port_command(OsProc#os_proc.port, [Data, $\n]),
- couch_io_logger:log_output(Data),
- Res.
readline(#os_proc{} = OsProc) ->
Res = readline(OsProc, []),
@@ -80,15 +76,6 @@ readline(#os_proc{port = Port} = OsProc, Acc) ->
throw({os_process_error, "OS process timed out."})
end.
-% Standard JSON functions
-writejson(OsProc, Data) when is_record(OsProc, os_proc) ->
- JsonData = ?JSON_ENCODE(Data),
- couch_log:debug(
- "OS Process ~p Input :: ~s",
- [OsProc#os_proc.port, JsonData]
- ),
- true = writeline(OsProc, JsonData).
-
readjson(OsProc) when is_record(OsProc, os_proc) ->
Line = iolist_to_binary(readline(OsProc)),
couch_log:debug("OS Process ~p Output :: ~s", [OsProc#os_proc.port, Line]),
@@ -147,12 +134,16 @@ init([Command]) ->
Spawnkiller = "\"" ++ filename:join(PrivDir, "couchspawnkillable") ++ "\"",
V = config:get("query_server_config", "os_process_idle_limit", "300"),
IdleLimit = list_to_integer(V) * 1000,
+ T0 = erlang:monotonic_time(),
OsProc = #os_proc{
command = Command,
port = open_port({spawn, Spawnkiller ++ " " ++ Command},
?PORT_OPTIONS),
idle = IdleLimit
},
KillCmd = iolist_to_binary(readline(OsProc)),
+ T1 = erlang:monotonic_time(),
+ DtUSec = erlang:convert_time_unit(T1 - T0, native, microsecond),
+ bump_time_stat(spawn_proc, DtUSec),
Pid = self(),
couch_log:debug("OS Process Start :: ~p", [OsProc#os_proc.port]),
couch_stats:increment_counter([couchdb, query_server, process_starts]),
@@ -177,9 +168,17 @@ handle_call({set_timeout, TimeOut}, _From, #os_proc{idle =
Idle} = OsProc) ->
{reply, ok, OsProc#os_proc{timeout = TimeOut}, Idle};
handle_call({prompt, Data}, _From, #os_proc{idle = Idle} = OsProc) ->
try
- writejson(OsProc, Data),
couch_stats:increment_counter([couchdb, query_server,
process_prompts]),
- {reply, {ok, readjson(OsProc)}, OsProc, Idle}
+ JsonData = ?JSON_ENCODE(Data),
+ couch_log:debug("OS Process ~p Input :: ~s", [OsProc#os_proc.port,
JsonData]),
+ couch_io_logger:log_output(JsonData),
+ T0 = erlang:monotonic_time(),
+ true = port_command(OsProc#os_proc.port, [JsonData, $\n]),
+ Response = readjson(OsProc),
+ T1 = erlang:monotonic_time(),
+ DtUSec = erlang:convert_time_unit(T1 - T0, native, microsecond),
+ bump_cmd_time_stat(Data, DtUSec),
+ {reply, {ok, Response}, OsProc, Idle}
catch
throw:{error, OsError} ->
couch_stats:increment_counter([couchdb, query_server,
process_errors]),
@@ -229,3 +228,30 @@ killer(KillCmd) ->
after 1000 ->
killer(KillCmd)
end.
+
+bump_cmd_time_stat(Cmd, USec) when is_list(Cmd), is_integer(USec) ->
+ case Cmd of
+ [<<"map_doc">> | _] ->
+ bump_time_stat(map, USec);
+ [<<"reduce">> | _] ->
+ bump_time_stat(reduce, USec);
+ [<<"rereduce">> | _] ->
+ bump_time_stat(reduce, USec);
+ [<<"reset">> | _] ->
+ bump_time_stat(reset, USec);
+ [<<"add_fun">> | _] ->
+ bump_time_stat(add_fun, USec);
+ [<<"ddoc">>, <<"new">> | _] ->
+ bump_time_stat(ddoc_new, USec);
+ [<<"ddoc">>, _, [<<"validate_doc_update">> | _] | _] ->
+ bump_time_stat(ddoc_vdu, USec);
+ [<<"ddoc">>, _, [<<"filters">> | _] | _] ->
+ bump_time_stat(ddoc_filter, USec);
+ [<<"ddoc">> | _] ->
+ bump_time_stat(ddoc_other, USec);
+ _ ->
+ bump_time_stat(other, USec)
+ end.
+
+bump_time_stat(Stat, USec) when is_atom(Stat), is_integer(USec) ->
+ couch_stats:increment_counter([couchdb, query_server, time, Stat], USec).
diff --git a/src/couch/test/eunit/couch_js_tests.erl
b/src/couch/test/eunit/couch_js_tests.erl
index 6fa6cad8d..94a02b1ea 100644
--- a/src/couch/test/eunit/couch_js_tests.erl
+++ b/src/couch/test/eunit/couch_js_tests.erl
@@ -11,7 +11,7 @@
% the License.
-module(couch_js_tests).
--include_lib("eunit/include/eunit.hrl").
+-include_lib("couch/include/couch_eunit.hrl").
couch_js_test_() ->
{
@@ -20,22 +20,23 @@ couch_js_test_() ->
setup,
fun test_util:start_couch/0,
fun test_util:stop_couch/1,
- [
- fun should_create_sandbox/0,
- fun should_reset_properly/0,
- fun should_freeze_doc_object/0,
- fun should_roundtrip_utf8/0,
- fun should_roundtrip_modified_utf8/0,
- fun should_replace_broken_utf16/0,
- fun should_allow_js_string_mutations/0,
- {timeout, 60000, fun should_exit_on_oom/0},
- {timeout, 60000, fun should_exit_on_internal_error/0}
- ]
+ with([
+ ?TDEF(should_create_sandbox),
+ ?TDEF(should_reset_properly),
+ ?TDEF(should_freeze_doc_object),
+ ?TDEF(should_roundtrip_utf8),
+ ?TDEF(should_roundtrip_modified_utf8),
+ ?TDEF(should_replace_broken_utf16),
+ ?TDEF(should_allow_js_string_mutations),
+ ?TDEF(should_bump_timing_stats),
+ ?TDEF(should_exit_on_oom, 60000),
+ ?TDEF(should_exit_on_internal_error, 60000)
+ ])
}
}.
%% erlfmt-ignore
-should_create_sandbox() ->
+should_create_sandbox(_) ->
% Try and detect whether we can see out of the
% sandbox or not.
Src = <<"
@@ -48,8 +49,8 @@ should_create_sandbox() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
- Result = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, {[]}]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
+ Result = prompt(Proc, [<<"map_doc">>, {[]}]),
?assertMatch([[[true, <<_/binary>>]]], Result),
[[[true, ErrMsg]]] = Result,
?assertNotEqual([], binary:matches(ErrMsg, <<"not defined">>)),
@@ -61,7 +62,7 @@ should_create_sandbox() ->
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_reset_properly() ->
+should_reset_properly(_) ->
Src = <<"
function(doc) {
var a = [0,1,2];
@@ -71,20 +72,20 @@ should_reset_properly() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc = {[]},
- Result1 = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result1 = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[0, null]]], Result1),
- Result2 = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result2 = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[42, 43]]], Result2),
- true = couch_query_servers:proc_prompt(Proc, [<<"reset">>]),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
- Result3 = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ true = prompt(Proc, [<<"reset">>]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
+ Result3 = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[0, null]]], Result3),
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_freeze_doc_object() ->
+should_freeze_doc_object(_) ->
Src = <<"
function(doc) {
emit(doc.foo, doc.bar);
@@ -94,16 +95,16 @@ should_freeze_doc_object() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc = {[{<<"bar">>, 1041}]},
- Result1 = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result1 = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[null, 1041], [null, 1041]]], Result1),
- Result2 = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result2 = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[null, 1041], [null, 1041]]], Result2),
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_roundtrip_utf8() ->
+should_roundtrip_utf8(_) ->
% Try round tripping UTF-8 both directions through
% couchjs. These tests use hex encoded values of
% Ä (C384) and Ü (C39C) so as to avoid odd editor/Erlang encoding
@@ -114,17 +115,17 @@ should_roundtrip_utf8() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc =
{[
{<<"value">>, <<16#C3, 16#84>>}
]},
- Result = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[<<16#C3, 16#84>>, <<16#C3, 16#9C>>]]], Result),
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_roundtrip_modified_utf8() ->
+should_roundtrip_modified_utf8(_) ->
% Mimicking the test case from the mailing list
Src = <<"
function(doc) {
@@ -132,17 +133,17 @@ should_roundtrip_modified_utf8() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc =
{[
{<<"value">>, <<16#C3, 16#84>>}
]},
- Result = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result = prompt(Proc, [<<"map_doc">>, Doc]),
?assertEqual([[[<<16#C3, 16#A4>>, <<16#C3, 16#9C>>]]], Result),
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_replace_broken_utf16() ->
+should_replace_broken_utf16(_) ->
% This test reverse the surrogate pair of
% the Boom emoji U+1F4A5
Src = <<"
@@ -151,12 +152,12 @@ should_replace_broken_utf16() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc =
{[
{<<"value">>, list_to_binary(xmerl_ucs:to_utf8([16#1F4A5]))}
]},
- Result = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result = prompt(Proc, [<<"map_doc">>, Doc]),
% Invalid UTF-8 gets replaced with the 16#FFFD replacement
% marker
Markers = list_to_binary(xmerl_ucs:to_utf8([16#FFFD, 16#FFFD])),
@@ -164,7 +165,7 @@ should_replace_broken_utf16() ->
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_allow_js_string_mutations() ->
+should_allow_js_string_mutations(_) ->
% This binary corresponds to this string: мама мыла раму
% Which I'm told translates to: "mom was washing the frame"
MomWashedTheFrame = <<
@@ -213,11 +214,11 @@ should_allow_js_string_mutations() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src1]),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src2]),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src3]),
+ true = prompt(Proc, [<<"add_fun">>, Src1]),
+ true = prompt(Proc, [<<"add_fun">>, Src2]),
+ true = prompt(Proc, [<<"add_fun">>, Src3]),
Doc = {[{<<"value">>, MomWashedTheFrame}]},
- Result = couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc]),
+ Result = prompt(Proc, [<<"map_doc">>, Doc]),
Expect = [
[[<<"length">>, 14]],
[[<<"substring">>, Washed]],
@@ -227,7 +228,101 @@ should_allow_js_string_mutations() ->
couch_query_servers:ret_os_process(Proc).
%% erlfmt-ignore
-should_exit_on_oom() ->
+should_bump_timing_stats(_) ->
+ Proc = couch_query_servers:get_os_process(<<"javascript">>),
+ ?assert(sample_time(spawn_proc) > 0),
+
+ ResetTime = sample_time(reset),
+ true = prompt(Proc, [<<"reset">>]),
+ ?assert(sample_time(reset) > ResetTime),
+
+ AddFunTime = sample_time(add_fun),
+ true = prompt(Proc, [
+ <<"add_fun">>,
+ <<"function(doc) {emit(doc.x, doc.y);}">>
+ ]),
+ ?assert(sample_time(add_fun) > AddFunTime),
+
+ MapTime = sample_time(map),
+ [[[1, 2]]] = prompt(Proc, [
+ <<"map_doc">>,
+ {[{<<"x">>, 1}, {<<"y">>, 2}]}
+ ]),
+ ?assert(sample_time(map) > MapTime),
+
+ ReduceTime = sample_time(reduce),
+ [true, [2]] = prompt(Proc, [
+ <<"reduce">>,
+ [<<"function(k, v) {return sum(v);}">>], [[1, 2]]
+ ]),
+ ?assert(sample_time(reduce)> ReduceTime),
+
+ ReduceTime1 = sample_time(reduce),
+ [true, [7]] = prompt(Proc, [
+ <<"rereduce">>,
+ [<<"function(k, v) {return sum(v);}">>], [3, 4]
+ ]),
+ ?assert(sample_time(reduce) > ReduceTime1),
+
+ FilterFun = <<"function(doc, req) {return true;}">>,
+ UpdateFun = <<"function(doc, req) {return [null, 'something'];}">>,
+ VduFun = <<"function(cur, old, ctx, sec) {return true;}">>,
+ DDocId = <<"_design/ddoc1">>,
+ DDoc = #{
+ <<"_id">> => DDocId,
+ <<"_rev">> => <<"1-a">>,
+ <<"filters">> => #{<<"f1">> => FilterFun},
+ <<"updates">> => #{<<"u1">> => UpdateFun},
+ <<"validate_doc_update">> => VduFun
+ },
+
+ NewDDocTime = sample_time(ddoc_new),
+ true = prompt(Proc, [
+ <<"ddoc">>,
+ <<"new">>,
+ DDocId,
+ DDoc
+ ]),
+ ?assert(sample_time(ddoc_new) > NewDDocTime),
+
+ VduTime = sample_time(ddoc_vdu),
+ 1 = prompt(Proc, [
+ <<"ddoc">>,
+ DDocId,
+ [<<"validate_doc_update">>],
+ [#{}, #{}]
+ ]),
+ ?assert(sample_time(ddoc_vdu) > VduTime),
+
+ FilterTime = sample_time(ddoc_filter),
+ [true, [true]] = prompt(Proc, [
+ <<"ddoc">>,
+ DDocId,
+ [<<"filters">>, <<"f1">>],
+ [[#{}], #{}]
+ ]),
+ ?assert(sample_time(ddoc_filter) > FilterTime),
+
+ DDocOtherTime = sample_time(ddoc_other),
+ prompt(Proc, [
+ <<"ddoc">>,
+ DDocId,
+ [<<"updates">>, <<"u1">>],
+ [null, #{}]
+ ]),
+ ?assert(sample_time(ddoc_other) > DDocOtherTime),
+
+ OtherTime = sample_time(other),
+ true = prompt(Proc, [
+ <<"add_lib">>,
+ #{<<"foo">> => <<"exports.bar = 42;">>}
+ ]),
+ ?assert(sample_time(other) > OtherTime),
+
+ couch_query_servers:ret_os_process(Proc).
+
+%% erlfmt-ignore
+should_exit_on_oom(_) ->
Src = <<"
var state = [];
function(doc) {
@@ -239,11 +334,11 @@ should_exit_on_oom() ->
}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
trigger_oom(Proc).
%% erlfmt-ignore
-should_exit_on_internal_error() ->
+should_exit_on_internal_error(_) ->
% A different way to trigger OOM which previously used to
% throw an InternalError on SM. Check that we still exit on that
% type of error
@@ -260,11 +355,11 @@ should_exit_on_internal_error() ->
emit(42, j.length);}
">>,
Proc = couch_query_servers:get_os_process(<<"javascript">>),
- true = couch_query_servers:proc_prompt(Proc, [<<"reset">>]),
- true = couch_query_servers:proc_prompt(Proc, [<<"add_fun">>, Src]),
+ true = prompt(Proc, [<<"reset">>]),
+ true = prompt(Proc, [<<"add_fun">>, Src]),
Doc = {[]},
try
- couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, Doc])
+ prompt(Proc, [<<"map_doc">>, Doc])
catch
% Expect either an internal error thrown if it catches it and
% emits an error log before dying
@@ -285,7 +380,7 @@ should_exit_on_internal_error() ->
trigger_oom(Proc) ->
Status =
try
- couch_query_servers:proc_prompt(Proc, [<<"map_doc">>, <<"{}">>]),
+ prompt(Proc, [<<"map_doc">>, <<"{}">>]),
continue
catch
throw:{os_process_error, {exit_status, 1}} ->
@@ -295,3 +390,9 @@ trigger_oom(Proc) ->
continue -> trigger_oom(Proc);
done -> ok
end.
+
+sample_time(Stat) ->
+ couch_stats:sample([couchdb, query_server, time, Stat]).
+
+prompt(Proc, Cmd) ->
+ couch_query_servers:proc_prompt(Proc, Cmd).
