Chunk方式のStepで例外発生時にリトライさせてみる

Posted on Monday Feb 10, 2014 at 06:56PM in Technology

例外発生時のリトライをさせてみてどんな挙動か確認してみる

環境・前提条件

Chunk方式のStepを使ってみると同じ。この記事で作ったプロジェクトや資源がすでに存在するものとする

バッチを作る

仕様

入力、出力、処理内容は基本的にChunk方式のStepを使ってみるでやったのと同じ
6件目のデータ処理時にItemReaderでRuntimeExceptionが起こる
- RuntimeExceptionはretryable-exception-classesに指定されているので、リトライが走る
- リトライしても同じところで例外が合計3回起こるようになっている
- 4回目のリトライでは例外が起こらない。以降は最後まで処理が完走する

資源

資源はこのへんにまとめて全部ある

バッチ本体
テスト
- ChunkRetryJobTest.java

動かしてみる

ログ

17:43:59,756 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) postConstruct(): divide=2
17:43:59,757 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) open(): checkpoint=null, index starts at=0
17:43:59,759 DEBUG [org.hibernate.SQL] (batch-batch - 8) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
17:43:59,762 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) open(): checkpoint=null, index starts at=0
17:43:59,763 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=0, failAt=5, fails=3, retryCount=0
17:43:59,763 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=0, input=0, processed=false]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=0, input=0, processed=false], output=ChunkOutputItem [id=0, result=0]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=1
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=1, failAt=5, fails=3, retryCount=0
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=1, input=10, processed=false]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=1, input=10, processed=false], output=ChunkOutputItem [id=1, result=5]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=2
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=2, failAt=5, fails=3, retryCount=0
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=2, input=20, processed=false]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=2, input=20, processed=false], output=ChunkOutputItem [id=2, result=10]
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=3
17:43:59,764 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=0
17:43:59,765 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=0, result=0]
17:43:59,765 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=1, result=5]
17:43:59,765 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=2, result=10]
17:43:59,765 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=3
17:43:59,765 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=1
17:43:59,767 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=3
17:43:59,771 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,772 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,773 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,801 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=3, failAt=5, fails=3, retryCount=0
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=4
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=4, failAt=5, fails=3, retryCount=0
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,802 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=5, failAt=5, fails=3, retryCount=0
17:43:59,802 WARNING [org.nailedtothex.jbatch.example.chunkretry.MyRetryReadListener] (batch-batch - 8) onRetryReadException(): java.lang.RuntimeException: 0
    at org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader.readItem(ChunkRetryItemReader.java:48) [classes:]
    at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:346) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:291) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:193) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:149) [wildfly-jberet-8.0.0.Final.jar:8.0.0.Final]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_51]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_51]
    at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51]
    at org.jboss.threads.JBossThread.run(JBossThread.java:122)

17:43:59,804 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,804 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) close()
17:43:59,804 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) close()
17:43:59,804 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) open(): checkpoint=3, index starts at=3
17:43:59,804 DEBUG [org.hibernate.SQL] (batch-batch - 8) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) open(): checkpoint=1, index starts at=1
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=3
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=3, failAt=5, fails=3, retryCount=1
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=4
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=1
17:43:59,807 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=3, result=15]
17:43:59,808 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=4
17:43:59,808 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=2
17:43:59,809 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=4
17:43:59,810 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=4, failAt=5, fails=3, retryCount=1
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=2
17:43:59,839 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=4, result=20]
17:43:59,840 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,840 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=3
17:43:59,842 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,843 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,872 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=5, failAt=5, fails=3, retryCount=1
17:43:59,872 WARNING [org.nailedtothex.jbatch.example.chunkretry.MyRetryReadListener] (batch-batch - 8) onRetryReadException(): java.lang.RuntimeException: 1
    at org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader.readItem(ChunkRetryItemReader.java:48) [classes:]
    at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:346) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:291) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:193) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:149) [wildfly-jberet-8.0.0.Final.jar:8.0.0.Final]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_51]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_51]
    at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51]
    at org.jboss.threads.JBossThread.run(JBossThread.java:122)

