[STORM-1007] Added tuple arrival rate and tuple sojourn time to QueueMetrics

[wangli1426]

I added two important metrics, namely arrival time and sojourn time, to QueueMetrics.

Modification Summary:

1. Created a new RateTracker utility, which could report instantaneous rate upon certain event;
2. Added test cases for RateTracker;
3. Added arrival rate and sojourn time metrics to QueueMetrics;
4. Use sampling in QueueMetrics to reduce the metric maintenance cost.

Such metrics are very useful to performance tuning, especially for application with strong constraint on processing latency such as threat detection and smart traffic. A high sojourn time, for example, indicates that a higher degree of parallelism should be applied to the current bolt in order to reduce processing delay.

Any comment or suggestion regarding to this pull request is welcomed.

Thanks.

[HeartSaVioR]

Great work. Since it can affect performance I recommend you to include benchmark test result.
You can refer #521 (comment) to how to do it.

[wangli1426]

Hi @HeartSaVioR,

Thank you for your comment. I understand your concern, as DisruptorQueue plays an important role in Storm.

Following your suggestion, I have done performance test using [https://github.com/yahoo/storm-perf-test]. As expected, the results show that the new metrics do not introduce noticeable overhead.

Environment:

Factors	Configurations
CPU	Intel(R) Xeon(R) CPU E5-1620 v3 @ 3.50GHz
RAM	16GB
DISK	2TB
OS	Ubuntu 14.02

Parameters:

--bolt 3 --name test -l 1 -n 1 --workers 4 --spout 3 --testTimeSec 900 -c topology.max.spout.pending=1092 --messageSize 10

Result summary:

master at 154e9ec:
Throughput in MB/s
AVG: 7.974807415
MIN : 7.878930664
MAX: 8.095523041

PR at f15ac94:
Throughput in MB/s
AVG: 7.977237486
MIN : 7.844562531
MAX: 8.251005809

The details of runs at master(154e9ec)

RUNNING 1 4 4 6 6 1441452581500 30000 24470400 7.878930664
RUNNING 1 4 4 6 6 1441452611500 30000 24962680 7.935422262
RUNNING 1 4 4 6 6 1441452641500 30000 24765960 7.972886658
RUNNING 1 4 4 6 6 1441452671500 30000 24576620 7.982697093
RUNNING 1 4 4 6 6 1441452701500 30000 24901860 7.916088104
RUNNING 1 4 4 6 6 1441452731500 30000 25191040 8.008015951
RUNNING 1 4 4 6 6 1441452761501 30001 24791180 7.880641192
RUNNING 1 4 4 6 6 1441452791500 29999 25126800 7.987860867
RUNNING 1 4 4 6 6 1441452821500 30000 25071180 7.969913483
RUNNING 1 4 4 6 6 1441452851500 30000 25098540 7.978610992
RUNNING 1 4 4 6 6 1441452881501 30001 24966120 7.996251266
RUNNING 1 4 4 6 6 1441452911500 29999 24836340 8.095523041
RUNNING 1 4 4 6 6 1441452941500 30000 25004480 7.968710124
RUNNING 1 4 4 6 6 1441452971500 30000 25371360 8.065338135
RUNNING 1 4 4 6 6 1441453001500 30000 24972160 7.938435872
RUNNING 1 4 4 6 6 1441453031500 30000 25382020 8.068726858
RUNNING 1 4 4 6 6 1441453061500 30000 25021280 7.9540507
RUNNING 1 4 4 6 6 1441453091500 30000 25011120 7.950820923
RUNNING 1 4 4 6 6 1441453121500 30000 24690680 7.94895579
RUNNING 1 4 4 6 6 1441453151500 30000 24954060 7.972682037
RUNNING 1 4 4 6 6 1441453181500 30000 24899040 7.98519165
RUNNING 1 4 4 6 6 1441453211501 30001 24737460 7.963564633
RUNNING 1 4 4 6 6 1441453241500 29999 24996060 7.946298354
RUNNING 1 4 4 6 6 1441453271500 30000 24986100 7.942867279
RUNNING 1 4 4 6 6 1441453301500 30000 24906920 7.997696635
RUNNING 1 4 4 6 6 1441453331500 30000 25041520 7.960484823
RUNNING 1 4 4 6 6 1441453361500 30000 25121880 7.986030579
RUNNING 1 4 4 6 6 1441453391500 30000 25126380 7.98746109
RUNNING 1 4 4 6 6 1441453421500 30000 25043860 7.981228689
RUNNING 1 4 4 6 6 1441453451501 30001 24923920 8.022836695
RUNNING 1 4 4 6 6 1441448928080 30000 24357580 7.974807415
RUNNING 1 4 4 6 6 1441448958080 30000 24497360 7.878930664

The details of runs at this PR(f15ac94)

RUNNING 1 4 4 6 6 1441450879792 30001 25703700 8.170713818
RUNNING 1 4 4 6 6 1441450909791 29999 25916500 8.238908104
RUNNING 1 4 4 6 6 1441450939791 30000 25955420 8.251005809
RUNNING 1 4 4 6 6 1441450969791 30000 25774120 8.193372091
RUNNING 1 4 4 6 6 1441450999791 30000 25701440 8.170267741
RUNNING 1 4 4 6 6 1441451029791 30000 25872800 8.224741618
RUNNING 1 4 4 6 6 1441451059791 30000 25357260 8.060855865
RUNNING 1 4 4 6 6 1441451089791 30000 24899640 7.915382385
RUNNING 1 4 4 6 6 1441451119791 30000 25170260 8.001410166
RUNNING 1 4 4 6 6 1441451149792 30001 25220280 8.017043861
RUNNING 1 4 4 6 6 1441451179791 29999 24963440 7.93592839
RUNNING 1 4 4 6 6 1441451209791 30000 24913380 7.919750214
RUNNING 1 4 4 6 6 1441451239791 30000 24676860 7.844562531
RUNNING 1 4 4 6 6 1441451269791 30000 25074360 7.970924377
RUNNING 1 4 4 6 6 1441451299791 30000 24991800 7.94467926
RUNNING 1 4 4 6 6 1441451329791 30000 24966800 7.936731974
RUNNING 1 4 4 6 6 1441451359791 30000 24789820 7.880471547
RUNNING 1 4 4 6 6 1441451389791 30000 24931320 7.925453186
RUNNING 1 4 4 6 6 1441451419791 30000 24845840 7.898279826
RUNNING 1 4 4 6 6 1441451449791 30000 24802200 7.884407043
RUNNING 1 4 4 6 6 1441451479792 30001 24923140 7.922588748
RUNNING 1 4 4 6 6 1441451509791 29999 24936560 7.927383183
RUNNING 1 4 4 6 6 1441451539791 30000 24810660 7.887096405
RUNNING 1 4 4 6 6 1441451569792 30001 25181340 8.004665581
RUNNING 1 4 4 6 6 1441451599791 29999 24692140 7.849681568
RUNNING 1 4 4 6 6 1441451629791 30000 24900600 7.915687561
RUNNING 1 4 4 6 6 1441451659791 30000 24762280 7.871716817
RUNNING 1 4 4 6 6 1441451689791 30000 24952080 7.932052612
RUNNING 1 4 4 6 6 1441451719791 30000 24917080 7.920926412
RUNNING 1 4 4 6 6 1441451749791 30000 25054500 7.964611053
RUNNING 1 4 4 6 6 1441451779791 30000 24871820 7.906538645

Please let me know, if you have any question regarding to this tests or this PR.

Thanks
Li Wang

[HeartSaVioR]

@wangli1426
Great.
One thing which blocks me voting +1 is that I can't understand how RateTracker works.
Could you explain how it works?

[wangli1426]

Hi @HeartSaVioR,

I am glad to explain the mechanism of RateTracker as follows.

In general, RateTracker provides a way to monitor the rate of certain event. We notify RateTracker upon the occurrence of the event by calling notify() method, and call reportRate() to retrieve the instantaneous rate of the event.

The rate is calculated as counts of occurrence / time. As RateTracker reports instantaneous rate, it only maintains the counts of occurrences within a given period of time as specified by validTimeWindowInMils. This is implemented by dividing the validTimeWindowInMils into numOfSlides time slides and employing a timer to periodically (every validTimeWindowInMils/ numOfSlides milliseconds) clean the count in the oldest time slide.

Finally, RateTracker is very efficient. First, notify() only does addition on a count and thus can be finished within few CPU cycles. Second, the update to the counts is also light-weight and only happens periodically, e.g., every 1 or 2 seconds. Third, all the instances of RateTracker share the same timer, avoiding using too many threads.

If you have further question, please let me know.

Thanks.

[HeartSaVioR]

@wangli1426
If I'm understanding right, when we're having several RateTracker instances with different validTimeWindowInMils and numOfSlides, we should not share _timer.
Its value is hardcoded to QueueMetrics so they're always same, but I think RateTracker should not rely on precondition to make itself more usable.

Btw, maybe we can share timer between RateTracker instances which have same validTimeWindowInMils / numOfSlides value.

[HeartSaVioR]

@wangli1426 My bad, turns out I didn't understand Timer properly. Please ignore my last comment.

[HeartSaVioR]

+1
Thanks for providing great feature and benchmark result.

[wangli1426]

@HeartSaVioR
Thanks for voting +1.

By the way, in my original design, I didn't use timer to update the histograms. Instead, the histograms were updated in notify(). However, such a design requires to call System.currentTimeMills() every time when notify() is called, to determine whether an update to the histograms is needed. System.currentTimeMills() is fairly expensive to be called so frequently. So, in current implementation, I use a timer to periodically update the histograms.

[wangli1426]

@HeartSaVioR

Sorry to interrupt, but may I ask when this PR could be merged? I am planing to display the new metrics on the web UI, if this PR gets merged. Thanks.

[HeartSaVioR]

@wangli1426 Sorry for the delay. I intended to wait for other committers to review, but since no one is reviewing I'll merge right now.