Significant latency regression between TypeScript SDKs v0.4.10 and v1.0.0

[CodingCanuck]

I've just upgrade our codebase from braintrust v0.4.10 to braintrust v1.0.0, which caused our eval runs to get significantly slower (from 1.5 min before to 5 min after for a few hundred tasks).

The majority of the time seems to be spent uploading logs to a /logs3 API endpoint in a sequential upload loop here that was introduced in this commit (and later re-done in this commit).

It looks like the goal of these commits was to reduce memory usage, but it looks like it inadvertently changed blocking behavior (I think logging previously wasn't blocked on / awaited, but now the code seemingly awaits these ~small sequential RPCs after each task). (I don't know Braintrust's code, but @CLowbrow is likely familiar with the tradeoffs that were optimized for here)

With Codex's help, I've created a little benchmark script that reproduces the regression without a dependency on our internal repo, along with an explanation of possible root causes: https://github.com/CodingCanuck/braintrust-sdk/blob/latency-regression-in-1.0/js/repro/latency-regression/BUG_REPORT.md

The main symptom we're noticing is a lot of sequential upload calls, whose wall time corresponds to the increase in wall time of our eval runs. Unfortunately there's no change in latency when setting noSendLogs to true, but my local eval time drops from 5 min to 77s if I patch out logging/flush functions to be no-ops:

    const state = _internalGetGlobalState();
    const httpLogger = state.httpLogger() as unknown as {
      flush?: () => Promise<void>;
      flushOnce?: (args?: unknown) => Promise<void>;
      submitLogsRequest?: (...args: unknown[]) => Promise<unknown>;
      triggerActiveFlush?: () => void;
    };
    if (httpLogger) {
      if (typeof httpLogger.submitLogsRequest === 'function') {
        httpLogger.submitLogsRequest = async () => undefined;
      }
      if (typeof httpLogger.flushOnce === 'function') {
        httpLogger.flushOnce = async () => undefined;
      }
      if (typeof httpLogger.flush === 'function') {
        httpLogger.flush = async () => undefined;
      }
      if (typeof httpLogger.triggerActiveFlush === 'function') {
        httpLogger.triggerActiveFlush = () => undefined;
      }

I see the same slowdown in all releases after v0.4.10 (including the latest v3.0.0 release).

For our use case, we're not at all concerned with memory usage, but we're very concerned with end-to-end latency for fast iteration when experimenting with prompt changes. Could we fix this latency regression without breaking the intended memory optimization? We'd happily run with a --fast-but-ram-hungry flag or similar.

Note: we're directly executing Eval instances and using Braintrust's TypeScript SDK: we're not using Braintrust's CLI (we're not running npx braintrust).

[AbhiPrasad]

Hey @CodingCanuck thanks for writing in and providing a repro. I think we can probably process a couple calls to flushWrappedItemsChunk at a time, and probably introduce some better async processing down the pipeline as well. Let me take a look!

[CodingCanuck]

Thanks, @AbhiPrasad !

I'll admit that I don't fully understand what the behavior was before this regression: was logging simply faster, or did evals potentially end/exit without waiting for logging to finish (so logs were incomplete)? Or was there just less logging happening?

If evals could exit without complete log uploads in the v0.4.x releases, what's the implication of that? (We didn't notice any problems with evals that I'd associate with missing or truncated logs: would it cause some more subtle issue? Is there a way to get that exit-without-waiting-for-uploads behavior back?)

Edit: this smaller monkey patch also gets us back down to ~75s. In contrast, if I instead make flush() fire-and-forget, our eval code finishes faster but the process still stays alive for ~5 minutes as it waits for uploads to run serially.

  const state = _internalGetGlobalState();
  const httpLogger = state.httpLogger() as unknown as {
    flushWrappedItemsChunk?: (wrappedItems: unknown[], batchSize: number) => Promise<void>;
  };
  if (httpLogger && typeof httpLogger.flushWrappedItemsChunk === 'function') {
    const flushWrappedItemsChunk = httpLogger.flushWrappedItemsChunk.bind(httpLogger);
    httpLogger.flushWrappedItemsChunk = async (wrappedItems, batchSize) => {
      // Fire-and-forget chunk uploads, but still surface errors in logs.
      flushWrappedItemsChunk(wrappedItems, batchSize).catch((err) => {
        console.error('Error flushing log chunk:', err);
      });
    };
  }

Edit: for at least our local eval runs in our project, we see negligible difference in the eval process's peak RSS value (3.3GB with/without the fire-and-forget flush change, though across 4 runs with/without this monkey patching the fire-and-forget flush measurements were 42MB higher, aka 1% higher). So for us, the latency reduction of this patch (which we've applied locally) is totally worth it, since it reduces our eval runs from 5m back down to ~75s.

[CLowbrow]

Hi @CodingCanuck! We are going to look at this. Out of curiosity, are you using maxConcurrency in your eval call? I think that the major change that would be difficult to roll back is that we changed the behavior to say that the row isn't done for maxConcurrency purposes until the logs are flushed. If you aren't then this looks like just a regression. We will look independently but giving us the config you're running your eval with would help.

[CodingCanuck]

Thanks for the update!

No, we're not setting maxConcurrency. We're also running running several Eval instances in parallel (several different Eval implementations), in case that's relevant.

I can't make our full eval codebase public, but let me know if there's other details you need, or other measurements I can provide.

[CLowbrow]

@CodingCanuck could you try setting BRAINTRUST_LOG_FLUSH_CHUNK_SIZE to see if that improves things at all?

I ran it with your benchmark and it seems to speed things up:

Apologies for not having this documented I'm going to add it to the docs.

[xXMrNidaXx]

Sequential log uploads killing throughput - classic trade-off issue!

Quick fix suggestion - add batched async mode:

interface LoggerOptions {
  mode: 'sequential' | 'batched' | 'fire-and-forget';
  batchSize?: number;  // default 100
  batchTimeoutMs?: number;  // default 1000
}

// In logger.ts
if (options.mode === 'batched') {
  // Batch logs and upload in parallel chunks
  const batches = chunk(logs, options.batchSize);
  await Promise.all(batches.map(batch => 
    this.uploadBatch(batch)
  ));
} else if (options.mode === 'fire-and-forget') {
  // Queue for background upload, don't await
  this.backgroundQueue.push(...logs);
}

Your workaround is valid but fragile across versions.

Better workaround:

// Wrap Eval to batch flushes
const originalFlush = httpLogger.flush;
let pendingFlushes: Promise<void>[] = [];

httpLogger.flush = async () => {
  pendingFlushes.push(originalFlush.call(httpLogger));
  if (pendingFlushes.length >= 10) {
    await Promise.all(pendingFlushes);
    pendingFlushes = [];
  }
};

Flag suggestion: BRAINTRUST_LOG_MODE=batched env var would be cleaner than CLI flag.

---

If you build eval/observability systems:

https://www.revolutionai.io/find-work

Production AI projects 💼

[CodingCanuck]

@CodingCanuck could you try setting BRAINTRUST_LOG_FLUSH_CHUNK_SIZE to see if that improves things at all?

@CLowbrow sure! A large BRAINTRUST_LOG_FLUSH_CHUNK_SIZE does improve our eval timings, but it doesn't reach their previous speed. (I think I tried to set it before filing this issue, but I think I set it in a way that doesn't apply to subprocesses: my bad)

# No workaround / HEAD:
✨  Done in 281.33s.
yarn eval  64.31s user 8.25s system 25% cpu 4:41.45 total

# export BRAINTRUST_LOG_FLUSH_CHUNK_SIZE=10000000:
✨  Done in 75.01s.
yarn eval  50.72s user 6.71s system 76% cpu 1:15.19 total

# workaround to monkey-patch flushWrappedItemsChunk to not await / fire-and-forget:
✨  Done in 65.40s.
yarn eval  58.11s user 7.43s system 99% cpu 1:05.58 total

So large chunks greatly reduces the regression, but doesn't eliminate it (we're still noticeably slower than the v0.4.x releases).

