If you had a time machine, would you need to spend so much on logging?

DEBUG and trace-level logs provide the detail you need to investigate a failure, but collecting them continuously means paying for vast amounts of data you may never use (and bills you’re certain to get complaints about). But Antithesis’ built-in time machine — our deterministic hypervisor — lets you keep verbose logging enabled in your application, discard selected output during testing, and then reconstruct it from simulation when there is something worth investigating.

The result is dramatically cheaper access to detailed logs: generate and collect the relevant output on demand instead of retaining everything just in case. We call this feature Retroactive Logging, and here’s how it works.

Antithesis runs your system inside our deterministic hypervisor. Our fuzzer sends randomness to your system while it runs in the hypervisor, receiving logs and other information in return. These get sent to our production database, Pangolin, then accessed by the user via the web app or API. If the user wants to capture trace-level logging from an 8-hour test run, this is a lot of bits to move.

Now, when you’re running in Antithesis, the costs of trace-level logging are nowhere near as bad as in production, because instead of slowing customers down, the performance drag is “only” slowing Antithesis’ exploration – it takes longer to find bugs. For this reason, many customers looking to maximize their test efficiency still limit their logging when they can.

One solution to the performance problem might be to ask users to turn verbose logging on only when they encounter a problem, but this is more complicated than it might seem. Changing the logging level actually changes system state, in subtle ways. You can’t do it on the fly while maintaining determinism.

But the deterministic hypervisor confers an interesting superpower — we can change the rest of our system around the hypervisor, knowing that we can always replay events in any test run exactly as they occurred. As long as the original test was run with verbose logging turned on, we can always recover those logs by replaying the run. And if those logs never leave the hypervisor, the rest of the system won’t take as much of a performance hit.

Our hypervisor now includes a “black hole” – an output sink – where the system under test can send most of its logs. If the test run is uneventful, no one has to think about that data ever again. It’s never even written to our database, and you’ll never get a storage bill. Some logging output from the system under test helps guide Antithesis’ exploration, and it gets sent through the rest of the system as normal.

But if something interesting happens, deterministic replay allows us to “look inside” the black hole. We replay the relevant portions of the run with the black hole turned off, and the data streams out of the hypervisor and into the Logs Explorer or wherever else you need to send it.

Not moving all that data around creates significant efficiency gains. We ran a UDP Echo Test with one server across three clients and our fault injector enabled. We set the system to divert logs labeled [DBG] to the output sink. Each client sent a packet to the [DBG] logs every 1 ms, and summary stats were logged every 100 ms.

Turning verbose logging on increases output volume 6x, causing a 91% drop in test efficiency (vtime/walltime ratio drops from 1.81 to 0.16). But when we turn Retroactive Logging on, output volume actually decreases, while test efficiency is reduced only 44%. In other words, Antithesis is spending more time exploring diverse execution paths instead of waiting for uploads of low-level trace data.

The results actually understate the real improvement, because we were using a toy workload that just did packet i/o and logging, so when we turned verbose logging on, it spent a lot of time formatting [DBG] strings! With an actual production workload, we’d expect the vtime/walltime ratio to be even better.

And Retroactive Logging creates negligible performance overhead if you happen to run it without verbose logging in the system.

You can select which logs to send into the black hole by filtering on regular expressions (e.g. DEBUG) or particular containers/pods when you launch a test, and recover them by using the Multiverse Debugger.

While this doesn’t (yet) allow us to reduce our Cloudwatch bill, we’re still pretty pleased with this feature. Partly because we’re always glad to find another unexpected use for determinism, and partly because this literally grew out of a hackathon project (when you’ve got a foundation like the deterministic hypervisor to build on, you can build some pretty nifty things) — but mostly because this is a stepping stone to something much bigger, coming your way this fall.

If you’re using Release 61.8 or later, Retroactive Logging is available to you today.