Dieterbe
commented
8 years ago no luck yet. in raintank-docker i'm trying to fill up a bunch of data ( up to 3 days back) and then suddenly launch a similar request workload as seen in prod:
+./fake_metrics_to_nsq -keys-per-org 100 -orgs 10 -statsd-addr statsdaemon:8125 -nsqd-tcp-address nsqd:4150 -offset 3d -speedup 400 -stop-at-now &> /var/log/raintank/fake.log
+./fake_metrics_to_nsq -keys-per-org 100 -orgs 10 -statsd-addr statsdaemon:8125 -nsqd-tcp-address nsqd:4150 &> /var/log/raintank/fake2.log &followed by:
$ cat repro-prod-issue.sh
#!/bin/sh
./inspect-es -es-index metric -format vegeta-mt -from 3d -es-addr elasticsearch:9200 > mc.txt
./inspect-es -es-index metric -format vegeta-mt -from 9min -es-addr elasticsearch:9200 > m.txt
ls -alh mc.txt m.txt
cat mc.txt | sed 's#18763#6063#' | ./vegeta attack -duration 100s -rate 500 > mc.out &
cat m.txt | sed 's#18763#6063#' | ./vegeta attack -duration 100s -rate 5000 > m.out &
echo "launched!"
sleep 110but MT handles this just fine and memory only goes up by a gig or so. maybe cause i'm working with a smaller amount of metrics here (1k vs 500k in prod). it would take too long to on-demand backload a similar volume on my laptop and since there's no caching going on (at least not in MT) requesting the same data multiple times should work just as well. notably in prod:
- all cpu cores went up to 50% strongly suggesting GC (https://snapshot.raintank.io/dashboard/snapshot/vsz4vUuRUdEoVuD80GP0cTM951CnnIsh)
- also seeing high request handle durations and cassandra response times, but this could be due to cpu maxing out. (https://snapshot.raintank.io/dashboard/snapshot/xL0hmAdISWcCMHeYtwRD5Wi5GhA3EgX7) cassandra dash shows read latency avg of no higher than 5ms (real bummer it only shows averages)
maybe i can do a qa run with similar-to-prod metric volume.
now i'm trying something else: i suspect that maybe the index for the new graphite endpoint introduces too many new pointers and keeps the GC busier so using basically a steady instream like so:
+./fake_metrics_to_nsq -keys-per-org 100 -orgs 100 -statsd-addr statsdaemon:8125 -nsqd-tcp-address nsqd:4150 -offset 3h -speedup 10 -stop-at-now &> /var/log/raintank/fake.log
+./fake_metrics_to_nsq -keys-per-org 100 -orgs 100 -statsd-addr statsdaemon:8125 -nsqd-tcp-address nsqd:4150 &> /var/log/raintank/fake2.log &and just running metric-tank with +GODEBUG=gctrace=1 ./metric_tank
with a patched GC like so:
diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go
index 94301c6..b0d3528 100644
--- a/src/runtime/mgc.go
+++ b/src/runtime/mgc.go
@@ -1297,6 +1297,7 @@ func gcMarkTermination() {
if work.mode != gcBackgroundMode {
print(" (forced)")
}
+ print(" sw ", gcController.scanWork, " bgscancred ", gcController.bgScanCredit)
print("\n")
printunlock()
}latest master: sys dash: https://snapshot.raintank.io/dashboard/snapshot/D1A8qzn673G2v01syp32bxlZ516cH8qb MT dash: https://snapshot.raintank.io/dashboard/snapshot/j5hPeum00o8Itpa8234TYC8cV2bfKgkz
dd69883 (pre graphite endpoint): MT dash: https://snapshot.raintank.io/dashboard/snapshot/o8J1vnIUnjSNV11wmo2hw2uc10XHh7zA sys dash:https://snapshot.raintank.io/dashboard/snapshot/ta3trxmlqTPL1I0l1vaY4Z7LE82dOQP3
unfortunately all cpu/mem looks identical. i also compared the GC data using gcvis (patched for the 2 new params) and everything looks identical, also the timings :(
it's the first time seeing this in prod, when deploying f040a9e5741ca16c84ebc763314f7b4391c98900 with
agg-settings = 10min:6h:2:38d:true,2h:6h:2:120d:true, not sure it's because of these changes or because the load pattern has changed (increased) due to recent extra signups:i've seen this twice:
MT dash: https://grafana-monitor.raintank.io/dashboard/snapshot/IWAPH7sho06f0n0TgBmdWsuQykwZfVmM
sys dash: https://grafana-monitor.raintank.io/dashboard/snapshot/Fv7Rb3G0yR5enyZF7oS2kF2iyMMaBPIW
will try to repro in QA hypothesis:maybe extensive GC workload maxing out cpu and blocking progress, but mem usage shouldn't be that high i think. gctrace will help.