GHC waiting on DB during GC

20ms-GCidle-annotated-1kRPS.png

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

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

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:

local-pg.conf

db-uri = "postgres://authenticator:speedofsound@172.17.0.2:5432/postgres"
db-schema = "loadtest"
db-anon-role = "web_anon"
db-pool = 10
db-pool-timeout = 10

server-host = "*6"
server-port = 3001

perf-probe-LongGCSync.png

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 &

threadscope-300RPS.png

threadscope-700RPS-compacting.png

threadscope-700RPS.png

vegeta-plot-300RPS.png

vegeta-plot-700RPS-compacting.png

vegeta-plot-700RPS.png

vegeta-targets

GET http://localhost:3001/foobar