refactor findCache to use fewer resources

[robert-milan]

fix #1262

[woodsaj]

I like this approach, but findCacheBackoff cant be a global, it needs to be part of the FindCache struct.

[woodsaj]

actually, findCacheBackoff metric doesnt work at all with the partitioned Index, as there are multiple findCaches that could all have different states.

[Dieterbe]

why, to make it clear that no other code in the package should mess with it? if that, we could solve it with a better comment

[woodsaj]

I would just add a "backoff" field to the FindCache struct. Then in triggerBackoff() i would

time.AfterFunc(c.backoffTime, func() {
   findCacheBackoff.SetFalse
   c.Lock()
   c.backoff = false
   c.Unlock()
})

[woodsaj]

why, to make it clear that no other code in the package should mess with it

It is just a bad idea to mix structs and fields together. you can have multiple instances of a findCache at any one time, so controlling how the instance behaves through a global variable is just a recipe for disaster.

[Dieterbe]

actually, findCacheBackoff metric doesnt work at all with the partitioned Index, as there are multiple findCaches that could all have different states.

hmm I didn't consider this. good catch. will follow your suggestion

[Dieterbe]

actually to accommodate PartitionedIndex, we can't use a backoff bool either. maybe it should be a gauge that is incremented and decremented.

[woodsaj]

LGTM

[Dieterbe]