The same effect is visible in the benchmark, when patching in this code to the main() method in run-one.msj to restore fire-and-forget behavior:

if (typeof bt._internalGetGlobalState === "function") {
    const state = bt._internalGetGlobalState();
    const httpLogger = state?.httpLogger?.();
    if (httpLogger && typeof httpLogger.flushWrappedItemsChunk === "function") {
      const flushWrappedItemsChunk =
        httpLogger.flushWrappedItemsChunk.bind(httpLogger);
      httpLogger.flushWrappedItemsChunk = async (wrappedItems, batchSize) => {
        // Fire-and-forget chunk uploads, but still surface errors in logs.
        flushWrappedItemsChunk(wrappedItems, batchSize).catch((err) => {
          console.error("Error flushing log chunk:", err);
        });
      };
    }
  }

For the the benchmark's log-heavy / work-light workload, bigger chunks are ~2x faster, but fire-and-forget (no per-task blocking on log upload) is a further ~10x faster than larger chunks (so ~20x faster than head):

# No workaround / HEAD:
wall=18.232s totalRequests=53 uploadRequests=50 uploadLatencyMs=16938
node "./js/repro/latency-regression/run-one.mjs"  1.13s user 0.20s system 7% cpu 18.488 total

# export BRAINTRUST_LOG_FLUSH_CHUNK_SIZE=10000000:
wall=9.312s totalRequests=23 uploadRequests=20 uploadLatencyMs=7909
node "./js/repro/latency-regression/run-one.mjs"  0.96s user 0.18s system 12% cpu 9.470 total

