You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by "BewareMyPower (via GitHub)" <gi...@apache.org> on 2025/09/25 11:53:52 UTC

[PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

BewareMyPower opened a new pull request, #24785:
URL: https://github.com/apache/pulsar/pull/24785

   ### Motivation
   
   The topic loading timeout starts at `loadOrCreatePersistentTopic`: https://github.com/apache/pulsar/blob/46a76e98d6a6f2a86839d93467c5337bb205f851/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L1661-L1663
   
   However, there could be two asynchronous tasks before that:
   
   1. Check if the topic exists
   
   https://github.com/apache/pulsar/blob/46a76e98d6a6f2a86839d93467c5337bb205f851/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L1165
   
   2. Get the topic policies (`__change_events` topic will be replayed)
   
   https://github.com/apache/pulsar/blob/46a76e98d6a6f2a86839d93467c5337bb205f851/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L1171
   
   The 1st task should be okay in most time, but the 2nd task could be time-consuming and risky. I have seen when replaying `__change_events` topic was stuck in production env. If this case happens, there is no metric or log and it can be only aware  from client side.
   
   P.S. as the comment shows, it actually does not make sense to execute the 2nd task here but I want to improve the topic loading process in other PRs.
   
   The topic loading metric (`pulsar_topic_load_times`) starts even later at `createPersistent0`: https://github.com/apache/pulsar/blob/46a76e98d6a6f2a86839d93467c5337bb205f851/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L1769
   
   It does not even include the time when the topic loading is in `BrokerService#pendingTopicLoadingQueue`, which happens when the number of pending topic loading tasks exceeds the `maxConcurrentTopicLoadRequest` config.
   
   ### Modifications
   
   - Refactor `TopicLoadingContext` to add latency info and create this context from the beginning before `checkNonPartitionedTopicExists`, so the latency could include the time before `createPersistent0`
   - Log latency when the topic is loaded successfully or fails to load, specially, if the topic has been added to the pending queue due to `maxConcurrentTopicLoadRequest` limitation, log the pending time as well
   
   ### Verifying this change
   
   - [x] Make sure that the change passes the CI checks.
   
   Here are example outputs from `BrokerServiceTest.testConcurrentLoadTopicExceedLimitShouldNotBeAutoCreated`
   
   ```
   Created topic persistent://prop/concurrentLoad/my-topic_0 - dedup is disabled (latency: 156 ms)
   Created topic persistent://prop/concurrentLoad/my-topic_1 - dedup is disabled (latency: 20 ms)
   Created topic persistent://prop/concurrentLoad/my-topic_2 - dedup is disabled (latency: 20 ms)
   Created topic persistent://prop/concurrentLoad/my-topic_0 - dedup is disabled (latency: 4 ms)
   Created topic persistent://prop/concurrentLoad/my-topic_1 - dedup is disabled (latency: 7 ms (queued: 3))
   Created topic persistent://prop/concurrentLoad/my-topic_2 - dedup is disabled (latency: 12 ms (queued: 7))
   ```
   
   `queued` means how long it stays in `pendingTopicLoadingQueue`. 
   
   ### Does this pull request potentially affect one of the following parts:
   
   <!-- DO NOT REMOVE THIS SECTION. CHECK THE PROPER BOX ONLY. -->
   
   *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
   - [x] The metrics
   - [ ] Anything that affects deployment
   
   ### Documentation
   
   <!-- DO NOT REMOVE THIS SECTION. CHECK THE PROPER BOX ONLY. -->
   
   - [ ] `doc` <!-- Your PR contains doc changes. -->
   - [ ] `doc-required` <!-- Your PR changes impact docs and you will update later -->
   - [x] `doc-not-needed` <!-- Your PR changes do not impact docs -->
   - [ ] `doc-complete` <!-- Docs have been already added -->
   
   ### Matching PR in forked repository
   
   PR in forked repository: <!-- ENTER URL HERE -->
   
   <!--
   After opening this PR, the build in apache/pulsar will fail and instructions will
   be provided for opening a PR in the PR author's forked repository.
   
   apache/pulsar pull requests should be first tested in your own fork since the 
   apache/pulsar CI based on GitHub Actions has constrained resources and quota.
   GitHub Actions provides separate quota for pull requests that are executed in 
   a forked repository.
   
   The tests will be run in the forked repository until all PR review comments have
   been handled, the tests pass and the PR is approved by a reviewer.
   -->
   


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "BewareMyPower (via GitHub)" <gi...@apache.org>.
BewareMyPower commented on code in PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#discussion_r2386807684


##########
pulsar-broker/src/main/java/org/apache/pulsar/broker/service/TopicLoadingContext.java:
##########
@@ -0,0 +1,65 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.pulsar.broker.service;
+
+import java.util.Map;
+import java.util.Optional;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.TimeUnit;
+import lombok.Getter;
+import lombok.RequiredArgsConstructor;
+import lombok.Setter;
+import org.apache.pulsar.common.naming.TopicName;
+import org.jspecify.annotations.Nullable;
+
+@RequiredArgsConstructor
+public class TopicLoadingContext {
+
+    private static final String EXAMPLE_LATENCY_OUTPUTS = "1234 ms (queued: 567)";
+
+    private final long startNs = System.nanoTime();
+    @Getter
+    private final TopicName topicName;
+    @Getter
+    private final boolean createIfMissing;
+    @Getter
+    private final CompletableFuture<Optional<Topic>> topicFuture;
+    @Getter
+    @Setter
+    @Nullable private Map<String, String> properties;
+    private long polledFromQueueNs = -1L;
+
+    public void polledFromQueue() {
+        polledFromQueueNs = System.nanoTime();
+    }
+
+    public long latencyMs(long nowInNanos) {
+        return TimeUnit.NANOSECONDS.toMillis(nowInNanos - startNs);
+    }
+

Review Comment:
   Adding a time to avoid calling `System.nanoTime()` twice.
   
   ```java
   long nowInNanos = System.nanoTime();
   long topicLoadLatencyMs = context.latencyMs(nowInNanos);
   log.info("Created topic {} - dedup is {} (latency: {})", topic,
           persistentTopic.isDeduplicationEnabled() ? "enabled" : "disabled",
           context.latencyString(nowInNanos));
   ```



-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "Demogorgon314 (via GitHub)" <gi...@apache.org>.
Demogorgon314 commented on code in PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#discussion_r2384875166


##########
pulsar-broker/src/main/java/org/apache/pulsar/broker/service/TopicLoadingContext.java:
##########
@@ -0,0 +1,65 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.pulsar.broker.service;
+
+import java.util.Map;
+import java.util.Optional;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.TimeUnit;
+import lombok.Getter;
+import lombok.RequiredArgsConstructor;
+import lombok.Setter;
+import org.apache.pulsar.common.naming.TopicName;
+import org.jspecify.annotations.Nullable;
+
+@RequiredArgsConstructor
+public class TopicLoadingContext {
+
+    private static final String EXAMPLE_LATENCY_OUTPUTS = "1234 ms (queued: 567)";
+
+    private final long startNs = System.nanoTime();
+    @Getter
+    private final TopicName topicName;
+    @Getter
+    private final boolean createIfMissing;
+    @Getter
+    private final CompletableFuture<Optional<Topic>> topicFuture;
+    @Getter
+    @Setter
+    @Nullable private Map<String, String> properties;
+    private long polledFromQueueNs = -1L;
+
+    public void polledFromQueue() {
+        polledFromQueueNs = System.nanoTime();
+    }
+
+    public long latencyMs(long nowInNanos) {
+        return TimeUnit.NANOSECONDS.toMillis(nowInNanos - startNs);
+    }
+

Review Comment:
   Can we add a no-arg method here?
   ```
       public long latencyMs() {
           return latencyMs(System.nanoTime());
       }
   ```



##########
pulsar-broker/src/main/java/org/apache/pulsar/broker/service/TopicLoadingContext.java:
##########
@@ -0,0 +1,65 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.pulsar.broker.service;
+
+import java.util.Map;
+import java.util.Optional;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.TimeUnit;
+import lombok.Getter;
+import lombok.RequiredArgsConstructor;
+import lombok.Setter;
+import org.apache.pulsar.common.naming.TopicName;
+import org.jspecify.annotations.Nullable;
+
+@RequiredArgsConstructor
+public class TopicLoadingContext {
+
+    private static final String EXAMPLE_LATENCY_OUTPUTS = "1234 ms (queued: 567)";
+
+    private final long startNs = System.nanoTime();
+    @Getter
+    private final TopicName topicName;
+    @Getter
+    private final boolean createIfMissing;
+    @Getter
+    private final CompletableFuture<Optional<Topic>> topicFuture;
+    @Getter
+    @Setter
+    @Nullable private Map<String, String> properties;
+    private long polledFromQueueNs = -1L;
+
+    public void polledFromQueue() {
+        polledFromQueueNs = System.nanoTime();
+    }
+
+    public long latencyMs(long nowInNanos) {
+        return TimeUnit.NANOSECONDS.toMillis(nowInNanos - startNs);
+    }
+
+    public String latencyString(long nowInNanos) {
+        final var builder = new StringBuilder(EXAMPLE_LATENCY_OUTPUTS.length());
+        builder.append(latencyMs(nowInNanos));
+        builder.append(" ms");
+        if (polledFromQueueNs >= 0) {
+            builder.append(" (queued: ").append(TimeUnit.NANOSECONDS.toMillis(polledFromQueueNs - startNs)).append(")");

Review Comment:
   ```suggestion
               builder.append(" (queued: ").append(latencyMs(polledFromQueueNs)).append(")");
   ```



##########
pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java:
##########
@@ -1142,25 +1143,60 @@ public CompletableFuture<Optional<Topic>> getTopic(final TopicName topicName, bo
                     return FutureUtil.failedFuture(new NotAllowedException(
                             "Broker is unable to load persistent topic"));
                 }
-                return checkNonPartitionedTopicExists(topicName).thenCompose(exists -> {
+                final CompletableFuture<Optional<Topic>> topicFuture = FutureUtil.createFutureWithTimeout(
+                        Duration.ofSeconds(pulsar.getConfiguration().getTopicLoadTimeoutSeconds()), executor(),
+                        () -> FAILED_TO_LOAD_TOPIC_TIMEOUT_EXCEPTION);
+                final var context = new TopicLoadingContext(topicName, createIfMissing, topicFuture);
+                if (properties != null) {
+                    context.setProperties(properties);
+                }
+                topicFuture.exceptionally(t -> {
+                    if (FutureUtil.unwrapCompletionException(t) instanceof TimeoutException) {
+                        log.warn("Failed to load {} after {}", topicName, context.latencyMs(System.nanoTime()));

Review Comment:
   ```suggestion
                           log.warn("Failed to load {} after {} ms", topicName, context.latencyMs(System.nanoTime()));
   ```



-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "BewareMyPower (via GitHub)" <gi...@apache.org>.
BewareMyPower commented on PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#issuecomment-3381127303

   The cherry-picking is done. But when I cherry-picked this PR, I found a regression of this PR that if the topic policies failed to get, the topic loading future won't be complete. I will push a fix soon.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "BewareMyPower (via GitHub)" <gi...@apache.org>.
BewareMyPower commented on PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#issuecomment-3380385371

   Sure, I will do that


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "codecov-commenter (via GitHub)" <gi...@apache.org>.
codecov-commenter commented on PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#issuecomment-3347698071

   ## [Codecov](https://app.codecov.io/gh/apache/pulsar/pull/24785?dropdown=coverage&src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) Report
   :white_check_mark: All modified and coverable lines are covered by tests.
   :white_check_mark: Project coverage is 74.20%. Comparing base ([`1050f48`](https://app.codecov.io/gh/apache/pulsar/commit/1050f48035c97a14094b812467f046f6d37ff6f4?dropdown=coverage&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache)) to head ([`8e50c15`](https://app.codecov.io/gh/apache/pulsar/commit/8e50c15be29d8221273072ccabbdf7ff03ed0f80?dropdown=coverage&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache)).
   :warning: Report is 4 commits behind head on master.
   
   <details><summary>Additional details and impacted files</summary>
   
   
   
   [![Impacted file tree graph](https://app.codecov.io/gh/apache/pulsar/pull/24785/graphs/tree.svg?width=650&height=150&src=pr&token=acYqCpsK9J&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache)](https://app.codecov.io/gh/apache/pulsar/pull/24785?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache)
   
   ```diff
   @@              Coverage Diff              @@
   ##             master   #24785       +/-   ##
   =============================================
   + Coverage     38.67%   74.20%   +35.53%     
   - Complexity    13237    33387    +20150     
   =============================================
     Files          1850     1912       +62     
     Lines        144540   149072     +4532     
     Branches      16763    17299      +536     
   =============================================
   + Hits          55895   110620    +54725     
   + Misses        81156    29608    -51548     
   - Partials       7489     8844     +1355     
   ```
   
   | [Flag](https://app.codecov.io/gh/apache/pulsar/pull/24785/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) | Coverage Δ | |
   |---|---|---|
   | [inttests](https://app.codecov.io/gh/apache/pulsar/pull/24785/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) | `26.60% <83.58%> (-0.09%)` | :arrow_down: |
   | [systests](https://app.codecov.io/gh/apache/pulsar/pull/24785/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) | `22.75% <73.13%> (-0.06%)` | :arrow_down: |
   | [unittests](https://app.codecov.io/gh/apache/pulsar/pull/24785/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) | `73.73% <100.00%> (+38.86%)` | :arrow_up: |
   
   Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache#carryforward-flags-in-the-pull-request-comment) to find out more.
   
   | [Files with missing lines](https://app.codecov.io/gh/apache/pulsar/pull/24785?dropdown=coverage&src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache) | Coverage Δ | |
   |---|---|---|
   | [...rg/apache/pulsar/broker/service/BrokerService.java](https://app.codecov.io/gh/apache/pulsar/pull/24785?src=pr&el=tree&filepath=pulsar-broker%2Fsrc%2Fmain%2Fjava%2Forg%2Fapache%2Fpulsar%2Fbroker%2Fservice%2FBrokerService.java&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache#diff-cHVsc2FyLWJyb2tlci9zcmMvbWFpbi9qYXZhL29yZy9hcGFjaGUvcHVsc2FyL2Jyb2tlci9zZXJ2aWNlL0Jyb2tlclNlcnZpY2UuamF2YQ==) | `83.28% <100.00%> (+25.36%)` | :arrow_up: |
   | [...che/pulsar/broker/service/TopicLoadingContext.java](https://app.codecov.io/gh/apache/pulsar/pull/24785?src=pr&el=tree&filepath=pulsar-broker%2Fsrc%2Fmain%2Fjava%2Forg%2Fapache%2Fpulsar%2Fbroker%2Fservice%2FTopicLoadingContext.java&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache#diff-cHVsc2FyLWJyb2tlci9zcmMvbWFpbi9qYXZhL29yZy9hcGFjaGUvcHVsc2FyL2Jyb2tlci9zZXJ2aWNlL1RvcGljTG9hZGluZ0NvbnRleHQuamF2YQ==) | `100.00% <100.00%> (ø)` | |
   
   ... and [1410 files with indirect coverage changes](https://app.codecov.io/gh/apache/pulsar/pull/24785/indirect-changes?src=pr&el=tree-more&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=apache)
   </details>
   <details><summary> :rocket: New features to boost your workflow: </summary>
   
   - :snowflake: [Test Analytics](https://docs.codecov.com/docs/test-analytics): Detect flaky tests, report on failures, and find test suite problems.
   - :package: [JS Bundle Analysis](https://docs.codecov.com/docs/javascript-bundle-analysis): Save yourself from yourself by tracking and limiting bundle sizes in JS merges.
   </details>


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "Technoboy- (via GitHub)" <gi...@apache.org>.
Technoboy- merged PR #24785:
URL: https://github.com/apache/pulsar/pull/24785


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] [fix][broker] Fix incorrect topic loading latency metric and timeout might not be respected [pulsar]

Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari commented on PR #24785:
URL: https://github.com/apache/pulsar/pull/24785#issuecomment-3380064883

   @BewareMyPower There are some merge conflicts when cherry-picking this to branch-4.0. Could you please handle cherry-picking to branch-4.0? Perhaps there are some dependent PRs that need to be cherry-pick or there's a need to backport. 


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org