SOLR-6650: Add optional slow request logging at WARN level; this closes #101

git-svn-id: https://svn.apache.org/repos/asf/lucene/dev/trunk@1634086 13f79535-47bb-0310-9956-ffa450edef68

solr/CHANGES.txt

@@ -187,6 +187,9 @@ New Features
 * SOLR-6633: /update/json/docs path can now save the underlying json doc asa string field
   and better support added to the default example (Noble Paul)
 
+* SOLR-6650: Add optional slow request logging at WARN level
+  (Jessica Cheng Mallet via Timothy Potter)
+
 Bug Fixes
 ----------------------
 

solr/core/src/java/org/apache/solr/core/SolrConfig.java

@@ -241,6 +241,7 @@ public class SolrConfig extends Config {
       jmxConfig = new JmxConfiguration(false, null, null, null);
     }
      maxWarmingSearchers = getInt("query/maxWarmingSearchers",Integer.MAX_VALUE);
+     slowQueryThresholdMillis = getInt("query/slowQueryThresholdMillis", 1000);
 
      loadPluginInfo(SolrRequestHandler.class,"requestHandler",
                     REQUIRE_NAME, REQUIRE_CLASS, MULTI_OK);
@@ -400,6 +401,7 @@ public class SolrConfig extends Config {
   public final boolean useColdSearcher;
   public final Version luceneMatchVersion;
   protected String dataDir;
+  public final int slowQueryThresholdMillis;  // threshold above which a query is considered slow
   
   //JMX configuration
   public final JmxConfiguration jmxConfig;

solr/core/src/java/org/apache/solr/core/SolrCore.java

@@ -666,6 +666,7 @@ public final class SolrCore implements SolrInfoMBean, Closeable {
     this.solrConfig = null;
     this.startTime = System.currentTimeMillis();
     this.maxWarmingSearchers = 2;  // we don't have a config yet, just pick a number.
+    this.slowQueryThresholdMillis = 1000;
     this.resourceLoader = null;
     this.updateHandler = null;
     this.isReloaded = true;
@@ -766,6 +767,7 @@ public final class SolrCore implements SolrInfoMBean, Closeable {
     this.dataDir = dataDir;
     this.startTime = System.currentTimeMillis();
     this.maxWarmingSearchers = config.maxWarmingSearchers;
+    this.slowQueryThresholdMillis = config.slowQueryThresholdMillis;
 
     booleanQueryMaxClauseCount();
   
@@ -1357,6 +1359,7 @@ public final class SolrCore implements SolrInfoMBean, Closeable {
   private Object searcherLock = new Object();  // the sync object for the searcher
   private ReentrantLock openSearcherLock = new ReentrantLock(true);     // used to serialize opens/reopens for absolute ordering
   private final int maxWarmingSearchers;  // max number of on-deck searchers allowed
+  private final int slowQueryThresholdMillis;  // threshold above which a query is considered slow
 
   private RefCounted<SolrIndexSearcher> realtimeSearcher;
   private Callable<DirectoryReader> newReaderCreator;
@@ -1983,8 +1986,15 @@ public final class SolrCore implements SolrInfoMBean, Closeable {
     handler.handleRequest(req,rsp);
     postDecorateResponse(handler, req, rsp);
 
-    if (log.isInfoEnabled() && rsp.getToLog().size() > 0) {
+    if (rsp.getToLog().size() > 0) {
-      log.info(rsp.getToLogAsString(logid));
+      if (log.isInfoEnabled()) {
+        log.info(rsp.getToLogAsString(logid));
+      } else if (log.isWarnEnabled()) {
+        final int qtime = (int)(rsp.getEndTime() - req.getStartTime());
+        if (qtime >= slowQueryThresholdMillis) {
+          log.warn(rsp.getToLogAsString(logid));
+        }
+      }
     }
   }
 

solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java

@@ -49,11 +49,13 @@ import org.slf4j.LoggerFactory;
 public class LogUpdateProcessorFactory extends UpdateRequestProcessorFactory implements UpdateRequestProcessorFactory.RunAlways {
   
   int maxNumToLog = 10;
+  int slowUpdateThresholdMillis = 1000;
   @Override
   public void init( final NamedList args ) {
     if( args != null ) {
       SolrParams params = SolrParams.toSolrParams( args );
       maxNumToLog = params.getInt( "maxNumToLog", maxNumToLog );
+      slowUpdateThresholdMillis = params.getInt("slowUpdateThresholdMillis", slowUpdateThresholdMillis);
     }
   }
 
@@ -78,6 +80,7 @@ class LogUpdateProcessor extends UpdateRequestProcessor {
   private List<String> deletes;
 
   private final int maxNumToLog;
+  private final int slowUpdateThresholdMillis;
 
   private final boolean logDebug = log.isDebugEnabled();//cache to avoid volatile-read
 
@@ -88,6 +91,7 @@ class LogUpdateProcessor extends UpdateRequestProcessor {
     maxNumToLog = factory.maxNumToLog;  // TODO: make configurable
     // TODO: make log level configurable as well, or is that overkill?
     // (ryan) maybe?  I added it mostly to show that it *can* be configurable
+    slowUpdateThresholdMillis = factory.slowUpdateThresholdMillis;
 
     this.toLog = new SimpleOrderedMap<>();
   }
@@ -181,23 +185,32 @@ class LogUpdateProcessor extends UpdateRequestProcessor {
     // LOG A SUMMARY WHEN ALL DONE (INFO LEVEL)
 
     if (log.isInfoEnabled()) {
-      StringBuilder sb = new StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
+      log.info(getLogStringAndClearRspToLog());
-
+    } else if (log.isWarnEnabled()) {
-      rsp.getToLog().clear();   // make it so SolrCore.exec won't log this again
-
-      // if id lists were truncated, show how many more there were
-      if (adds != null && numAdds > maxNumToLog) {
-        adds.add("... (" + numAdds + " adds)");
-      }
-      if (deletes != null && numDeletes > maxNumToLog) {
-        deletes.add("... (" + numDeletes + " deletes)");
-      }
       long elapsed = rsp.getEndTime() - req.getStartTime();
-
+      if (elapsed >= slowUpdateThresholdMillis) {
-      sb.append(toLog).append(" 0 ").append(elapsed);
+        log.warn(getLogStringAndClearRspToLog());
-      log.info(sb.toString());
+      }
     }
   }
+
+  private String getLogStringAndClearRspToLog() {
+    StringBuilder sb = new StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
+
+    rsp.getToLog().clear();   // make it so SolrCore.exec won't log this again
+
+    // if id lists were truncated, show how many more there were
+    if (adds != null && numAdds > maxNumToLog) {
+      adds.add("... (" + numAdds + " adds)");
+    }
+    if (deletes != null && numDeletes > maxNumToLog) {
+      deletes.add("... (" + numDeletes + " deletes)");
+    }
+    long elapsed = rsp.getEndTime() - req.getStartTime();
+
+    sb.append(toLog).append(" 0 ").append(elapsed);
+    return sb.toString();
+  }
 }
 
 

solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml

@@ -35,6 +35,7 @@
   </processor>
   <processor class="solr.LogUpdateProcessorFactory" >
    <int name="maxNumToLog">100</int>
+   <int name="slowUpdateThresholdMillis">2000</int>
   </processor>
   <processor class="solr.CustomUpdateRequestProcessorFactory" >
    <lst name="name">

solr/core/src/test-files/solr/collection1/conf/solrconfig.xml

@@ -183,6 +183,8 @@
     </listener>
     -->
 
+    <slowQueryThresholdMillis>2000</slowQueryThresholdMillis>
+
   </query>
   
   <queryResponseWriter name="xml" default="true"

solr/core/src/test/org/apache/solr/core/SolrCoreTest.java

@@ -238,6 +238,14 @@ public class SolrCoreTest extends SolrTestCaseJ4 {
     assertNotNull("bean not registered", bean);
   }
 
+  @Test
+  public void testConfiguration() throws Exception {
+    assertEquals("wrong config for slowQueryThresholdMillis", 2000, solrConfig.slowQueryThresholdMillis);
+    assertEquals("wrong config for maxBooleanClauses", 1024, solrConfig.booleanQueryMaxClauseCount);
+    assertEquals("wrong config for enableLazyFieldLoading", true, solrConfig.enableLazyFieldLoading);
+    assertEquals("wrong config for queryResultWindowSize", 10, solrConfig.queryResultWindowSize);
+  }
+
 }
 
 

solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java

@@ -53,10 +53,12 @@ public class UpdateRequestProcessorFactoryTest extends AbstractSolrTestCase {
     assertEquals("wrong factory at front of chain",
                  LogUpdateProcessorFactory.class, first.getClass());
     LogUpdateProcessorFactory log = (LogUpdateProcessorFactory)first;
-    assertEquals("wrong config for LogUpdateProcessorFactory",
+    assertEquals("wrong config for LogUpdateProcessorFactory.maxNumToLog",
                  100, log.maxNumToLog );
-    
+    assertEquals("wrong config for LogUpdateProcessorFactory.slowUpdateThresholdMillis",
-    
+                 2000, log.slowUpdateThresholdMillis);
+
+
     UpdateRequestProcessorChain custom = core.getUpdateProcessingChain( null );
     CustomUpdateRequestProcessorFactory link = (CustomUpdateRequestProcessorFactory) custom.getFactories()[0];
     

solr/example/solr/collection1/conf/solrconfig.xml

@@ -481,6 +481,21 @@
       -->
     <maxBooleanClauses>1024</maxBooleanClauses>
 
+ 
+    <!-- Slow Query Threshold (in millis)
+    
+         At high request rates, logging all requests can become a bottleneck 
+         and therefore INFO logging is often turned off. However, it is still
+         useful to be able to set a latency threshold above which a request
+         is considered "slow" and log that request at WARN level so we can
+         easily identify slow queries.
+
+         This setting only applies if the logger for the
+         org.apache.solr.core.SolrCore is set to WARN or greater.
+
+    --> 
+    <slowQueryThresholdMillis>1000</slowQueryThresholdMillis>
+
 
     <!-- Solr Internal Query Caches