+1
On Tue, Sep 10, 2019 at 4:51 PM Adam Kocoloski <kocol...@apache.org> wrote: > > Yeah, I meant the latter — joining CouchDB’s span information to spans in an > app built against CouchDB so a developer can see the end-to-end story. Wasn’t > proposing user-customized spans inside the DB :) > > Adam > > > On Sep 10, 2019, at 5:43 PM, Paul Davis <paul.joseph.da...@gmail.com> wrote: > > > > Looks pretty awesome. I've got basically the same questions as Koco on > > performance. There are also games like the lager transforms that > > conditionally enable/disable log levels at runtime. If memory serves, > > it ended up being a single function call overhead to check for > > disabled based on some dynamically compiled module or ets lookup I > > think. > > > > Koco, are client inherited spans an opentracing concept? At first I > > read it as "let a user specify points in CouchDB to insert trace > > markers at runtime" and it sounded kinda crazy. But if you mean > > somehow connecting the CouchDB generated span with some other span in > > a different application that sounds like something reasonable to > > support. > > > > Ilya, you mentioned hopping from the coordinator to RPC workers which > > is definitely an open problem. I only skimmed the docs months ago but > > one of the things I came across was trying to figure out how to > > represent parallel traces. Given we have a coordinator that has N>1 > > RPC workers running in parallel I wasn't sure how that'd work. Granted > > that was on the shallowest of shallow dives skimming their docs when > > someone mentioned the tracing thing somewhere. > > > > On Tue, Sep 10, 2019 at 3:46 PM Adam Kocoloski <kocol...@apache.org> wrote: > >> > >> I think this is a great idea overall, particularly given the number of > >> significant changes that are happening in the codebase between 3.0 and 4.0. > >> > >> For me the main question is how much overhead is associated with tracing. > >> Can an admin safely configure it to run in production? Is it possible to > >> sample just a small percentage of events? Does the overhead change if no > >> OpenTracing tracer is configured? > >> > >> I also think a full picture here might include the ability to inherit > >> client-provided spans, so an app developer could drill down from her own > >> code into the database internals and figure out why some DB request was > >> unexpectedly slow. > >> > >> Thanks for starting this discussion. Cheers, > >> > >> Adam > >> > >>> On Sep 10, 2019, at 2:32 PM, Ilya Khlopotov <iil...@apache.org> wrote: > >>> > >>> Hi, > >>> > >>> I wanted to run this idea by the ML to see if there is any interest > >>> before investing time into preparing formal RFC. > >>> > >>> # Problem statement > >>> > >>> Collecting profiling data is very tricky at the moment. Developers have > >>> to run generic profiling tools which are not aware of CouchDB specifics. > >>> This makes it hard to do the performance optimization work. We need a > >>> tool which would allow us to get profiling data from specific points in > >>> the codebase. This means code instrumentation. > >>> > >>> # Proposed solution > >>> > >>> There is an https://opentracing.io/ project, which is a vendor-neutral > >>> APIs and instrumentation for distributed tracing. In Erlang it is > >>> implemented by https://github.com/Bluehouse-Technology/otter library. The > >>> library provides a nice abstraction to start/finish tracing spans as well > >>> as adding tags and log entries to a given span. In the context of CouchDB > >>> this means that we can do something like the following: > >>> - start tracing span on every HTTP request > >>> - add tags to capture additional information such as "database > >>> name"/"name of endpoint"/"nonce" > >>> - add otter logs in critical parts of the codebase to get profiling data > >>> for these points. > >>> > >>> The otter is the most useful in combination with > >>> [zipkin](https://zipkin.io/) compatible server such as > >>> [jaeger](https://github.com/jaegertracing/jaeger). However it can be used > >>> even without zipkin. It has a configurable set of counters, which makes > >>> it possible to get answers on questions like: > >>> - what kind of requests are slow > >>> - if we get a slow request (taking longer then configured threshold) what > >>> was the trace (annotated with time spent between trace points) > >>> - which function in the trace taking the most time > >>> > >>> # Otter API > >>> > >>> The otter has multiple APIs which we would choose on a case by case basis: > >>> - functional API - the span structure need to be passed around (we could > >>> extend `#http{}`/`#user_ctx{}`/`#db{}`) > >>> - simple process dictionary API - the span data are stored in the process > >>> dictionary > >>> - Multiple span process dictionary API - supports multiple spans per > >>> process > >>> - Span id API - starts a process per span > >>> > >>> # Roadblocks > >>> > >>> One of the problems we would need to solve is to how to do multiple nodes > >>> spans. We would need this functionality to trace the request from the > >>> HTTP endpoint handler running on coordinator to the shard updater process > >>> running on the storage nodes. > >>> > >>> We could use either: > >>> - extend rexi or fabric to pass and aggregate span information > >>> - pass span info explicitly in every fabric function. > >>> > >>> # Quick demo (warning very technical content) > >>> > >>> The goal of this demo is to demonstrate the value of otter without zipkin > >>> server. > >>> > >>> ``` > >>> diff --git a/rebar.config.script b/rebar.config.script > >>> index c38b6e235..c2b162751 100644 > >>> --- a/rebar.config.script > >>> +++ b/rebar.config.script > >>> @@ -129,6 +129,11 @@ OptionalDeps = case WithProper of > >>> [] > >>> end, > >>> > >>> +ManualDeps = [ > >>> + {otter, {url, "https://github.com/Bluehouse-Technology/otter"}, > >>> {branch, "master"}}, > >>> + {otter_lib, {url, > >>> "https://github.com/Bluehouse-Technology/otter_lib"}, {branch, "master"}} > >>> +], > >>> + > >>> BaseUrl = "https://github.com/apache/";, > >>> > >>> MakeDep = fun > >>> @@ -152,7 +157,7 @@ end, > >>> AddConfig = [ > >>> {require_otp_vsn, "19|20|21|22"}, > >>> {deps_dir, "src"}, > >>> - {deps, lists:map(MakeDep, DepDescs ++ OptionalDeps)}, > >>> + {deps, lists:map(MakeDep, DepDescs ++ OptionalDeps ++ ManualDeps)}, > >>> {sub_dirs, SubDirs}, > >>> {lib_dirs, ["src"]}, > >>> {erl_opts, [{i, "../"} | ErlOpts]}, > >>> diff --git a/src/chttpd/src/chttpd.erl b/src/chttpd/src/chttpd.erl > >>> index 1e1d638be..a7aad5010 100644 > >>> --- a/src/chttpd/src/chttpd.erl > >>> +++ b/src/chttpd/src/chttpd.erl > >>> @@ -158,6 +158,7 @@ handle_request(MochiReq0) -> > >>> > >>> handle_request_int(MochiReq) -> > >>> Begin = os:timestamp(), > >>> + otter_span_pdict_api:start_with_tags("http request", [{"begin_ts", > >>> Begin}]), > >>> case config:get("chttpd", "socket_options") of > >>> undefined -> > >>> ok; > >>> @@ -233,6 +234,7 @@ handle_request_int(MochiReq) -> > >>> > >>> % put small token on heap to keep requests synced to backend calls > >>> erlang:put(nonce, Nonce), > >>> + otter_span_pdict_api:tag("nonce", Nonce), > >>> > >>> % suppress duplicate log > >>> erlang:put(dont_log_request, true), > >>> @@ -282,6 +284,8 @@ after_request(HttpReq, HttpResp0) -> > >>> end, > >>> HttpResp2 = update_stats(HttpReq, HttpResp1), > >>> chttpd_stats:report(HttpReq, HttpResp2), > >>> + otter_span_pdict_api:tag("status", HttpResp2#httpd_resp.status), > >>> + otter_span_pdict_api:log("completed"), > >>> + otter_span_pdict_api:finish(), > >>> maybe_log(HttpReq, HttpResp2), > >>> HttpResp2. > >>> > >>> diff --git a/src/fabric/src/fabric.erl b/src/fabric/src/fabric.erl > >>> index 27fa8c045..a1972b445 100644 > >>> --- a/src/fabric/src/fabric.erl > >>> +++ b/src/fabric/src/fabric.erl > >>> @@ -56,6 +56,7 @@ all_dbs() -> > >>> %% @doc returns a list of all database names > >>> -spec all_dbs(Prefix::iodata()) -> {ok, [binary()]}. > >>> all_dbs(Prefix) when is_binary(Prefix) -> > >>> + otter_span_pdict_api:tag("request_type", "_all_dbs"), > >>> Length = byte_size(Prefix), > >>> MatchingDbs = mem3:fold_shards(fun(#shard{dbname=DbName}, Acc) -> > >>> case DbName of > >>> ``` > >>> > >>> ``` > >>> application:start(otter_lib). > >>> application:start(otter). > >>> f(Rules), Rules = [ > >>> {[ > >>> {greater, otter_span_duration, 10} > >>> ],[ > >>> {snapshot_count, [long_span], [otter_span_name]}, > >>> send_to_zipkin > >>> ]} > >>> ]. > >>> otter_config:write(filter_rules, Rules). > >>> otter:counter_snapshot([long_span,"http request"]). > >>> [{[long_span,"http request"], > >>> [{snap_timestamp,{2019,9,10,13,46,43,368208}}, > >>> {data,{span,1568123203366286,17299637839902614236, > >>> "http request",782788946072648712,undefined, > >>> [{"begin_ts",{1568,123203,366255}}, > >>> {"nonce","a0a1d7c58e"}, > >>> {"status",ok}], > >>> [],1911}}]}] > >>> ``` > >>> > >>> Unfortunately `counter_snapshot` API doesn't return log events. However > >>> this problem is very easy to overcome. Here is the example of how to get > >>> matching spans logged into a log file. > >>> > >>> ``` > >>> diff --git a/src/chttpd/src/chttpd.erl b/src/chttpd/src/chttpd.erl > >>> index 1e1d638be..5f2d60690 100644 > >>> --- a/src/chttpd/src/chttpd.erl > >>> +++ b/src/chttpd/src/chttpd.erl > >>> @@ -33,7 +33,7 @@ > >>> send_chunked_error/2, send_json/2,send_json/3,send_json/4, > >>> validate_ctype/2]). > >>> > >>> --export([authenticate_request/3]). > >>> +-export([authenticate_request/3, zipkin_log/2]). > >>> > >>> @@ -1207,6 +1216,10 @@ get_user(#httpd{user_ctx = #user_ctx{name = > >>> User}}) -> > >>> get_user(#httpd{user_ctx = undefined}) -> > >>> "undefined". > >>> > >>> +zipkin_log(_URL, EncodedSpans) -> > >>> + Spans = otter_lib_zipkin_thrift:decode_spans(EncodedSpans), > >>> + couch_log:error("ZIPKIN :: ~p~n", [Spans]). > >>> + > >>> ``` > >>> > >>> ``` > >>> otter_config:write(http_client, {chttpd, zipkin_log}). > >>> ``` > >>> > >>> This would produce the log events looking as the following: > >>> ``` > >>> [error] 2019-09-10T18:01:38.758631Z node1@127.0.0.1 <0.4737.0> -------- > >>> ZIPKIN :: [{span,1568138498710679,3212384889493927141,<<"http > >>> request">>,345610195655038913,undefined,[{<<"lc">>,<<>>,{<<"otter_test">>,{127,0,0,1},0}},{<<"begin_ts">>,<<"{1568,138498,710639}">>},{<<"path">>,<<"_all_dbs">>},{<<"method">>,<<"GET">>},{<<"nonce">>,<<"c225c6aef1">>},{<<"status">>,<<"ok">>}],[{1568138498712456,<<"completed">>}],1784}] > >>> ``` > >>> > >>> As you can see the timestamp of the `completed` event is included in the > >>> entry. Also, since it is a function call we can format the event in any > >>> way we like. > >>> > >>> # Conclusion > >>> > >>> - The otter configuration is simple and presence of `http_client` > >>> parameter allows us to use otter without zipkin server. > >>> - The API is simple which makes it possible to replace otter with > >>> something else if we wouldn't be happy with the implementation. > >>> - The codebase of otter is concise and easy to re-implement in case we > >>> would need to. > >>> > >>> Overall I don't think it will be too complicated to introduce basic > >>> functionality and extend it latter when we need to. > >>> > >>> In case you agree with direction I would appreciate any feedback which > >>> would help to form requirements for the RFC and PR in the future. > >>> > >>> Best regards, > >>> ILYA (aka iilyak) > >> >
