You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@lucene.apache.org by th...@apache.org on 2014/10/24 18:22:00 UTC

svn commit: r1634086 - in /lucene/dev/trunk/solr: ./ core/src/java/org/apache/solr/core/ core/src/java/org/apache/solr/update/processor/ core/src/test-files/solr/collection1/conf/ core/src/test/org/apache/solr/core/ core/src/test/org/apache/solr/update...

Author: thelabdude
Date: Fri Oct 24 16:21:59 2014
New Revision: 1634086

URL: http://svn.apache.org/r1634086
Log:
SOLR-6650: Add optional slow request logging at WARN level; this closes #101

Modified:
    lucene/dev/trunk/solr/CHANGES.txt
    lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrConfig.java
    lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrCore.java
    lucene/dev/trunk/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
    lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml
    lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.xml
    lucene/dev/trunk/solr/core/src/test/org/apache/solr/core/SolrCoreTest.java
    lucene/dev/trunk/solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java
    lucene/dev/trunk/solr/example/solr/collection1/conf/solrconfig.xml

Modified: lucene/dev/trunk/solr/CHANGES.txt
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/CHANGES.txt?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/CHANGES.txt (original)
+++ lucene/dev/trunk/solr/CHANGES.txt Fri Oct 24 16:21:59 2014
@@ -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
 ----------------------
 

Modified: lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrConfig.java
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrConfig.java?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrConfig.java (original)
+++ lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrConfig.java Fri Oct 24 16:21:59 2014
@@ -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;

Modified: lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrCore.java
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrCore.java?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrCore.java (original)
+++ lucene/dev/trunk/solr/core/src/java/org/apache/solr/core/SolrCore.java Fri Oct 24 16:21:59 2014
@@ -666,6 +666,7 @@ public final class SolrCore implements S
     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 S
     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 S
   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 S
     handler.handleRequest(req,rsp);
     postDecorateResponse(handler, req, rsp);
 
-    if (log.isInfoEnabled() && rsp.getToLog().size() > 0) {
-      log.info(rsp.getToLogAsString(logid));
+    if (rsp.getToLog().size() > 0) {
+      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));
+        }
+      }
     }
   }
 

Modified: lucene/dev/trunk/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java (original)
+++ lucene/dev/trunk/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java Fri Oct 24 16:21:59 2014
@@ -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 UpdateR
   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 UpdateR
     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,22 +185,31 @@ class LogUpdateProcessor extends UpdateR
     // 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()) {
+      long elapsed = rsp.getEndTime() - req.getStartTime();
+      if (elapsed >= slowUpdateThresholdMillis) {
+        log.warn(getLogStringAndClearRspToLog());
+      }
+    }
+  }
 
-      rsp.getToLog().clear();   // make it so SolrCore.exec won't log this again
+  private String getLogStringAndClearRspToLog() {
+    StringBuilder sb = new StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
 
-      // 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();
+    rsp.getToLog().clear();   // make it so SolrCore.exec won't log this again
 
-      sb.append(toLog).append(" 0 ").append(elapsed);
-      log.info(sb.toString());
+    // 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();
   }
 }
 

Modified: lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml (original)
+++ lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-transformers.xml Fri Oct 24 16:21:59 2014
@@ -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">

Modified: lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.xml
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.xml?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.xml (original)
+++ lucene/dev/trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.xml Fri Oct 24 16:21:59 2014
@@ -183,6 +183,8 @@
     </listener>
     -->
 
+    <slowQueryThresholdMillis>2000</slowQueryThresholdMillis>
+
   </query>
   
   <queryResponseWriter name="xml" default="true"

Modified: lucene/dev/trunk/solr/core/src/test/org/apache/solr/core/SolrCoreTest.java
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/test/org/apache/solr/core/SolrCoreTest.java?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/test/org/apache/solr/core/SolrCoreTest.java (original)
+++ lucene/dev/trunk/solr/core/src/test/org/apache/solr/core/SolrCoreTest.java Fri Oct 24 16:21:59 2014
@@ -238,6 +238,14 @@ public class SolrCoreTest extends SolrTe
     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);
+  }
+
 }
 
 

Modified: lucene/dev/trunk/solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java (original)
+++ lucene/dev/trunk/solr/core/src/test/org/apache/solr/update/processor/UpdateRequestProcessorFactoryTest.java Fri Oct 24 16:21:59 2014
@@ -53,10 +53,12 @@ public class UpdateRequestProcessorFacto
     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];
     