I did an experiment with docker stack to confirm the improvements. (also with #1265 applied)
I ran some scripts that generate an ingest workload, then start background http request load, making sure to populate the findcache with patterns that will need to be revisited (and invalidated) because then we increase the volume of the ingestion rate, adding more metrics with names that match what we already cached. Of particular interest is what happens right when the new metrics come in and the cache needs to invalidate. Collected snapshots and cpu profiles at these times

Did it like so:

git diff # to make sure we're not affected by chunk saving intervals etc, as long as we don't pass 6h intervals at any point during the tests
diff --git a/docker/docker-dev-custom-cfg-kafka/storage-schemas.conf b/docker/docker-dev-custom-cfg-kafka/storage-schemas.conf
index 2d3083b5..54f0f4b2 100644
--- a/docker/docker-dev-custom-cfg-kafka/storage-schemas.conf
+++ b/docker/docker-dev-custom-cfg-kafka/storage-schemas.conf
@@ -50,11 +50,7 @@
 # This example has 3 retention definitions, the first and last override some default options (to use 10minutely and 2hourly chunks and only keep one of them in memory
 # and the last rollup is marked as not ready yet for querying.
 
-[raw]
-pattern = fakemetrics.raw
-retentions = 1s:6h:2min:2
-
 [default]
 pattern = .*
-retentions = 1s:6h:2min:2,1min:35d:6h:1
+retentions = 1s:6h:6h:2
 # reorderBuffer = 20

run make and then start these scripts at the same time:

~/g/s/g/g/metrictank ❯❯❯ cat test-index-add-cpu-launch.sh
#!/bin/bash

source util.sh
source scripts/version-tag.sh

wait_time 120
docker-compose -f docker/docker-dev-custom-cfg-kafka/docker-compose.yml up --force-recreate -V
~/g/s/g/g/metrictank ❯❯❯ cat test-index-add-cpu-tests.sh
#!/bin/bash

source util.sh
source scripts/version-tag.sh

# does queries such that the find-cache will be full with patterns that will later become invalidated and pruned once we introduce more metrics
renderWorkload () {
     num=1000
     for i in $(seq 1 $num); do
     	echo "GET http://localhost:6060/render?target=some.id.of.a.metric.*$i&from=-5min"
     	echo "X-Org-Id: 1"
     	echo
     done | vegeta attack -duration 180s | vegeta report
}

echo "killing any fakemetrics currently running"
pkill -f fakemetrics

wait_time 120
sleep 120
log "feed 10kHz"
fakemetrics feed --kafka-mdm-addr localhost:9092 --period 1s --mpo 10000 &
pid=$!

sleep 60

# needs at least 20s to populate index cache
renderWorkload &

sleep 60

kill $pid
pgrep -a fakemetrics
log "feed 10kHz -> 15kHz"
fakemetrics feed --kafka-mdm-addr localhost:9092 --period 1s --mpo 15000 &
log "getting profile"
curl 'http://localhost:6060/debug/pprof/profile?seconds=5' --output cpu-$version.prof

~/g/s/g/g/metrictank ❯❯❯ cat util.sh
#!/bin/bash

log () {
  echo "$(date +'%F %H:%M:%S') $1"
}

# converts a number of ns to a specificaton for `sleep`
ns_to_sleep() {
	local ns=$1
	printf "%010d\n" $ns | sed 's/\(.\{9\}\)$/.\1/'
}

# sleep until the next round timestamp (snap), but offsetted
# eg wait_time 60 7 will sleep until 7 seconds after the next whole minute
# obviously this is isn't accurate to the ns, due to overhead of executing commands, etc
# on Dieter's laptop, there is typically 5.7 to 5.8 millis of overhead, hence the compensation
wait_time() {
	local snap=$(($1 * 1000000000))
	local offset=$((${2:-0} * 1000000000))
	now=$(date +%s%N)
	sleep_ns=$(($snap - (($now + 5700000 - $offset) % $snap)))
	sleep $(ns_to_sleep $sleep_ns)
}

v0.11.0-185-ga7c8203d

https://snapshot.raintank.io/dashboard/snapshot/esH0WpwdEXf3RUd2konLB21B4NOgRVVe?orgId=2

killing any fakemetrics currently running
2019-04-03 10:54:00 feed 10kHz
2019/04/03 10:54:00 [I] starting listener on :6764
params: orgs=1, mpo=10000, period=1, flush=1000, offset=0, speedup=1, stopAtNow=false
per org:         each 1s, flushing 10000 metrics so rate of 10000 Hz. (10000 total unique series)
times    1 orgs: each 1s, flushing 10000 metrics so rate of 10000 Hz. (10000 total unique series)
2019-04-03 10:54:01.016186533 +0200 CEST m=+1.011586194 10000 metrics could not be sent as v2 MetricPoint
2019-04-03 10:56:00 feed 10kHz -> 15kHz
2019-04-03 10:56:00 getting profile
2019/04/03 10:56:00 [I] starting listener on :6764
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0params: orgs=1, mpo=15000, period=1, flush=1000, offset=0, speedup=1, stopAtNow=false
per org:         each 1s, flushing 15000 metrics so rate of 15000 Hz. (15000 total unique series)
times    1 orgs: each 1s, flushing 15000 metrics so rate of 15000 Hz. (15000 total unique series)
2019-04-03 10:56:01.029251223 +0200 CEST m=+1.010394697 15000 metrics could not be sent as v2 MetricPoint
100 22377    0 22377    0     0   4371      0 --:--:--  0:00:05 --:--:--  5708
~/g/s/g/g/metrictank ❯❯❯ Requests      [total, rate]            9000, 50.01
Duration      [total, attack, wait]    2m59.982985565s, 2m59.980043196s, 2.942369ms
Latencies     [mean, 50, 95, 99, max]  9.225303ms, 11.215829ms, 17.353998ms, 20.158164ms, 279.760029ms
Bytes In      [total, mean]            18000, 2.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:9000  
Error Set:

~/g/s/g/g/metrictank ❯❯❯ go tool pprof cpu-v0.11.0-185-ga7c8203.prof
File: metrictank
Type: cpu
Time: Apr 3, 2019 at 10:56am (CEST)
Duration: 5.12s, Total samples = 4.36s (85.24%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 3.22s, 73.85% of 4.36s total
Dropped 219 nodes (cum <= 0.02s)
Showing top 20 nodes out of 172
      flat  flat%   sum%        cum   cum%
     1.15s 26.38% 26.38%      2.12s 48.62%  regexp.(*Regexp).tryBacktrack
     0.53s 12.16% 38.53%      0.53s 12.16%  regexp.(*bitState).shouldVisit
     0.33s  7.57% 46.10%      0.33s  7.57%  regexp.(*inputString).step
     0.19s  4.36% 50.46%      0.19s  4.36%  syscall.Syscall
     0.14s  3.21% 53.67%      0.26s  5.96%  runtime.scanobject
     0.13s  2.98% 56.65%      0.13s  2.98%  runtime.memclrNoHeapPointers
     0.12s  2.75% 59.40%      0.54s 12.39%  runtime.mallocgc
     0.10s  2.29% 61.70%      0.13s  2.98%  runtime.heapBitsSetType
     0.08s  1.83% 63.53%      0.11s  2.52%  regexp.(*bitState).push
     0.06s  1.38% 64.91%      0.09s  2.06%  runtime.findObject
     0.06s  1.38% 66.28%      0.14s  3.21%  sync.(*Pool).Put
     0.05s  1.15% 67.43%      2.43s 55.73%  regexp.(*Regexp).backtrack
     0.05s  1.15% 68.58%      0.05s  1.15%  runtime.procPin
     0.04s  0.92% 69.50%      0.04s  0.92%  runtime.nextFreeFast
     0.04s  0.92% 70.41%      0.04s  0.92%  strings.IndexAny
     0.03s  0.69% 71.10%      0.04s  0.92%  github.com/grafana/metrictank/vendor/github.com/klauspost/compress/flate.(*compressor).deflateSSE
     0.03s  0.69% 71.79%      2.46s 56.42%  regexp.(*Regexp).doExecute
     0.03s  0.69% 72.48%      0.03s  0.69%  regexp.(*inputString).context
     0.03s  0.69% 73.17%      0.03s  0.69%  runtime.acquirem
     0.03s  0.69% 73.85%      0.12s  2.75%  runtime.findrunnable
(pprof) 

v0.11.0-219-g88830e3

https://snapshot.raintank.io/dashboard/snapshot/aeX0vbOIQswQN6tycV2Xl7S9oKx9l8m8?orgId=2

~/g/s/g/g/metrictank ❯❯❯ ./test-index-add-cpu-tests.sh
make sure no fakemetrics currently running
30685 fakemetrics feed --kafka-mdm-addr localhost:9092 --period 1s --mpo 15000
2019-04-03 10:20:00 feed 10kHz
2019/04/03 10:20:00 [I] starting listener on :6764
params: orgs=1, mpo=10000, period=1, flush=1000, offset=0, speedup=1, stopAtNow=false
per org:         each 1s, flushing 10000 metrics so rate of 10000 Hz. (10000 total unique series)
times    1 orgs: each 1s, flushing 10000 metrics so rate of 10000 Hz. (10000 total unique series)
2019-04-03 10:20:01.014758663 +0200 CEST m=+1.011742224 10000 metrics could not be sent as v2 MetricPoint
2019-04-03 10:22:00 feed 10kHz -> 15kHz
2019-04-03 10:22:00 getting profile
2019/04/03 10:22:00 [I] starting listener on :6764
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0params: orgs=1, mpo=15000, period=1, flush=1000, offset=0, speedup=1, stopAtNow=false
per org:         each 1s, flushing 15000 metrics so rate of 15000 Hz. (15000 total unique series)
times    1 orgs: each 1s, flushing 15000 metrics so rate of 15000 Hz. (15000 total unique series)
2019-04-03 10:22:01.033584424 +0200 CEST m=+1.013603378 15000 metrics could not be sent as v2 MetricPoint
100 16490    0 16490    0     0   3210      0 --:--:--  0:00:05 --:--:--  4192
~/g/s/g/g/metrictank ❯❯❯ Requests      [total, rate]            9000, 50.01
Duration      [total, attack, wait]    2m59.982225827s, 2m59.979974721s, 2.251106ms
Latencies     [mean, 50, 95, 99, max]  9.018946ms, 11.244317ms, 17.437262ms, 20.039491ms, 41.928506ms
Bytes In      [total, mean]            18000, 2.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:9000  
Error Set:

~/g/s/g/g/metrictank ❯❯❯ go tool pprof cpu-v0.11.0-219-g88830e3.prof
File: metrictank
Type: cpu
Time: Apr 3, 2019 at 10:22am (CEST)
Duration: 5.13s, Total samples = 3.58s (69.75%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 2.94s, 82.12% of 3.58s total
Dropped 134 nodes (cum <= 0.02s)
Showing top 20 nodes out of 181
      flat  flat%   sum%        cum   cum%
     1.10s 30.73% 30.73%      2.34s 65.36%  regexp.(*Regexp).tryBacktrack
     0.70s 19.55% 50.28%      0.70s 19.55%  regexp.(*bitState).shouldVisit
     0.39s 10.89% 61.17%      0.39s 10.89%  regexp.(*inputString).step
     0.14s  3.91% 65.08%      0.15s  4.19%  syscall.Syscall
     0.11s  3.07% 68.16%      0.11s  3.07%  regexp.(*bitState).push
     0.06s  1.68% 69.83%      0.06s  1.68%  runtime.futex
     0.05s  1.40% 71.23%      0.05s  1.40%  runtime.memclrNoHeapPointers
     0.04s  1.12% 72.35%      0.08s  2.23%  github.com/grafana/metrictank/mdata.(*AggMetric).add
     0.04s  1.12% 73.46%      0.04s  1.12%  regexp.(*inputString).context
     0.04s  1.12% 74.58%      0.06s  1.68%  runtime.scanobject
     0.04s  1.12% 75.70%      0.04s  1.12%  runtime.usleep
     0.03s  0.84% 76.54%      0.04s  1.12%  regexp.(*bitState).reset
     0.03s  0.84% 77.37%      0.03s  0.84%  runtime.epollwait
     0.03s  0.84% 78.21%      0.03s  0.84%  runtime.mapaccess2
     0.03s  0.84% 79.05%      0.05s  1.40%  sync.(*Pool).Get
     0.03s  0.84% 79.89%      0.04s  1.12%  sync.(*Pool).pin
     0.02s  0.56% 80.45%      0.02s  0.56%  github.com/grafana/metrictank/vendor/github.com/klauspost/compress/flate.(*compressor).deflateSSE
     0.02s  0.56% 81.01%      2.51s 70.11%  regexp.(*Regexp).doExecute
     0.02s  0.56% 81.56%      0.02s  0.56%  runtime.(*itabTableType).find
     0.02s  0.56% 82.12%      0.02s  0.56%  runtime.findObject

go tool pprof -diff_base cpu-v0.11.0-185-ga7c8203.prof cpu-v0.11.0-219-g88830e3.prof # show the savings in alloc and GC overhead
File: metrictank
Type: cpu
Time: Apr 3, 2019 at 10:22am (CEST)
Duration: 10.25s, Total samples = 4.36s (42.54%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top30
Showing nodes accounting for -0.53s, 12.16% of 4.36s total
Dropped 12 nodes (cum <= 0.02s)
Showing top 30 nodes out of 457
      flat  flat%   sum%        cum   cum%
     0.17s  3.90%  3.90%      0.17s  3.90%  regexp.(*bitState).shouldVisit
    -0.10s  2.29%  1.61%     -0.44s 10.09%  runtime.mallocgc
    -0.10s  2.29%  0.69%     -0.20s  4.59%  runtime.scanobject
    -0.09s  2.06%  2.75%     -0.12s  2.75%  runtime.heapBitsSetType
    -0.08s  1.83%  4.59%     -0.08s  1.83%  runtime.memclrNoHeapPointers
     0.06s  1.38%  3.21%      0.06s  1.38%  regexp.(*inputString).step
    -0.05s  1.15%  4.36%      0.22s  5.05%  regexp.(*Regexp).tryBacktrack
    -0.05s  1.15%  5.50%     -0.11s  2.52%  sync.(*Pool).Put
    -0.05s  1.15%  6.65%     -0.04s  0.92%  syscall.Syscall
    -0.04s  0.92%  7.57%      0.06s  1.38%  regexp.(*Regexp).backtrack
    -0.04s  0.92%  8.49%     -0.07s  1.61%  runtime.findObject
     0.04s  0.92%  7.57%      0.04s  0.92%  runtime.futex
    -0.04s  0.92%  8.49%     -0.04s  0.92%  runtime.procPin
     0.04s  0.92%  7.57%      0.04s  0.92%  runtime.usleep
    -0.04s  0.92%  8.49%     -0.04s  0.92%  strings.IndexAny
     0.03s  0.69%  7.80%      0.06s  1.38%  github.com/grafana/metrictank/mdata.(*AggMetric).add
    -0.03s  0.69%  8.49%     -0.03s  0.69%  runtime.acquirem
    -0.03s  0.69%  9.17%     -0.03s  0.69%  runtime.findrunnable
    -0.03s  0.69%  9.86%     -0.04s  0.92%  runtime.heapBits.next
    -0.03s  0.69% 10.55%     -0.03s  0.69%  runtime.spanOf
     0.03s  0.69%  9.86%      0.03s  0.69%  sync.(*Pool).Get
    -0.02s  0.46% 10.32%     -0.13s  2.98%  regexp.freeBitState
     0.02s  0.46%  9.86%      0.02s  0.46%  runtime.(*itabTableType).find
    -0.02s  0.46% 10.32%     -0.02s  0.46%  runtime.mapaccess2_faststr
    -0.02s  0.46% 10.78%     -0.02s  0.46%  runtime.newdefer
    -0.02s  0.46% 11.24%     -0.02s  0.46%  runtime.nextFreeFast
    -0.02s  0.46% 11.70%     -0.02s  0.46%  runtime.pageIndexOf
    -0.02s  0.46% 12.16%      0.01s  0.23%  runtime.runqgrab
    -0.02s  0.46% 12.61%     -0.02s  0.46%  runtime.scanblock
     0.02s  0.46% 12.16%      0.02s  0.46%  runtime.siftupTimer

conclusion:

• old code had larger cpu spike when the new series come in and did significantly more allocations and GC
• in prod we saw something extreme where we spent several cpu cores on invalidation, slowing everything to a halt, and backoff not kicking in. I think the workload here was probably not high enough to reproduce that, but at least we demonstrated that the new backoff system works
• new code has slightly lower request latency in general, and lower memory idx operation timings