Performance under load

Performance under load

We pushed a server hard with and without BxLens to answer one question: is BxLens the bottleneck? The short answer:

• BxLens adds a fixed cost to every request. On the demo pages, which are very cheap (2 to 3 ms of CPU each), light with the bar off added about 1.2 ms of CPU per request and the bar added about 1 ms more. In percent of throughput that looks large on pages this small. On a page that spends 50 ms of CPU, the same 1 to 5 ms is 2% to 10% (arithmetic, not a measurement).
• It does not become the bottleneck when something else is. With a slow database query, a full worker pool, or a flood of identical or unique errors, the throughput is set by the application and BxLens stays out of the way. The work queue never dropped or failed an event in any run.
• It stays bounded. The error flood guard held, the issue count stopped at its cap, and memory and threads were flat over a four minute soak with a few MB retained after a full garbage collection.

For production use collect.level light and turn the bar off. See Running BxLens in production. Older figures at low concurrency are on Performance.

How it was measured

• Machine. A shared cloud container with 4 vCPU and 16 GB RAM. The load client runs on the same machine as the server and takes cores from it, so read the numbers as relative, never as capacity.
• Server. OpenJDK 21, BoxLang 1.19.0-snapshot on MiniServer, the demo harness (harness/), derby in memory. BoxLang+ features are on for every BxLens setting.
• Settings. No module installed, then light and full with the bar off and on. The bar adds a script tag and a snapshot to HTML pages.
• Traffic. Closed loop clients (each waits for its answer) at 64 connections for 30 seconds after an 8 second warm up, unless a scenario says otherwise. Pages are ones that behave the same without the module.
• Repeats. Three rounds, every setting once per round, the order rotated each round so that drift of a shared machine hits every setting alike. Tables show the median and, in brackets, the lowest to the highest of the three. Scenarios marked "one run" ran once, so no spread is shown.
• Cost per request. Server process CPU and allocation over JMX divided by the requests served.

Cost per request

Mixed pages, 64 connections

Query heavy pages (N+1 and transactions), 64 connections

One uncaught bug hit again and again, 64 connections

What these say:

• The pages cost 2 to 3 ms of CPU without the module, so a fixed 1 to 3 ms is a large share. Read the CPU ms per request columns, not the percentages.
• light with the bar off adds about 1.2 ms (mixed), 2.0 ms (query heavy) and 0.5 ms (one error). The bar adds about 0.9 to 1.1 ms more on the pages that render it (the error page does not).
• full costs most on query heavy pages (collecting the caller and bound values of every statement): 3.4 ms with the bar off and 5.3 ms with the bar on, over the 2.7 ms baseline.
• These are higher than the 0.05 to 0.4 ms measured with 4 connections for Performance. At 64 connections on 4 shared cores, the JVM also spends time on queuing, garbage collection and the background worker, and the client competes for the same cores. Both are real; the lower figure is for an idle machine and the higher for a saturated one.

Errors

Every request a new kind of error, 64 connections (one run)

The flood guard keeps this cheap: at most 1000 events per second are counted, only 20 new issues per minute are opened (after that they go into one overflow issue) and the issue list stops at 200. In the runs the issue count stayed at 21 (20 new plus the overflow issue) after a unique error run and at 48 to 52 after the soak, and the console stayed responsive. Error events dropped by the flood guard below is by design.

Bottlenecks, peak and soak

• peak (256 connections, one run per setting): light with the bar off was within the noise of no module (about 3% lower). full with the bar on served about half as many requests per second, which is the same per request cost as above, now with the cores saturated.
• slowsql: the database burns the CPU and the rate is 2 to 3 requests per second for everyone. With full and the bar on, 40 requests finished in the window against 64 without the module. This is one run, and the difference is the extra CPU competing with a CPU bound query, so do not read more into it than "BxLens adds CPU, and a CPU bound server notices".
• stall: every setting served the same 288 requests in the same time (p50 13.6 s). The app held its threads, and BxLens added nothing.
• soak: throughput without the module was 1580 requests per second, 1396 with light and the bar off and 1169 with full and the bar on. No failed requests.

What BxLens itself counted

The work queue never had anything waiting, and dropped or failed nothing, in any run. Events dropped by the flood guard are errors it chose not to record, not a failure. "Statements kept" is the number of different statements in the statistics.

Memory and threads over the soak

Heap use rises and falls with the garbage collector in all three settings. What the server holds after a full collection at the end is 11 to 12 MB more with BxLens (32 MB without, 43 and 44 MB with), the thread count is about 10 higher (BxLens worker and stream threads) and the share of time in garbage collection goes from 0.7% to 0.8% and 1.0%. Nothing grew during the run.

The server's own log

Uncaught errors write a stack trace to the server log whether BxLens is installed or not (a gigabyte over four minutes of soak). Rotate or cap that log on a server that can fail at this rate. It is not caused by BxLens.

One request while the worker pool is full

The console runs inside the same server, so with every worker thread busy it waits like any other request. In the stall run the console overview took 13.5 s while the pool was full, the same as an app page (13.3 s without the module), and 15 to 25 ms five seconds after the stall ended. Use the monitoring that runs outside the server (a health probe, JMX, your platform) to tell you that the pool is full; BxLens shows what filled it once a worker is free. The raw results of this run are in tools/perf/results/load-report/.

What this means

• Pages that spend most of their time in your code or in the database see a small relative cost. Pages that are nearly free see a large one, because the cost is fixed per request.
• Running the console with collect.level light and the bar off is the cheapest setting that still records requests, queries, errors and the history.
• The bar and full collection are for development and for looking into a problem. Switch them on for a while and off again.
• Errors, however many and however varied, are bounded in work, memory and disk.

Caveats

• One shared 4 vCPU machine, the client on the same cores, a demo app. Absolute numbers will differ on yours, and three runs per cell is few: the spread in brackets is large for some cells (mixed pages with no module ran from 806 to 1090 requests per second).
• Scenarios unique, peak, slowsql, stall and soak ran once per setting, and only for no module, light with the bar off and full with the bar on. The standard level was not part of this run; it is close to light in an earlier run.
• A closed loop client slows down when the server does, so the latency figures understate what an open arrival rate would show.
• Garbage collection, JIT and a noisy neighbour move single runs by tens of percent.

Repeat it

Everything is in tools/perf/ (see its README). Build the module first, then:

./gradlew shadowJar --offline -q
RESULTS_DIR=/tmp/lens-load tools/perf/stress-rounds.sh      # about an hour, resumes where it stopped
java -jar harness/.cache/boxlang-*.jar tools/perf/stress-summary.bxs /tmp/lens-load   # the tables on this page

tools/perf/stress.sh <setting> [scenarios] runs one setting. console-health.bxs and stress-summary.bxs are BoxLang scripts. Run on a quiet machine with the load client elsewhere if you want numbers to quote.