Modified: lucene/dev/trunk/solr/example/solr/collection1/conf/solrconfig.xml
URL: http://svn.apache.org/viewvc/lucene/dev/trunk/solr/example/solr/collection1/conf/solrconfig.xml?rev=1634086&r1=1634085&r2=1634086&view=diff
==============================================================================
--- lucene/dev/trunk/solr/example/solr/collection1/conf/solrconfig.xml (original)
+++ lucene/dev/trunk/solr/example/solr/collection1/conf/solrconfig.xml Fri Oct 24 16:21:59 2014
@@ -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
 



Re: svn commit: r1634086 - in /lucene/dev/trunk/solr: ./ core/src/java/org/apache/solr/core/ core/src/java/org/apache/solr/update/processor/ core/src/test-files/solr/collection1/conf/ core/src/test/org/apache/solr/core/ core/src/test/org/apache/solr/update...

Posted by Jessica Mallet <me...@gmail.com>.
Sounds good. I can make that change.

Thanks,
Jessica

On Fri, Oct 24, 2014 at 11:16 AM, Chris Hostetter <ho...@fucit.org>
wrote:

>
> : I see what you're saying. My thought was that since both lines are
> logging
> : exactly the same message, it'd be redundant to log it twice. I can
> : definitely see logging it in both levels, but modifying the warn message
> to
> : have a "slow query:" prefix or something. What do you think?
>
> yeah -- it's definitely a trade off between redundency vs convinience --
> but i'm +1 for being redundent in this case.
>
> the biggest worry i have: some existing Ops or DW team has a tier of Solr
> servers with log crunching all setup to get stats on queries, looking
> explicitly at the existing INFO messages -- and then some dev with the
> best intentions at heart comes along and adds this new config option so
> they can focus on problematic queries, w/o realizing how it will affect
> the existing monitoring -- and now the stats coming out of hte existing
> log monitoring are totally skewed.
>
>
> Anyone in a situation where the redundency would be unwelcome is probably
> either dealing with a high enough volume that INFO logging is disabled
> anyway, or a low evenough volume that they don't need this feature, they
> can check for "slow" queries themselves from the INFO level messages.
>
>
> : On Fri, Oct 24, 2014 at 10:58 AM, Chris Hostetter <
> hossman_lucene@fucit.org>
> : wrote:
> :
> : >
> : > Does it really make sense for this to be an if/else situation?
> : >
> : > it seems like the INFO logging should be completley independent from
> the
> : > WANR logging, so people could have INFO level logs of all the requests
> in
> : > one place, and WARN level logs of slow queries go to a distinct file
> for
> : > higher profile analysis.  AS things stand right now, you have to merge
> the
> : > logs if you wnat stats on all requests (ie: to compute percentiles of
> : > response time, or what the most requested fq params are, etc..)
> : >
> : > : +      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));
> : >
> : >
> : > :      if (log.isInfoEnabled()) {
> : > : -      StringBuilder sb = new
> : > StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
> : > : +      log.info(getLogStringAndClearRspToLog());
> : > : +    } else if (log.isWarnEnabled()) {
> : > : +      long elapsed = rsp.getEndTime() - req.getStartTime();
> : > : +      if (elapsed >= slowUpdateThresholdMillis) {
> : > : +        log.warn(getLogStringAndClearRspToLog());
> : > : +      }
> : >
> : >
> : >
> : > -Hoss
> : > http://www.lucidworks.com/
> : >
> : > ---------------------------------------------------------------------
> : > To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> : > For additional commands, e-mail: dev-help@lucene.apache.org
> : >
> : >
> :
>
> -Hoss
> http://www.lucidworks.com/
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
>

Re: svn commit: r1634086 - in /lucene/dev/trunk/solr: ./ core/src/java/org/apache/solr/core/ core/src/java/org/apache/solr/update/processor/ core/src/test-files/solr/collection1/conf/ core/src/test/org/apache/solr/core/ core/src/test/org/apache/solr/update...

Posted by Chris Hostetter <ho...@fucit.org>.
: I see what you're saying. My thought was that since both lines are logging
: exactly the same message, it'd be redundant to log it twice. I can
: definitely see logging it in both levels, but modifying the warn message to
: have a "slow query:" prefix or something. What do you think?

yeah -- it's definitely a trade off between redundency vs convinience -- 
but i'm +1 for being redundent in this case.

the biggest worry i have: some existing Ops or DW team has a tier of Solr 
servers with log crunching all setup to get stats on queries, looking 
explicitly at the existing INFO messages -- and then some dev with the 
best intentions at heart comes along and adds this new config option so 
they can focus on problematic queries, w/o realizing how it will affect 
the existing monitoring -- and now the stats coming out of hte existing 
log monitoring are totally skewed.


Anyone in a situation where the redundency would be unwelcome is probably 
either dealing with a high enough volume that INFO logging is disabled 
anyway, or a low evenough volume that they don't need this feature, they 
can check for "slow" queries themselves from the INFO level messages.


: On Fri, Oct 24, 2014 at 10:58 AM, Chris Hostetter <ho...@fucit.org>
: wrote:
: 
: >
: > Does it really make sense for this to be an if/else situation?
: >
: > it seems like the INFO logging should be completley independent from the
: > WANR logging, so people could have INFO level logs of all the requests in
: > one place, and WARN level logs of slow queries go to a distinct file for
: > higher profile analysis.  AS things stand right now, you have to merge the
: > logs if you wnat stats on all requests (ie: to compute percentiles of
: > response time, or what the most requested fq params are, etc..)
: >
: > : +      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));
: >
: >
: > :      if (log.isInfoEnabled()) {
: > : -      StringBuilder sb = new
: > StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
: > : +      log.info(getLogStringAndClearRspToLog());
: > : +    } else if (log.isWarnEnabled()) {
: > : +      long elapsed = rsp.getEndTime() - req.getStartTime();
: > : +      if (elapsed >= slowUpdateThresholdMillis) {
: > : +        log.warn(getLogStringAndClearRspToLog());
: > : +      }
: >
: >
: >
: > -Hoss
: > http://www.lucidworks.com/
: >
: > ---------------------------------------------------------------------
: > To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
: > For additional commands, e-mail: dev-help@lucene.apache.org
: >
: >
: 

-Hoss
http://www.lucidworks.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org


Re: svn commit: r1634086 - in /lucene/dev/trunk/solr: ./ core/src/java/org/apache/solr/core/ core/src/java/org/apache/solr/update/processor/ core/src/test-files/solr/collection1/conf/ core/src/test/org/apache/solr/core/ core/src/test/org/apache/solr/update...

Posted by Jessica Mallet <me...@gmail.com>.
Hi Chris,

I see what you're saying. My thought was that since both lines are logging
exactly the same message, it'd be redundant to log it twice. I can
definitely see logging it in both levels, but modifying the warn message to
have a "slow query:" prefix or something. What do you think?

Thanks,
Jessica

On Fri, Oct 24, 2014 at 10:58 AM, Chris Hostetter <ho...@fucit.org>
wrote:

>
> Does it really make sense for this to be an if/else situation?
>
> it seems like the INFO logging should be completley independent from the
> WANR logging, so people could have INFO level logs of all the requests in
> one place, and WARN level logs of slow queries go to a distinct file for
> higher profile analysis.  AS things stand right now, you have to merge the
> logs if you wnat stats on all requests (ie: to compute percentiles of
> response time, or what the most requested fq params are, etc..)
>
> : +      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));
>
>
> :      if (log.isInfoEnabled()) {
> : -      StringBuilder sb = new
> StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
> : +      log.info(getLogStringAndClearRspToLog());
> : +    } else if (log.isWarnEnabled()) {
> : +      long elapsed = rsp.getEndTime() - req.getStartTime();
> : +      if (elapsed >= slowUpdateThresholdMillis) {
> : +        log.warn(getLogStringAndClearRspToLog());
> : +      }
>
>
>
> -Hoss
> http://www.lucidworks.com/
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
>

Re: svn commit: r1634086 - in /lucene/dev/trunk/solr: ./ core/src/java/org/apache/solr/core/ core/src/java/org/apache/solr/update/processor/ core/src/test-files/solr/collection1/conf/ core/src/test/org/apache/solr/core/ core/src/test/org/apache/solr/update...

Posted by Chris Hostetter <ho...@fucit.org>.
Does it really make sense for this to be an if/else situation?

it seems like the INFO logging should be completley independent from the 
WANR logging, so people could have INFO level logs of all the requests in 
one place, and WARN level logs of slow queries go to a distinct file for 
higher profile analysis.  AS things stand right now, you have to merge the 
logs if you wnat stats on all requests (ie: to compute percentiles of 
response time, or what the most requested fq params are, etc..)

: +      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));


:      if (log.isInfoEnabled()) {
: -      StringBuilder sb = new StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
: +      log.info(getLogStringAndClearRspToLog());
: +    } else if (log.isWarnEnabled()) {
: +      long elapsed = rsp.getEndTime() - req.getStartTime();
: +      if (elapsed >= slowUpdateThresholdMillis) {
: +        log.warn(getLogStringAndClearRspToLog());
: +      }



-Hoss
http://www.lucidworks.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org