[improve][broker] Trace the asynchronous tasks in logs when loading topics by BewareMyPower · Pull Request #26163 · apache/pulsar

BewareMyPower · 2026-07-08T12:14:06Z

Motivation

The topic loading time could be high with pressure, but it's hard to measure which sub-task takes the most time. This is a follow-up work of #24785 to improve the logs that show topic loading latency.

Modifications

Add a simple tracing class LatencyTracer and trace asynchronous futures during topic loading. When tracing a future, if the future is already done, skip tracing it because such tasks are usually not CPU-bounded.

Verifying this change

LatencyTracerTest covers functionality of all public methods with injected timestamps. The topic loading logs can be checked by running testConcurrentLoadTopicExceedLimitShouldNotBeAutoCreated:

Loaded topic {dedupEnabled=false, latency=total: 122 ms, ml-config: 9 ms, open-ml: 58 ms, init: 53 ms, done: 870 us, topic=persistent://prop/concurrentLoad/my-topic_0}
Loaded topic {dedupEnabled=false, latency=total: 19 ms, ml-config: 936 us, open-ml: 17 ms, init: 1 ms, done: 110 us, topic=persistent://prop/concurrentLoad/my-topic_1}
Loaded topic {dedupEnabled=false, latency=total: 20 ms, ml-config: 834 us, open-ml: 18 ms, init: 1 ms, done: 122 us, topic=persistent://prop/concurrentLoad/my-topic_2}
Loaded topic {dedupEnabled=false, latency=total: 4 ms, properties: 2 ms, ml-config: 911 us, open-ml: 89 us, init: 642 us, done: 91 us, topic=persistent://prop/concurrentLoad/my-topic_0}
Loaded topic {dedupEnabled=false, latency=total: 7 ms, queued: 2 ms, properties: 2 ms, ml-config: 692 us, open-ml: 88 us, init: 788 us, done: 147 us, topic=persistent://prop/concurrentLoad/my-topic_1}
Loaded topic {dedupEnabled=false, latency=total: 12 ms, queued: 7 ms, properties: 3 ms, ml-config: 907 us, open-ml: 93 us, init: 634 us, done: 81 us, topic=persistent://prop/concurrentLoad/my-topic_2}

Out of scope

In my previous tests, opening managed ledger could also take much time, this LatencyTracer class can be used to track managed ledger open process as well.

…opics

void-ptr974

Thanks for the improvement! The additional timing details should help with understanding topic-loading latency. I left a couple of minor comments.

…ce() call

BewareMyPower · 2026-07-13T04:16:36Z

Hi, @Denovo1998 @void-ptr974 I've addressed your comments in latest commit with a few improvements, PTAL.

Before that, the tracer requires users to explicitly call trace before calling latencyInMillis() or latencyString(), which is not friendly, so the latest design adopts an efficient CAS call to ensure the last timestamp could be computed lazily with "done" as the stage description.
For thread safety issue, I think it's caused by a bad design of the topic loading timeout mechanism. But I'd like to avoid touching that issue in this PR, so I will simply change TopicLoadingContext's timepoints to a thread safe queue. If the timeout mechanism can be removed in future, it can be changed back to a not thread safe queue like LinkedList.

Denovo1998

Perhaps the implementation can be simpler?

Each time a log or metric needs to be output, call snapshot() once, take the current time as endNs within it, collect only the checkpoints not later than endNs, and then return an immutable LatencySnapshot. Both logs and metrics take values from the same snapshot.

This approach eliminates the need for intermediate states like -1/-2, and reading latency will not inadvertently permanently end the tracer. Even if timeout logs have been printed, the background topic loading can still continue to record subsequent stages.

Additionally, currently, when a timeout occurs, incomplete stages only show something like done: 29999 ms. It's not clear from the logs whether the actual stall is in the system topic, open-ml, or another future. Since the main goal of this PR is to identify which specific stage is consuming time, it's best to record the current action when a future starts and record the end upon completion. This way, the timeout logs can directly indicate at which step the process is stuck.

…end time

BewareMyPower · 2026-07-13T13:22:25Z

I agree that freezing the end time in latencyString or latencyInMillis is not a good idea. I adopted a simplified implementation and completed topicFuture exceptionally when checkNonPartitionedTopicExists fails, could you take a look again? @Denovo1998

BewareMyPower · 2026-07-14T03:23:15Z

@Denovo1998 I pushed a new commit, which unifies the rule of logging when topic loading fails.

All fail paths now go through failTopicFuture, which removes the topic future from cache and triggering the topicFuture.exceptionally that logs the detailed latency trace and exception message.
Some existing warn logs are retained but they won't include latency or exceptional message.

Denovo1998

LGTM!
The remaining concerns are limited to diagnostic reliability rather than topical correctness.

void-ptr974

Thanks for the updates. This fills an observability gap in the core async topic-loading path. Do you have any thoughts on where this tracer would be most useful next? I would be happy to help follow or review related follow-ups if useful.

BewareMyPower · 2026-07-15T03:44:18Z

@void-ptr974 I've used this tracer to follow managed ledger initialization. Because I found after switching to metadata store based topic policies (see PIP-469), the topic loading latency could still be high (1 second or more). The most time consuming part is the managed ledger initialization, where most parts should be ZooKeeper write paths.

BewareMyPower self-assigned this Jul 8, 2026

BewareMyPower added release/4.2.4 release/4.0.13 type/enhancement The enhancements for the existing features or docs. e.g. reduce memory usage of the delayed messages area/broker labels Jul 8, 2026

BewareMyPower requested review from Technoboy-, codelipenghui, coderzc, dao-jun, merlimat, nodece and shibd July 8, 2026 12:14

BewareMyPower marked this pull request as draft July 8, 2026 12:16

BewareMyPower marked this pull request as ready for review July 8, 2026 12:29

BewareMyPower closed this Jul 9, 2026

BewareMyPower reopened this Jul 9, 2026

BewareMyPower added this to the 5.0.0-M2 milestone Jul 9, 2026

BewareMyPower added 3 commits July 9, 2026 13:14

[improve][broker] Trace the asynchronous tasks in logs when loading t…

b8c1805

…opics

improve LatencyTracer implementation

dbb036e

move to pulsar-common

7ed63b7

BewareMyPower force-pushed the bewaremypower/topic-load-tracing branch from 0cf2bee to 7ed63b7 Compare July 9, 2026 05:14

dao-jun approved these changes Jul 9, 2026

View reviewed changes

void-ptr974 reviewed Jul 11, 2026

View reviewed changes

Comment thread pulsar-broker/src/main/java/org/apache/pulsar/broker/service/TopicLoadingContext.java Outdated

Comment thread pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java Outdated

Denovo1998 suggested changes Jul 12, 2026

View reviewed changes

Comment thread pulsar-common/src/main/java/org/apache/pulsar/common/util/LatencyTracer.java Outdated

BewareMyPower marked this pull request as draft July 13, 2026 02:51

BewareMyPower added 2 commits July 13, 2026 12:10

make latency tracer pluggable and not require an explicit markEnd tra…

d98b1b4

…ce() call

Merge branch 'master' into bewaremypower/topic-load-tracing

ccbcfdf

BewareMyPower marked this pull request as ready for review July 13, 2026 04:11

change some logs to use latencyString

9f15124

Denovo1998 suggested changes Jul 13, 2026

View reviewed changes

Comment thread pulsar-common/src/main/java/org/apache/pulsar/common/util/LatencyTracer.java

Comment thread pulsar-common/src/main/java/org/apache/pulsar/common/util/LatencyTracer.java Outdated

Comment thread pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java

simplify the implementation and remove confusing semantic of setting …

de9e6a7

…end time

Denovo1998 suggested changes Jul 13, 2026

View reviewed changes

improve logging

b32c02e

Denovo1998 approved these changes Jul 14, 2026

View reviewed changes

void-ptr974 approved these changes Jul 14, 2026

View reviewed changes

BewareMyPower merged commit 29028de into apache:master Jul 15, 2026
43 checks passed

BewareMyPower deleted the bewaremypower/topic-load-tracing branch July 15, 2026 03:44

Uh oh!

Conversation

BewareMyPower commented Jul 8, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Motivation

Modifications

Verifying this change

Out of scope

Uh oh!

void-ptr974 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

BewareMyPower commented Jul 13, 2026

Uh oh!

Denovo1998 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

BewareMyPower commented Jul 13, 2026

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

BewareMyPower commented Jul 14, 2026

Uh oh!

Denovo1998 left a comment

Choose a reason for hiding this comment

Uh oh!

void-ptr974 left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BewareMyPower commented Jul 15, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

BewareMyPower commented Jul 8, 2026 •

edited

Loading

void-ptr974 left a comment •

edited

Loading