xsnap message timestamp logging/reporting

[warner]

What is the Problem Being Solved?

Our "slogfile" currently records kernel-side timestamps of messages going to and from vats: deliveries, syscall requests, syscall responses, and delivery results.

To support investigations like #5139, as well as to collect data for performance improvements, it would be nice if we also had worker-side timestamps for those same messages. We expect the cross-process messaging to be quick, but we don't actually have enough data to prove it. And we expect the kernel to be idle and thus react immediately to a worker's syscall request, but if the kernel were stuck for some reason (VM thrashing, waiting for some IO write), then a late timestamp on the receipt of a syscall request would look identical to the worker spending a long time before emitting the syscall.

Description of the Design

I'm thinking that xsnap.c should have an array (maybe pre-allocated) of timestamps. Whenever it receives the end of a netstring frame, it should append a gettimeofday (ideally as 64-bit seconds-plus-microseconds-since-epoch) to the array. When it sends a string to the parent process, it should also append a timestamp. We might need to include a tiny bit (maybe just one character) of the message so we can distinguish between console messages and syscalls.

When the delivery is complete and the worker is serializing the results, it should fetch one last timestamp, then serialize the entire array and include it in the metering results. Then it should reset the array length to zero in preparation for the next delivery to begin.

On the kernel side, we already include the full metering record in the slogfile. As long as the kernel doesn't attempt to interpret the additional data, we need no additional modifications.

With this information in the slogfile, we can write post-mortem tools that correlate the sends and receives of each syscall request and response, and build a picture of how long the worker spent working, as opposed to how long it spent waiting for the kernel.

Security Considerations

None, the additional metering data is not shared elsewhere in the kernel, and is not included in consensus.

Test Plan

Unit tests in packages/xsnap/ asserting the presence of the timetable and its correct length, and that the values are sorted and bounded by parent-side timestamps captured before and after the worker interaction.

[Tartuffo]

@warner Is this needed for MN-1 or can it go into the Product Backlog?

[warner]

This would help with the perf investigations called for by #5507 and #5361 .

[warner]

Here's a (python) tool to scan a slogfile with the new meterResults.timestamps data and produce a report:

import sys, json, gzip, re, time
from collections import defaultdict
from pprint import pprint

class Syscall:
    def __init__(self, vsc, num, rx_request):
        self.num = num
        self.vsc = vsc
        self.tx_request = None
        self.rx_request = rx_request
        self.tx_result = None
        self.rx_result = None
        if vsc[0] == "send":
            target = vsc[1]
            msg = vsc[2]
            methargsCD = msg["methargs"]
            method = json.loads(methargsCD["body"])[0]
            result = msg.get("result")
            self.description = "(%s).%s -> %s" % (target, method, result)
        elif vsc[0] == "callNow":
            target = vsc[1]
            method = vsc[2]
            self.description = "D(%s).%s" % (target, method)
        elif vsc[0] == "subscribe":
            vpid = vsc[1]
            self.description = "subscribe(%s)" % vpid
        elif vsc[0] == "resolve":
            vpid_strings = []
            for [vpid, reject, data] in vsc[1]:
                r = "!" if reject else ""
                vpid_strings.append(r + vpid)
            self.description = "notify %s" % ",".join(vpid_strings)
        elif vsc[0] in ["dropImports", "retireImports", "retireExports"]:
            self.description = "%s(%s)" % (vsc[0], ",".join(vsc[1]))
        else:
            self.description = vsc[0]
    def got_result(self, when):
        self.tx_result = when
    def set_tx_request(self, when):
        self.tx_request = when
    def set_rx_result(self, when):
        self.rx_result = when

class Delivery:
    def __init__(self, cranknum, vd, when):
        self.cranknum = cranknum
        self.syscalls = []
        self.tx_delivery = when
        self.rx_delivery = None
        self.tx_result = None
        self.rx_result = None
        self.vd = vd
        if vd[0] == "message":
            target = vd[1]
            msg = vd[2]
            methargsCD = msg["methargs"]
            method = json.loads(methargsCD["body"])[0]
            result = msg.get("result")
            self.description = "(%s).%s -> %s" % (target, method, result)
        elif vd[0] == "notify":
            vpid_strings = []
            for [vpid, reject, data] in vd[1]:
                r = "!" if reject else ""
                vpid_strings.append(r + vpid)
            self.description = "notify %s" % ",".join(vpid_strings)
        else:
            self.description = vd[0]
    def add_syscall(self, vsc, when):
        num = len(self.syscalls)
        s = Syscall(vsc, num, when)
        self.syscalls.append(s)
    def num_syscalls(self):
        return len(self.syscalls)
    def get_syscall(self, which):
        return self.syscalls[which]
    def set_rx_result(self, when):
        self.rx_result = when
    def set_rx_delivery(self, when):
        self.rx_delivery = when
    def set_tx_result(self, when):
        self.tx_result = when
        
    
fn = sys.argv[1]
vatID = sys.argv[2] if len(sys.argv) > 2 else None

deliveries = []

opener = gzip.open if fn.endswith(".gz") else open
with opener(sys.argv[1]) as f:
    for line in f:
        if isinstance(line, bytes):
            line = line.decode("utf-8")
        if not line.strip():
            continue

        data = json.loads(line.strip())
        if vatID and data["vatID"] != vat:
            continue
        type = data["type"]
        when = data["time"]

        if type == 'deliver':
            cranknum = data["crankNum"]
            deliverynum = data["deliveryNum"]
            d = Delivery(cranknum, data["vd"], when)
            deliveries.append(d)
        if type == 'syscall':
            deliveries[-1].add_syscall(data['vsc'], when)
        if type == 'syscall-result':
            deliveries[-1].get_syscall(-1).got_result(when)
        if type == 'deliver-result':
            deliveries[-1].set_rx_result(when)
            dr = data["dr"]
            mr = dr[2]
            if mr and "timestamps" in dr[2]:
                timestamps = mr["timestamps"]
                d = deliveries[-1]
                if len(timestamps):
                    d.set_rx_delivery(timestamps.pop(0))
                for syscallnum in range(d.num_syscalls()):
                    s = d.get_syscall(syscallnum)
                    if len(timestamps):
                        s.set_tx_request(timestamps.pop(0))
                    if len(timestamps):
                        s.set_rx_result(timestamps.pop(0))
                if len(timestamps):
                    d.set_tx_result(timestamps.pop(0))

fill = "                         "
prev_d = None
for d in deliveries:
    total_worker = 0
    total_kernel = 0
    total_pipe = 0
    if prev_d:
        kerneltime = d.tx_delivery - prev_d.rx_result
        print("                                          %.6f kern between-cranks" % kerneltime)
    prev_d = d
    print("c%d %s" % (d.cranknum, d.description))
    if d.rx_delivery:
        print("                                                          k -> %.6f -> w   (send delivery)" % (d.rx_delivery - d.tx_delivery))
        #d.tx_result - d.rx_delivery,
        total_pipe += (d.rx_delivery - d.tx_delivery)
    else:
        print("                                             k -> w   (send delivery)")
    prev_s = None
    for s in d.syscalls:
        if not prev_s and d.rx_delivery and s.tx_request:
            print("%s%.6f worker" % (fill, s.tx_request - d.rx_delivery))
            total_worker += (s.tx_request - d.rx_delivery)
        if prev_s and prev_s.rx_result and s.tx_request:
            print("%s%.6f worker" % (fill, s.tx_request - prev_s.rx_result))
            total_worker += (s.tx_request - prev_s.rx_result)
        prev_s = s
        if s.tx_request and s.rx_result:
            print("   w -> %.6f -> k,                    %.6f kern,  k -> %.6f -> w : %s" % (
                s.rx_request - s.tx_request,
                s.tx_result - s.rx_request,
                s.rx_result - s.tx_result,
                s.description))
            total_pipe += (s.rx_request - s.tx_request)
            total_kernel += (s.tx_result - s.rx_request)
            total_pipe += (s.rx_result - s.tx_result)
        else:
            print("  w -> k,                    %.6f kern,  k -> w : %s" % (
                s.tx_result - s.rx_request,
                s.description))
    if prev_s and d.tx_result:
        print("%s%.6f worker" % (fill, d.tx_result - prev_s.rx_result))
        total_worker += (d.tx_result - prev_s.rx_result)
    if not prev_s and d.tx_result:
        print("%s%.6f worker" % (fill, d.tx_result - d.rx_delivery))
        total_worker += (d.tx_result - d.rx_delivery)
    if d.tx_result:
        print("   w -> %.6f -> k                                                          (return result)" % (d.rx_result - d.tx_result))
        total_pipe += (d.rx_result - d.tx_result)
    else:
        print("  w -> k                                              (return result)")
    k_to_k = d.rx_result - d.tx_delivery
    if d.tx_result:
        print("   pipe %.6f, worker %.6f, kernel %.6f    total  (k->k %.6f)" % (
            total_pipe, total_worker, total_kernel, k_to_k))
    else:
        print("         total  (k->k %.6f)" % k_to_k)
    

A sample report looks like:

c74 retireExports
                                                          k -> 0.000078 -> w   (send delivery)
                         0.000148 worker
   w -> 0.000121 -> k                                                          (return result)
   pipe 0.000199, worker 0.000148, kernel 0.000000    total  (k->k 0.000347)
                                          0.000346 kern between-cranks
c75 bringOutYourDead
                                                          k -> 0.000066 -> w   (send delivery)
                         0.001141 worker
   w -> 0.000188 -> k,                    0.000071 kern,  k -> 0.000053 -> w : vatstoreGet
                         0.000067 worker
   w -> 0.000098 -> k,                    0.000145 kern,  k -> 0.000059 -> w : vatstoreGetAfter
                         0.000062 worker
   w -> 0.000187 -> k,                    0.000025 kern,  k -> 0.000057 -> w : dropImports(o-50)
                         0.000060 worker
   w -> 0.000234 -> k,                    0.000025 kern,  k -> 0.000062 -> w : retireImports(o-50)
                         0.000044 worker
   w -> 0.000171 -> k                                                          (return result)
   pipe 0.001175, worker 0.001374, kernel 0.000266    total  (k->k 0.002815)

which shows two deliveries (retireExports in crank 74, then bringOutYourDead in crank 75). The kernel spent 346us thinking between the end of the retireExports and the beginning of bringOutYourDead. The BOYD started with a 66us delay to send the VatDeliveryObject from the (k)ernel to the (w)orker. Then the worker spent 1.141ms thinking. then the worker sent a vatstoreGet syscall, which took 188us to get from worker to kernel, 71us in the kernel (doing a DB read), then 53us to get the syscal results back to the worker. Then the worker though for 67us before sending a vatstoreGetAfter syscall, etc. The worker's VatDeliveryResult object took 171us to be sent from worker to kernel. Overall, the delivery took 2.815ms (from the delivery leaving the kernel, to the result arriving back at the kernel), of which 1.374ms was spent in the worker, 266us was spent in the kernel, and 1.175ms was spent sending things back and forth through pipes.

This dataset came from a unit test, so it's pretty quiet (there's no chain activity going on).

The next step is to adapt this code into slog-to-otel.js and build spans out of all these little chunks of activity.

[warner]

The timestamps we're recording look like this:

The red dashed boxes are potential sources of the unexpected delays we've observed in testnet data.

[Tartuffo]

@mhofman estimate please?

[warner]

The xsnap.c and slog-recording portions are landed. Once slog-to-otel.js is converting an adequate amount of this data into spans for telemetry, we can close this ticket.