Changes to support calculation wall-clock time taken by a set of hystrix commands #356

praveen27 · 2014-12-14T14:24:35Z

Added in support for calculation wall-clock time taken by a set of hystrix commands usually within the scope of a request.

Use-Case:
We develop and own a service say postUserComments which in turn depends on a set of independent services say

detectSpammyURLInContent
detectAbuse
postToTwitter
buildSecondaryIndices
....

All but buildSecondaryIndices are external services that are beyond the scope of current service/system. These are executed in parallel or in sequence depending upon service semantics.

The added feature will help capture true "wall-clock" overhead of postUserComments service, which can be used by service implementations to monitor/alert and optimize on SLA's guaranteed by services.

…overlapping commands

… fixed a conditional path bug

cloudbees-pull-request-builder · 2014-12-14T14:25:20Z

Hystrix-pull-requests #177 FAILURE
Looks like there's a problem with this pull request

cloudbees-pull-request-builder · 2014-12-14T14:35:17Z

Hystrix-pull-requests #178 FAILURE
Looks like there's a problem with this pull request

mjball · 2014-12-14T17:01:52Z

hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java

@@ -1401,6 +1402,12 @@ private ExecutionResult(List<HystrixEventType> events, int executionTime, Except
            // because we control the original list in 'newEvent'
            this.events = events;
            this.executionTime = executionTime;
+            if (executionTime >= 0 ) {
+                this.commandRunStartTime = System.currentTimeMillis() - this.executionTime;


Consider using System.nanoTime() for execution timing.

Thought about it :-), the execution time is in millis, so the option was
use nanos to and then convert it to millis and then get the start time in
ms wasn't achieving any thing substantially better.

I am open to ideas on using nanos if it is significantly better though, it
is really small change really.

Regards,

Praveen Ramachandra

On Dec 14, 2014 9:02 AM, "Matt Ball" notifications@github.com wrote:

In hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java
#356 (diff):

@@ -1401,6 +1402,12 @@ private ExecutionResult(List events, int executionTime, Except
// because we control the original list in 'newEvent'
this.events = events;
this.executionTime = executionTime;

if (executionTime >= 0 ) {

this.commandRunStartTime = System.currentTimeMillis() - this.executionTime;

Consider using System.nanoTime() for execution timing.

—
Reply to this email directly or view it on GitHub
https://github.com/Netflix/Hystrix/pull/356/files#r21797497.

Thought about it :-), the execution time is in millis, so the option was
use nanos to and then convert it to millis and then get the start time in
ms wasn't achieving any thing substantially better.

I am open to ideas on using nanos if it is significantly better though, it
is really small change really.

May be we could modify the API's consistently in a way where report in
millis and micros (depending upon what the caller asks), if this has been a
need that has been expressed by the community.

On Sun, Dec 14, 2014 at 9:02 AM, Matt Ball notifications@github.com wrote:

In hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java
#356 (diff):

@@ -1401,6 +1402,12 @@ private ExecutionResult(List events, int executionTime, Except
// because we control the original list in 'newEvent'
this.events = events;
this.executionTime = executionTime;

if (executionTime >= 0 ) {

this.commandRunStartTime = System.currentTimeMillis() - this.executionTime;

Consider using System.nanoTime() for execution timing.

—
Reply to this email directly or view it on GitHub
https://github.com/Netflix/Hystrix/pull/356/files#r21797497.

Regards,
Praveen Ramachandra

The main issue with using System.currentTimeMillis() is that it's not monotonically increasing. If the OS time jumps (say, time zone or NTP adjustment), System.currentTimeMillis() is affected. System.nanoTime() is not.

http://stackoverflow.com/a/351571/139010

Thanks for suggestion Matt. Updated and the new code reflects usage of
System.nanoTime() . I have reflected the changed semantics in method names
as well explicitly. Please look at the updated pull-request.

Regards,

Praveen Ramachandra

Got it. Let me put in the change by eod today.
On Dec 14, 2014 9:20 AM, "Matt Ball" notifications@github.com wrote:

In hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java
#356 (diff):

@@ -1401,6 +1402,12 @@ private ExecutionResult(List events, int executionTime, Except
// because we control the original list in 'newEvent'
this.events = events;
this.executionTime = executionTime;

if (executionTime >= 0 ) {

this.commandRunStartTime = System.currentTimeMillis() - this.executionTime;

The main issue with System.currentTimeMillis() is that it's not
monotonically increasing.

http://stackoverflow.com/a/351571/139010

—
Reply to this email directly or view it on GitHub
https://github.com/Netflix/Hystrix/pull/356/files#r21797619.

….currenttimeMillis is not monotonically increasing all the time across all the OSes and hostsgit statusgit status

cloudbees-pull-request-builder · 2014-12-15T00:48:34Z

Hystrix-pull-requests #180 FAILURE
Looks like there's a problem with this pull request

benjchristensen · 2014-12-15T18:56:17Z

Why does this need to be part of the core library? Hystrix is already crazy complicated so I'm hesitant to add more functionality such as this.

It seems that all of this behavior can be achieved through plugins that are customized to your use cases. Is there anything that does not work via plugins?

praveen27 · 2014-12-15T19:07:15Z

Hi Ben,

It fills the critical gap that is required for all service implementations
using hystrix and it has "zero" application logic.

All that was required was

Field in ExecutionResult
One line Accessor method implementation in AbstractCommand & reflect
the change in interface HystrixExecutableInfo
Utility method in HystrixRequestLog similar to HystrixRequestLog::
getExecutedCommandsAsString

When I first explored writing as plugins, I felt that I was writing more
stuff just to have it working and most of the work was already done in the
base frameworks. I also strongly believe that it belongs to the framework
and I am sure many developers would like to use it.

On Mon, Dec 15, 2014 at 10:56 AM, Ben Christensen notifications@github.com
wrote:

Why does this need to be part of the core library? Hystrix is already
crazy complicated so I'm hesitant to add more functionality such as this.

It seems that all of this behavior can be achieved through plugins that
are customized to your use cases. Is there anything that does not work via
plugins?

—
Reply to this email directly or view it on GitHub
#356 (comment).

Regards,
Praveen Ramachandra

mattrjacobs · 2014-12-15T21:50:50Z

Thanks for the unit tests along with the code, @praveen27.

I'm having trouble understanding how the wall-clock value will be used. In general, each instance of a dependency-command instance should correspond with a remote call, so that seems like the right level of granularity for capturing metrics and alerting.

Can you provide an example of an action are you able to take from knowledge of this wall-clock time that you aren't otherwise able to take?

mattrjacobs · 2014-12-19T00:38:16Z

Talked to @praveen27 in person, and he opened #366 to replace this one. We decided this functionality made for a fine plugin, but did not belong in hystrix-core

Praveenramchandra added 3 commits December 13, 2014 05:11

Support for calculating wall clock time to execute interleved and/or …

82d49ed

…overlapping commands

Support for calculating wall clock time to execute interleved and/or …

f7cc149

…overlapping commands

Moved test cases from HystrixCommandTest to HystrixRequestLogTest and…

b2846fd

… fixed a conditional path bug

Fixing java 6 based compiler issues

cf2f19c

mjball reviewed Dec 14, 2014
View reviewed changes

Using System.nanoTime() instead of System.currentTimeMillis(). System…

c3cc2ac

….currenttimeMillis is not monotonically increasing all the time across all the OSes and hostsgit statusgit status

mattrjacobs closed this Dec 19, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Changes to support calculation wall-clock time taken by a set of hystrix commands #356

Changes to support calculation wall-clock time taken by a set of hystrix commands #356

praveen27 commented Dec 14, 2014

cloudbees-pull-request-builder commented Dec 14, 2014

cloudbees-pull-request-builder commented Dec 14, 2014

mjball Dec 14, 2014

praveen27 Dec 14, 2014

praveen27 Dec 14, 2014

mjball Dec 14, 2014

praveen27 Dec 15, 2014

cloudbees-pull-request-builder commented Dec 15, 2014

benjchristensen commented Dec 15, 2014

praveen27 commented Dec 15, 2014

mattrjacobs commented Dec 15, 2014

mattrjacobs commented Dec 19, 2014

Changes to support calculation wall-clock time taken by a set of hystrix commands #356

Changes to support calculation wall-clock time taken by a set of hystrix commands #356

Conversation

praveen27 commented Dec 14, 2014

cloudbees-pull-request-builder commented Dec 14, 2014

cloudbees-pull-request-builder commented Dec 14, 2014

mjball Dec 14, 2014

Choose a reason for hiding this comment

praveen27 Dec 14, 2014

Choose a reason for hiding this comment

praveen27 Dec 14, 2014

Choose a reason for hiding this comment

mjball Dec 14, 2014

Choose a reason for hiding this comment

praveen27 Dec 15, 2014

Choose a reason for hiding this comment

cloudbees-pull-request-builder commented Dec 15, 2014

benjchristensen commented Dec 15, 2014

praveen27 commented Dec 15, 2014

mattrjacobs commented Dec 15, 2014

mattrjacobs commented Dec 19, 2014