# workaround to monkey-patch flushWrappedItemsChunk to not await / fire-and-forget:
wall=0.876s totalRequests=2 uploadRequests=0 uploadLatencyMs=0
node "./js/repro/latency-regression/run-one.mjs"  0.94s user 0.23s system 34% cpu 3.387 total

This makes me think:

1. The new behavior of blocking on serial chunked log load explains this latency regression.
2. It's worse with big logs, because per-chunk overhead is high (e.g. starting/stopping connections), and its impact is reduced with large chunk sizes.
3. Per-task blocking with large chunks is still slower than fire-and-forget / non-awaiting log upload, which is more visible in tasks with less CPU work (which have less work to parallelize while waiting for network traffic).

For some more data, here's timing from 5 runs of our eval with large chunk size, mean time = 83.4s, mean CPU utilization 84% (likely network or I/O-bound):

✨  Done in 84.86s.
yarn eval  65.17s user 9.10s system 87% cpu 1:25.07 total

✨  Done in 93.51s.
yarn eval  82.12s user 13.06s system 101% cpu 1:33.62 total

✨  Done in 94.63s.
yarn eval  56.98s user 7.10s system 67% cpu 1:34.73 total

✨  Done in 74.88s.
yarn eval  52.64s user 6.69s system 79% cpu 1:15.01 total

✨  Done in 69.16s.
yarn eval  54.50s user 6.91s system 88% cpu 1:09.29 total

Compare to 5 runs with the monkey-patched fire-and-forget workaround, mean time = 60.0s, mean CPU utilization 103% (likely CPU-bound):

✨  Done in 60.95s.
yarn eval  56.85s user 6.74s system 104% cpu 1:01.08 total

✨  Done in 62.64s.
yarn eval  57.93s user 6.97s system 103% cpu 1:02.75 total

✨  Done in 76.60s.
yarn eval  72.76s user 9.94s system 107% cpu 1:16.78 total

✨  Done in 63.40s.
yarn eval  58.84s user 7.24s system 104% cpu 1:03.51 total

✨  Done in 63.38s.
yarn eval  54.98s user 6.47s system 96% cpu 1:03.48 total

So the old fire-and-forget behavior was ~70% of the end-to-end time compared to the chunked approach in our case.

And note that our times are inflated because we spin up some docker containers to bring up helpers like PostgreSQL at the start of eval and tear them down at the end, which means these end-to-end timings under-emphasize this upload speed regression. E.g. running our eval pipeline with 0 evals takes 29s (to start & stop those docker containers):

# Empty eval timing:
✨  Done in 28.60s.
yarn eval --filter potato  24.12s user 2.80s system 93% cpu 28.693 total

This means that in our eval case, we see:

• fire-and-forget log upload: eval portion is ~30s
• large chunk size: eval portion is ~50s
• default chunk size: eval portion is ~250s