ferrix/scripts/profile/full-table.sh

#!/bin/bash
# Profiles the daemon as it takes in a full Internet routing table, on a
# Linux machine: a flame graph and a flat profile of where the CPU time
# goes, and how long the table takes to arrive and to reach the kernel.
#
#   scripts/profile/full-table.sh                 one peer sends the table
#   PEERS=4 scripts/profile/full-table.sh         four peers send it at once
#   KERNEL=0 scripts/profile/full-table.sh        the routes stay in the table
#   SCALE_DOWN=10 scripts/profile/full-table.sh   a tenth of the table
#   COLLECTOR=1 scripts/profile/full-table.sh     a route collector is sent every path
#   HEAP=1 scripts/profile/full-table.sh          where the memory goes, not the time
#
# From a machine that is not Linux: scripts/linux-vm.sh scripts/profile/full-table.sh
#
# The daemon runs in a network namespace of its own, so that nothing it
# installs touches the machine's own routing, joined by a veth pair to a
# second namespace where the load generator (crates/bench/examples/feed.rs)
# plays the peers: neighbours on the link, as real peers would be. `perf`
# samples the daemon's threads meanwhile. Needs perf, inferno (cargo
# install inferno), curl and jq, and sudo for the namespaces and the
# kernel's routing table.
#
# Results go to $OUT (default ~/profile): flame.svg, top-self.txt (functions
# by their own time), top-children.txt (by the time of everything they
# call), perf.data, and the daemon's and the load generator's logs.
set -eu

peers=${PEERS:-1}
scale=${SCALE_DOWN:-1}
kernel=${KERNEL:-1}
collector=${COLLECTOR:-0}
heap=${HEAP:-0}
hold=${HOLD_SECS:-30}
level=${LOG_LEVEL:-warn}
freq=${FREQ:-1999}
out=${OUT:-$HOME/profile}
ns=ferrix-profile
ns_peer=ferrix-profile-peer

repository="$(cd "$(dirname "$0")/../.." && pwd)"
target="${CARGO_TARGET_DIR:-$repository/target}"
daemon_bin="$target/profiling/bgp"
feed_bin="$target/profiling/examples/feed"

fail() { echo "error: $*" >&2; exit 1; }
for tool in perf inferno-collapse-perf inferno-flamegraph curl jq; do
    command -v "$tool" >/dev/null || fail "$tool not found"
done

# Release code with line tables, and frame pointers for perf to walk the
# stacks by (cheaper and more complete than DWARF unwinding here; the
# allocator is built with them too).
cd "$repository"
export RUSTFLAGS="-C force-frame-pointers=yes" CFLAGS="-fno-omit-frame-pointer"
# With HEAP=1 the daemon is built with jemalloc's heap profiler and told
# to sample allocations and to write a profile at exit; jeprof turns the
# profile into collapsed stacks for a flame graph of where the memory is.
features=()
[ "$heap" = 1 ] && features=(--features heap-profiling)
cargo build --profile profiling --locked -p bgp --bin bgp "${features[@]}"
cargo build --profile profiling --locked -p bgp-bench --example feed

mkdir -p "$out"
run() { sudo ip netns exec "$ns" "$@"; }
peer() { sudo ip netns exec "$ns_peer" "$@"; }
cleanup() {
    sudo pkill -x bgp 2>/dev/null || true
    sudo pkill -x feed 2>/dev/null || true
    sudo ip netns del "$ns" 2>/dev/null || true
    sudo ip netns del "$ns_peer" 2>/dev/null || true
}
trap cleanup EXIT
cleanup
sudo ip netns add "$ns"
sudo ip netns add "$ns_peer"
sudo ip link add bench0 netns "$ns" type veth peer name peer0 netns "$ns_peer"
run ip link set lo up
run ip addr add 192.0.2.254/24 dev bench0
run ip -6 addr add 2001:db8::ffff/64 dev bench0 nodad
run ip link set bench0 up
peer ip link set lo up
for n in $(seq "$((peers + collector))"); do
    peer ip addr add "192.0.2.$n/24" dev peer0
    peer ip -6 addr add "2001:db8::$n/64" dev peer0 nodad
done
peer ip link set peer0 up
peer ping -c 1 -W 2 192.0.2.254 > /dev/null || fail "the namespaces do not reach each other"

