Uploaded image for project: 'Apache Storm'
  1. Apache Storm
  2. STORM-2912

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

    Details

      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

        Attachments

          Activity

            People

            • Assignee:
              kabhwan Jungtaek Lim
              Reporter:
              kabhwan Jungtaek Lim
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0h
                0h
                Logged:
                Time Spent - 3h 20m
                3h 20m