You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@kylin.apache.org by "Xiaoxiang Yu (Jira)" <ji...@apache.org> on 2020/07/31 12:20:01 UTC
[jira] [Closed] (KYLIN-4307) ExponentialBackoffRetry implemented a
incorrect retry policy
[ https://issues.apache.org/jira/browse/KYLIN-4307?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Xiaoxiang Yu closed KYLIN-4307.
-------------------------------
Resolved in release 3.1.0 (2020-07-03)
> ExponentialBackoffRetry implemented a incorrect retry policy
> ------------------------------------------------------------
>
> Key: KYLIN-4307
> URL: https://issues.apache.org/jira/browse/KYLIN-4307
> Project: Kylin
> Issue Type: Bug
> Components: Storage - HBase
> Affects Versions: v2.6.4
> Environment: HBase 1.1.5
> Reporter: Liang Geng
> Assignee: Yaqian Zhang
> Priority: Major
> Fix For: v3.1.0
>
> Attachments: Screen Shot 2019-12-19 at 12.16.05.png, image-2020-02-13-15-58-23-114.png
>
>
> Today we had encountered a build error. The step "Build N-Dimension Cuboid : level 1" failed caused by WriteConflictException.
>
>
> {code:java}
> 2019-12-19 03:19:59,049 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696795196, to newTs: 1576696799048, operation result: true2019-12-19 03:19:59,049 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696795196, to newTs: 1576696799048, operation result: true2019-12-19 03:20:02,775 INFO [BadQueryDetector] service.BadQueryDetector:147 : Detect bad query.2019-12-19 03:20:03,254 TRACE [Scheduler 1528161485 Job d33e65d0-4214-3b96-9256-607a730cb53f-880] hbase.HBaseResourceStore:335 : Update row /execute_output/d33e65d0-4214-3b96-9256-607a730cb53f-10 from oldTs: 1576696793142, to newTs: 1576696803253, operation result: true2019-12-19 03:20:03,256 TRACE [Scheduler 1528161485 Job d33e65d0-4214-3b96-9256-607a730cb53f-880] hbase.HBaseResourceStore:335 : Update row /execute_output/d33e65d0-4214-3b96-9256-607a730cb53f-10 from oldTs: 1576696803253, to newTs: 1576696803255, operation result: true2019-12-19 03:20:04,187 INFO [FetcherRunner 2062551616-143] threadpool.DefaultFetcherRunner:85 : Job Fetcher: 2 should running, 2 actual running, 0 stopped, 0 ready, 1754 already succeed, 7 error, 10 discarded, 0 others2019-12-19 03:20:09,124 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696799048, to newTs: 1576696809122, operation result: true2019-12-19 03:20:09,125 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696809122, to newTs: 1576696809124, operation result: true2019-12-19 03:20:13,263 TRACE [Scheduler 1528161485 Job d33e65d0-4214-3b96-9256-607a730cb53f-880] hbase.HBaseResourceStore:335 : Update row /execute_output/d33e65d0-4214-3b96-9256-607a730cb53f-10 from oldTs: 1576696803255, to newTs: 1576696813262, operation result: true2019-12-19 03:20:24,133 INFO [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] persistence.ExponentialBackoffRetry:87 : Will try to re-connect after 1 seconds.2019-12-19 03:20:25,228 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696809124, to newTs: 1576696819131, operation result: false2019-12-19 03:20:25,284 TRACE [Scheduler 1528161485 Job d33e65d0-4214-3b96-9256-607a730cb53f-880] hbase.HBaseResourceStore:335 : Update row /execute_output/d33e65d0-4214-3b96-9256-607a730cb53f-10 from oldTs: 1576696813262, to newTs: 1576696825245, operation result: true2019-12-19 03:20:25,299 ERROR [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] common.MapReduceExecutable:198 : error execute MapReduceExecutable{id=4759f195-9443-2604-5358-d5804d9aaefc-08, name=Build N-Dimension Cuboid : level 1, state=RUNNING}org.apache.kylin.common.persistence.WriteConflictException: Overwriting conflict /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08, expect old TS 1576696809124, but it is 1576696819131 at org.apache.kylin.storage.hbase.HBaseResourceStore.checkAndPutResourceImpl(HBaseResourceStore.java:338) at org.apache.kylin.common.persistence.ResourceStore.lambda$checkAndPutResourceWithRetry$3(ResourceStore.java:423) at org.apache.kylin.common.persistence.ExponentialBackoffRetry.doWithRetry(ExponentialBackoffRetry.java:52) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResourceWithRetry(ResourceStore.java:423) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResourceCheckpoint(ResourceStore.java:411) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:405) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:388) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:368) at org.apache.kylin.job.dao.ExecutableDao.writeJobOutputResource(ExecutableDao.java:252) at org.apache.kylin.job.dao.ExecutableDao.updateJobOutput(ExecutableDao.java:426) at org.apache.kylin.job.execution.ExecutableManager.addJobInfo(ExecutableManager.java:566) at org.apache.kylin.engine.mr.common.MapReduceExecutable.doWork(MapReduceExecutable.java:163) at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:167) at org.apache.kylin.job.execution.DefaultChainedExecutable.doWork(DefaultChainedExecutable.java:71) at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:167) at org.apache.kylin.job.impl.threadpool.DefaultScheduler$JobRunner.run(DefaultScheduler.java:114) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
> {code}
>
> At 03:20:24,133, a thread "Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879" is trying to write content to the path "/execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08" but the exception was raised for some reasons. We don't know what kind of exception happened because the exception was eaten by doWithRetry.
> ExponentialBackoffRetry will retry if the following exceptions happened: SocketTimeoutException, or ConnectException, or RetriesExhaustedException or any other exceptions configured in "kylin.resourcestore.connection-exceptions".
> By default the retry policy is disabled, but we have enabled it by setting "kylin.resourcestore.reconnect-enabled".
>
> {code:java}
> // A successful written, 1576696809122 -> 1576696809124// A successful written, 1576696809122 -> 15766968091242019-12-19 03:20:09,125 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696809122, to newTs: 1576696809124, operation result: true
> // A written with exception but actually persistence to HBase, 1576696809124 -> 1576696819131// ExponentialBackoffRetry.doWithRetry catched the exception, and then back-off2019-12-19 03:20:24,133 INFO [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] persistence.ExponentialBackoffRetry:87 : Will try to re-connect after 1 seconds.
> // Retry as back-off time reached. But this time, the invoking of checkAndPut failed because the content is already written.2019-12-19 03:20:25,228 TRACE [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] hbase.HBaseResourceStore:335 : Update row /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08 from oldTs: 1576696809124, to newTs: 1576696819131, operation result: false
> // checkAndPutResourceImpl throws WriteConflictException2019-12-19 03:20:25,299 ERROR [Scheduler 1528161485 Job 4759f195-9443-2604-5358-d5804d9aaefc-879] common.MapReduceExecutable:198 : error execute MapReduceExecutable{id=4759f195-9443-2604-5358-d5804d9aaefc-08, name=Build N-Dimension Cuboid : level 1, state=RUNNING}org.apache.kylin.common.persistence.WriteConflictException: Overwriting conflict /execute_output/4759f195-9443-2604-5358-d5804d9aaefc-08, expect old TS 1576696809124, but it is 1576696819131 at org.apache.kylin.storage.hbase.HBaseResourceStore.checkAndPutResourceImpl(HBaseResourceStore.java:338) at org.apache.kylin.common.persistence.ResourceStore.lambda$checkAndPutResourceWithRetry$3(ResourceStore.java:423) at org.apache.kylin.common.persistence.ExponentialBackoffRetry.doWithRetry(ExponentialBackoffRetry.java:52) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResourceWithRetry(ResourceStore.java:423) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResourceCheckpoint(ResourceStore.java:411) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:405) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:388) at org.apache.kylin.common.persistence.ResourceStore.checkAndPutResource(ResourceStore.java:368) at org.apache.kylin.job.dao.ExecutableDao.writeJobOutputResource(ExecutableDao.java:252) at org.apache.kylin.job.dao.ExecutableDao.updateJobOutput(ExecutableDao.java:426) at org.apache.kylin.job.execution.ExecutableManager.addJobInfo(ExecutableManager.java:566) at org.apache.kylin.engine.mr.common.MapReduceExecutable.doWork(MapReduceExecutable.java:163) at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:167) at org.apache.kylin.job.execution.DefaultChainedExecutable.doWork(DefaultChainedExecutable.java:71) at org.apache.kylin.job.execution.AbstractExecutable.execute(AbstractExecutable.java:167) at org.apache.kylin.job.impl.threadpool.DefaultScheduler$JobRunner.run(DefaultScheduler.java:114) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
> {code}
>
> As shown in the log, the thread failed to call checkAndPutResourceImpl and sleep 1 second to back-off at "2019-12-19 03:20:25,228".
> At 03:20:25,299, the WriteConflictException was raised. The message is "expect old TS 1576696809124, but it is 1576696819131". Obviously, the thread is trying to update with the same timestamp. That proves the first written is successful but throws exceptions. And then, that exception was caught by doWithRetry.
> I'm not a HBase expert, the picture above shows my rough guess: !Screen Shot 2019-12-19 at 12.16.05.png!
> Thus, we think ExponentialBackoffRetry implemented an incorrect retry policy. Determining whether to retry only by the type of exception is not reliable. At least, we should pull the last modified time to verify the written is successful or not. Right?
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)