[jira] [Comment Edited] (OAK-2302) Simplify query debugging with MDC

["Chetan Mehrotra (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/OAK-2302?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14227373#comment-14227373 ] 

Chetan Mehrotra edited comment on OAK-2302 at 11/27/14 8:15 AM:
----------------------------------------------------------------

Patch which populates the MDC with following variable
* {{oak.query.id}} - Unique incrementing counter for current query being executed. This can be used to corelate logs for single query statement from different categories
* {{oak.query.debug}} - Set to true if either of {{explain}} or {{measure}} is enabled

With above setup and following logback config

{code:xml}
<configuration>
  <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
    <Key>oak.query.debug</Key>
    <DefaultThreshold>INFO</DefaultThreshold>
    <MDCValueLevelPair>
      <value>true</value>
      <level>TRACE</level>
    </MDCValueLevelPair>
  </turboFilter>

  <appender name="query" class="ch.qos.logback.core.FileAppender">
    <file>target/unit-tests-query.log</file>
    <encoder>
      <pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %marker %X{oak.query.id} %X{oak.query.debug} %msg%n
      </pattern>
    </encoder>
  </appender>

  <logger name="org.apache.jackrabbit.oak.query" level="DEBUG" additivity="false">
    <appender-ref ref="query"/>
  </logger>
</configuration>
{code}

It makes use of [DynamicThresholdFilter|http://logback.qos.ch/apidocs/ch/qos/logback/classic/turbo/DynamicThresholdFilter.html] to set log level to TRACE if given MDC key value is found to be true

Debug level logs for {{org.apache.jackrabbit.oak.query}} would only be generated for that thread and code path where the MDC {{oak.query.debug}} is found to be true.

With this user gets precise logs and system would not be flooded with debug level logs from all query executions

[~tmueller] Can you have a look. I would like it to be made part of 1.0 branch to simplify query related debugging while using newer LucenePropertyIndex as it generates quite a bit of logging


was (Author: chetanm):
Patch which populates the MDC with following variable
* {{oak.query.id}} - Unique incrementing counter for current query being executed
* {{oak.query.debug}} - Set to true if either of {{explain}} or {{measure}} is enabled

With above setup and following logback config

{code:xml}
<configuration>
  <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
    <Key>oak.query.debug</Key>
    <DefaultThreshold>INFO</DefaultThreshold>
    <MDCValueLevelPair>
      <value>true</value>
      <level>TRACE</level>
    </MDCValueLevelPair>
  </turboFilter>

  <appender name="query" class="ch.qos.logback.core.FileAppender">
    <file>target/unit-tests-query.log</file>
    <encoder>
      <pattern>%date{HH:mm:ss.SSS} %-5level %-40([%thread] %F:%L) %marker %X{oak.query.id} %X{oak.query.debug} %msg%n
      </pattern>
    </encoder>
  </appender>

  <logger name="org.apache.jackrabbit.oak.query" level="DEBUG" additivity="false">
    <appender-ref ref="query"/>
  </logger>
</configuration>
{code}

Debug level logs for {{org.apache.jackrabbit.oak.query}} would only be generated for that thread and code path where the MDC {{oak.query.debug}} is found to be true.

With this user gets precise logs and system would not be flooded with debug level logs from all query executions

[~tmueller] Can you have a look. I would like it to be made part of 1.0 branch to simplify query related debugging while using newer LucenePropertyIndex as it generates quite a bit of logging

> Simplify query debugging with MDC
> ---------------------------------
>
>                 Key: OAK-2302
>                 URL: https://issues.apache.org/jira/browse/OAK-2302
>             Project: Jackrabbit Oak
>          Issue Type: Improvement
>          Components: query
>            Reporter: Chetan Mehrotra
>            Priority: Minor
>             Fix For: 1.0.9, 1.2
>
>         Attachments: OAK-2302.patch
>
>
> QueryEngine in Oak has support for {{explain}} and {{measure}} to enable a user to determine how a query is executed by the engine. Result returned via explain call just tell what index would be used to execute the query. However often we need to see which all indexes were consulted and what cost were obtained from them.
> To get that data one has to enable debug level log for {{org.apache.jackrabbit.oak.query}}. Enabling them on a bigger system often results in lots of logs due to invocation of queries done by various part. Mostly the log is flooded with reference query invoked by authentication layer thus making it hard to find out relevant logs.
> To simplify getting only debug level logs for query which had explain enabled it would be helpful to provide support via MDC [1] (which is part of Slf4j API already being used in Oak)
> (patch and usage details to follow)
> [1] http://logback.qos.ch/manual/mdc.html



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)