[STORM-2912] Tick tuple is being shared without resetting start time and incur side-effect to break metrics

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 2.0.0, 1.2.0, 1.1.2, 1.0.6
• Fix Version/s: 2.0.0, 1.2.0, 1.1.2, 1.0.6
• Component/s: storm-client, storm-core
• Labels: pull-request-available
• Assignee: Jungtaek Lim
• Reporter: Jungtaek Lim
• Created: 25/Jan/18 06:10
• Updated: 27/Jan/18 21:13
• Resolved: 26/Jan/18 18:28

Description

In STORM-2786 we have applied small optimization: create tick tuple only once and reuse. The optimization completely makes sense, but when measuring built-in metrics, when reused tick tuple is selected for sampling, we never reset start time unless it is selected for sampling again, hence further tick tuple is always considered as sampled with start time unchanged.

What I've observed is that delta for tick tuple is gradually increasing for some time-period, and reset to 0, which messes up latencies. It also messes up executed as well because it is always considered as selected tuple (hence recorded to 20x for tick tuple), but unless interval of tick tuple is super small, the effect is much smaller then latency.

 

Here's part of log denoting this issue. Please take a look at DELTA values, which shouldn't be such huge.

2018-01-25 13:34:41.464 o.a.s.d.executor Thread-14-__acker-executor[1 1] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [30] TASK: 1 DELTA: 0
2018-01-25 13:34:41.658 o.a.s.d.executor Thread-12-counter-executor[3 3] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 3 DELTA: 87083
2018-01-25 13:34:41.658 o.a.s.d.executor Thread-8-counter-executor[2 2] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 2 DELTA: 6003
2018-01-25 13:34:41.728 o.a.s.d.executor Thread-26-counter-executor[5 5] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 5 DELTA: 30036
2018-01-25 13:34:41.728 o.a.s.d.executor Thread-4-intermediateRanker-executor[8 8] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 8 DELTA: 4001
2018-01-25 13:34:41.729 o.a.s.d.executor Thread-32-counter-executor[4 4] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 4 DELTA: 156155
2018-01-25 13:34:41.813 o.a.s.d.executor Thread-16-finalRanker-executor[6 6] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 6 DELTA: 24043
2018-01-25 13:34:41.813 o.a.s.d.executor Thread-10-intermediateRanker-executor[7 7] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 7 DELTA: 14025
2018-01-25 13:34:41.813 o.a.s.d.executor Thread-18-intermediateRanker-executor[9 9] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 9 DELTA: 52091
2018-01-25 13:34:41.886 o.a.s.d.executor Thread-28-intermediateRanker-executor[10 10] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 10 DELTA: 18025
2018-01-25 13:34:43.731 o.a.s.d.executor Thread-4-intermediateRanker-executor[8 8] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 8 DELTA: 6004
2018-01-25 13:34:43.817 o.a.s.d.executor Thread-16-finalRanker-executor[6 6] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 6 DELTA: 26047
2018-01-25 13:34:43.817 o.a.s.d.executor Thread-10-intermediateRanker-executor[7 7] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 7 DELTA: 16029
2018-01-25 13:34:43.817 o.a.s.d.executor Thread-18-intermediateRanker-executor[9 9] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 9 DELTA: 1
2018-01-25 13:34:43.890 o.a.s.d.executor Thread-28-intermediateRanker-executor[10 10] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 10 DELTA: 20029
2018-01-25 13:34:44.661 o.a.s.d.executor Thread-12-counter-executor[3 3] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 3 DELTA: 90086
2018-01-25 13:34:44.662 o.a.s.d.executor Thread-8-counter-executor[2 2] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 2 DELTA: 9007
2018-01-25 13:34:44.734 o.a.s.d.executor Thread-26-counter-executor[5 5] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 5 DELTA: 33042
2018-01-25 13:34:44.734 o.a.s.d.executor Thread-32-counter-executor[4 4] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 4 DELTA: 159160
2018-01-25 13:34:45.735 o.a.s.d.executor Thread-4-intermediateRanker-executor[8 8] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 8 DELTA: 8008
2018-01-25 13:34:45.820 o.a.s.d.executor Thread-18-intermediateRanker-executor[9 9] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 9 DELTA: 2004
2018-01-25 13:34:45.821 o.a.s.d.executor Thread-16-finalRanker-executor[6 6] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 6 DELTA: 28051
2018-01-25 13:34:45.821 o.a.s.d.executor Thread-10-intermediateRanker-executor[7 7] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 7 DELTA: 18033
2018-01-25 13:34:45.892 o.a.s.d.executor Thread-28-intermediateRanker-executor[10 10] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 10 DELTA: 22031
2018-01-25 13:34:47.663 o.a.s.d.executor Thread-12-counter-executor[3 3] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 3 DELTA: 93088
2018-01-25 13:34:47.664 o.a.s.d.executor Thread-8-counter-executor[2 2] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 2 DELTA: 12009
2018-01-25 13:34:47.734 o.a.s.d.executor Thread-32-counter-executor[4 4] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 4 DELTA: 162160
2018-01-25 13:34:47.736 o.a.s.d.executor Thread-4-intermediateRanker-executor[8 8] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 8 DELTA: 10009
2018-01-25 13:34:47.736 o.a.s.d.executor Thread-26-counter-executor[5 5] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [3] TASK: 5 DELTA: 36044
2018-01-25 13:34:47.825 o.a.s.d.executor Thread-10-intermediateRanker-executor[7 7] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 7 DELTA: 20037
2018-01-25 13:34:47.826 o.a.s.d.executor Thread-16-finalRanker-executor[6 6] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 6 DELTA: 30056
2018-01-25 13:34:47.826 o.a.s.d.executor Thread-18-intermediateRanker-executor[9 9] [INFO] Execute done TUPLE source: __system:-1, stream: __tick, id: {}, [2] TASK: 9 DELTA: 4010

Issue Links

• links to: GitHub Pull Request #2532
• links to: GitHub Pull Request #2533