[bk-gc] Fix GC thread gets blocked #1937

rdhabalia · 2019-02-06T22:01:49Z

Motivation

It addresses below thread-stuck while performing gc in bookie.

Thread 3363: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)
 - java.lang.Object.wait() @bci=2, line=502 (Compiled frame)
 - org.apache.bookkeeper.util.ZkUtils.getChildrenInSingleNode(org.apache.zookeeper.ZooKeeper, java.lang.String) @bci=34, line=243 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator.getChildrenAt(java.lang.String) @bci=8, line=165 (Compiled fr
ame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$LeafIterator.<init>(org.apache.bookkeeper.meta.LongHierarchic
alLedgerManager$LongHierarchicalLedgerRangeIterator, java.lang.String) @bci=11, line=187 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$InnerIterator.advance() @bci=137, line=261 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$InnerIterator.next() @bci=28, line=281 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$InnerIterator.next() @bci=4, line=278 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$InnerIterator.next() @bci=4, line=278 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator$InnerIterator.next() @bci=4, line=278 (Compiled frame)
 - org.apache.bookkeeper.meta.LongHierarchicalLedgerManager$LongHierarchicalLedgerRangeIterator.next() @bci=8, line=304 (Compiled frame)
 - org.apache.bookkeeper.meta.HierarchicalLedgerManager$HierarchicalLedgerRangeIterator.next() @bci=26, line=117 (Compiled frame)
 - org.apache.bookkeeper.bookie.ScanAndCompareGarbageCollector.gc(org.apache.bookkeeper.bookie.GarbageCollector$GarbageCleaner) @bci=195, line=168 (Compiled frame)
 - org.apache.bookkeeper.bookie.GarbageCollectorThread.doGcLedgers() @bci=8, line=393 (Compiled frame)
 - org.apache.bookkeeper.bookie.GarbageCollectorThread.runWithFlags(boolean, boolean, boolean) @bci=39, line=355 (Compiled frame)
 - org.apache.bookkeeper.bookie.GarbageCollectorThread.safeRun() @bci=28, line=333 (Compiled frame)
 - org.apache.bookkeeper.common.util.SafeRunnable.run() @bci=1, line=36 (Compiled frame)
 - java.util.concurrent.Executors$RunnableAdapter.call() @bci=4, line=511 (Compiled frame)
 - java.util.concurrent.FutureTask.runAndReset() @bci=47, line=308 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask) @bci=1, line=180 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run() @bci=37, line=294 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95, line=1142 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=617 (Interpreted frame)
 - io.netty.util.concurrent.FastThreadLocalRunnable.run() @bci=4, line=30 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=748 (Interpreted frame)

Changes

add time-out to zk operation to avoid GC thread blocking.

jvrao · 2019-02-06T22:03:20Z

@athanatos

athanatos · 2019-02-06T22:36:53Z

Fwiw, we saw a similar hang which turned out to be caused by apache/zookeeper#787

I think this patch may be a good idea nevertheless. I'd like to see the timeout passed as a param, however.

merlimat · 2019-02-06T23:09:29Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/util/ZkUtils.java

            while (!ctx.done) {
-                ctx.wait();
+                try {
+                    ctx.wait(TimeUnit.SECONDS.toMillis(OP_TIME_OUT_SEC));


In this case, if no one calls ctx.done = true, the thread will just keep waiting in 2sec blocks, but it will never exit, right?

umm.. if no one calls ctx.done = true; ctx.notifyAll(); at line#238 then ctx.wait(timeout) will throw InterruptedException and ctx.done will be true; at line#249 which takes out thread out of while loop. So, it will not keep waiting but exit. right?

athanatos · 2019-02-06T23:56:31Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/meta/FlatLedgerManager.java

                try {
                    zkActiveLedgers = ledgerListToSet(
-                            ZkUtils.getChildrenInSingleNode(zk, ledgerRootPath), ledgerRootPath);
+                            ZkUtils.getChildrenInSingleNode(zk, ledgerRootPath, ZkUtils.OP_TIME_OUT_SEC),


What I mean is, it should probably be passed in from the gc thread. The gc caller should probably get its value from a config. Doing it here doesn't allow different users with different tolerances to provide different bounds. Also, passing in 0 should mean no limit.

+1 to what @athanatos suggested. I would like to see a setting configurable.

reddycharan · 2019-02-07T00:06:46Z

@rdhabalia without fixing the real issue (taking forever to fetch ledgerznodes), how would this fix help? It can run into the same issue again, right?

rdhabalia · 2019-02-07T00:47:45Z

@reddycharan

without fixing the real issue (taking forever to fetch ledgerznodes), how would this fix help? It can run into the same issue again, right?

the real issue is when zk does zxid rollover, it restarts the leader and zk-client doesn't receive the callback for in transit requests. however, new outgoing requests will not have the issue once zk quorum will come back. so, with this fix, blocked zk-call will be timeout and next time it will succeed.

athanatos · 2019-02-07T01:28:40Z

@rdhabalia No, the patch I linked above addresses a problem with the zk client side cxid (which unlike the zxid increments with reads), not the zk server side zxid. Rolling the client side cxid is actually harmless and does not require a leader election. With that patch, this call won't hang in the first place. However, that may not be the only such bug and there are other ways for zk calls to hang, so this patch may nevertheless be useful for some auxiliary zk users like the gc scan.

eolivelli · 2019-02-07T07:27:12Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/ServerConfiguration.java

    }

+    /**
+     * Get zk-operation timeout in seconds used by GC while performing zk


If this is only for GC we should provide a more meaningful name.
Can you change it please?

i think this could be generic configuration for timeout and can be used at anywhere where bookie needs blocking zk call. However, I think we can also use existing zkTimeout which can genuinely guarantees that zk-session is alive and callback couldn't complete. or let me know if you guys think we need different name?

We can save adding this new knob and use zkTimeout * N in your change, infact our problem is that we want to put an upperbound to the time spent waiting.

I think that our Zookeeper clients retries and creates new 'sessions' in case of session expiration. So I don't know which value is most suitable for N, we can start with 2.

How does this sounds to you?

@eolivelli sure, that will be also fine. I have fixed it.

bookkeeper-server/src/main/java/org/apache/bookkeeper/util/ZkUtils.java

eolivelli

Looks good.
Thank you

eolivelli

You didn't update etcd driver and CI is failing.
Please fix

sijie

can you add the settings to conf/bk_server.conf?

eolivelli · 2019-02-08T13:40:27Z

can you add the settings to conf/bk_server.conf?
@sijie there is no new setting any more

sijie · 2019-02-08T13:48:39Z

@eolivelli sorry I didn't follow the discussion. I just checked the conversation. I am not sure if using 2 * zkTimeout is a good idea. I would prefer a separate setting called zkOpTimeout, so people can really configure op timeout. We can set the default zkOpTimeout as 2 * zkTimeout.

eolivelli · 2019-02-08T13:50:49Z

@eolivelli sorry I didn't follow the discussion. I just checked the conversation. I am not sure if using 2 * zkTimeout is a good idea. I would prefer a separate setting called zkOpTimeout, so people can really configure op timeout. We can set the default zkOpTimeout as 2 * zkTimeout.

Ok @sijie
The initial idea was to have a tunable parameter, and @rdhabalia introduced a generic timeout, used only in GC. So I proposed to cal that parameter with a name with an explicit reference to GC.
Then we ended with dropping the parameter.

A new parameter works for me as well but I think it should be stated clearly that it is only for GC operations

sijie · 2019-02-08T14:04:56Z

A new parameter works for me as well but I think it should be stated clearly that it is only for GC operations

if it is only for GC operations, I am fine with current approach.

rdhabalia · 2019-02-08T18:05:09Z

@sijie

if it is only for GC operations, I am fine with current approach.

Yes, in previous commit, I have added separate config but then we realize that for now, it only needs for GC and GC should expect response before zk-session time out happens so, zkTimeout can be used to set this timeout for now so, we moved forward with this change.

rdhabalia · 2019-02-09T00:29:31Z

run integration tests

rdhabalia · 2019-02-11T18:25:08Z

run integration tests

rdhabalia · 2019-02-15T22:30:38Z

@eolivelli can we merge this PR?

eolivelli

Sure. Go ahead
Sorry, I forgot to 'approve'

eolivelli · 2019-02-16T14:56:39Z

Merging now

rdhabalia mentioned this pull request Feb 6, 2019

[bk-gc] Prevent OOM: Restrict number of entry-loggers extraction #1938

Open

[bk-gc] Fix GC thread gets blocked

d822932

rdhabalia force-pushed the gc_dead branch from e8bce3c to d822932 Compare February 6, 2019 22:27

merlimat reviewed Feb 6, 2019

View reviewed changes

add timeout in parameter

dc51fed

athanatos reviewed Feb 6, 2019

View reviewed changes

eolivelli requested changes Feb 7, 2019

View reviewed changes

keep timeout configurable

6040f2a

rdhabalia force-pushed the gc_dead branch from 39c614a to 6040f2a Compare February 7, 2019 19:57

derive zkoptimeout from zktimeout

ddc4828

eolivelli approved these changes Feb 8, 2019

View reviewed changes

eolivelli requested changes Feb 8, 2019

View reviewed changes

sijie requested changes Feb 8, 2019

View reviewed changes

fix EtcdLedgerManager

80cd5eb

sijie approved these changes Feb 9, 2019

View reviewed changes

eolivelli approved these changes Feb 16, 2019

View reviewed changes

eolivelli added this to the 4.10.0 milestone Feb 16, 2019

eolivelli added area/autorecovery release/4.10.0 type/improvement labels Feb 16, 2019

eolivelli assigned rdhabalia Feb 16, 2019

eolivelli merged commit d511f59 into apache:master Feb 16, 2019

rdhabalia mentioned this pull request Feb 25, 2019

[bk-gc] avoid blocking call in gc-thread #1940

Merged

[bk-gc] Fix GC thread gets blocked #1937

[bk-gc] Fix GC thread gets blocked #1937

Uh oh!

Conversation

rdhabalia commented Feb 6, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Motivation

Changes

Uh oh!

jvrao commented Feb 6, 2019

Uh oh!

athanatos commented Feb 6, 2019

Uh oh!

merlimat Feb 6, 2019

Choose a reason for hiding this comment

Uh oh!

rdhabalia Feb 6, 2019

Choose a reason for hiding this comment

Uh oh!

athanatos Feb 6, 2019 • 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!

sijie Feb 7, 2019

Choose a reason for hiding this comment

Uh oh!

reddycharan commented Feb 7, 2019

Uh oh!

rdhabalia commented Feb 7, 2019

Uh oh!

athanatos commented Feb 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

eolivelli Feb 7, 2019

Choose a reason for hiding this comment

Uh oh!

rdhabalia Feb 7, 2019

Choose a reason for hiding this comment

Uh oh!

eolivelli Feb 7, 2019

Choose a reason for hiding this comment

Uh oh!

rdhabalia Feb 7, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

sijie left a comment

Choose a reason for hiding this comment

Uh oh!

eolivelli commented Feb 8, 2019

Uh oh!

sijie commented Feb 8, 2019

Uh oh!

eolivelli commented Feb 8, 2019

Uh oh!

sijie commented Feb 8, 2019

Uh oh!

rdhabalia commented Feb 8, 2019

Uh oh!

rdhabalia commented Feb 9, 2019

Uh oh!

rdhabalia commented Feb 11, 2019

Uh oh!

rdhabalia commented Feb 15, 2019

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

eolivelli commented Feb 16, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

rdhabalia commented Feb 6, 2019 •

edited

Loading

athanatos Feb 6, 2019 •

edited

Loading

athanatos commented Feb 7, 2019 •

edited

Loading