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:

   org.nuxeo.vcs.query.log_min_duration_ms=100
   
   

2. Activate the log for org.nuxeo.ecm.core.storage.sql at the INFO level. Here an example of lib/log4j.xml to get them in a separate file:

   <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>
   

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 ...