Uploaded image for project: 'Kylin'
  1. Kylin
  2. KYLIN-4307

ExponentialBackoffRetry implemented a incorrect retry policy

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • v2.6.4
    • v3.1.0
    • Storage - HBase
    • None
    • HBase 1.1.5

    Description

      Today we had encountered a build error. The step "Build N-Dimension Cuboid : level 1" failed caused by WriteConflictException.

       

       

      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)

       

      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".

       

      // 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)

       

      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:

      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?
       

      Attachments

        1. Screen Shot 2019-12-19 at 12.16.05.png
          46 kB
          Liang Geng
        2. image-2020-02-13-15-58-23-114.png
          159 kB
          Yaqian Zhang

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. KYLIN-4376 WriteConflictException: Overwriting conflict /execute_output/0e62262a-9204-1807-cdf0-d9d47c7d6678-08, expect old TS 1581419911636, but it is 1581419921751

          • Major - Major loss of function.
          • Closed
          links to

          Web Link GitHub Pull Request #1107

          Activity

            People

              zhangyaqian Yaqian Zhang
              pwrliang Liang Geng
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: