Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

With the LAST() selector the response time increases linear with the number of points in the series. #6704

Closed
janpaulus opened this issue May 23, 2016 · 4 comments

Comments

@janpaulus
Copy link

janpaulus commented May 23, 2016

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

@jeremyVignelles
Copy link

Noticed something similar but did not have time to measure the times. I also noticed an increase of the RAM usage, but I don't know if this is related to the big number of points or the big number of fields in my measurement...

@jwilder
Copy link
Contributor

jwilder commented Oct 24, 2016

@janpaulus Have you tested on 1.0.2?

@jsternberg Would #7497 help this particular query? I'm assuming since there is a group by, the answer is no.

@janpaulus
Copy link
Author

janpaulus commented Oct 25, 2016

@jwilder and @jsternberg In 1.0.2 it is the same problem. I also tried #7497 and it is a huge improvement. Without this commit a query takes 2:50 minutes with #7497 it take only 3 seconds. And the received query content is the same. Thanks a lot.

@jsternberg
Copy link
Contributor

Thanks @janpaulus. @jwilder this query should be sped up by #7497 and it seems like empirically it does so that PR should work for resolving this issue. We have more difficulty with GROUP BY time(...) where it becomes more difficult.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants