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/10/27 11:51:02 UTC
[I] [Bug] Broker close time is too long even if there is no connection [pulsar]
BewareMyPower opened a new issue, #24894:
URL: https://github.com/apache/pulsar/issues/24894
### Search before reporting
- [x] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.
### Read release policy
- [x] I understand that [unsupported versions](https://pulsar.apache.org/contribute/release-policy/#supported-versions) don't get bug fixes. I will attempt to reproduce the issue on a supported version of Pulsar client and Pulsar broker.
### User environment
commit: 14b08210a02a4cd7dcffdd941a27d9fd7092a2d4
### Issue Description
When I restarted a broker with only 1 producer connected, I found the close time was too long.
Logs:
```
2025-10-10T13:33:34,985+0000 [pulsar-service-shutdown] INFO ProducerIdManagerImpl - Shutdown complete: last producerId assigned 1479
2025-10-10T13:33:39,033+0000 [pulsar-service-shutdown] INFO PulsarService - Closing PulsarService
2025-10-10T13:33:41,601+0000 [pulsar-service-shutdown] INFO BrokerService - Disable broker in load manager completed in 2.555 seconds
2025-10-10T13:33:41,673+0000 [pulsar-service-shutdown] INFO BrokerService - Shutting down Pulsar Broker service
2025-10-10T13:33:46,992+0000 [BrokerService-shutdown-phase2] INFO BrokerService - Continuing to second phase in shutdown.
```
- Protocol handlers close: 4.048 s
- Disable load manager: 2.567 s
- Closing other tasks before starting closing `BrokerService`: 0.072 s
- Shut down all event loops: 5.319 s
The main close time come from closing event loops gracefully.
### Error messages
```text
```
### Reproducing the issue
```java
import java.util.Optional;
import java.util.concurrent.TimeUnit;
import java.util.function.Supplier;
import lombok.Cleanup;
import org.apache.pulsar.broker.PulsarService;
import org.apache.pulsar.broker.ServiceConfiguration;
import org.apache.pulsar.zookeeper.LocalBookkeeperEnsemble;
import org.testng.Assert;
import org.testng.annotations.AfterClass;
import org.testng.annotations.BeforeClass;
import org.testng.annotations.Test;
@Test
public class BrokerEventLoopShutdownTest {
private LocalBookkeeperEnsemble bk;
@BeforeClass(alwaysRun = true)
public void setup() throws Exception {
bk = new LocalBookkeeperEnsemble(2, 0, () -> 0);
bk.start();
}
@AfterClass(alwaysRun = true, timeOut = 30000)
public void cleanup() throws Exception {
bk.stop();
}
@Test(timeOut = 60000)
public void testCloseOneBroker() throws Exception {
final var clusterName = "test";
final Supplier<ServiceConfiguration> configSupplier = () -> {
final var config = new ServiceConfiguration();
config.setClusterName(clusterName);
config.setAdvertisedAddress("localhost");
config.setBrokerServicePort(Optional.of(0));
config.setWebServicePort(Optional.of(0));
config.setMetadataStoreUrl("zk:127.0.0.1:" + bk.getZookeeperPort());
return config;
};
@Cleanup final var broker0 = new PulsarService(configSupplier.get());
@Cleanup final var broker1 = new PulsarService(configSupplier.get());
broker0.start();
broker1.start();
final var startNs = System.nanoTime();
broker0.close();
final var closeTimeMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
Assert.assertTrue(closeTimeMs < 1000, "close time: " + closeTimeMs + " ms");
}
}
```
Outputs:
```
java.lang.AssertionError: close time: 5132 ms
```
It can be reproduced by the simple test above added to `pulsar-broker`. As you can see, even though the `close()` method is called immediately after `start()`, it still take 5+ seconds to complete.
### Additional information
_No response_
### Are you willing to submit a PR?
- [x] I'm willing to submit a PR!
--
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.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Broker close time is too long even if there is no connection [pulsar]
Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari closed issue #24894: [Bug] Broker close time is too long even if there is no connection
URL: https://github.com/apache/pulsar/issues/24894
--
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: [I] [Bug] Broker close time is too long even if there is no connection [pulsar]
Posted by "BewareMyPower (via GitHub)" <gi...@apache.org>.
BewareMyPower commented on issue #24894:
URL: https://github.com/apache/pulsar/issues/24894#issuecomment-3450985038
The root cause is that Pulsar uses the configured `brokerShutdownTimeoutMs` to determine the 1st argument passed to `EventExecutorGroup#shutdownGracefully`.
https://github.com/apache/pulsar/blob/7c6a4aae336a631e0b88998cf54c656c2f193ba4/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L209-L211
https://github.com/apache/pulsar/blob/7c6a4aae336a631e0b88998cf54c656c2f193ba4/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/BrokerService.java#L964-L973
When `brokerShutdownTimeoutMs` is greater than 20000, the 1st argument will be 5000.
This parameter represents the period to check if there was a new task executed since when the last task finished. See https://github.com/netty/netty/blob/6bb1a6bcae503423343b9155ac48b161f60368b5/common/src/main/java/io/netty/util/concurrent/SingleThreadEventExecutor.java#L785
```java
if (nanoTime - lastExecutionTime <= gracefulShutdownQuietPeriod) {
// Check if any tasks were added to the queue every 100ms.
// TODO: Change the behavior of takeTask() so that it returns on timeout.
taskQueue.offer(WAKEUP_TASK);
try {
Thread.sleep(100);
} catch (InterruptedException e) {
// Ignore
}
return false;
}
```
i.e. assuming the 1st argument is 5000, if the last task finished at `t` and `confirmShutdown` was called at `t + 1ms`, then it would sleep for 100 ms in a loop for at least 50 times so that the current time is greater than `t + 5000`.
Here is a simple test to verify the behavior:
```java
@Test
public void test() {
final SingleThreadEventExecutor executor = new DefaultEventExecutor();
executor.execute(new Runnable() {
@Override
public void run() {
System.out.println(Thread.currentThread() + " " + System.currentTimeMillis() + " started");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
throw new IllegalStateException(e);
}
System.out.println(Thread.currentThread() + " " + System.currentTimeMillis() + " finished");
}
});
final long startNs = System.nanoTime();
executor.shutdownGracefully(5000, 10000, TimeUnit.MILLISECONDS).syncUninterruptibly();
final long elapsedMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
System.out.println(Thread.currentThread() + " " + System.currentTimeMillis() + " shutdown: "
+ elapsedMs + " ms");
}
```
Outputs:
```
Thread[defaultEventExecutor-1-1,5,main] 1761566989756 started
Thread[defaultEventExecutor-1-1,5,main] 1761566990761 finished
Thread[main,5,main] 1761566995846 shutdown: 6090 ms
```
Pulsar's `EventLoop` object created by `EventLoopUtils#newEventLoopGroup` uses `NioEventLoop` as the executor, which does not change the `confirmShutdown` and `shutdownGracefully` methods from the `SingleThreadEventExecutor` base class.
--
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