With the LAST() selector the response time increases linear with the number of points in the series. #6704
Description
System info: Influxdb 0.13
CPU: 4 x 2 Ghz Xeon
RAM: 8 GB
When doing a query with the LAST() selector it is fast on series with less points. A query on a series with more points takes much longer. There is a linear dependency between the number of points in the series and the response time of the query.
These are my observations:
| number of points | response time [sec] |
|---|---|
| 500 | 3 |
| 8208000 | 10 |
| 10800000 | 12,3 |
| 11232000 | 13 |
| 18360000 | 20 |
| 21600000 | 24 |
| 49464000 | 53 |
The number of series is constant.
Expected behavior:
I expected a constant response time regardless of the number of points in the series.
Actual behavior:
Actually the response time increases linear with the number of points in the series.
Additional info:
These are the go profiling results for a long running query with the LAST() selector:
SELECT time, TAG1, TAG2, LAST(value) FROM measurement WHERE time <= now() GROUP BY TAG1, TAG2
In our case it is not possible to specify the time range in the WHERE clause, because we have series with very different update frequencies. Some series receive a new value every second other only one per month or even less.
(pprof) top 50
3.48mins of 4.02mins total (86.66%)
Dropped 495 nodes (cum <= 0.02mins)
Showing top 50 nodes out of 136 (cum >= 0.04mins)
flat flat% sum% cum cum%
0.45mins 11.09% 11.09% 1.21mins 30.10% runtime.mallocgc
0.17mins 4.34% 15.43% 1.79mins 44.61% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_floatIterator).Next
0.14mins 3.60% 19.02% 0.59mins 14.67% runtime.concatstrings
0.13mins 3.31% 22.34% 0.13mins 3.31% runtime.(_mspan).sweep.func1
0.13mins 3.14% 25.48% 0.31mins 7.59% runtime.scanobject
0.13mins 3.11% 28.59% 0.29mins 7.21% runtime.pcvalue
0.12mins 2.86% 31.46% 0.12mins 2.86% runtime.memmove
0.11mins 2.79% 34.24% 0.21mins 5.23% runtime.mapaccess1_faststr
0.11mins 2.64% 36.88% 0.18mins 4.55% runtime.mapaccess2_faststr
0.09mins 2.28% 39.17% 0.09mins 2.28% runtime.memeqbody
0.09mins 2.18% 41.35% 0.12mins 2.88% runtime.greyobject
0.09mins 2.12% 43.47% 0.09mins 2.12% runtime.readvarint
0.08mins 2.01% 45.48% 3.22mins 80.15% github.com/influxdata/influxdb/influxql.(_floatReduceFloatIterator).reduce
0.08mins 2.00% 47.48% 3.22mins 80.15% github.com/influxdata/influxdb/influxql.(_floatMergeIterator).Next
0.07mins 1.86% 49.34% 0.07mins 1.86% runtime.heapBitsForObject
0.07mins 1.82% 51.16% 0.93mins 23.06% runtime.convT2E
0.07mins 1.71% 52.87% 0.20mins 5.03% runtime.heapBitsSweepSpan
0.07mins 1.63% 54.51% 0.07mins 1.63% runtime.memhash
0.06mins 1.56% 56.07% 0.06mins 1.58% runtime.heapBitsSetType
0.06mins 1.37% 57.43% 0.14mins 3.53% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_TimeDecoder).decodePacked
0.05mins 1.33% 58.77% 0.07mins 1.68% github.com/influxdata/influxdb/influxql.(_FloatFuncReducer).AggregateFloat
0.05mins 1.31% 60.08% 0.14mins 3.44% runtime.step
0.05mins 1.27% 61.35% 0.12mins 3.09% runtime.typedmemmove
0.05mins 1.26% 62.62% 0.76mins 18.90% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_stringLiteralCursor).nextAt
0.05mins 1.25% 63.87% 0.05mins 1.25% runtime.prefetchnta
0.05mins 1.24% 65.11% 3.22mins 80.16% github.com/influxdata/influxdb/influxql.(_bufFloatIterator).Next
0.05mins 1.24% 66.34% 0.53mins 13.25% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_bufCursor).nextAt
0.05mins 1.22% 67.56% 0.05mins 1.22% runtime.duffcopy
0.05mins 1.17% 68.73% 0.12mins 2.89% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_FloatDecoder).Next
0.05mins 1.17% 69.91% 0.24mins 5.88% github.com/influxdata/influxdb/tsdb/engine/tsm1.DecodeFloatBlock
0.05mins 1.17% 71.08% 0.05mins 1.17% runtime.memclr
0.05mins 1.12% 72.20% 0.22mins 5.56% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_integerAscendingCursor).nextInteger
0.04mins 1.11% 73.31% 0.31mins 7.80% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_floatAscendingCursor).nextFloat
0.04mins 1.11% 74.41% 0.39mins 9.78% runtime.gentraceback
0.04mins 1.07% 75.49% 0.08mins 2.01% github.com/jwilder/encoding/simple8b.(_Decoder).Next
0.04mins 1.07% 76.56% 0.07mins 1.71% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_BitReader).ReadBits
0.04mins 1.06% 77.62% 0.22mins 5.44% github.com/influxdata/influxdb/influxql.keysMatch
0.04mins 0.97% 78.59% 0.04mins 1.06% runtime.findfunc
0.04mins 0.92% 79.51% 0.39mins 9.70% runtime.rawstring
0.04mins 0.91% 80.42% 0.15mins 3.73% github.com/influxdata/influxdb/tsdb/engine/tsm1.DecodeIntegerBlock
0.03mins 0.73% 81.15% 0.84mins 20.91% runtime.newobject
0.03mins 0.71% 81.86% 0.48mins 12.01% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_bufCursor).next
0.03mins 0.65% 82.51% 0.03mins 0.65% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_BitReader).readBuf
0.03mins 0.65% 83.15% 0.07mins 1.79% runtime.(_mcentral).grow
0.03mins 0.63% 83.78% 0.03mins 0.63% runtime/internal/atomic.Or8
0.03mins 0.62% 84.40% 0.03mins 0.66% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_integerAscendingCursor).peekCache
0.02mins 0.59% 85.00% 3.22mins 80.15% github.com/influxdata/influxdb/influxql.(_floatInterruptIterator).Next
0.02mins 0.58% 85.58% 0.03mins 0.69% github.com/influxdata/influxdb/tsdb/engine/tsm1.(_floatAscendingCursor).peekCache
0.02mins 0.54% 86.12% 2.02mins 50.27% github.com/influxdata/influxdb/influxql.(_bufFloatIterator).NextInWindow
0.02mins 0.54% 86.66% 0.04mins 0.94% github.com/jwilder/encoding/simple8b.(_Decoder).read