# An AS number that is in none of the synthetic paths: a route with the
# daemon's own AS in its path is refused as a loop.
prefixes=$(( 1000000 / scale + 230000 / scale ))
routes=$(( prefixes * peers ))
cat > "$out/daemon.textpb" <<CONFIG
router_id: "192.0.2.254"
local_asn: 4200000000
listen_endpoints { address: "192.0.2.254" port: 1790 }
listen_endpoints { address: "2001:db8::ffff" port: 1790 }
http_endpoint { address: "127.0.0.1" port: 8080 }
CONFIG
# The peers are configured as a router's would be, with how many routes
# to expect of each. They have private AS numbers and the synthetic table
# has a few bogon prefixes, so bogons are taken. With a collector, every
# peer has a role, since the collector is told what they send.
for n in $(seq "$peers"); do
    cat >> "$out/daemon.textpb" <<CONFIG
peers {
  name: "peer$n"
  endpoint { address: "192.0.2.$n" port: 179 }
  remote_asn: $(( 64512 + n ))
  expected_routes: $prefixes
  role: PEER
  import { accept_bogons: true }
}
CONFIG
done
if [ "$collector" = 1 ]; then
    cat >> "$out/daemon.textpb" <<CONFIG
peers {
  name: "collector"
  endpoint { address: "2001:db8::$((peers + 1))" port: 179 }
  remote_asn: 212232
  role: CUSTOMER
  add_path: ADD_PATH_SEND
  import { max_prefixes: 1 }
  export { learned_routes: true all_paths: true }
}
CONFIG
fi
if [ "$kernel" = 1 ]; then
    echo 'kernel { stale_seconds: 0 }' >> "$out/daemon.textpb"
fi

# `JEMALLOC_CONF`, if set, is jemalloc's MALLOC_CONF for the daemon:
# "thp:always", say. The symbols are prefixed, hence the variable's name.
malloc_conf=${JEMALLOC_CONF:-}
if [ "$heap" = 1 ]; then
    # One sample every 512 KiB allocated, and a profile every 1 GiB
    # allocated: the last of them is the nearest to the table being in.
    rm -f "$out"/heap.*.heap
    malloc_conf="prof:true,prof_active:true,lg_prof_sample:19,lg_prof_interval:30,prof_prefix:$out/heap${malloc_conf:+,$malloc_conf}"
fi
run env _RJEM_MALLOC_CONF="$malloc_conf" "$daemon_bin" "$out/daemon.textpb" --level "$level" > "$out/daemon.log" 2>&1 &
for _ in $(seq 100); do
    run curl -sf http://127.0.0.1:8080/api/status > /dev/null 2>&1 && break
    sleep 0.1
done
daemon_pid=$(pgrep -nx bgp) || fail "the daemon did not start; see $out/daemon.log"
status() { run curl -sf "http://127.0.0.1:8080/api/$1" | jq -r "$2"; }
now() { date +%s.%N; }
since() { echo "$(now) - $1" | bc; }

sudo perf record -F "$freq" -g -o "$out/perf.data" -p "$daemon_pid" > "$out/perf.log" 2>&1 &
perf_pid=$!
sleep 1

peer env FEED_TO=192.0.2.254:1790 FEED_PEERS="$peers" FEED_SCALE_DOWN="$scale" \
    FEED_FROM=192.0.2 FEED_HOLD_SECS="$hold" FEED_COLLECTOR="$collector" \
    FEED_COLLECTOR_TO="[2001:db8::ffff]:1790" FEED_COLLECTOR_FROM="2001:db8::$((peers + 1))" "$feed_bin" > "$out/feed.log" 2>&1 &
feed_pid=$!
feeding() { kill -0 "$feed_pid" 2>/dev/null || fail "the load generator stopped; see $out/feed.log"; }

# The clock starts at the first route in, not when the load generator
# starts: making the table takes it a while.
while [ "$(status status .received_routes)" = 0 ]; do feeding; sleep 0.02; done
start=$(now)
# Routes the policy refuses (the synthetic table has a few bogons in it)
# count as dealt with.
dealt_with() {
    status status .received_routes
    status peers '[.[] | .rejected_routes // 0] | add // 0'
}
while [ "$(dealt_with | paste -sd+ | bc)" -lt "$routes" ]; do feeding; sleep 0.05; done
arrived=$(since "$start")
received=$(status status .received_routes)
refused=$(status peers '[.[] | .rejected_routes // 0] | add // 0')
echo "$routes routes dealt with after $arrived s ($(echo "$routes / $arrived / 1000000" | bc -l | cut -c1-4) M routes/s): $received taken, $refused refused"
[ "$refused" = 0 ] || run curl -sf http://127.0.0.1:8080/api/rejections | jq -c '.' | cut -c1-400
if [ "$kernel" = 1 ]; then
    prefixes=$(status status .received_prefixes)
    while [ "$(status kernel '.synced and .installed >= '"$prefixes")" != true ]; do feeding; sleep 0.05; done
    installed=$(since "$start")
    echo "$prefixes routes in the kernel after $installed s ($(echo "$prefixes / $installed / 1000" | bc -l | cut -c1-3) k routes/s)"
