Skip to content

Instantly share code, notes, and snippets.

@ulidtko

ulidtko/20ms-GCidle-annotated-1kRPS.png

Last active July 2, 2020 16:02
Show Gist options
  • Save ulidtko/b5821533af6f760cde58bd1d0dcefce8 to your computer and use it in GitHub Desktop.
Save ulidtko/b5821533af6f760cde58bd1d0dcefce8 to your computer and use it in GitHub Desktop.
Download ZIP
GHC waiting on DB during GC
Raw
README.md

Setup

Database / postgres

If you have docker, it's easiest to run a Postgres container:

docker run -d \
    --name postgres \
    --net=host \
    -e POSTGRES_PASSWORD=true \
    --expose 5432 \
    postgres:11

Put the DB URI, password etc into local-pg.conf here; I configured a separate user per the PostgREST guide.

To query the container IP address:

docker inspect -f '{{.NetworkSettings.IPAddress}}' postgres

PostgREST

Install from source with profiling to have threadscope graphs.

git clone https://github.com/PostgREST/postgrest
cd postgrest
stack build --profile --ghc-options='-threaded -eventlog'

HTTP load / vegeta

go get github.com/tsenart/vegeta or brew install vegeta or grab a binary from GitHub

bpftrace

https://github.com/iovisor/bpftrace

Run

sudo -v; RPS=1000 DURATION=20s ./run.sh

Raw
gc-sampler.bpft.template
#!/usr/bin/env bpftrace
BEGIN {
// global switch of all-threads regular-interval sampling
@sampling = 0;
// loosely tracks which thread is in GC the longest
@worstpause = (0, 0);
// longest GC, for final report
@worstpause_overall = @worstpause;
@zz_n_samples_total = 0;
}
profile:hz:197 /pid == @TARGET_PID@ && @sampling > 0/ {
//@stacks[ustack,tid] = count();
@stacks[ustack] = count();
@zz_n_samples_total++;
}
uprobe:/home/ulidtko/.local/bin/postgrest:scheduleDoGC {
@entry[tid] = nsecs;
}
uretprobe:/home/ulidtko/.local/bin/postgrest:scheduleDoGC {
@entry[tid] = (uint64)-1;
if (tid == @worstpause.1) {
if (@worstpause_overall.0 < @worstpause.0) {
@worstpause_overall = @worstpause;
}
@worstpause = (0, 0);
}
}
profile:ms:1 {
if (@entry[tid] != (uint64)-1 && @entry[tid] != 0) {
$pause = nsecs - @entry[tid];
if (@worstpause.0 < $pause) {
@worstpause = ($pause, tid);
}
//@worstpause = max($pause); // -- different type, int-incompatible
}
}
// probe "interval" runs on single CPU
interval:ms:1 {
// start sampling whenever any thread stays >= 1ms in scheduleDoGC
// and stop otherwise
@sampling = (@worstpause.0 >= 1000000) ? 1 : 0;
}
END {
// purge gc entry timestamp map before exit -- it'll contain MAX_UINT's only
clear(@entry);
// ditto, these always are 0 at the end.
clear(@sampling);
// @worstpause_overall will have useful info saved & shown
clear(@worstpause);
}
// vim: ts=2 sw=2 et
Raw
gc-sampling-report-500RPS-nounsafe.txt
Here's a sample report from a 20s profiling run @ 500 RPS HTTP load,
with postgresql-libpq patched to remove most "unsafe" FFI imports.
Highlights (most interesting part of report is the end):
* the worst http req latency here was 134.554ms
* the worst gc pause was 62.178ms (might not be measured 100% correctly)
* in total, 141 samples captured by bpftrace @ 197 Hz whenever
any one thread stayed in scheduleDoGC for >= 1ms
* most of the sampled stacks point to gcWorkerThread+381
which is RELEASE_SPIN_LOCK(&gct->gc_spin)
https://gitlab.haskell.org/ghc/ghc/-/blob/ghc-8.8.3-release/rts/sm/GC.c#L1174
=================================================================
@stacks[
gcWorkerThread+113
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
GarbageCollect+2013
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
GarbageCollect+2002
]: 1
@stacks[
GarbageCollect+2017
]: 1
@stacks[
GarbageCollect+2013
]: 1
@stacks[
gcWorkerThread+365
]: 1
@stacks[
__GI___sched_yield+11
0x4200701fc0
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
GarbageCollect+2017
]: 1
@stacks[
gcWorkerThread+381
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
pthread_cond_signal@@GLIBC_2.3.2+169
]: 1
@stacks[
__GI___sched_yield+11
0x42000002c0
]: 1
@stacks[
stg_PAP_apply+0
0x4200813dc0
0x4200813c19
0x48088b48000000ae
]: 1
@stacks[
__GI___sched_yield+11
0x4200501ac0
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
__GI___sched_yield+11
0x4200800880
]: 1
@stacks[
gcWorkerThread+367
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
GarbageCollect+2017
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
__GI___poll+79
]: 1
@stacks[
__send+108
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
gcWorkerThread+93
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
__GI___sched_yield+11
0x42000002c0
]: 1
@stacks[
GarbageCollect+2002
]: 1
@stacks[
__send+108
]: 1
@stacks[
__send+108
]: 1
@stacks[
gcWorkerThread+365
]: 1
@stacks[
__send+108
]: 1
@stacks[
base_GHCziEventziEPoll_new9_info+64
0x2d70671
0xf5b8b4807438b48
]: 1
@stacks[
__GI___sched_yield+11
0x42007021c0
]: 1
@stacks[
GarbageCollect+2009
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
gcWorkerThread+372
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
gcWorkerThread+107
]: 1
@stacks[
GarbageCollect+2017
]: 1
@stacks[
__GI___sched_yield+11
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
gcWorkerThread+372
]: 1
@stacks[
GarbageCollect+2009
]: 1
@stacks[
warpzm3zi3zi10zmFdfU8tfQOFAGi8WId2fDPj_NetworkziWaiziHandlerziWarpziHeader_zdwrequestKeyIndex_info+44
warpzm3zi3zi10zmFdfU8tfQOFAGi8WId2fDPj_NetworkziWaiziHandlerziWarpziHeader_zdwtraverseHeader_info+344
0x44c7491977000003
]: 1
@stacks[
__GI___sched_yield+11
0x42007009c0
]: 1
@stacks[
__GI___sched_yield+11
0x4200902600
]: 1
@stacks[
gcWorkerThread+367
]: 1
@stacks[
gcWorkerThread+372
]: 1
@stacks[
GarbageCollect+2002
]: 1
@stacks[
__GI___sched_yield+11
0x4200700d00
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
gcWorkerThread+107
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
__GI___sched_yield+11
0x4200702700
]: 1
@stacks[
gcWorkerThread+365
]: 1
@stacks[
__GI___sched_yield+11
0x42001024c0
]: 1
@stacks[
__GI___sched_yield+11
0x4200202c80
]: 1
@stacks[
GarbageCollect+2013
]: 1
@stacks[
gcWorkerThread+381
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
gcWorkerThread+372
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
GarbageCollect+2002
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
gcWorkerThread+113
]: 1
@stacks[
_int_malloc+2093
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
GarbageCollect+2002
]: 1
@stacks[
gcWorkerThread+372
]: 1
@stacks[
__GI___sched_yield+11
0x4200200140
]: 1
@stacks[
__GI___sched_yield+11
]: 1
@stacks[
GarbageCollect+2009
]: 1
@stacks[
__GI___sched_yield+11
0x4200100440
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
gcWorkerThread+381
]: 1
@stacks[
gcWorkerThread+104
]: 1
@stacks[
__GI___sched_yield+11
0x4200301980
]: 1
@stacks[
GarbageCollect+2009
]: 1
@stacks[
__GI___sched_yield+11
0x4200403580
]: 1
@stacks[
__GI___sched_yield+11
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
gcWorkerThread+381
__stg_gc_enter_1+0
0x4
]: 1
@stacks[
GarbageCollect+2017
]: 1
@stacks[
__GI___sched_yield+11
]: 2
@stacks[
gcWorkerThread+367
]: 2
@stacks[
__GI___sched_yield+11
]: 2
@stacks[
__libc_recv+108
]: 2
@stacks[
gcWorkerThread+372
]: 2
@stacks[
gcWorkerThread+95
]: 2
@stacks[
gcWorkerThread+381
]: 2
@stacks[
GarbageCollect+2009
]: 2
@stacks[
__GI___sched_yield+11
0x42001024c0
]: 2
@stacks[
__GI___sched_yield+11
]: 2
@stacks[
__GI___sched_yield+11
]: 2
@stacks[
gcWorkerThread+381
]: 2
@stacks[
__GI___sched_yield+11
]: 2
@stacks[
GarbageCollect+2013
]: 2
@stacks[
GarbageCollect+2002
]: 2
@stacks[
__GI___sched_yield+11
]: 3
@stacks[
gcWorkerThread+381
]: 3
@stacks[
gcWorkerThread+381
]: 4
@stacks[
gcWorkerThread+381
]: 4
@stacks[
gcWorkerThread+381
]: 4
@stacks[
__GI___sched_yield+11
]: 4
@stacks[
gcWorkerThread+381
]: 4
@stacks[
__GI___sched_yield+11
]: 5
@stacks[
__GI___sched_yield+11
]: 5
@stacks[
gcWorkerThread+381
]: 6
@worst_pause_report: (62178, 208212)
@zz_n_samples_total: 141
3,926,034,168 bytes allocated in the heap
20,812,744 bytes copied during GC
2,332,296 bytes maximum residency (3 sample(s))
92,720 bytes maximum slop
2 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 994 colls, 994 par 0.882s 0.460s 0.0005s 0.0261s
Gen 1 3 colls, 2 par 0.067s 0.064s 0.0213s 0.0619s
Parallel GC work balance: 30.02% (serial 0%, perfect 100%)
TASKS: 27 (1 bound, 26 peak workers (26 total), using -N4)
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
INIT time 0.003s ( 0.007s elapsed)
MUT time 6.368s ( 22.588s elapsed)
GC time 0.949s ( 0.524s elapsed)
EXIT time 0.000s ( 0.003s elapsed)
Total time 7.320s ( 23.122s elapsed)
Alloc rate 616,521,593 bytes per MUT second
Productivity 87.0% of total user, 97.7% of total elapsed
Bucket # % Histogram
[3.3ms, 10ms] 412 4.12% ###
[10ms, 33ms] 162 1.62% #
[33ms, 100ms] 71 0.71%
[100ms, 333ms] 15 0.15%
[333ms, 1s] 0 0.00%
[1s, 3s] 0 0.00%
[3s, 10s] 0 0.00%
[10s, 33s] 0 0.00%
Requests [total, rate, throughput] 10000, 500.05, 500.01
Duration [total, attack, wait] 20s, 19.998s, 1.685ms
Latencies [min, mean, 50, 90, 95, 99, max] 937.528µs, 2.894ms, 1.983ms, 2.694ms, 4.389ms, 30.251ms, 134.554ms
Bytes In [total, mean] 1380000, 138.00
Bytes Out [total, mean] 0, 0.00
Success [ratio] 100.00%
Status Codes [code:count] 200:10000
Error Set:
Raw
local-pg.conf
db-uri = "postgres://authenticator:[email protected]:5432/postgres"
db-schema = "loadtest"
db-anon-role = "web_anon"
db-pool = 10
db-pool-timeout = 10
server-host = "*6"
server-port = 3001
Raw
run.sh
#!/bin/bash
cd "$(dirname "$0")" || exit
# ulimit -n 65536
PGRESTCONF=./local-pg.conf
TARGETS=./vegeta-targets
REQLOG=./vegeta.reqlog
PLOTHTML=./vegeta.plot.html
BPFSCRIPT=./gc-sampler.bpft
RPS=${RPS:-1000}
DURATION=${DURATION:-20s}
DURATION_NSEC=$((${DURATION%s} * 1000000 * 1000000 * 9 / 10))
#-- CHECK BPFSCRIPT --#
#sudo bpftrace -d $BPFSCRIPT || exit $?
#-- LAUNCH TARGET --#
postgrest "$PWD/$PGRESTCONF" +RTS -l -s --long-gc-sync=0.01 >/dev/null & TGT=$!
set -o pipefail; while ! curl -s http://localhost:3001/foobar | grep -wq whiskey; do sleep 0.01; done # readiness poll
#-- SETUP PROFILER --#
sed -e "s/@TARGET_PID@/$TGT/" \
-e "s/@DURATION_NSEC@/$DURATION_NSEC/" \
$BPFSCRIPT.template > $BPFSCRIPT
sudo $BPFSCRIPT & sleep 0.065
#-- PUT LOAD --#
vegeta attack -duration $DURATION -rate $RPS -timeout 10s < $TARGETS > $REQLOG
#-- TERMINATE --#
#-- caveat 1: bash's $! will record sudo's PID; use killall
sudo killall -INT bpftrace;
#-- caveat 2: bpf stack printout turns to ash as target dies
while pgrep bpftrace >/dev/null; do sleep 0.1; done; sleep 2
kill -INT $TGT; sleep 0.1
#-- RENDER RESULTS --#
# the histogram is wrong in the highest bucket https://github.com/tsenart/vegeta/issues/522
vegeta report -type hist -buckets '[3.3ms,10ms,33ms,100ms,333ms,1s,3s,10s,33s]' < $REQLOG
vegeta report -type text < $REQLOG
vegeta plot < $REQLOG > $PLOTHTML && xdg-open $PLOTHTML
threadscope postgrest.eventlog &
Raw
vegeta-targets
GET http://localhost:3001/foobar
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment