Loading a pcap with Brimcap takes a bit longer than it did with zqd

[philrz]

As this issue captures performance results, all numbers shown are actually the average across three different runs. Numbers will be shown with the average first, followed by the three individual numbers in parentheses.

---

A community user recently reported on public Slack (message, thread):

I noticed a strange behavior when running brimcap load or brimcap analyze : the analysis is stuck at the very beginning (0.3%, 0.7%) and then it goes quite fast, which makes the global speed slower than using the "classic zed backend".

I noticed that on Linux, Ubuntu 21.04

@mattnibs, who has done the bulk of the Brimcap development, summarized:

I'm not sure what would account for the 10 second slowdown vs the previous version. I do know that suricata takes a considerably longer time to startup than zeek, though I don't think it's anything like 10 seconds. Also brimcap uses the same version of suricata that the current released version of brim ships with.

Indeed, I'm also familiar with this long Suricata startup time. To cite a specific example, I found that using the v0.24.0 macOS zeekrunner & suricatarunner separately to process the very tiny ifconfig.pcapng.gz (after uncompressing) took 6.1 seconds (6.1, 6.7, 5.5) with the suricatarunner and 0.76 seconds (0.80, 0.75, 0.74) with the zeekrunner. Per the point from @mattnibs about the artifacts being equivalent, with the runners packaged with Brim beta 8d26e6e it took 7.46 seconds (7.5, 7.6, 7.3) and 0.75 seconds (0.70, 0.75, 0.81), respectively. That delta between the two on the Suricata side seems a little wider than expected variance, but in absolute numbers it's just a bit over 1 second, so I'm not inclined to get obsessed with that one right now.

Here's example command lines to get those results.

v0.24.0

time (cat ~/pcap/ifconfig.pcapng | /Applications/Brim.app/Contents/Resources/app/zdeps/suricata/suricatarunner -)

Beta

time (cat ~/pcap/ifconfig.pcapng | /Applications/Brim.app/Contents/Resources/app.asar.unpacked/zdeps/suricata/suricatarunner -)

I recall the dynamics being different between zqd era and Brimcap era in terms of how the progress of the multiple processes are rolled up to the user-facing status report, so I'm hesitant to get fixated on an apples-to-apples comparison of the progress behaviors. Specifically, I seem to recall zqd's approach might have "masked" Suricata's slower startup time because early testing determined that Suricata tended to finish sooner than Zeek and so the progress may have been metered primarily based on the Zeek (Dev could confirm). Granted, based on what we just showed, that conclusion was surely based on larger pcaps. Indeed, this does seem to hold up when testing with this wrccdc pcap that was processed by the v0.24.0 macOS suricatarunner in 28.0 seconds (27.7, 31.3, 24.9) and zeekrunner in 34.8 seconds (34.1, 36.1, 34.2). Equivalent numbers for the Brim beta 8d26e6e are suricatarunner in 31.4 seconds (30.5, 33.2, 30.4) and zeekrunner in 36.8 seconds (35.5, 40.0, 34.9).

Up-leveling to the arguably more important overall load time as perceived by the user, the perceived gap does indeed seem to be somewhat wider. Dragging the wrccdc pcap into macOS (so, to get all Zeek+Suricata logs turned into Zed storage format, and pcap indexed) v0.24.0 took 46.85 seconds (45.70, 47.25, 47.60) and the Brim beta 8d26e6e took 60.8 seconds (63, 56, 63.4).

I also crafted command lines to attempt the equivalent operations at the shell, and the same pattern holds up. That command line for v0.24.0:

time /Applications/Brim.app/Contents/Resources/app/zdeps/zapi -s wrccdc postpcap -f ~/pcap/wrccdc.pcap

For the Brim beta 8d26e6e:

time ( /Applications/Brim.app/Contents/Resources/app.asar.unpacked/zdeps/zapi create -p wrccdc &&  /Applications/Brim.app/Contents/Resources/app.asar.unpacked/zdeps/brimcap index -root "$HOME/Library/Application Support/Brim/data/brimcap-root" -r ~/pcap/wrccdc.pcap &&  /Applications/Brim.app/Contents/Resources/app.asar.unpacked/zdeps/brimcap analyze -json ~/pcap/wrccdc.pcap |  /Applications/Brim.app/Contents/Resources/app.asar.unpacked/zdeps/zapi load -p wrccdc -)

With these, loading the wrccdc.pcap for v0.24.0 took 46.1 seconds (43.1, 47.2, 48.1) and Brim beta 8d26e6e took 59.5 seconds (58.4, 60.4, 59.8). If we want to dig deeper, this is probably the result to focus on since it's easy to repeat at the shell.

I originally ran these variations on Ubuntu 21.04 since that's what the user was running and I wanted to rule out any issue unique to that platform. Alas, the desktop Ubuntu test environment I could most quickly provision was in a VM on this same macOS laptop. The relative deltas observed were similar to what I showed for macOS (I'm skipping an exhaustive write-up of the numbers for the sake of brevity) but with wider variance, which I suspect might be due to the virtualization and the fact that the Linux VM insisted on swapping during testing, despite my attempt to give it plenty of memory. Since the Brim team basically all runs Macs, I figured it would be more effective to repro the delta on macOS.

Overall, we know lots has changed between the pcap-processing approach used in v0.24.0 and the approach in current beta Brim (e.g. the transition to Brimcap, storage being in Zed Lakes, the shaper code in Zed evolving, etc.) so we could perhaps dig deeper into these results and try to determine where the observed ~13 second difference comes from.