VictoriaMetrics: Queries intermittently return no data for discontinuous series
Describe the bug
/api/v1/series and /api/v1/query_range inconsistently return no data from a successful query.
For query_range, behavior seems influenced by step size, and whether the series has active data at both the start and end date of the query.
To Reproduce I was unable to build a clean room data set that reproduces the problem, but can provide a (723MB) data set where I can consistently reproduce the problem.
The tested series has data in ~5s intervals between 2022/10/03 14:00 and 2022/10/03 15:30, and then again from 2022/10/18 15:45 onwards.
The below query consistently yields data:
curl -sS \
-H 'Content-Type: application/x-www-form-urlencoded' \
-X POST \
-d 'query=avg_over_time({__name__="spark4/SystemInfo/uptime[second]"})' \
-d 'trace=1' \
-d 'step=60s' \
-d 'start=2022-10-03T15:00:00Z' \
-d 'end=2022-10-20T15:00:00Z' \
http://localhost:8428/api/v1/query_range
This query often returns an empty success. It is different only in end date.
curl -sS \
-H 'Content-Type: application/x-www-form-urlencoded' \
-X POST \
-d 'query=avg_over_time({__name__="spark4/SystemInfo/uptime[second]"})' \
-d 'trace=1' \
-d 'step=60s' \
-d 'start=2022-10-03T15:00:00Z' \
-d 'end=2022-10-05T15:00:00Z' \
http://localhost:8428/api/v1/query_range
For the second query, the output can vary based on the step argument. I have been unable to consistently reproduce behavior, but varying step size between 10s and 400s will randomly cause the query to return an empty success.
Expected behavior For the query to return the relevant data when successful, and an error message when not.
Logs
Trace output from an empty query result
{
"status": "success",
"data": {
"resultType": "matrix",
"result": []
},
"trace": {
"duration_msec": 20.233,
"message": "/api/v1/query_range: start=1664809200000, end=1664982000000, step=60000, query=\"avg_over_time({__name__=\\\"spark4/SystemInfo/uptime[second]\\\"})\": series=0",
"children": [
{
"duration_msec": 19.621,
"message": "eval: query=avg_over_time(spark4\\/SystemInfo\\/uptime\\[second\\]), timeRange=[2022-10-03T15:00:00Z..2022-10-05T15:00:00Z], step=60000, mayCache=true: series=0, points=0, pointsPerSeries=0",
"children": [
{
"duration_msec": 19.52,
"message": "rollup avg_over_time(): timeRange=[2022-10-03T15:00:00Z..2022-10-05T15:00:00Z], step=60000, window=0: neededMemoryBytes=0",
"children": [
{
"duration_msec": 0.059,
"message": "rollup cache get: query=avg_over_time(spark4\\/SystemInfo\\/uptime\\[second\\]), timeRange=[2022-10-03T15:00:00Z..2022-10-05T15:00:00Z], step=60000, window=0",
"children": [
{
"duration_msec": 0.043,
"message": "nothing found"
}
]
},
{
"duration_msec": 19.093,
"message": "fetch matching series: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-05T15:00:00Z]",
"children": [
{
"duration_msec": 11.318,
"message": "init series search: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-05T15:00:00Z]",
"children": [
{
"duration_msec": 11.185,
"message": "search for matching tsids: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-05T15:00:00Z]",
"children": [
{
"duration_msec": 10.836,
"message": "search for tsids in the current indexdb",
"children": [
{
"duration_msec": 0.046,
"message": "search for tsids in tag filters cache",
"children": [
{
"duration_msec": 0.031,
"message": "cache miss"
}
]
},
{
"duration_msec": 4.119,
"message": "search for metric ids: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-05T15:00:00Z], maxMetrics=300000",
"children": [
{
"duration_msec": 4.041,
"message": "update metric ids: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, timeRange=[2022-10-03T14:54:00Z..2022-10-05T15:00:00Z]: updated 0 metric ids",
"children": [
{
"duration_msec": 3.967,
"message": "parallel search for metric ids in per-day index: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, dayRange=[19268..19270]",
"children": [
{
"duration_msec": 3.903,
"message": "parallel thread for date=2022-10-03",
"children": [
{
"duration_msec": 3.567,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-03, maxMetrics=300001",
"children": [
{
"duration_msec": 3.476,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 3.372,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-03, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 3.324,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.011,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.011,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 3.82,
"message": "parallel thread for date=2022-10-04",
"children": [
{
"duration_msec": 3.568,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-04, maxMetrics=300001",
"children": [
{
"duration_msec": 3.461,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 3.333,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-04, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 3.285,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.012,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.011,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 3.771,
"message": "parallel thread for date=2022-10-05",
"children": [
{
"duration_msec": 3.624,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-05, maxMetrics=300001",
"children": [
{
"duration_msec": 3.525,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 3.411,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-05, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 3.349,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.012,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.011,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.01,
"message": "found zero metric ids"
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"duration_msec": 0.198,
"message": "search for tsids in the previous indexdb",
"children": [
{
"duration_msec": 0.06,
"message": "search for tsids in tag filters cache",
"children": [
{
"duration_msec": 0.044,
"message": "cache miss"
}
]
},
{
"duration_msec": 0.072,
"message": "put 0 tsids in cache",
"children": [
{
"duration_msec": 0.013,
"message": "marshaled 0 tsids into 9 bytes"
},
{
"duration_msec": 0.044,
"message": "store 0 tsids into cache"
}
]
}
]
},
{
"duration_msec": 0.011,
"message": "merge 0 tsids from the current indexdb with 0 tsids from the previous indexdb; result: 0 tsids"
},
{
"duration_msec": 0.017,
"message": "sort 0 tsids"
},
{
"duration_msec": 0.052,
"message": "put 0 tsids in cache",
"children": [
{
"duration_msec": 0.012,
"message": "marshaled 0 tsids into 9 bytes"
},
{
"duration_msec": 0.026,
"message": "store 0 tsids into cache"
}
]
}
]
},
{
"duration_msec": 0.024,
"message": "prefetch metric names for 0 tsids",
"children": [
{
"duration_msec": 0.01,
"message": "nothing to prefetch"
}
]
},
{
"duration_msec": 0.012,
"message": "search for parts with data for 0 series"
}
]
},
{
"duration_msec": 7.627,
"message": "fetch unique series=0, blocks=0, samples=0, bytes=0"
}
]
}
]
}
]
},
{
"duration_msec": 0.028,
"message": "sort series by metric name and labels"
},
{
"duration_msec": 0.221,
"message": "generate /api/v1/query_range response for series=0, points=0"
}
]
}
}
Trace output from a non-empty query
Values have been omitted manually from the output.
{
"status": "success",
"data": {
"resultType": "matrix",
"result": [
{
"metric": {
"__name__": "spark4/SystemInfo/uptime[second]"
},
"values": [
"OMITTED FOR BREVITY"
]
}
]
},
"trace": {
"duration_msec": 190.701,
"message": "/api/v1/query_range: start=1664809200000, end=1666278000000, step=60000, query=\"avg_over_time({__name__=\\\"spark4/SystemInfo/uptime[second]\\\"})\": series=1",
"children": [
{
"duration_msec": 176.198,
"message": "eval: query=avg_over_time(spark4\\/SystemInfo\\/uptime\\[second\\]), timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z], step=60000, mayCache=true: series=1, points=24481, pointsPerSeries=24481",
"children": [
{
"duration_msec": 176.117,
"message": "rollup avg_over_time(): timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z], step=60000, window=0: neededMemoryBytes=391696",
"children": [
{
"duration_msec": 0.058,
"message": "rollup cache get: query=avg_over_time(spark4\\/SystemInfo\\/uptime\\[second\\]), timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z], step=60000, window=0",
"children": [
{
"duration_msec": 0.041,
"message": "nothing found"
}
]
},
{
"duration_msec": 27.404,
"message": "fetch matching series: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-20T15:00:00Z]",
"children": [
{
"duration_msec": 22.812,
"message": "init series search: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-20T15:00:00Z]",
"children": [
{
"duration_msec": 20.767,
"message": "search for matching tsids: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-20T15:00:00Z]",
"children": [
{
"duration_msec": 20.474,
"message": "search for tsids in the current indexdb",
"children": [
{
"duration_msec": 0.048,
"message": "search for tsids in tag filters cache",
"children": [
{
"duration_msec": 0.033,
"message": "cache miss"
}
]
},
{
"duration_msec": 9.521,
"message": "search for metric ids: filters=[{__name__=\"spark4/SystemInfo/uptime[second]\"}], timeRange=[2022-10-03T14:54:00Z..2022-10-20T15:00:00Z], maxMetrics=300000",
"children": [
{
"duration_msec": 9.444,
"message": "update metric ids: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, timeRange=[2022-10-03T14:54:00Z..2022-10-20T15:00:00Z]: updated 1 metric ids",
"children": [
{
"duration_msec": 9.357,
"message": "parallel search for metric ids in per-day index: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, dayRange=[19268..19285]",
"children": [
{
"duration_msec": 2.824,
"message": "parallel thread for date=2022-10-03",
"children": [
{
"duration_msec": 2.593,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-03, maxMetrics=300001",
"children": [
{
"duration_msec": 2.493,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 2.397,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-03, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 2.349,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.012,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.011,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.01,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 9.219,
"message": "parallel thread for date=2022-10-04",
"children": [
{
"duration_msec": 6.526,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-04, maxMetrics=300001",
"children": [
{
"duration_msec": 6.439,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 6.313,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-04, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 6.241,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.012,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.128,
"message": "parallel thread for date=2022-10-05",
"children": [
{
"duration_msec": 0.266,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-05, maxMetrics=300001",
"children": [
{
"duration_msec": 0.188,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.105,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-05, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.07,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.011,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.716,
"message": "parallel thread for date=2022-10-06",
"children": [
{
"duration_msec": 0.25,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-06, maxMetrics=300001",
"children": [
{
"duration_msec": 0.174,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.095,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-06, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.062,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 5.027,
"message": "parallel thread for date=2022-10-07",
"children": [
{
"duration_msec": 0.248,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-07, maxMetrics=300001",
"children": [
{
"duration_msec": 0.171,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.093,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-07, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.061,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.315,
"message": "parallel thread for date=2022-10-08",
"children": [
{
"duration_msec": 0.28,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-08, maxMetrics=300001",
"children": [
{
"duration_msec": 0.204,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.122,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-08, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.079,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.377,
"message": "parallel thread for date=2022-10-09",
"children": [
{
"duration_msec": 0.253,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-09, maxMetrics=300001",
"children": [
{
"duration_msec": 0.177,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.097,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-09, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.065,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.7,
"message": "parallel thread for date=2022-10-10",
"children": [
{
"duration_msec": 0.25,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-10, maxMetrics=300001",
"children": [
{
"duration_msec": 0.173,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.095,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-10, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.063,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 5.116,
"message": "parallel thread for date=2022-10-11",
"children": [
{
"duration_msec": 0.248,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-11, maxMetrics=300001",
"children": [
{
"duration_msec": 0.173,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.095,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-11, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.063,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 3.564,
"message": "parallel thread for date=2022-10-12",
"children": [
{
"duration_msec": 2.335,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-12, maxMetrics=300001",
"children": [
{
"duration_msec": 2.249,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 2.159,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-12, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 2.089,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.012,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.193,
"message": "parallel thread for date=2022-10-13",
"children": [
{
"duration_msec": 2.064,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-13, maxMetrics=300001",
"children": [
{
"duration_msec": 1.976,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 1.887,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-13, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 1.841,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.011,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 3.4,
"message": "parallel thread for date=2022-10-14",
"children": [
{
"duration_msec": 0.255,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-14, maxMetrics=300001",
"children": [
{
"duration_msec": 0.176,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.096,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-14, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.063,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 3.748,
"message": "parallel thread for date=2022-10-15",
"children": [
{
"duration_msec": 0.271,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-15, maxMetrics=300001",
"children": [
{
"duration_msec": 0.194,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.097,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-15, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.061,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 2.98,
"message": "parallel thread for date=2022-10-16",
"children": [
{
"duration_msec": 0.267,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-16, maxMetrics=300001",
"children": [
{
"duration_msec": 0.187,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.106,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-16, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.072,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.01,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 4.447,
"message": "parallel thread for date=2022-10-17",
"children": [
{
"duration_msec": 0.262,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-17, maxMetrics=300001",
"children": [
{
"duration_msec": 0.183,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.101,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-17, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.069,
"message": "found 0 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 0 loops"
}
]
},
{
"duration_msec": 0.011,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 0 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 0 metric ids"
},
{
"duration_msec": 0.009,
"message": "found zero metric ids"
}
]
}
]
},
{
"duration_msec": 8.811,
"message": "parallel thread for date=2022-10-18",
"children": [
{
"duration_msec": 0.687,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-18, maxMetrics=300001",
"children": [
{
"duration_msec": 0.608,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.513,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-18, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.474,
"message": "found 1 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 1 loops"
}
]
},
{
"duration_msec": 0.024,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 1 series); use it"
}
]
},
{
"duration_msec": 0.011,
"message": "intersect the remaining 0 filters with the found 1 metric ids"
},
{
"duration_msec": 0.009,
"message": "found 1 metric ids"
}
]
}
]
},
{
"duration_msec": 8.736,
"message": "parallel thread for date=2022-10-19",
"children": [
{
"duration_msec": 0.366,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-19, maxMetrics=300001",
"children": [
{
"duration_msec": 0.208,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 0.106,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-19, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 0.074,
"message": "found 1 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 1 loops"
}
]
},
{
"duration_msec": 0.026,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 1 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 1 metric ids"
},
{
"duration_msec": 0.009,
"message": "found 1 metric ids"
}
]
}
]
},
{
"duration_msec": 2.481,
"message": "parallel thread for date=2022-10-20",
"children": [
{
"duration_msec": 2.338,
"message": "search for metric ids on a particular day: filters={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-20, maxMetrics=300001",
"children": [
{
"duration_msec": 2.253,
"message": "search for the first non-negative filter with the smallest cost",
"children": [
{
"duration_msec": 2.149,
"message": "get metric ids for filter and date: filter={__name__=\"spark4/SystemInfo/uptime[second]\"}, date=2022-10-20, maxMetrics=15000050, maxLoopsCount=9223372036854775807",
"children": [
{
"duration_msec": 1.506,
"message": "found 1 metric ids for filter={__name__=\"spark4/SystemInfo/uptime[second]\"} using exact search; spent 1 loops"
}
]
},
{
"duration_msec": 0.028,
"message": "the filter={__name__=\"spark4/SystemInfo/uptime[second]\"} matches less than 15000050 series (actually 1 series); use it"
}
]
},
{
"duration_msec": 0.01,
"message": "intersect the remaining 0 filters with the found 1 metric ids"
},
{
"duration_msec": 0.009,
"message": "found 1 metric ids"
}
]
}
]
}
]
}
]
}
]
},
{
"duration_msec": 0.014,
"message": "sort 1 matching metric ids"
},
{
"duration_msec": 4.193,
"message": "load 1 tsids from 1 metric ids"
}
]
},
{
"duration_msec": 0.153,
"message": "search for tsids in the previous indexdb",
"children": [
{
"duration_msec": 0.038,
"message": "search for tsids in tag filters cache",
"children": [
{
"duration_msec": 0.026,
"message": "cache miss"
}
]
},
{
"duration_msec": 0.049,
"message": "put 0 tsids in cache",
"children": [
{
"duration_msec": 0.011,
"message": "marshaled 0 tsids into 9 bytes"
},
{
"duration_msec": 0.025,
"message": "store 0 tsids into cache"
}
]
}
]
},
{
"duration_msec": 0.009,
"message": "merge 1 tsids from the current indexdb with 0 tsids from the previous indexdb; result: 1 tsids"
},
{
"duration_msec": 0.016,
"message": "sort 1 tsids"
},
{
"duration_msec": 0.049,
"message": "put 1 tsids in cache",
"children": [
{
"duration_msec": 0.012,
"message": "marshaled 1 tsids into 33 bytes"
},
{
"duration_msec": 0.025,
"message": "store 1 tsids into cache"
}
]
}
]
},
{
"duration_msec": 0.035,
"message": "prefetch metric names for 1 tsids",
"children": [
{
"duration_msec": 0.01,
"message": "1 out of 1 metric names must be pre-fetched"
},
{
"duration_msec": 0.013,
"message": "skip pre-fetching metric names for low number of metrid ids=1"
}
]
},
{
"duration_msec": 1.901,
"message": "search for parts with data for 1 series"
}
]
},
{
"duration_msec": 4.46,
"message": "fetch unique series=1, blocks=6, samples=41856, bytes=486"
}
]
},
{
"duration_msec": 103.502,
"message": "rollup avg_over_time() over 1 series; rollupConfigs=[timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z], step=60000, window=0, points=24481]",
"children": [
{
"duration_msec": 103.426,
"message": "parallel process of fetched data: series=1, samples=34279"
},
{
"duration_msec": 0.041,
"message": "samplesScanned=68558"
}
]
},
{
"duration_msec": 43.832,
"message": "rollup cache put: query=avg_over_time(spark4\\/SystemInfo\\/uptime\\[second\\]), timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z], step=60000, window=0, series=1",
"children": [
{
"duration_msec": 1.848,
"message": "marshal 1 series on a timeRange=[2022-10-03T15:00:00Z..2022-10-20T15:00:00Z] into 391736 bytes"
},
{
"duration_msec": 41.401,
"message": "compress 391736 bytes into 88659 bytes"
},
{
"duration_msec": 0.549,
"message": "store 88659 bytes in the cache"
}
]
}
]
}
]
},
{
"duration_msec": 1.158,
"message": "sort series by metric name and labels"
},
{
"duration_msec": 12.992,
"message": "generate /api/v1/query_range response for series=1, points=2953"
}
]
}
}
Version Reproduced with docker images:
- victoriametrics/victoria-metrics:v1.79.0
- victoriametrics/victoria-metrics:v1.82.1
Host platform is a Pi 3 running Raspberry Pi OS.
$ uname -a
Linux brewpipi 5.10.103-v7l+ #1529 SMP Tue Mar 8 12:24:00 GMT 2022 armv7l GNU/Linux
$ lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description: Raspbian GNU/Linux 10 (buster)
Release: 10
Codename: buster
Used command-line flags
--retentionPeriod=100y
--influxMeasurementFieldSeparator=/
--http.pathPrefix=/victoria
--search.latencyOffset=10s
No change in behavior was observed when using --search.setLookbackToStep=true.
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Comments: 31 (13 by maintainers)
Hi all! Sorry for delay, i will check this issue again on new version of VM, and will take the answer or the bug will be fixed
VM 1.86.1 the issue is still there with another rollup function:
Hi @elcojacobs ! No, I think that is enough information. We are continuing to investigate where can be the problem. Sorry for some delay
Update: I can confirm that the bug is still present in 1.83.1.