[improve][cli] pulsar-perf: cut latency histogram memory ~100x, fix range units and static stats state - #26466

Motivation

A heap dump of a pulsar-perf produce run (1.03 GB live) showed 246 MB — 25% of the client heap — held by HdrHistogram counts arrays before a single message had been sent. Eclipse MAT attributed it to class objects, i.e. static fields:

class PerformanceProducer     88,090,448   8.52%
class PerformanceTransaction  88,084,968   8.52%
class PerformanceConsumer     29,363,080   2.84%
class PerformanceReader       29,362,392   2.84%
class ManagedLedgerWriter     23,073,760   2.23%

Only produce was running. Investigating this turned up two independent problems.

1. The histograms are built at HdrHistogram's maximum precision

All 13 Recorder construction sites in pulsar-testclient used numberOfSignificantValueDigits = 5, which is the maximum the API allows. HdrHistogram sizes a fixed-range histogram's counts array as (bucketsNeeded + 1) * subBucketHalfCount, where subBucketHalfCount = 2^ceil(log2(2 * 10^digits)) / 2 — so each additional digit multiplies the allocation by roughly 10. Measured against HdrHistogram 2.2.2 over the range PerformanceProducer used:

Because these recorders are static fields and PulsarPerfTestTool.initCommander reflectively instantiates every registered subcommand before parsing arguments (PulsarPerfTestTool.java:72, constructor.newInstance()), each class's <clinit> runs on every invocation. So pulsar-perf produce was also paying for transaction, consume, read and managed-ledger — about 170 MB of histograms for commands that never ran.

The 5th digit is not visible anywhere in the output. The microsecond-based tools divide by 1000 and print milliseconds with %7.3f; the millisecond-based tools print whole milliseconds with %d. Over 2M synthetic lognormal samples, 3 vs 5 digits differ by at most 0.088%:

  p50     5-digit=    2.001 ms   3-digit=    2.001 ms   rel.err=0.0000%
  p99     5-digit=   12.840 ms   3-digit=   12.847 ms   rel.err=0.0545%
  p99.99  5-digit=   38.243 ms   3-digit=   38.271 ms   rel.err=0.0732%
  p100    5-digit=  143.872 ms   3-digit=  143.999 ms   rel.err=0.0883%

That is far below the run-to-run variance of a throughput benchmark, and 3 digits is HdrHistogram's own recommended default. The quantization is one-sided upward for percentiles and Max, so reduced precision can only inflate a reported tail, never understate it.

The precision change is also provably incapable of introducing a new ArrayIndexOutOfBoundsException: the throw threshold is a function of the range alone. Measured first-throwing values are byte-identical at 5 and at 3 digits for every range used here.

Note that switching to an auto-resizing Recorder is not the fix: Recorder(int) uses ConcurrentHistogram, which keeps both an active and an inactive counts array. Measured, new Recorder(5) starts at 4.2 MB and grows to 44 MB — twice the fixed-range cost.

2. Two ranges are in the wrong unit, and two record sites can throw

new Recorder(highestTrackableValue, digits) builds a fixed-range histogram that throws ArrayIndexOutOfBoundsException on an out-of-range value. #5786 fixed such a mismatch in PerformanceProducer by switching its range from SECONDS.toMillis(120000) to SECONDS.toMicros(120000), but the same bug was left in place elsewhere:

• ManagedLedgerWriter records latencyMicros (NANOSECONDS.toMicros(...)) into a range of SECONDS.toMillis(120000) = 1.2e8. Its real ceiling is therefore about two minutes, not 120000 seconds. There is no clamp and no handler — the recordValue sits directly in the AddEntryCallback.addComplete callback. Present since the file was added in Added ManagedLedger perf tool #1270.
• SimpleTestProducerSocket (pulsar-perf websocket-producer) has exactly the same mismatch, inside an @OnWebSocketMessage handler. Dates to the initial import.
• PerformanceReader records a wall-clock latencyMillis with only a >= 0 guard. PerformanceConsumer was given an upper clamp in [bug] pulsar-perf consume, do not fail in case of reading data older than 10 days #17160 ("do not fail in case of reading data older than 10 days"); PerformanceReader never was, so reading a sufficiently old backlog throws out of the read loop.

Note that the declared highestTrackableValue is not itself the throw threshold — HdrHistogram rounds the counts array up to the next power-of-two bucket boundary, so each histogram tolerates 12-24% more than its declared range. Measured first-throwing values: 134,217,728 us (134.2 s) for the two mismatched ranges, and 1,073,741,824 ms (12.43 days) for consume/read. The bugs stand; only the exact ceilings differ from the declared ones.

Separately, the 33.3-hour (SECONDS.toMicros(120000)) ceiling on the publish-side recorders is not a meaningful latency bound for a send or an ack. Consume and read keep their 10-day range on purpose, because a backlogged message legitimately can be that old.

3. The same fields are JVM-global for no reason

While fixing the above it became clear the recorders did not need to be static at all, and neither do the 51 LongAdder counters sitting next to them in the same declaration blocks. The only static accessors are printAggregatedStats and printAggregatedThroughput, and those are called from a shutdown-hook lambda that is already constructed inside run():

// PerformanceReader.java:156 — inside run(), the lambda already captures `this`
Thread shutdownHookThread = addShutdownHook(() -> {
    printAggregatedThroughput(start);
    printAggregatedStats();
});

PerformanceProducer and PerformanceConsumer had in fact already made printAggregatedThroughput an instance method, so their counters had no static accessor left.

What the static did cost is 26 defensive reset() calls, under a comment that names the problem:

public void run() throws Exception {
    // Reset static counters to avoid stale state from previous runs in the same JVM
    messagesSent.reset();
    ...

and the compensation is incomplete: PerformanceReader, ManagedLedgerWriter and PerformanceClient have no resets at all, so a second run in the same JVM folds the first run's messages, bytes and latencies into its aggregate stats. PerformanceProducerTest already constructs four PerformanceProducer instances in one JVM.

This is handled here rather than in a follow-up because it is the same fields, in the same declaration blocks, in the same six classes this PR already rewrites — splitting it would mean touching every one of those lines twice for no reviewer benefit.

Modifications

• Add PerfClientUtils.LATENCY_HISTOGRAM_SIGNIFICANT_DIGITS = 3 and use it at all 13 Recorder construction sites, with the sizing rationale documented on the constant.
• Give each publish-side recorder a MAX_LATENCY_MICROS = TimeUnit.HOURS.toMicros(1) ceiling (PerformanceProducer, PerformanceTransaction, ManagedLedgerWriter, SimpleTestProducerSocket) — correcting the unit for the latter two — and clamp with Math.min before recording. Consume/read keep TimeUnit.DAYS.toMillis(10).
• Clamp in PerformanceReader, matching what PerformanceConsumer already does.
• Rename PerformanceConsumer.MAX_LATENCY to MAX_LATENCY_MILLIS; unit-ambiguous names are what allowed this class of bug in the first place.
• Drop the now-unnecessary ArrayIndexOutOfBoundsException branch in PerformanceProducer's exceptionally handler. It was a workaround for the recorder throwing; with clamping it can only mask a genuine error.

And, for the JVM-global state:

• Make all 12 Recorder and 51 LongAdder fields instance fields, and printAggregatedStats / printAggregatedThroughput / printTxnAggregatedThroughput instance methods, across PerformanceProducer, PerformanceConsumer, PerformanceReader, PerformanceTransaction, ManagedLedgerWriter and PerformanceClient.
• Delete the 26 compensating reset() calls; the state now cannot outlive the command object.
• SimpleTestProducerSocket.recorder was the one field with a genuine reason to be shared, since PerformanceClient creates one socket per connection. PerformanceClient now owns the Recorder and injects it through the constructor, which keeps the aggregation while dropping the JVM-global.

That part is a pure refactor with no behaviour change for a single run, and it is net-negative in size (-116 / +81 lines). One piece of mutable static state remains in PerformanceClient (messageFormatter); it is unrelated to the stats and left alone.

Measured effect on the startup allocation for a pulsar-perf produce run (the 14 arrays MAT observed):

  before = 257,956,864 bytes (246.0 MB)
  after  =   2,579,456 bytes (2.46 MB)   -> 100x smaller

Reported percentiles shift by at most ~0.09% (visible only in the third decimal of the millisecond figures); the %d millisecond reports are unchanged for any value below ~2 seconds, where 3-digit buckets are still exact.

This does not address the underlying issue that every subcommand is instantiated at startup. That is worth fixing separately and would recover the ~170 MB attributable to commands that never run. It is also a comparatively recent regression: before #22388 (PIP-343, May 2024) bin/pulsar-perf exec-ed one main class per subcommand (exec $JAVA $OPTS org.apache.pulsar.testclient.PerformanceProducer ...), so only the selected command's <clinit> ran. Registering the subcommand Class objects with picocli instead of pre-built instances would restore that property — picocli defers CommandUserObject.getInstance() until a subcommand is actually selected.

Verifying this change

• Make sure that the change passes the CI checks.

This change added tests and can be verified as follows:

• The de-staticizing is verified by the compiler: had any of the 63 fields genuinely needed to be static, the build would fail. PerformanceProducerTest, which constructs four PerformanceProducer instances in one JVM, passes without the reset calls that previously made that safe.
• Added PerfClientUtilsTest.latencyHistogramsStaySmallAtTheConfiguredPrecision, which asserts that a Recorder built at LATENCY_HISTOGRAM_SIGNIFICANT_DIGITS over each range the perf clients use stays under 512 KB. Verified that it pins the change: it fails with the constant set back to 5 (Expecting actual ... to be less than 524288) and passes at 3.
• The array-sizing figures above were measured by running against HdrHistogram-2.2.2.jar directly, and the three array lengths seen in the heap dump (2,752,512 / 1,835,008 / 1,441,792) reproduce exactly from the declared ranges.
• Also confirmed that this is not a regression from the recent HdrHistogram 2.1.9 -> 2.2.2 bump ([improve][monitor] Upgrade Dropwizard Metrics to 4.2.39 and HdrHistogram to 2.2.2 #26353). Both versions compute byte-identical counts-array sizes for these declarations. If anything the bump helped: in 2.1.9 Recorder allocated both the active and the inactive histogram up front (measured 44,040,224 B per Recorder at construction), whereas 2.2.2 leaves inactiveHistogram null until the first getIntervalHistogram() (22,020,112 B). The same dump taken before [improve][monitor] Upgrade Dropwizard Metrics to 4.2.39 and HdrHistogram to 2.2.2 #26353 would have carried 24 arrays / 427,819,392 B rather than 14 arrays / 257,949,920 B. The ranges and the digit count are the Pulsar-side cause, and they predate both versions.

Does this pull request potentially affect one of the following parts:

If the box was checked, please highlight the changes

• Dependencies (add or upgrade a dependency)
• The public API
• The schema
• The default values of configurations
• The threading model
• The binary protocol
• The REST endpoints
• The admin CLI options
• The metrics
• Anything that affects deployment