fi
if [ "$collector" = 1 ]; then
    # Nearly every taken route goes to the collector: not one with its AS
    # on the path or a well-known community that says not to. The count
    # has settled when it has not moved for a few seconds.
    advertised() { status peers '[.[] | select(.name == "collector") | .advertised_routes] | add // 0'; }
    last=-1
    while :; do
        feeding; sleep 3
        now_held=$(advertised)
        echo "  collector holds $now_held of $received after $(since "$start") s"
        [ "$now_held" -gt 0 ] && [ "$now_held" = "$last" ] && break
        last=$now_held
    done
    echo "collector: $(advertised) routes advertised after $(since "$start") s"
    collector_addr=$(status peers '.[] | select(.name == "collector") | .peer_addr')
    run curl -sf "http://127.0.0.1:8080/api/tcp?peer=$collector_addr" \
        | jq -r '.connection | "collector tcp: busy \(.busy_ms / 1000 | . * 10 | round / 10) s, rwnd-limited \(.limited_by_receive_window_share * 100 | round)%, rtt \(.rtt_ms) ms, cwnd \(.cwnd_segments), sent \(.bytes_sent / 1048576 | round) MiB in \(.segments_out) segments"'
fi
memory_report() {
    rss=$(awk '/VmRSS/ { printf "%.0f", $2 / 1024 }' "/proc/$daemon_pid/status")
    echo "daemon: $rss MiB resident $1"
    status status '.memory | to_entries | map("\(.key) \(.value / 1048576 | floor) MiB") | join(", ")' | sed 's/^/jemalloc: /'
}
memory_report "with the table in"
# And once the allocator has had its decay time to give back what the
# load allocated and freed: the figure a router shows for the long run.
sleep 30
memory_report "30 s later"
run curl -sf http://127.0.0.1:8080/metricz | grep '^bgp_kernel_route_changes_total' | sed 's/^/kernel: /'
sleep 1
sudo kill -INT "$perf_pid"
wait "$perf_pid" || true
cat "$out/feed.log"

sudo chown "$(id -u)" "$out/perf.data"
if [ "$heap" = 1 ]; then
    sudo chown "$(id -u)" "$out"/heap.*.heap 2>/dev/null || true
    # jeprof comes with jemalloc's sources as a template; the prefix the
    # allocator's symbols carry is filled in.
    template=$(find "$HOME/.cargo/registry/src" -path "*tikv-jemalloc-sys*" -name jeprof.in | head -1)
    [ -n "$template" ] || fail "jeprof.in not found in the cargo registry"
    sed -e 's/@JEMALLOC_PREFIX@/_rjem_/g' -e 's/@jemalloc_version@/5.3/' "$template" > "$out/jeprof"
    # The latest profile is the one nearest to the table being in.
    profile=$(ls -t "$out"/heap.*.heap | head -1)
    perl "$out/jeprof" --collapsed "$daemon_bin" "$profile" > "$out/heap.folded" 2> "$out/jeprof.log" \
        || fail "jeprof failed; see $out/jeprof.log"
    inferno-flamegraph --title "ferrix heap: $peers peer(s), $prefixes prefixes each$([ "$collector" = 1 ] && echo ", a collector")" --countname bytes --colors mem --width 1600 "$out/heap.folded" > "$out/heap.svg"
    perl "$out/jeprof" --text "$daemon_bin" "$profile" 2>/dev/null | head -40 > "$out/heap-top.txt"
    echo "heap profile $profile: heap.svg heap-top.txt"
fi
# Without the period field, so that each sample counts one whatever event
# perf sampled by (cpu-clock on a machine without performance counters).
perf script -i "$out/perf.data" -F comm,pid,tid,time,event,ip,sym,dso 2> /dev/null \
    | inferno-collapse-perf > "$out/stacks.folded"
title="ferrix: $peers peer(s) send $prefixes prefixes each"
[ "$kernel" = 1 ] && title="$title, into the kernel"
inferno-flamegraph --title "$title" --countname samples --width 1600 "$out/stacks.folded" > "$out/flame.svg"
perf report -i "$out/perf.data" --no-children --stdio --sort symbol --percent-limit 0.5 -g none 2> /dev/null \
    | grep -v '^#' | grep -v '^$' | sed 's/  *$//' | head -80 > "$out/top-self.txt"
perf report -i "$out/perf.data" --children --stdio --sort symbol --percent-limit 1 -g none 2> /dev/null \
    | grep -v '^#' | grep -v '^$' | sed 's/  *$//' | head -80 > "$out/top-children.txt"
echo "samples: $(awk '{ s += $NF } END { print s }' "$out/stacks.folded")"
echo "results in $out: flame.svg top-self.txt top-children.txt"