Monitoring Slow NXQL Queries

It is possible to easily pinpoint slow NXQL. If you want trace all the queries that take more than 100ms:

1. Add the following line in your nuxeo.conf:

   • For VCS:

     org.nuxeo.vcs.query.log_min_duration_ms=100
     
     

   • For DBS (since Nuxeo Platform 8.3): 

     org.nuxeo.dbs.query.log_min_duration_ms=100
     
     

2. Activate the log for session you use (VCS or DBS) at the INFO level. Here an example of lib/log4j.xml to get them in a separate file:

   • For VCS:

     <category name="org.nuxeo.ecm.core.storage.sql.SessionImpl" additivity="false">
         <priority value="INFO" />
         <appender-ref ref="SLOW" />
     </category>
     <appender name="SLOW" class="org.apache.log4j.FileAppender">
         <errorHandler class="org.apache.log4j.helpers.OnlyOnceErrorHandler" />
         <param name="File" value="${nuxeo.log.dir}/slow-query.log" />
         <param name="Append" value="false" />
         <layout class="org.apache.log4j.PatternLayout">
           <param name="ConversionPattern" value="%d{ISO8601} %-5p [%t][%c] %m%X%n" />
         </layout>
     </appender>
     

   • For DBS (since Nuxeo Platform 8.3):

     <category name="org.nuxeo.ecm.core.storage.dbs.DBSSession" additivity="false">
         <priority value="INFO" />
         <appender-ref ref="SLOW" />
     </category>
     <appender name="SLOW" class="org.apache.log4j.FileAppender">
         <errorHandler class="org.apache.log4j.helpers.OnlyOnceErrorHandler" />
         <param name="File" value="${nuxeo.log.dir}/slow-query.log" />
         <param name="Append" value="false" />
         <layout class="org.apache.log4j.PatternLayout">
           <param name="ConversionPattern" value="%d{ISO8601} %-5p [%t][%c] %m%X%n" />
         </layout>
     </appender>
     

To get the slowest queries:

$ grep duration_ms log/slow-query.log | sed -e's/^[^\t]*\t//g' -e 's/{.*$//g' |sort -nr | head

802.89  QueryFilter(principal=system, limit=0, offset=0)        query   SELECT * FROM Document WHERE ....
12.87   QueryFilter(principal=bob, limit=0, offset=0)        queryAndFetch   Select DISTINCT ecm:uuid...
10.12   QueryFilter(principal=system, limit=50, offset=0) count total results UNLIMITED query   SELECT * FROM Document WHERE ...
5.35    QueryFilter(principal=Administrator, limit=20, offset=0) count total results up to 20   query   SELECT * FROM ...