kapacitor: Window works unexpected

Hi,

I am using window in my tick script, and I found some weird behaviour with window. I am emitting data every 1s, and running the next tick script:

stream.from().measurement('cpu')
           .window().every(1s).period(20s)

Points - TestStream_Yosi.txt this is the same format as the srpl files in the integration tests

I have checked this tick script (using httpOut) and injected 20 values (every 1s) and got only 19 results (where the last value was 119) and not 20 (and the last value should be 120) as I expected.

I have debugged the window source code and added some log to check the code before line 54 - https://github.com/influxdata/kapacitor/blob/master/window.go#L54,L61

w.logger.Printf("D! Next emit:%s, Current point: %s (value = %v)", wnd.nextEmit, p.Time, p.Fields["value"])

And got the next results -

[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:01 +0000 UTC, Current point: 1971-01-01 00:00:00 +0000 UTC (value = 101)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:01 +0000 UTC, Current point: 1971-01-01 00:00:01 +0000 UTC (value = 102)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:02 +0000 UTC, Current point: 1971-01-01 00:00:02 +0000 UTC (value = 103)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:03 +0000 UTC, Current point: 1971-01-01 00:00:03 +0000 UTC (value = 104)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:04 +0000 UTC, Current point: 1971-01-01 00:00:04 +0000 UTC (value = 105)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:05 +0000 UTC, Current point: 1971-01-01 00:00:05 +0000 UTC (value = 106)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:06 +0000 UTC, Current point: 1971-01-01 00:00:06 +0000 UTC (value = 107)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:07 +0000 UTC, Current point: 1971-01-01 00:00:07 +0000 UTC (value = 108)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:08 +0000 UTC, Current point: 1971-01-01 00:00:08 +0000 UTC (value = 109)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:09 +0000 UTC, Current point: 1971-01-01 00:00:09 +0000 UTC (value = 110)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:10 +0000 UTC, Current point: 1971-01-01 00:00:10 +0000 UTC (value = 111)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:11 +0000 UTC, Current point: 1971-01-01 00:00:11 +0000 UTC (value = 112)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:12 +0000 UTC, Current point: 1971-01-01 00:00:12 +0000 UTC (value = 113)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:13 +0000 UTC, Current point: 1971-01-01 00:00:13 +0000 UTC (value = 114)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:14 +0000 UTC, Current point: 1971-01-01 00:00:14 +0000 UTC (value = 115)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:15 +0000 UTC, Current point: 1971-01-01 00:00:15 +0000 UTC (value = 116)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:16 +0000 UTC, Current point: 1971-01-01 00:00:16 +0000 UTC (value = 117)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:17 +0000 UTC, Current point: 1971-01-01 00:00:17 +0000 UTC (value = 118)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:18 +0000 UTC, Current point: 1971-01-01 00:00:18 +0000 UTC (value = 119)
[TestStream_Yosi:window2] 2016/02/06 00:38:30 D! Next emit:1971-01-01 00:00:19 +0000 UTC, Current point: 1971-01-01 00:00:19 +0000 UTC (value = 120)

As you can see the the last line, we should emit the value 120, and I have digger more… and put log to see the first value and the last value of every emit and saw that -

[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 1 points, first 101 and last 101
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 2 points, first 101 and last 102
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 3 points, first 101 and last 103
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 4 points, first 101 and last 104
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 5 points, first 101 and last 105
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 6 points, first 101 and last 106
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 7 points, first 101 and last 107
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 8 points, first 101 and last 108
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 9 points, first 101 and last 109
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 10 points, first 101 and last 110
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 11 points, first 101 and last 111
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 12 points, first 101 and last 112
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 13 points, first 101 and last 113
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 14 points, first 101 and last 114
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 15 points, first 101 and last 115
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 16 points, first 101 and last 116
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 17 points, first 101 and last 117
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 18 points, first 101 and last 118
[TestStream_Yosi:window2] 2016/02/06 00:42:29 D! Emitting 19 points, first 101 and last 119

The last value is skipped.

I have did little code change, to insert to the window buffer before emitting and it fixed the problem, the logs now looks like this:

Window emits:

[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 2 points, first 101 and last 102
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 3 points, first 101 and last 103
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 4 points, first 101 and last 104
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 5 points, first 101 and last 105
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 6 points, first 101 and last 106
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 7 points, first 101 and last 107
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 8 points, first 101 and last 108
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 9 points, first 101 and last 109
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 10 points, first 101 and last 110
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 11 points, first 101 and last 111
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 12 points, first 101 and last 112
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 13 points, first 101 and last 113
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 14 points, first 101 and last 114
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 15 points, first 101 and last 115
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 16 points, first 101 and last 116
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 17 points, first 101 and last 117
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 18 points, first 101 and last 118
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 19 points, first 101 and last 119
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Emitting 20 points, first 101 and last 120

Next emit debug:

[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:01 +0000 UTC, Current point: 1971-01-01 00:00:00 +0000 UTC (value = 101)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:01 +0000 UTC, Current point: 1971-01-01 00:00:01 +0000 UTC (value = 102)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:02 +0000 UTC, Current point: 1971-01-01 00:00:02 +0000 UTC (value = 103)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:03 +0000 UTC, Current point: 1971-01-01 00:00:03 +0000 UTC (value = 104)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:04 +0000 UTC, Current point: 1971-01-01 00:00:04 +0000 UTC (value = 105)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:05 +0000 UTC, Current point: 1971-01-01 00:00:05 +0000 UTC (value = 106)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:06 +0000 UTC, Current point: 1971-01-01 00:00:06 +0000 UTC (value = 107)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:07 +0000 UTC, Current point: 1971-01-01 00:00:07 +0000 UTC (value = 108)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:08 +0000 UTC, Current point: 1971-01-01 00:00:08 +0000 UTC (value = 109)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:09 +0000 UTC, Current point: 1971-01-01 00:00:09 +0000 UTC (value = 110)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:10 +0000 UTC, Current point: 1971-01-01 00:00:10 +0000 UTC (value = 111)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:11 +0000 UTC, Current point: 1971-01-01 00:00:11 +0000 UTC (value = 112)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:12 +0000 UTC, Current point: 1971-01-01 00:00:12 +0000 UTC (value = 113)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:13 +0000 UTC, Current point: 1971-01-01 00:00:13 +0000 UTC (value = 114)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:14 +0000 UTC, Current point: 1971-01-01 00:00:14 +0000 UTC (value = 115)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:15 +0000 UTC, Current point: 1971-01-01 00:00:15 +0000 UTC (value = 116)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:16 +0000 UTC, Current point: 1971-01-01 00:00:16 +0000 UTC (value = 117)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:17 +0000 UTC, Current point: 1971-01-01 00:00:17 +0000 UTC (value = 118)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:18 +0000 UTC, Current point: 1971-01-01 00:00:18 +0000 UTC (value = 119)
[TestStream_Yosi:window2] 2016/02/06 00:41:44 D! Next emit:1971-01-01 00:00:19 +0000 UTC, Current point: 1971-01-01 00:00:19 +0000 UTC (value = 120)

Is this a bug? I can write integration test for showing the bug if this is needed.

About this issue

Original URL
State: closed
Created 8 years ago
Comments: 17 (16 by maintainers)

Most upvoted comments

That last value is not skipped its just still sitting in the window waiting to be pushed out by then next point behind it.

Add one more point:

dbname
rpname
cpu,type=idle,host=serverA value=121 0000000021

to your test file and see that value 120 will come out.

This is an artifact of how Kapacitor is designed to use the time of data points to understand time instead of real time. This means that unless a new data point comes along time never progresses and the window waits forever to emit the point. You will notice that there are always a few extra data points in the integration test files for exactly this purpose. For infinite streams this is not a problem as there will always be another point to push along the existing points.

The common use cases of Kapacitor are infinite streams, meaning there is no known end to the stream. Do you have a use case that specifically requires an exact amount of data to be processed? If so it might be possible to add some kind of flush mechanism to the pipeline so that all points are processed even if no new points arrive.

nathanielc on Feb 5, 2016