Expose the request phase durations stored by RequestLog #100

clayreimann · 2016-11-17T20:47:42Z

Add FiliTimingFilter to allow applications to use custom logging filters while retaining the non-logging related behaviors of the BardLoggingFilter
Refactored the RequestLog by spinning the model out into a seperate class and marking the existing class as a utility

New methods

RequestLogUtils.startTimingRequest
RequestLogUtils.stopTimingRequest

michael-mclawhorn · 2016-12-01T18:50:08Z

I'm pretty excited about this PR. I haven't had a chance to deep dive review in micro, but the broad strokes look very appealing.

michael-mclawhorn · 2016-12-01T18:48:52Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLogUtils.java

+    private static final List<String> LOGINFO_ORDER = generateLogInfoOrder();
+
+    private static final ThreadLocal<RequestLog> RLOG = ThreadLocal.withInitial(RequestLog::new);
+


This is an interesting way to do this. I wonder if SystemConfig should be tweaked in a similar way.

michael-mclawhorn · 2016-12-01T18:50:59Z

CHANGELOG definitely needs to be updated. Also, this will break every piece of downstream code, which won't make us many friends.

Well, any with logging.

michael-mclawhorn · 2016-12-08T19:25:39Z

@mangesh-pardeshi @codingwhatever
Could you guys give me an estimate of how many places you're calling RequestLog in your code? If the answer is very little, I'm inclined to let this change go through. If not, I'd like to know how much work this will produce for you.

codingwhatever · 2016-12-09T17:21:41Z

I can't find any uses in our code base.

michael-mclawhorn · 2017-01-03T17:44:52Z

@clayreimann Could I request you to rebase this forward on master and see if you have any build errors. Out of band conversations look like this will have low impact on known adopters.

clayreimann · 2017-01-04T15:10:28Z

@michael-mclawhorn @archolewa Rebased on master

archolewa

Overall, it looks pretty good. Looks like your editor's import settings don't quite line up with Fili's, so there's a bunch of imports that need to be fixed.

Also, I think we should move TimedPhase out into its own class, along with all the static methods from RequestLogUtils that manipulate timed phases. There's not really any point in having the TimedPhase be an inner class of RequestLog now that we've moved all of the stopwatch methods out of RequestLog.

archolewa · 2017-01-18T14:59:17Z

...core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java

@@ -2,10 +2,14 @@
 // Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.druid.client.impl;

-import static com.yahoo.bard.webservice.web.ErrorMessageFormat.DRUID_URL_INVALID;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;


Looks like the imports got a bit messed up. The static imports should remain up here, and the codahale and fasterxml imports should be moved back beneath the com.yahoo imports.

archolewa · 2017-01-18T14:59:44Z

...core/src/main/java/com/yahoo/bard/webservice/druid/client/impl/AsyncDruidWebServiceImpl.java

@@ -37,14 +32,17 @@
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;

+import javax.ws.rs.core.Response.Status;


I believe the javax imports go after the java imports.

archolewa · 2017-01-18T15:01:11Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java

-import static com.yahoo.bard.webservice.druid.client.impl.AsyncDruidWebServiceImpl.DRUID_QUERY_TIMER;
-import static com.yahoo.bard.webservice.util.StreamUtils.not;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;


Again, the imports got messed up. The static imports shuld remain at the top, and the com.codahale import should go back to where it was originally.

archolewa · 2017-01-18T15:17:33Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java