17:43:59,873 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,873 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) close()
17:43:59,873 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) close()
17:43:59,873 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) open(): checkpoint=5, index starts at=5
17:43:59,874 DEBUG [org.hibernate.SQL] (batch-batch - 8) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
17:43:59,876 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) open(): checkpoint=3, index starts at=3
17:43:59,876 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,876 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=5, failAt=5, fails=3, retryCount=2
17:43:59,876 WARNING [org.nailedtothex.jbatch.example.chunkretry.MyRetryReadListener] (batch-batch - 8) onRetryReadException(): java.lang.RuntimeException: 2
    at org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader.readItem(ChunkRetryItemReader.java:48) [classes:]
    at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:346) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:291) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:193) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:149) [wildfly-jberet-8.0.0.Final.jar:8.0.0.Final]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_51]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_51]
    at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51]
    at org.jboss.threads.JBossThread.run(JBossThread.java:122)

17:43:59,877 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,877 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) close()
17:43:59,877 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) close()
17:43:59,877 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) open(): checkpoint=5, index starts at=5
17:43:59,878 DEBUG [org.hibernate.SQL] (batch-batch - 8) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
17:43:59,879 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) open(): checkpoint=3, index starts at=3
17:43:59,879 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,879 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=5, failAt=5, fails=3, retryCount=3
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=5, input=50, processed=false]
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=5, input=50, processed=false], output=ChunkOutputItem [id=5, result=25]
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=6
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=3
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=5, result=25]
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=6
17:43:59,880 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=4
17:43:59,881 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=6
17:43:59,882 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,910 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=6, failAt=5, fails=3, retryCount=3
17:43:59,911 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=6, input=60, processed=false]
17:43:59,911 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=6, input=60, processed=false], output=ChunkOutputItem [id=6, result=30]
17:43:59,911 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=7
17:43:59,911 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=4
17:43:59,911 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=6, result=30]
17:43:59,912 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=7
17:43:59,912 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=5
17:43:59,913 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=7
17:43:59,914 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,943 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=7, failAt=5, fails=3, retryCount=3
17:43:59,944 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=7, input=70, processed=false]
17:43:59,944 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=7, input=70, processed=false], output=ChunkOutputItem [id=7, result=35]
17:43:59,944 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=8
17:43:59,944 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=5
17:43:59,944 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=7, result=35]
17:43:59,945 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=8
17:43:59,945 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=6
17:43:59,947 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=8
17:43:59,947 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=8, failAt=5, fails=3, retryCount=3
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=8, input=80, processed=false]
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=8, input=80, processed=false], output=ChunkOutputItem [id=8, result=40]
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=9
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=6
17:43:59,977 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=8, result=40]
17:43:59,978 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=9
17:43:59,978 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=7
17:43:59,980 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=9
17:43:59,980 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:44:00,009 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=9, failAt=5, fails=3, retryCount=3
17:44:00,009 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=9, input=90, processed=false]
17:44:00,010 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=9, input=90, processed=false], output=ChunkOutputItem [id=9, result=45]
17:44:00,010 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=10
17:44:00,010 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): index=7
17:44:00,010 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=9, result=45]
17:44:00,010 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=10
17:44:00,011 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) checkpointInfo(): returns=8
17:44:00,012 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=10
17:44:00,013 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
17:44:00,041 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): index=10, failAt=5, fails=3, retryCount=3
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) readItem(): returning=null
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) checkpointInfo(): returns=10
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) close()
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) close()
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemReader] (batch-batch - 8) close()
17:44:00,042 FINE  [org.nailedtothex.jbatch.example.chunkretry.ChunkRetryItemWriter] (batch-batch - 8) close()

Repository

job_execution

