nhttpslower.py

#!/usr/bin/env python
#
# nhttpslower   Snoops and prints Node.js HTTP requests slower than a threshold.
#               This tool is experimental and designed for teaching purposes
#               only; it is neither tested nor suitable for production work.
#
# NOTE: Node http__client* probes are not accurate in that they do not report
#       the fd, remote, and port. This makes it impossible to correlate request
#       and response probes, and a result the tool does not work correctly if
#       there are multiple client requests in flight in parallel.
#
# Copyright (C) Sasha Goldshtein, 2017

import argparse
import ctypes as ct
import sys
from bcc import BPF, USDT, DEBUG_PREPROCESSOR

# TODO This can also be done by using uprobes -- explore what it would take
# TODO Filter by HTTP method, or by URL prefix/substring

parser = argparse.ArgumentParser(description="Snoops and prints Node.js HTTP " +
    "requests and responses (client and server) slower than a threshold. " +
    "Requires Node.js built with --enable-dtrace (confirm by using tplist).")
parser.add_argument("pid", type=int, help="the Node.js process id")
parser.add_argument("threshold", type=int, nargs="?", default=0,
                    help="print only requests slower than this threshold (ms)")
parser.add_argument("-S", "--stack", action="store_true",
                    help="capture a stack trace for each event")
parser.add_argument("--client", action="store_true",
                    help="client events only (outgoing requests)")
parser.add_argument("--server", action="store_true",
                    help="server events only (incoming requests)")
parser.add_argument("-d", "--debug", action="store_true",
                    help="print the BPF program (for debugging purposes)")
args = parser.parse_args()

text = """
#include <uapi/linux/ptrace.h>

struct val_t {
    u64 start_ns;
    u64 duration_ns;
    int type;       // CLIENT, SERVER
#ifdef NEED_STACK
    int stackid;
#endif
    char method[16];
    char url[128];
};

struct data_t {
    u64 start_ns;
    u64 duration_ns;
    int port;
    int type;
    int stackid;
    char method[16];
    char url[128];
    char remote[128];
};

struct key_t {
    // TODO nhttpsnoop correlates by remote and port, while we use fd and port
    int fd;
    int port;
};

#define CLIENT 0
#define SERVER 1

BPF_PERF_OUTPUT(events);
BPF_STACK_TRACE(stacks, 1024);
BPF_HASH(starts, struct key_t, struct val_t);

#define THRESHOLD """ + str(args.threshold*1000000) + "\n"

probe = """
int PROBE_start(struct pt_regs *ctx) {
    struct val_t val = {0};
    struct key_t key = {0};
    char *str;

    bpf_usdt_readarg(7, ctx, &key.fd);
    bpf_usdt_readarg(4, ctx, &key.port);
    bpf_usdt_readarg(5, ctx, &str);
    bpf_probe_read(val.method, sizeof(val.method), str);
    bpf_usdt_readarg(6, ctx, &str);
    bpf_probe_read(val.url, sizeof(val.url), str);

    val.start_ns = bpf_ktime_get_ns();
    val.type = TYPE;
#ifdef NEED_STACK
    val.stackid = stacks.get_stackid(ctx,
                                     BPF_F_REUSE_STACKID | BPF_F_USER_STACK);
#endif

    starts.update(&key, &val);
    return 0;
}

int PROBE_end(struct pt_regs *ctx) {
    struct key_t key = {0};
    struct val_t *valp;
    struct data_t data = {0};
    u64 duration;
    char *remote;

    bpf_usdt_readarg(4, ctx, &key.fd);
    bpf_usdt_readarg(3, ctx, &key.port);

    valp = starts.lookup(&key);
    if (!valp)
        return 0;   // Missed the start event for this request

    duration = bpf_ktime_get_ns() - valp->start_ns;
    if (duration < THRESHOLD)
        goto EXIT;

    data.start_ns = valp->start_ns;
    data.duration_ns = duration;
    data.port = key.port;
    data.type = valp->type;
#ifdef NEED_STACK
    data.stackid = valp->stackid;
#endif
    __builtin_memcpy(data.method, valp->method, sizeof(data.method));
    __builtin_memcpy(data.url, valp->url, sizeof(data.url));

    bpf_usdt_readarg(2, ctx, &remote);
    bpf_probe_read(&data.remote, sizeof(data.remote), remote);

    events.perf_submit(ctx, &data, sizeof(data));

EXIT:
    starts.delete(&key);
    return 0;
}
"""

if not args.server:
    text += probe.replace("PROBE", "client").replace("TYPE", "CLIENT")
if not args.client:
    text += probe.replace("PROBE", "server").replace("TYPE", "SERVER")

CLIENT = 0
SERVER = 1

if args.stack:
    text = "#define NEED_STACK\n" + text

usdt = USDT(pid=args.pid)
if not args.server:
    usdt.enable_probe("http__client__request", "client_start")
    usdt.enable_probe("http__client__response", "client_end")
if not args.client:
    usdt.enable_probe("http__server__request", "server_start")
    usdt.enable_probe("http__server__response", "server_end")
bpf = BPF(text=text, usdt_contexts=[usdt],
          debug=DEBUG_PREPROCESSOR if args.debug else 0)

class Data(ct.Structure):
    _fields_ = [
        ("start_ns", ct.c_ulong),
        ("duration_ns", ct.c_ulong),
        ("port", ct.c_int),
        ("type", ct.c_int),
        ("stackid", ct.c_int),
        ("method", ct.c_char * 16),
        ("url", ct.c_char * 128),
        ("remote", ct.c_char * 128)
    ]

delta = 0
prev_ts = 0

def print_event(cpu, data, size):
    global delta, prev_ts
    event = ct.cast(data, ct.POINTER(Data)).contents
    typ = "CLI" if event.type == CLIENT else "SVR"
    if prev_ts != 0:
        delta += event.start_ns - prev_ts
    prev_ts = event.start_ns
    print("%-14.9f %3s %11.3f %-16s %-5d %-8s %s" %
          (delta/1e9, typ, event.duration_ns/1e6, event.remote,
           event.port, event.method, event.url))
    if args.stack:
        for addr in stacks.walk(event.stackid):
            print("\t%s" % bpf.sym(addr, args.pid, show_offset=True))
        print("")

bpf["events"].open_perf_buffer(print_event)
if args.stack:
    stacks = bpf["stacks"]
print("Snooping HTTP requests in Node process %d, Ctrl+C to quit." % args.pid)
print("%-14s %3s %-11s %-16s %-5s %-8s %s" %
      ("TIME_s", "TYP", "DURATION_ms", "REMOTE", "PORT", "METHOD", "URL"))
while 1:
    bpf.kprobe_poll()