-        private final String name;
-        private long start;
-        private long duration;
+    protected static class TimedPhase {


Since we're moving all of the stopwatch methods out of RequestLog, I think we should move TimedPhase out as well, since that's what the stopwatch methods are manipulating.

In fact, rather than having a RequestLogUtils class, I think we should have a TimedPhase class. That class has the definition of TimedPhase, along with all the static methods for manipulating them (i.e. starting, stopping, switching).

I disagree, the stopwatch methods all operate in the context of the tread's RequestLog

Well, erm, hmm. I actually have a PR out to address a separate issue that pulls the TimedPhase out: #143

Basically, to make starting and stopping timers cleaner, I had the TimedPhase implement auto-closeable, so that we could use Java's spiffy new try-with-resource block. But that required making the TimedPhase publicly available, and I'm not generally a fan of having public inner classes vs. just regular public classes. Don't really believe that they buy you much but code clutter.

archolewa · 2017-01-18T15:19:27Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLogUtils.java

+import static com.yahoo.bard.webservice.logging.RequestLog.LOG_ID_KEY;
+import static com.yahoo.bard.webservice.util.StreamUtils.not;
+import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
+import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;


The imports here are incorrect:

static imports should go at the very top.

Then com.yahoo in a separate paragraph

Then com.* where * != yahoo in separate paragraph

Then org.* in a separate paragraph

Then java.*

Then javax.*

archolewa · 2017-01-18T15:36:06Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/filters/FiliTimingFilter.java

+@PreMatching
+@Singleton
+@Priority(1)
+public class FiliTimingFilter implements ContainerResponseFilter, ContainerRequestFilter {


This could really use a better name, since it isn't just doing timing (it's also stashing the request-id header). Maybe FiliInitializationFilter?

archolewa · 2017-01-18T15:36:48Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/CacheRequestHandler.java

@@ -2,32 +2,30 @@
 // Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.web.handlers;

-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
-


archolewa · 2017-01-18T15:37:07Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/CacheV2RequestHandler.java

@@ -3,35 +3,33 @@
 package com.yahoo.bard.webservice.web.handlers;


-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.REQUEST_WORKFLOW_TIMER;
-import static com.yahoo.bard.webservice.web.handlers.workflow.DruidWorkflow.RESPONSE_WORKFLOW_TIMER;
-


archolewa · 2017-01-18T15:37:29Z

fili-core/src/main/java/com/yahoo/bard/webservice/web/handlers/SplitQueryRequestHandler.java

@@ -2,33 +2,31 @@
 // Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.web.handlers;

-import static com.yahoo.bard.webservice.web.ErrorMessageFormat.EMPTY_INTERVAL_FORMAT;
-


archolewa · 2017-01-18T15:37:57Z

.../main/java/com/yahoo/bard/webservice/web/responseprocessors/SplitQueryResponseProcessor.java

@@ -2,17 +2,16 @@
 // Licensed under the terms of the Apache license. Please see LICENSE.md file distributed with this work for terms.
 package com.yahoo.bard.webservice.web.responseprocessors;

+import com.fasterxml.jackson.databind.JsonNode;
+import com.fasterxml.jackson.databind.node.ArrayNode;
+import com.fasterxml.jackson.databind.node.JsonNodeFactory;


* Add FiliTimingFilter to allow applications to use custom logging filters while retaining the non-logging related behaviors of the BardLoggingFilter * Refactored the RequestLog by spinning the model out into a seperate class and marking the existing class as a utility

clayreimann · 2017-01-26T23:39:19Z

@michael-mclawhorn @archolewa Rebased again and addressed @archolewa's comments

archolewa

Had a few minor comments, but nothing major. 👍 once they've been addressed.

archolewa · 2017-01-27T16:57:21Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/RequestLog.java

                    }
+                    LOG.warn("Exporting duration while timer is running. Measurement might be wrong: {}", phase.name);


This can probably be simplified by using a positive conditional.

if (phase.isRunning()) { LOG.warn("Exporting duration while timer is running. Measurement might be wrong: {}", phase.name); }

archolewa · 2017-01-27T16:58:22Z

fili-core/src/main/java/com/yahoo/bard/webservice/logging/TimedPhase.java

+     * Start the phase.
+     */
+    protected void start() {
+        if (start != 0) {


Should probably replace start != 0 with isRunning().

michael-mclawhorn reviewed Dec 1, 2016

View reviewed changes

michael-mclawhorn requested a review from archolewa December 15, 2016 22:16

clayreimann force-pushed the extricate-timings-from-logging-filter branch 2 times, most recently from 92e0146 to eb37d13 Compare January 4, 2017 15:09

archolewa requested changes Jan 18, 2017

View reviewed changes

Clay Reimann added 2 commits January 26, 2017 17:06

Respond to comments

6a283a6

clayreimann force-pushed the extricate-timings-from-logging-filter branch from eb37d13 to 6a283a6 Compare January 26, 2017 23:38

archolewa approved these changes Jan 27, 2017

View reviewed changes

Respond to @archolewa's comments

d56fb16

michael-mclawhorn closed this Feb 1, 2017

michael-mclawhorn mentioned this pull request Feb 1, 2017

Expose the request phase durations stored by RequestLog: replaces Pr/100 #159

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expose the request phase durations stored by RequestLog #100

Expose the request phase durations stored by RequestLog #100

clayreimann commented Nov 17, 2016

michael-mclawhorn commented Dec 1, 2016

michael-mclawhorn Dec 1, 2016

michael-mclawhorn commented Dec 1, 2016 •

edited

Loading

michael-mclawhorn commented Dec 8, 2016 •

edited

Loading

codingwhatever commented Dec 9, 2016

michael-mclawhorn commented Jan 3, 2017

clayreimann commented Jan 4, 2017

archolewa left a comment

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

clayreimann Jan 26, 2017

archolewa Jan 27, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

archolewa Jan 18, 2017

clayreimann commented Jan 26, 2017

archolewa left a comment

archolewa Jan 27, 2017

archolewa Jan 27, 2017

		private static final List<String> LOGINFO_ORDER = generateLogInfoOrder();

		private static final ThreadLocal<RequestLog> RLOG = ThreadLocal.withInitial(RequestLog::new);

		}
		LOG.warn("Exporting duration while timer is running. Measurement might be wrong: {}", phase.name);

Expose the request phase durations stored by RequestLog #100

Expose the request phase durations stored by RequestLog #100

Conversation

clayreimann commented Nov 17, 2016

New methods

michael-mclawhorn commented Dec 1, 2016

Choose a reason for hiding this comment

michael-mclawhorn commented Dec 1, 2016 • edited Loading

michael-mclawhorn commented Dec 8, 2016 • edited Loading

codingwhatever commented Dec 9, 2016

michael-mclawhorn commented Jan 3, 2017

clayreimann commented Jan 4, 2017

archolewa left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

clayreimann commented Jan 26, 2017

archolewa left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michael-mclawhorn commented Dec 1, 2016 •

edited

Loading

michael-mclawhorn commented Dec 8, 2016 •

edited

Loading