You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@storm.apache.org by "P. Taylor Goetz (JIRA)" <ji...@apache.org> on 2018/01/26 18:29:00 UTC
[jira] [Resolved] (STORM-2912) Tick tuple is being shared without
resetting start time and incur side-effect to break metrics
[ https://issues.apache.org/jira/browse/STORM-2912?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
P. Taylor Goetz resolved STORM-2912.
------------------------------------
Resolution: Fixed
Fix Version/s: 1.0.6
1.1.2
1.2.0
2.0.0
Merged to master, 1.x-branch, 1.1.x-branch, 1.0.x-branch.
> Tick tuple is being shared without resetting start time and incur side-effect to break metrics
> ----------------------------------------------------------------------------------------------
>
> Key: STORM-2912
> URL: https://issues.apache.org/jira/browse/STORM-2912
> Project: Apache Storm
> Issue Type: Bug
> Components: storm-client, storm-core
> Affects Versions: 2.0.0, 1.2.0, 1.1.2, 1.0.6
> Reporter: Jungtaek Lim
> Assignee: Jungtaek Lim
> Priority: Blocker
> Labels: pull-request-available
> Fix For: 2.0.0, 1.2.0, 1.1.2, 1.0.6
>
> Time Spent: 3h 10m
> Remaining Estimate: 0h
>
> 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.
> {code:java}
> 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{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)