Help with POC on activity tracing

[Matt Ryan <ma...@apache.org>]

Hi oak-dev,

I'm currently working on some black-box tests that run against a
(non-Sling) servlet atop Oak.  When one of these tests runs, it will
automatically trace repository activity and report the results of those
traces.  To do this I've implemented technology in my servlet which is very
similar to the Sling Log Tracer [0] which uses custom log messages in the
Oak SessionDelegate [1] [2] to perform this function.  As in the Sling Log
Tracer, my code restricts the traces to only those related to the current
request thread, so this allows me to get a score on activity just for this
request.

So now when I run a test I can generate output that shows how often my
servlet makes calls into the repository, e.g.:

Tracing Score:
{
  'oak-query': 0,
  'oak-writes': 0,
  'oak-reads': 1349
}

While not perfect this seems to be working fine for my purposes for now,
giving me a tracing score that I can use to quantify how a use case
performs.

I'd like to do something similar at lower layers in Oak, particularly
places where behavior leaves Oak and we call out to external services.  For
example, in MongoDocumentStore, to trace how many calls are made from Oak
to MongoDB in the context of a servlet request.

I implemented a POC [3] to attempt this but it does not seem to be
generating any logging events.  If I log to the normal logger, I can see
that the code to log to the custom logger is being hit, but my tracer code
is not picking up any of these events so my count of e.g. MongoDB reads
always shows as 0.


Questions:
- Does anyone have insight into how this was done for SessionDelegate that
might help me figure out what I missed?
- Is this something we'd be interested in adding to Oak?  I was thinking in
the current document stores (MongoMK, RDBMK), cloud blob stores (Azure and
S3), cloud segment stores (Azure and S3) and oak-search-elastic might be
good candidates for this type of tracing.
- If we were to add this, do we want to take this approach or would we
prefer to formalize some different type of approach, and if so what would
that be (JMX, Dropwizard Metrics, ???)?


[0] - https://sling.apache.org/documentation/bundles/log-tracers.html
[1] -
https://github.com/apache/jackrabbit-oak/blob/5532cee474b11104cdc621b51ec41999e276e259/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java#L77
[2] -
https://github.com/apache/jackrabbit-oak/blob/5532cee474b11104cdc621b51ec41999e276e259/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java#L680
[3] -
https://github.com/apache/jackrabbit-oak/compare/trunk...mattvryan:mongo-document-store-tracing-prototype?expand=1


-MR