Reorder the sequence of the bookkeeper server shutdown so that there are no read/ write ops while shutting down the bookie #2888

pradeepbn · 2021-11-10T08:27:13Z

Descriptions of the changes in this PR:

Motivation

After the readcache has been shutdown, all the buffers will be released in memory. In the meantime, if read and write ops are performed on the read cache, then it results in the segmentation fault on invalid memory. So, this PR will shutdown the request processor that does readops and writeops before the bookie shutdown sequence.

Changes

Stop all the requestProcessor threads before bookie shutdown sequence to avoid read/write ops during bookie shutdown
Force shutdown the executors so that it is ensured to stop all executor threads before bookie shutdown.

How to reproduce

Apply this diff https://gist.github.com/pradeepbn/a033cae7171f9e6da9a7f92737f843b9 on the master branch to reproduce the issue
Use this (https://gist.github.com/pradeepbn/65ef387a164953fb3f90057860b12da1) client to pump traffic and initiate reads
Wait until the console shows Waiting for reads to be done and kill the bookie with ctrl+c

…are no read/ write ops while shutting down the bookie

Vanlightly · 2021-11-10T11:12:26Z

The order of the shutdown looks good. One significant problem is that the shutdown of the OrderExecutors was not done quite right, causing the shutdown to block for a significant time period (1000 seconds x number of total threads).

The forceShutdown method should only be called after having called shutdown() as what forceShutdown does is simply wait for the ExecutorService to terminate, for those 1000 seconds calling shutdownNow() if the timeout is reached. Because shutdown() wasn't called first the ExecutorService is still running normally. So you need to ensure that service.shutdown() is called first.

I would also say 1000 seconds is quite high, this is the upper bound for each thread, called serially. If we call shutdown() on all executors first, then we could time box the total time we're willing to wait for all executors to be terminated.

… active before sending response because it can be closed while responding; make bookie process as PID=1 in docker so that it can receive SIGINT

docker/scripts/entrypoint.sh

pradeepbn · 2021-11-16T01:36:07Z

The order of the shutdown looks good. One significant problem is that the shutdown of the OrderExecutors was not done quite right, causing the shutdown to block for a significant time period (1000 seconds x number of total threads).

The forceShutdown method should only be called after having called shutdown() as what forceShutdown does is simply wait for the ExecutorService to terminate, for those 1000 seconds calling shutdownNow() if the timeout is reached. Because shutdown() wasn't called first the ExecutorService is still running normally. So you need to ensure that service.shutdown() is called first.

I would also say 1000 seconds is quite high, this is the upper bound for each thread, called serially. If we call shutdown() on all executors first, then we could time box the total time we're willing to wait for all executors to be terminated.

@Vanlightly as discussed bumped it down to 10 seconds. By the time the first thread in the sequence is flushed, we expect other threads to have flushed as well. So, the max upper bound will be 10 + 5s.

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestProcessor.java

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBaseV3.java

…time of the closure

Vanlightly

LGTM

Vanlightly · 2021-11-22T09:02:48Z

@eolivelli could you review?

eolivelli · 2021-11-22T09:39:35Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBaseV3.java

-                    statsLogger.registerSuccessfulEvent(MathUtils.elapsedNanos(enqueueNanos), TimeUnit.NANOSECONDS);
-                } else {
-                    statsLogger.registerFailedEvent(MathUtils.elapsedNanos(enqueueNanos), TimeUnit.NANOSECONDS);
+        if (channel.isActive()) {


what about adding a "ELSE" branch with a log message ?

eolivelli · 2021-11-22T09:39:43Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBase.java


    protected void sendResponse(int rc, Object response, OpStatsLogger statsLogger) {
-        channel.writeAndFlush(response, channel.voidPromise());
+        if (channel.isActive()) {


what about adding a "ELSE" branch with a log message ?

Currently what happens when the BookieServer is shutdown is that for each in-progress op, when the response is sent it will fail because the channel is closed, and that will get logged as a metric:

if (!future.isSuccess()) { requestProcessor.getRequestStats().getChannelWriteStats() .registerFailedEvent(writeElapsedNanos, TimeUnit.NANOSECONDS); } else { requestProcessor.getRequestStats().getChannelWriteStats() .registerSuccessfulEvent(writeElapsedNanos, TimeUnit.NANOSECONDS); }

So either we add an ELSE branch with the same registerFailedEvent call, or we don't use an IF at all and allow it to use the existing logic flow.

@pradeepbn what was the reason for avoiding channel.writeAndFlush?

I'd say this change is not strictly related to shutdown reordering, so I think removing these channel checks can be removed from this PR.

@Vanlightly

bookie1_1 | 02:15:08,926 ERROR Failed to submit a listener notification task. Event loop shut down? bookie1_1 | java.util.concurrent.RejectedExecutionException: event executor terminated bookie1_1 | at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:923) ~[netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.SingleThreadEventExecutor.offerTask(SingleThreadEventExecutor.java:350) ~[netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:343) ~[netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:825) ~[netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:815) ~[netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.DefaultPromise.safeExecute(DefaultPromise.java:841) [netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:499) [netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:184) [netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:95) [netty-transport-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:30) [netty-transport-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at org.apache.bookkeeper.proto.PacketProcessorBaseV3.sendResponse(PacketProcessorBaseV3.java:91) [bookkeeper-server.jar:?] bookie1_1 | at org.apache.bookkeeper.proto.WriteEntryProcessorV3.sendResponse(WriteEntryProcessorV3.java:180) [bookkeeper-server.jar:?] bookie1_1 | at org.apache.bookkeeper.proto.WriteEntryProcessorV3$1.writeComplete(WriteEntryProcessorV3.java:108) [bookkeeper-server.jar:?] bookie1_1 | at org.apache.bookkeeper.bookie.Journal$QueueEntry.run(Journal.java:335) [bookkeeper-server.jar:?] bookie1_1 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] bookie1_1 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] bookie1_1 | at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.68.Final.jar:4.1.68.Final] bookie1_1 | at java.lang.Thread.run(Thread.java:829) [?:?]

If we do not check for isActive(), we will get this exception on channel.writeAndFlush at the time of shutdown. This happens because of nettyserver shutdown before the request processor.

This is a controlled exception within Netty but it will pollute the log during shutdown. So I think that's its worth keeping the IF statement. What do you think @eolivelli?

ok, let's keep the original "if"

we could add an "else" branch with a DEBUG log that says that we are skipping the write, this would help in debugging tests failures probably one day

Added the else statement with the logs. CC: @eolivelli @Vanlightly

…Flush

pradeepbn · 2021-11-23T19:41:02Z

rerun failed checks

pradeepbn · 2021-11-23T19:43:34Z

rerun failure checks

eolivelli · 2021-11-30T07:52:40Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBase.java

+        if (channel.isActive()) {
+            channel.writeAndFlush(response, channel.voidPromise());
+        } else {
+            LOGGER.info("Netty channel is inactive, hence bypassing netty channel writeAndFlush during sendResponse");


please report the channel(), it will bring useful information about the client that won't receive the response.
please use "debug" and not "info"

@eolivelli Changed it. As an example, it prints like this: Netty channel [id: 0x8f9a1f37, L:/192.168.160.3:3181 ! R:/192.168.160.1:61752] is inactive, hence bypassing netty channel writeAndFlush during sendResponse

… inactive during sendResponse()

eolivelli

LGTM

Reorders the sequence of the bookkeeper server shutdown so that any in-progress reads or writes don't hit ledger storage after it has been shutdown. Now the request processor is shutdown before the bookie. An additional check if the channel is active is performed in the packet processor callbacks before sending response to avoid RejectedExecutionException messages within Netty from polluting the log. (cherry picked from commit 7395bb4)

zymap · 2022-06-16T01:19:54Z

cherry-picked this to branch-4.14 to resolve the conflict

Reorders the sequence of the bookkeeper server shutdown so that any in-progress reads or writes don't hit ledger storage after it has been shutdown. Now the request processor is shutdown before the bookie. An additional check if the channel is active is performed in the packet processor callbacks before sending response to avoid RejectedExecutionException messages within Netty from polluting the log. (cherry picked from commit 7395bb4) (cherry picked from commit f8eb20d)

Reorders the sequence of the bookkeeper server shutdown so that any in-progress reads or writes don't hit ledger storage after it has been shutdown. Now the request processor is shutdown before the bookie. An additional check if the channel is active is performed in the packet processor callbacks before sending response to avoid RejectedExecutionException messages within Netty from polluting the log.

Reorder the sequence of the bookkeeper server shutdown so that there …

9f00279

…are no read/ write ops while shutting down the bookie

pradeepbn marked this pull request as draft November 10, 2021 08:30

pradeepbn mentioned this pull request Nov 10, 2021

Readops and writeops for the read cache are disabled after the readcache has been shutdown #2868

Closed

Fix the force shutdown on the requestProcess; Check if the channel is…

7fec12a

… active before sending response because it can be closed while responding; make bookie process as PID=1 in docker so that it can receive SIGINT

Vanlightly reviewed Nov 12, 2021

View reviewed changes

docker/scripts/entrypoint.sh Outdated Show resolved Hide resolved

Revert the Dockefile changes

66b2513

hsaputra reviewed Nov 16, 2021

View reviewed changes

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestProcessor.java Show resolved Hide resolved

Vanlightly reviewed Nov 16, 2021

View reviewed changes

bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBaseV3.java Show resolved Hide resolved

Add channel.isActive() mock

5a29761

pradeepbn marked this pull request as ready for review November 18, 2021 02:05

pradeepbn added 2 commits November 17, 2021 19:18

Revert nettyServer shutdown sequence

f8c2525

Added a log statement at the close of request processor for tracking …

b7908b9

…time of the closure

Vanlightly approved these changes Nov 19, 2021

View reviewed changes

eolivelli reviewed Nov 22, 2021

View reviewed changes

Adding logs when the netty channel is inactive to bypass the writeAnd…

e6b5501

…Flush

pradeepbn requested a review from eolivelli November 23, 2021 18:52

eolivelli reviewed Nov 30, 2021

View reviewed changes

pradeepbn force-pushed the ReorgShutdownSeq branch from f3a8f07 to b0b7e9c Compare November 30, 2021 20:36

Adding the channel information to the debug logs while the channel is…

15abe17

… inactive during sendResponse()

pradeepbn force-pushed the ReorgShutdownSeq branch from b0b7e9c to 15abe17 Compare November 30, 2021 22:29

pradeepbn requested a review from eolivelli December 1, 2021 01:57

eolivelli approved these changes Dec 1, 2021

View reviewed changes

Vanlightly merged commit 7395bb4 into apache:master Dec 1, 2021

zymap assigned pradeepbn Jun 16, 2022

zymap added the release/4.14.6 label Jun 16, 2022

hangc0276 added the cherry-picked/branch-4.14 label Nov 5, 2022

Reorder the sequence of the bookkeeper server shutdown so that there are no read/ write ops while shutting down the bookie #2888

Reorder the sequence of the bookkeeper server shutdown so that there are no read/ write ops while shutting down the bookie #2888

Uh oh!

Conversation

pradeepbn commented Nov 10, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Motivation

Changes

How to reproduce

Uh oh!

Vanlightly commented Nov 10, 2021

Uh oh!

Uh oh!

pradeepbn commented Nov 16, 2021

Uh oh!

Uh oh!

Uh oh!

Vanlightly left a comment

Choose a reason for hiding this comment

Uh oh!

Vanlightly commented Nov 22, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pradeepbn Nov 23, 2021 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pradeepbn commented Nov 23, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

pradeepbn commented Nov 23, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pradeepbn Nov 30, 2021 • 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!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

zymap commented Jun 16, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

pradeepbn commented Nov 10, 2021 •

edited

Loading

pradeepbn Nov 23, 2021 •

edited

Loading

pradeepbn commented Nov 23, 2021 •

edited

Loading

pradeepbn Nov 30, 2021 •

edited

Loading