jbatch=# select * from job_execution where jobexecutionid =80;
 jobexecutionid | jobinstanceid | version |       createtime        |        starttime        |         endtime         |     lastupdatedtime     | batchstatus | exitstatus |    jobparameters     | restartposition 
----------------+---------------+---------+-------------------------+-------------------------+-------------------------+-------------------------+-------------+------------+----------------------+-----------------
             80 |            75 |         | 2014-02-14 17:43:59.753 | 2014-02-14 17:43:59.753 | 2014-02-14 17:44:00.045 | 2014-02-14 17:44:00.045 | COMPLETED   | COMPLETED  | itemReaderFailAt = 5+| 
                |               |         |                         |                         |                         |                         |             |            | itemReaderFails = 3 +| 
                |               |         |                         |                         |                         |                         |             |            | divide = 2          +| 
                |               |         |                         |                         |                         |                         |             |            |                      | 
(1 row)

jbatch=#

step_execution

jbatch=# select * from step_execution where jobexecutionid =80;
 stepexecutionid | jobexecutionid | version | stepname |        starttime        |         endtime         | batchstatus | exitstatus | executionexception | persistentuserdata | readcount | writecount | commitcount | rollbackcount | readskipcount | processskipcount | filtercount | writeskipcount |                                                                         readercheckpointinfo                                                                         |                                                                         writercheckpointinfo                                                                         
-----------------+----------------+---------+----------+-------------------------+-------------------------+-------------+------------+--------------------+--------------------+-----------+------------+-------------+---------------+---------------+------------------+-------------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------
              95 |             80 |         | doChunk  | 2014-02-14 17:43:59.754 | 2014-02-14 17:44:00.042 | COMPLETED   | COMPLETED  |                    |                    |        12 |         10 |           9 |             3 |             0 |                0 |           0 |              0 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b02000078700000000a | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000008
(1 row)

jbatch=#

rollbackcount = 3
commitcount = 9
- 何故9なのか。謎
readcount = 12
- 無駄なreadは確かに2回あったけど。

処理の流れを見てみる

最初の例外発生まで (1-34行目)

ジョブXMLにはitem-count=3に設定してある
3件目までは処理が正常に終わり、コミットまで行われ出力がDBに書き込まれる
4, 5件目はItemProcessorの処理まで正常終了しているが、結果はバッファリングされており、まだDBに書き込まれていない

1回目の例外発生 (35-52行目)

6件目のreadItem()で例外が起きる
バッファリングされていた4, 5件目の処理結果はDBに書き込まれないまま破棄される

1回目のリトライ (54-98行目)

ItemReader, ItemWriter共に一旦close()で閉じられ、open()から再開となる
リトライ時にはitem-count=1に設定される[1]
item-count=1のため、結果のバッファリングは無効化され、4件目、5件目が1件ずつ処理されて完了
6件目で再度例外発生

2, 3回目のリトライ (100-124行目)

5件目まではすでに処理が完了しているため、2回目のリトライは6件目からの再開となる
2, 3回目のリトライはreadItem()で即死

4回目のリトライ (126行目以降)

4回目のリトライでは例外は起こらない
後続の処理は全てitem-count=1で処理されていき完走

備考

Webサイトのスクレイピングする時とかに使える気がする
リトライ回数の上限はジョブXMLで定義出来るが、デフォルトが無制限なのに注意
リトライ後はitem-count=1になるのは良い面もあるが、checkpointに達したときの処理は結構重いので、データ量が多い場合のパフォーマンス劣化が若干気になる

参考文献

JSR-000352 Batch Applications for the Java Platform - Final Release

Comments [0]

Tags: jbatch

No one has commented yet.

Welcome

You're viewing a weblog entry titled Chunk方式のStepで例外発生時にリトライさせてみる. If you like this entry you might want to:

Bookmark it

Digg it

This is just one entry in the weblog Kohei Nozaki's blog. Why don't you visit the main page of the weblog?

Kohei Nozaki's blog