Kohei Nozaki's blog 

Entries tagged [jbatch]

Chunk方式のStepの再実行時の挙動を確かめてみる

Posted on Thursday Feb 13, 2014 at 05:54PM in Technology

適切に実装されたChunk orientedのStepは、異常終了したジョブの再実行の際、処理済みのデータをスキップして未だ処理されていないデータのみを処理対象とする事が可能である。動作を確かめてみる。

環境・前提条件

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

準備

  • 資源の詳細はこのあたり
  • エンティティ、テストデータ等は流用する

バッチを構成する資源

chunkrestart.xml

  • Stepは1つ
  • あるジョブ引数を与えるとItemReaderで例外が起こりジョブが死ぬ

ChunkRestartItemReader.java

  • @BatchPropertyで与えられた引数に指定された番号のデータに達すると例外を投げて死ぬ
  • 引数がない場合は死なない

ChunkRestartItemProcessor.java

  • 一応コピーして作ったけど完全に前回と同じ

ChunkRestartItemWriter.java

  • 一応コピーして作ったけど完全に前回と同じ

テスト用資源

ChunkRestartJobTest.java

  • テスト内容は以下
    • テストメソッドitemReaderFailAt5(): 6件目のデータに達したところで異常終了する。item-count=3なので出力テーブルには3件目までが出力される
    • テストメソッドitemReaderRestart(): 異常終了後の再実行で10件目まで処理を完走する

expected0-2.yml

  • itemReaderFailAt5()の期待結果。3件だけ

実行してみる

どちらも正常だが内容はほぼかぶっているのでitemReaderRestart()の実行結果だけ見てみる

ログ

長いので初回実行部分と再実行部分を分ける

初回実行部分

18:45:00,733 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) postConstruct(): divide=2
18:45:00,733 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) open(): checkpoint=null, index starts at=0
18:45:00,737 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
18:45:00,740 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) open(): checkpoint=null, index starts at=0
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=0
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=0, input=0, processed=false]
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=0, input=0, processed=false], output=ChunkOutputItem [id=0, result=0]
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=1
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=1
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=1, input=10, processed=false]
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=1, input=10, processed=false], output=ChunkOutputItem [id=1, result=5]
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=2
18:45:00,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=2
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=2, input=20, processed=false]
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=2, input=20, processed=false], output=ChunkOutputItem [id=2, result=10]
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=3
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) writeItems(): index=0
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=0, result=0]
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=1, result=5]
18:45:00,742 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) writeItems(): item=ChunkOutputItem [id=2, result=10]
18:45:00,743 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=3
18:45:00,743 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) checkpointInfo(): returns=1
18:45:00,744 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=3
18:45:00,748 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:00,750 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:00,750 DEBUG [org.hibernate.SQL] (batch-batch - 8) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:00,779 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=3
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=4
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=4
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 8) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
18:45:00,780 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) checkpointInfo(): returns=5
18:45:00,781 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) readItem(): index=5
18:45:00,781 ERROR [org.jberet] (batch-batch - 8) JBERET000007: Failed to run job chunkrestart, doChunk, org.jberet.job.model.Chunk@53aaf456: java.lang.RuntimeException: 5
    at org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader.readItem(ChunkRestartItemReader.java:43) [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)

18:45:00,783 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 8) close()
18:45:00,783 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 8) close()

再実行分

18:45:01,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) postConstruct(): divide=2
18:45:01,741 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) open(): checkpoint=3, index starts at=3
18:45:01,742 DEBUG [org.hibernate.SQL] (batch-batch - 9) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
18:45:01,744 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) open(): checkpoint=1, index starts at=1
18:45:01,745 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=3
18:45:01,745 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=4
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=4
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=5
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=5
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=5, input=50, processed=false]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=5, input=50, processed=false], output=ChunkOutputItem [id=5, result=25]
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=6
18:45:01,746 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): index=1
18:45:01,747 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=3, result=15]
18:45:01,747 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=4, result=20]
18:45:01,747 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=5, result=25]
18:45:01,747 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=6
18:45:01,747 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) checkpointInfo(): returns=2
18:45:01,749 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=6
18:45:01,749 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,750 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,750 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=6
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=6, input=60, processed=false]
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=6, input=60, processed=false], output=ChunkOutputItem [id=6, result=30]
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=7
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=7
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=7, input=70, processed=false]
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=7, input=70, processed=false], output=ChunkOutputItem [id=7, result=35]
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=8
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=8
18:45:01,776 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=8, input=80, processed=false]
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=8, input=80, processed=false], output=ChunkOutputItem [id=8, result=40]
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=9
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): index=2
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=6, result=30]
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=7, result=35]
18:45:01,777 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=8, result=40]
18:45:01,778 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=9
18:45:01,778 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) checkpointInfo(): returns=3
18:45:01,779 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=9
18:45:01,779 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,780 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,781 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=9
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=ChunkInputItem [id=9, input=90, processed=false]
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemProcessor] (batch-batch - 9) processItem(): input=ChunkInputItem [id=9, input=90, processed=false], output=ChunkOutputItem [id=9, result=45]
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=10
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): index=10
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) readItem(): returning=null
18:45:01,807 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): index=3
18:45:01,808 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) writeItems(): item=ChunkOutputItem [id=9, result=45]
18:45:01,808 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=10
18:45:01,808 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) checkpointInfo(): returns=4
18:45:01,809 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) checkpointInfo(): returns=10
18:45:01,810 DEBUG [org.hibernate.SQL] (batch-batch - 9) insert into ChunkOutputItem (result, id) values (?, ?)
18:45:01,835 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) close()
18:45:01,835 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) close()
18:45:01,836 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader] (batch-batch - 9) close()
18:45:01,836 FINE  [org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemWriter] (batch-batch - 9) close()

ItemReaderのopen()に3が渡されてStepの実行が開始されているのがわかる。結果4件目から処理が再開され問題なく完走。

Repository

jbatch=# select * from step_execution where jobexecutionid in (30, 31) order by jobexecutionid, stepexecutionid;
 stepexecutionid | jobexecutionid | version | stepname |        starttime        |         endtime         | batchstatus | exitstatus |                                                       executionexception                                                       | persistentuserdata | readcount | writecount | commitcount | rollbackcount | readskipcount | processskipcount | filtercount | writeskipcount |                                                                         readercheckpointinfo                                                                         |                                                                         writercheckpointinfo                                                                         
-----------------+----------------+---------+----------+-------------------------+-------------------------+-------------+------------+--------------------------------------------------------------------------------------------------------------------------------+--------------------+-----------+------------+-------------+---------------+---------------+------------------+-------------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------
              46 |             30 |         | doChunk  | 2014-02-13 18:45:00.73  | 2014-02-13 18:45:00.782 | FAILED      | FAILED     | java.lang.RuntimeException: 5                                                                                                 +|                    |         5 |          3 |           1 |             0 |             0 |                0 |           0 |              0 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000003 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000001
                 |                |         |          |                         |                         |             |            |         at org.nailedtothex.jbatch.example.chunkrestart.ChunkRestartItemReader.readItem(ChunkRestartItemReader.java:43)       +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:346)                                               +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:291)                                  +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:193)                                                    +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204)                     +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131)                                    +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162)                      +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)     +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58)                                       +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:149)+|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)                                            +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.FutureTask.run(FutureTask.java:262)                                                           +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)                                    +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)                                    +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at java.lang.Thread.run(Thread.java:744)                                                                              +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |         at org.jboss.threads.JBossThread.run(JBossThread.java:122)                                                            +|                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
                 |                |         |          |                         |                         |             |            |                                                                                                                                |                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
              47 |             31 |         | doChunk  | 2014-02-13 18:45:01.739 | 2014-02-13 18:45:01.836 | COMPLETED   | COMPLETED  |                                                                                                                                |                    |         7 |          7 |           3 |             0 |             0 |                0 |           0 |              0 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b02000078700000000a | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000004
(2 rows)

jbatch=#

備考

  • ItemProcessorとかItemWriterでもそのうち試してみる。たぶん同じだろうけど

Comments [0]

Tags: jbatch

WildFly8.0.0.Finalで出るGuavaのNoClassDefFoundErrorの対処

Posted on Thursday Feb 13, 2014 at 04:24PM in Technology

環境

  • WildFly8.0.0.Final

問題

JSR352で実装したバッチからわざと例外を発生させると、こんな感じのstacktraceが出る

16:16:11,934 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 10) process(): stepName=step1, exception=null
16:16:11,955 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 10) process(): stepName=step2, exception=null
16:16:11,963 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 10) process(): stepName=step3, exception=true
16:16:11,963 WARN  [org.jberet] (batch-batch - 10) JBERET000001: Failed to run batchlet org.jberet.job.model.RefArtifact@495db27a: java.lang.RuntimeException: true
at org.nailedtothex.jbatch.example.aric.ExceptionBatchlet.process(ExceptionBatchlet.java:27) [classes:]
at org.jberet.runtime.runner.BatchletRunner.run(BatchletRunner.java:61) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:207) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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)

16:16:11,965 ERROR [org.jberet] (batch-batch - 10) JBERET000007: Failed to run job aric, step3, org.jberet.job.model.Step@30fbce4d: java.lang.NoClassDefFoundError: com/google/common/base/Throwables
at org.jberet.repository.JdbcRepository.formatException(JdbcRepository.java:924) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.repository.JdbcRepository.updateStepExecution(JdbcRepository.java:606) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.repository.JdbcRepository.savePersistentData(JdbcRepository.java:635) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.context.StepContextImpl.savePersistentData(StepContextImpl.java:165) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:144) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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)

16:16:11,965 ERROR [org.jberet] (batch-batch - 10) JBERET000007: Failed to run job aric, , org.jberet.job.model.Job@2dd10b: java.lang.NoClassDefFoundError: com/google/common/base/Throwables
at org.jberet.repository.JdbcRepository.formatException(JdbcRepository.java:924) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.repository.JdbcRepository.updateStepExecution(JdbcRepository.java:606) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:173) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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)

例外はわざと出しているからこれでいいのだが、気になるのはこの部分

java.lang.NoClassDefFoundError: com/google/common/base/Throwables

このせいで何かの処理が正常に動いてないと思われる。

対処: jberetのmodule.xmlにguavaへのdependencyを追加してやる

$WILDFLY_HOME/modules/system/layers/base/org/jberet/jberet-core/main/module.xmlのdependenciesの一番最後に以下の内容を追加してやる。

<module name="com.google.guava"/>

全体はこうなる

<module xmlns="urn:jboss:module:1.1" name="org.jberet.jberet-core">
    <properties>
        <property name="jboss.api" value="private"/>
    </properties>

    <resources>
        <resource-root path="jberet-core-1.0.0.Final.jar"/>
        <!-- Insert resources here -->
    </resources>

    <dependencies>
        <module name="javax.api"/>
        <module name="javaee.api"/>
        <module name="javax.transaction.api"/>
        <module name="org.jboss.jts"/>
        <module name="org.jboss.marshalling"/>
        <module name="org.jboss.logging"/>
        <module name="com.h2database.h2" optional="true"/>
        <module name="com.google.guava"/>
    </dependencies>
</module>

これで再起動すれば、jberetからWildFlyに元々入っているguavaのjarファイルが見えるようになるようだ。再起動後は、先ほどのバッチが出すstacktraceがこんな感じになる

16:23:10,913 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 1) process(): stepName=step1, exception=null
16:23:10,937 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 1) process(): stepName=step2, exception=null
16:23:10,943 FINE  [org.nailedtothex.jbatch.example.aric.ExceptionBatchlet] (batch-batch - 1) process(): stepName=step3, exception=true
16:23:10,943 WARN  [org.jberet] (batch-batch - 1) JBERET000001: Failed to run batchlet org.jberet.job.model.RefArtifact@21eec7fc: java.lang.RuntimeException: true
    at org.nailedtothex.jbatch.example.aric.ExceptionBatchlet.process(ExceptionBatchlet.java:27) [classes:]
    at org.jberet.runtime.runner.BatchletRunner.run(BatchletRunner.java:61) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:207) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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.runJobElement(CompositeExecutionRunner.java:126) [jberet-core-1.0.0.Final.jar:1.0.0.Final]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177) [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)

さらにstacktraceがRepositoryに残るようになる。こんな感じ。たぶんこれやるところで死んでたんだと思う。ちょっとすごい

jbatch=# select * from step_execution where jobexecutionid =15 order by stepexecutionid;;
 stepexecutionid | jobexecutionid | version | stepname |        starttime        |         endtime         | batchstatus | exitstatus |                                                       executionexception                                                       | persistentuserdata | readcount | writecount | commitcount | rollbackcount | readskipcount | processskipcount | filtercount | writeskipcount | readercheckpointinfo | writercheckpointinfo 
-----------------+----------------+---------+----------+-------------------------+-------------------------+-------------+------------+--------------------------------------------------------------------------------------------------------------------------------+--------------------+-----------+------------+-------------+---------------+---------------+------------------+-------------+----------------+----------------------+----------------------
              17 |             15 |         | step1    | 2014-02-13 16:23:10.894 | 2014-02-13 16:23:10.914 | COMPLETED   | SUCCESS    |                                                                                                                                |                    |         0 |          0 |           0 |             0 |             0 |                0 |           0 |              0 |                      | 
              18 |             15 |         | step2    | 2014-02-13 16:23:10.93  | 2014-02-13 16:23:10.937 | COMPLETED   | SUCCESS    |                                                                                                                                |                    |         0 |          0 |           0 |             0 |             0 |                0 |           0 |              0 |                      | 
              19 |             15 |         | step3    | 2014-02-13 16:23:10.941 | 2014-02-13 16:23:10.945 | FAILED      | FAILED     | java.lang.RuntimeException: true                                                                                              +|                    |         0 |          0 |           0 |             0 |             0 |                0 |           0 |              0 |                      | 
                 |                |         |          |                         |                         |             |            |         at org.nailedtothex.jbatch.example.aric.ExceptionBatchlet.process(ExceptionBatchlet.java:27)                          +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.BatchletRunner.run(BatchletRunner.java:61)                                               +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:207)                     +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131)                                    +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162)                      +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runJobElement(CompositeExecutionRunner.java:126)                +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177)                                    +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162)                      +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runJobElement(CompositeExecutionRunner.java:126)                +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:177)                                    +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162)                      +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)     +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58)                                       +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.wildfly.jberet.services.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:149)+|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)                                            +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.FutureTask.run(FutureTask.java:262)                                                           +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)                                    +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)                                    +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at java.lang.Thread.run(Thread.java:744)                                                                              +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |         at org.jboss.threads.JBossThread.run(JBossThread.java:122)                                                            +|                    |           |            |             |               |               |                  |             |                |                      | 
                 |                |         |          |                         |                         |             |            |                                                                                                                                |                    |           |            |             |               |               |                  |             |                |                      | 
(3 rows)

jbatch=#

単純に書き漏れたのだろうか。次のリリースでは直っていることを祈る

Comments [0]

Tags: jbatch

WildFly8でPostgreSQLをジョブレポジトリにしてみる

Posted on Thursday Feb 13, 2014 at 07:26AM in Technology

WildFly8でJDBCジョブレポジトリを使ってみるでH2を使ってやってみたけど、PostgreSQLでやってみると、XAデータソースとかではまったのでメモしておく

環境

  • WildFly8.0.0.Final
  • postgresql-9.3-1100.jdbc41.jar
  • Oracle JDK7u51
  • PostgreSQL 9.2.4
  • OS X 10.9.1

postgresql.confを編集する

max_prepared_transactionsを増やす

デフォルトだと、バッチ実行時にこういう例外が出て死ぬ。

10:56:53,218 WARN  [com.arjuna.ats.jta] (batch-batch - 1) ARJUNA016041: prepare on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a00010b:-79718ed6:52fc262f:17, node_name=1, branch_uid=0:ffff0a00010b:-79718ed6:52fc262f:1b, subordinatenodename=null, eis_name=java:jboss/jdbc/JBatchDS > (XAResourceWrapperImpl@4a5bf320[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@3c38e6e8 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.2.4 jndiName=java:jboss/jdbc/JBatchDS]) failed with exception XAException.XAER_RMERR: org.postgresql.xa.PGXAException: トランザクションの準備エラー
    at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:313)
    at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.prepare(XAManagedConnection.java:330)
    at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.prepare(XAResourceWrapperImpl.java:169)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:210) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2586) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2536) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2097) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1481) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1166) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]
    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:323) [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)
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transactions are disabled
  ヒント: Set max_prepared_transactions to a nonzero value.
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2161)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1890)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:560)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:403)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:331)
    at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:301)
    ... 26 more

[4]によると、何やらpostgresql.confの設定を変更せねばならんらしい。デフォルトが0で無効になっているらしい[5]。

#max_prepared_transactions = 0          # zero disables the feature
                                        # (change requires restart)

とりあえず20に増やすとOKっぽい

max_prepared_transactions = 20         # zero disables the feature

100にしてみたら、こんな感じで起動しなかった。何か設定が必要なのだろう

Feb 13 11:17:30 kyle-no-MacBook.local postgres[23553]: [1-1] 2014-02-13 11:17:30 JST FATAL:  could not create shared memory segment: Invalid argument
Feb 13 11:17:30 kyle-no-MacBook.local postgres[23553]: [1-2] 2014-02-13 11:17:30 JST DETAIL:  Failed system call was shmget(key=5432001, size=36937728, 03600).
Feb 13 11:17:30 kyle-no-MacBook.local postgres[23553]: [1-3] 2014-02-13 11:17:30 JST HINT:  This error usually means that PostgreSQL's request for a shared memory segment exceeded your kernel's SHMMAX parameter.  You can either reduce the request size or reconfigure the kernel with larger SHMMAX.  To reduce the request size (currently 36937728 bytes), reduce PostgreSQL's shared memory usage, perhaps by reducing shared_buffers or max_connections.
Feb 13 11:17:30 kyle-no-MacBook.local postgres[23553]: [1-4]    If the request size is already small, it's possible that it is less than your kernel's SHMMIN parameter, in which case raising the request size or reconfiguring SHMMIN is called for.
Feb 13 11:17:30 kyle-no-MacBook.local postgres[23553]: [1-5]    The PostgreSQL documentation contains more information about shared memory configuration.

再起動

sudo launchctl stop com.edb.launchd.postgresql-9.2
sudo launchctl start com.edb.launchd.postgresql-9.2

ジョブレポジトリ用のXAデータソースを定義する

jboss-cliを使う。こういう感じ

batch
xa-data-source add \
      --name=JBatchDS \
      --driver-name=postgresql \
      --jndi-name=java:jboss/jdbc/JBatchDS \
      --user-name=postgres \
      --password=***
/subsystem=datasources/xa-data-source="JBatchDS"/xa-datasource-properties=ServerName:add(value="localhost")
/subsystem=datasources/xa-data-source="JBatchDS"/xa-datasource-properties=PortNumber:add(value="5432")
/subsystem=datasources/xa-data-source="JBatchDS"/xa-datasource-properties=DatabaseName:add(value="jbatch")
run-batch

接続テストとかその他のデータソース関連操作はWildFly - CLIでデータソースを定義するに書いたのも何かの参考になるかも

アプリ用のXAデータソースを定義する

アプリ用の方は普通のデータソースでもよいのかしら？わからん。ジョブレポジトリ用と同じ感じです。

ジョブレポジトリを変更

WildFly8でJDBCジョブレポジトリを使ってみるで書いたのと同じ感じなので省略。

バッチを動かしてみる

Chunk方式のStepを使ってみるで作ったバッチを動かしてみると、Repository用のDDLが勝手に流されて必要なテーブルやシーケンスを勝手に作ってくれる。ログを見ているとこういうのが流れている

2014-02-13 09:57:02,584 INFO  [org.jberet] (pool-2-thread-1) JBERET000021: About to initialize batch job repository with ddl-file: sql/jberet-postgresql.ddl for database PostgreSQL

Repositoryのテーブル一覧を見てみる

jbatch=# \d
                         List of relations
 Schema |                Name                |   Type   |  Owner   
--------+------------------------------------+----------+----------
 public | job_execution                      | table    | postgres
 public | job_execution_jobexecutionid_seq   | sequence | postgres
 public | job_instance                       | table    | postgres
 public | job_instance_jobinstanceid_seq     | sequence | postgres
 public | partition_execution                | table    | postgres
 public | step_execution                     | table    | postgres
 public | step_execution_stepexecutionid_seq | sequence | postgres
(7 rows)

jbatch=#

Repositoryのテーブルに入っているレコードも見てみる

FAILEDになっているのはXAデータソースがらみではまって死んだところ。いろいろと設定を加えて再実行した結果COMPLETEDが1件できた

jbatch=# select * from job_execution;
 jobexecutionid | jobinstanceid | version |       createtime        |        starttime        |         endtime         |     lastupdatedtime     | batchstatus | exitstatus | jobparameters | restartposition 
----------------+---------------+---------+-------------------------+-------------------------+-------------------------+-------------------------+-------------+------------+---------------+-----------------
              1 |             1 |         | 2014-02-13 09:57:02.685 | 2014-02-13 09:57:02.685 | 2014-02-13 09:57:02.999 | 2014-02-13 09:57:02.999 | FAILED      | FAILED     | divide = 2   +| 
                |               |         |                         |                         |                         |                         |             |            |               | 
              2 |             2 |         | 2014-02-13 09:58:59.033 | 2014-02-13 09:58:59.033 | 2014-02-13 09:58:59.058 | 2014-02-13 09:58:59.058 | FAILED      | FAILED     | divide = 2   +| 
                |               |         |                         |                         |                         |                         |             |            |               | 
              3 |             3 |         | 2014-02-13 10:01:44.972 | 2014-02-13 10:01:44.972 | 2014-02-13 10:01:44.994 | 2014-02-13 10:01:44.994 | FAILED      | FAILED     | divide = 2   +| 
                |               |         |                         |                         |                         |                         |             |            |               | 
              4 |             4 |         | 2014-02-13 10:56:52.962 | 2014-02-13 10:56:52.962 | 2014-02-13 10:56:53.231 | 2014-02-13 10:56:53.231 | FAILED      | FAILED     | divide = 2   +| 
                |               |         |                         |                         |                         |                         |             |            |               | 
              5 |             5 |         | 2014-02-13 11:18:51.947 | 2014-02-13 11:18:51.947 | 2014-02-13 11:18:52.28  | 2014-02-13 11:18:52.28  | COMPLETED   | COMPLETED  | divide = 2   +| 
                |               |         |                         |                         |                         |                         |             |            |               | 
(5 rows)

jbatch=# select * from job_instance;
 jobinstanceid | version | jobname | applicationname 
---------------+---------+---------+-----------------
             1 |         | chunk   | jbatchtest
             2 |         | chunk   | jbatchtest
             3 |         | chunk   | jbatchtest
             4 |         | chunk   | jbatchtest
             5 |         | chunk   | jbatchtest
(5 rows)

jbatch=# select * from step_execution;
 stepexecutionid | jobexecutionid | version | stepname |        starttime        |         endtime         | batchstatus | exitstatus | executionexception | persistentuserdata | readcount | writecount | commitcount | rollbackcount | readskipcount | processskipcount | filtercount | writeskipcount |                                                                         readercheckpointinfo                                                                         |                                                                         writercheckpointinfo                                                                         
-----------------+----------------+---------+----------+-------------------------+-------------------------+-------------+------------+--------------------+--------------------+-----------+------------+-------------+---------------+---------------+------------------+-------------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------
               1 |              1 |         | doChunk  | 2014-02-13 09:57:02.726 |                         | STARTED     |            |                    |                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
               2 |              2 |         | doChunk  | 2014-02-13 09:58:59.036 |                         | STARTED     |            |                    |                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
               3 |              3 |         | doChunk  | 2014-02-13 10:01:44.974 |                         | STARTED     |            |                    |                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
               4 |              4 |         | doChunk  | 2014-02-13 10:56:52.98  |                         | STARTED     |            |                    |                    |           |            |             |               |               |                  |             |                |                                                                                                                                                                      | 
               5 |              5 |         | doChunk  | 2014-02-13 11:18:51.965 | 2014-02-13 11:18:52.276 | COMPLETED   | COMPLETED  |                    |                    |        10 |         10 |           4 |             0 |             0 |                0 |           0 |              0 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b02000078700000000a | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000004
(5 rows)

jbatch=# select * from partition_execution ;
 partitionexecutionid | stepexecutionid | version | batchstatus | exitstatus | executionexception | persistentuserdata | readercheckpointinfo | writercheckpointinfo 
----------------------+-----------------+---------+-------------+------------+--------------------+--------------------+----------------------+----------------------
(0 rows)

jbatch=#

アプリのテーブルを見てみる

まあ普通

jbatch=# \c jbatcharts
You are now connected to database "jbatcharts" as user "kyle".
jbatcharts=# select * from chunkoutputitem ;
 id | result 
----+--------
  0 |      0
  1 |      5
  2 |     10
  3 |     15
  4 |     20
  5 |     25
  6 |     30
  7 |     35
  8 |     40
  9 |     45
(10 rows)

jbatcharts=#

備考

勝手に作られるRepositoryにはインデックスがほとんどないので、履歴が増えてきたときに備えていくつか作っておいたほうが良いような気もする。

参考文献

  1. WildFlyにXA DataSourceを登録する
  2. Creating XA Datasource from the CLI fails | Community
  3. JDBC XAデータソース - nekopの日記
  4. Glassfish, XA Transactions, and PostgreSQL | Ryan Cuprak's Blog
  5. 資源の消費

Comments [0]

Tags: jbatch

Chunk方式のStepでJDBCを使ってみる

Posted on Thursday Feb 13, 2014 at 07:25AM in Technology

Chunk方式のStepを使ってみるではJPAだったが、同じ事をJDBCでやってみる。一応大量のデータを想定した感じに作ってみる。実際に大量のデータでの実験はしてないけど。

JSR 352 Implementation - Connection close probl… | Communityによると、ここに書いてあるような実装はよろしくないようです。SELECT文の発行などは全て同一トランザクション内で完結する必要があるらしい。open()で取得するのはPKだけにして、実際のデータはreadItem()で別途取得するようにするなどした方が良いかも

トランザクション境界を跨いでJDBCの資源（Connection, Statement, ResultSet等）を使う場合は，非JTAデータソースを使いましょう．詳細はこちらを参照．また，このエントリで出している例のようにopen()でConnection, PreparedStatementを作るのはよろしくないようです．writeItems()内で，つどつど作りましょう．

環境・前提条件

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

準備

  • 資源の詳細はこのあたり
  • エンティティ、テストデータは流用する
  • @ResourceでDataSourceを注入するのでweb.xmlとjboss-web.xmlを置いてある

バッチを構成する資源

chunkjdbc.xml

  • ジョブXML。artifact以外は前回と同じ

ChunkJDBCItemReader.java

  • SELECT文でOFFSET使ってるのでPostgreSQL以外の場合は適当に変えてやる

ChunkJDBCItemProcessor.java

  • 一応コピーして作ったけど完全に前回と同じ
  • DTO作るのが面倒ならResultSetを受け取ってもよかったかも

ChunkJDBCItemWriter.java

  • PreparedStatement#addBatch()とexecuteBatch()を使ってみた
  • この例は誤っていて，open()でConnection, PreparedStatementを作るのはよろしくないようです．writeItems()内で，つどつど作りましょう．

テスト用資源

ChunkJDBCJobTest.java

  • テストクラス。ジョブの名前以外前回と同じ

実行してみる

ログはこんな感じ。実行結果もテーブル出力も特に問題なさげ

14:41:53,140 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) postConstruct(): divide=2
14:41:53,140 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) open(): checkpoint=null, index starts at=0
14:41:53,142 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) open(): checkpoint=null, index starts at=0
14:41:53,142 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=0
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=0, input=0, processed=false]
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=0, input=0, processed=false], output=ChunkOutputItem [id=0, result=0]
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=1
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=1
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=1, input=10, processed=false]
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=1, input=10, processed=false], output=ChunkOutputItem [id=1, result=5]
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=2
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=2
14:41:53,143 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=2, input=20, processed=false]
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=2, input=20, processed=false], output=ChunkOutputItem [id=2, result=10]
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=3
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): index=0
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=0, result=0]
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=1, result=5]
14:41:53,144 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=2, result=10]
14:41:53,151 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,152 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,152 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,152 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=3
14:41:53,152 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) checkpointInfo(): returns=1
14:41:53,154 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=3
14:41:53,160 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=3
14:41:53,160 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
14:41:53,160 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=4
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=4
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=5
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=5
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=5, input=50, processed=false]
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=5, input=50, processed=false], output=ChunkOutputItem [id=5, result=25]
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=6
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): index=1
14:41:53,161 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=3, result=15]
14:41:53,162 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=4, result=20]
14:41:53,162 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=5, result=25]
14:41:53,168 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,168 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,168 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,168 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=6
14:41:53,169 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) checkpointInfo(): returns=2
14:41:53,170 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=6
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=6
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=6, input=60, processed=false]
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=6, input=60, processed=false], output=ChunkOutputItem [id=6, result=30]
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=7
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=7
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=7, input=70, processed=false]
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=7, input=70, processed=false], output=ChunkOutputItem [id=7, result=35]
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=8
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=8
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=8, input=80, processed=false]
14:41:53,171 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=8, input=80, processed=false], output=ChunkOutputItem [id=8, result=40]
14:41:53,172 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=9
14:41:53,172 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): index=2
14:41:53,172 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=6, result=30]
14:41:53,172 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=7, result=35]
14:41:53,172 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=8, result=40]
14:41:53,173 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,173 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,173 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,173 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=9
14:41:53,173 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) checkpointInfo(): returns=3
14:41:53,174 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=9
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=9
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=ChunkInputItem [id=9, input=90, processed=false]
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemProcessor] (batch-batch - 7) processItem(): input=ChunkInputItem [id=9, input=90, processed=false], output=ChunkOutputItem [id=9, result=45]
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=10
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): index=10
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) readItem(): returning=null
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): index=3
14:41:53,175 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): item=ChunkOutputItem [id=9, result=45]
14:41:53,176 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) writeItems(): ps#executeBatch() result=1
14:41:53,176 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=10
14:41:53,176 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) checkpointInfo(): returns=4
14:41:53,177 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) checkpointInfo(): returns=10
14:41:53,178 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) close()
14:41:53,178 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) close()
14:41:53,178 WARN  [com.arjuna.ats.jta] (batch-batch - 7) ARJUNA016087: TransactionImple.delistResource - unknown resource
14:41:53,178 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemReader] (batch-batch - 7) close()
14:41:53,178 FINE  [org.nailedtothex.jbatch.example.chunkjdbc.ChunkJDBCItemWriter] (batch-batch - 7) close()

備考

  • 定型コードが多い。SQL文とバインド変数を外出しすれば、かなり共通化できるような気もするが…。CDIをうまく使えばなんとかなりそうな気もするけど。そのうちまたいろいろ試してみる。
  • closeするところはDbUtils.closeQuietly()使えばちょっと楽になりそう

参考文献

  1. 2. SQL文の実行 (3) | TECHSCORE(テックスコア)
  2. SOLVED: Re: HELP: How to tame the 8.3.x JDBC driver with a biq guery result set
  3. JDBC: ResultSet

Comments [0]

Tags: jbatch

Chunk方式のStepで例外発生時にリトライさせてからスキップさせてみる

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

Chunk方式のStepで例外発生時にスキップさせてみる でリトライとスキップをそれぞれ別々に試してみたが、ここではリトライを試み、それでも成功しない場合は、そのデータをスキップして処理を継続させる、というのをやってみる

環境・前提条件

JSR352仕様を確認する

[1]に以下のようにある

8.2.1.4.3 Retry and Skip the Same Exception

When the same exception is specified as both retryable and skippable, retryable takes precedence over skippable during regular processing of the chunk. While the chunk is retrying, skippable takes precedence over retryable since the exception is already being retried.

This allows an exception to initially be retried for the entire chunk and then skipped if it recurs. When retrying with default retry behavior (see section 8.2.1.4.4) the skips can occur for individual items, since the retry is done with an item-count of 1.

リトライの回数は1回で固定になるようだ。失敗後は1回はリトライするが、それでも駄目ならスキップとなる。retry-limitを指定してみたが、ここでリトライ回数を指定するために使われる値ではないようだ。

バッチを作る

仕様

  • 入力、出力、処理内容は基本的にChunk方式のStepで例外発生時にスキップさせてみるでやったのと同じ
  • 6件目のデータ処理時にItemReaderでRuntimeExceptionが起こる。リトライが試みられたあとさらに例外が起こり、スキップされる
    • RuntimeExceptionは以下の両方に設定してある
      • skippable-exception-classes
      • retryable-exception-classes

資源

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

動かしてみる

ログ

16:36:59,072 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) open(): checkpoint=null, index starts at=0
16:36:59,076 DEBUG [org.hibernate.SQL] (batch-batch - 5) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
16:36:59,078 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) open(): checkpoint=null, index starts at=0
16:36:59,079 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=0, failAt=5
16:36:59,079 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=0, input=0, processed=false]
16:36:59,079 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=0, input=0, processed=false], output=ChunkOutputItem [id=0, result=0]
16:36:59,079 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=1
16:36:59,079 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=1, failAt=5
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=1, input=10, processed=false]
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=1, input=10, processed=false], output=ChunkOutputItem [id=1, result=5]
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=2
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=2, failAt=5
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=2, input=20, processed=false]
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=2, input=20, processed=false], output=ChunkOutputItem [id=2, result=10]
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=3
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): index=0
16:36:59,080 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=0, result=0]
16:36:59,081 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=1, result=5]
16:36:59,081 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=2, result=10]
16:36:59,081 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=3
16:36:59,081 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) checkpointInfo(): returns=1
16:36:59,083 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=3
16:36:59,086 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,087 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,088 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,116 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=3, failAt=5
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=4
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=4, failAt=5
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
16:36:59,117 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=5
16:36:59,118 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=5, failAt=5
16:36:59,118 WARNING [org.nailedtothex.jbatch.example.chunkretry.MyRetryReadListener] (batch-batch - 5) onRetryReadException(): java.lang.RuntimeException: 5
    at org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader.readItem(ChunkRetrySkipItemReader.java:43) [classes:]
    at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:343) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:288) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:190) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    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)

16:36:59,119 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=6
16:36:59,119 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) close()
16:36:59,119 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) close()
16:36:59,119 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) open(): checkpoint=3, index starts at=3
16:36:59,120 DEBUG [org.hibernate.SQL] (batch-batch - 5) select chunkinput0_.id as id1_0_, chunkinput0_.input as input2_0_, chunkinput0_.processed as processe3_0_ from ChunkInputItem chunkinput0_ order by chunkinput0_.id
16:36:59,122 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) open(): checkpoint=1, index starts at=1
16:36:59,122 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=3
16:36:59,122 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=3, failAt=5
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=3, input=30, processed=false]
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=3, input=30, processed=false], output=ChunkOutputItem [id=3, result=15]
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=4
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): index=1
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=3, result=15]
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=4
16:36:59,123 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) checkpointInfo(): returns=2
16:36:59,125 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=4
16:36:59,125 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,152 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=4, failAt=5
16:36:59,152 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=4, input=40, processed=false]
16:36:59,152 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=4, input=40, processed=false], output=ChunkOutputItem [id=4, result=20]
16:36:59,153 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=5
16:36:59,153 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): index=2
16:36:59,153 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=4, result=20]
16:36:59,153 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=5
16:36:59,153 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) checkpointInfo(): returns=3
16:36:59,155 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=5
16:36:59,155 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,183 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=5, failAt=5
16:36:59,183 WARNING [org.nailedtothex.jbatch.example.chunkskip.MySkipReadListener] (batch-batch - 5) onSkipReadItem(): java.lang.RuntimeException: 5
    at org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader.readItem(ChunkRetrySkipItemReader.java:43) [classes:]
    at org.jberet.runtime.runner.ChunkRunner.readItem(ChunkRunner.java:343) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.ChunkRunner.readProcessWriteItems(ChunkRunner.java:288) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.ChunkRunner.run(ChunkRunner.java:190) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:204) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:131) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:162) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:58) [jberet-core-1.0.1.Beta-SNAPSHOT.jar:1.0.1.Beta-SNAPSHOT]
    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)

16:36:59,185 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=6
16:36:59,185 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=6, failAt=5
16:36:59,186 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=6, input=60, processed=false]
16:36:59,186 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=6, input=60, processed=false], output=ChunkOutputItem [id=6, result=30]
16:36:59,186 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=7
16:36:59,186 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=7, failAt=5
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=7, input=70, processed=false]
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=7, input=70, processed=false], output=ChunkOutputItem [id=7, result=35]
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=8
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=8, failAt=5
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=8, input=80, processed=false]
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=8, input=80, processed=false], output=ChunkOutputItem [id=8, result=40]
16:36:59,187 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=9
16:36:59,188 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): index=3
16:36:59,188 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=6, result=30]
16:36:59,188 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=7, result=35]
16:36:59,189 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=8, result=40]
16:36:59,189 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=9
16:36:59,189 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) checkpointInfo(): returns=4
16:36:59,191 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=9
16:36:59,191 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,192 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,193 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=9, failAt=5
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=ChunkInputItem [id=9, input=90, processed=false]
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemProcessor] (batch-batch - 5) processItem(): input=ChunkInputItem [id=9, input=90, processed=false], output=ChunkOutputItem [id=9, result=45]
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=10
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): index=10, failAt=5
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) readItem(): returning=null
16:36:59,221 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): index=4
16:36:59,222 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) writeItems(): item=ChunkOutputItem [id=9, result=45]
16:36:59,222 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=10
16:36:59,222 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) checkpointInfo(): returns=5
16:36:59,223 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) checkpointInfo(): returns=10
16:36:59,224 DEBUG [org.hibernate.SQL] (batch-batch - 5) insert into ChunkOutputItem (result, id) values (?, ?)
16:36:59,252 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) close()
16:36:59,269 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) close()
16:36:59,270 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemReader] (batch-batch - 5) close()
16:36:59,270 FINE  [org.nailedtothex.jbatch.example.chunkretryskip.ChunkRetrySkipItemWriter] (batch-batch - 5) close()

Repository

job_execution

jbatch=# select * from job_execution order by jobexecutionid desc limit 1;
 jobexecutionid | jobinstanceid | version |       createtime        |        starttime        |         endtime         |     lastupdatedtime     | batchstatus | exitstatus |    jobparameters     | restartposition 
----------------+---------------+---------+-------------------------+-------------------------+-------------------------+-------------------------+-------------+------------+----------------------+-----------------
            127 |           122 |         | 2014-02-15 16:36:59.068 | 2014-02-15 16:36:59.068 | 2014-02-15 16:36:59.272 | 2014-02-15 16:36:59.272 | COMPLETED   | COMPLETED  | itemReaderFailAt = 5+| 
                |               |         |                         |                         |                         |                         |             |            | divide = 2          +| 
                |               |         |                         |                         |                         |                         |             |            |                      | 
(1 row)

step_execution

jbatch=# select * from step_execution where jobexecutionid =127;
 stepexecutionid | jobexecutionid | version | stepname |       starttime        |        endtime         | batchstatus | exitstatus | executionexception | persistentuserdata | readcount | writecount | commitcount | rollbackcount | readskipcount | processskipcount | filtercount | writeskipcount |                                                                         readercheckpointinfo                                                                         |                                                                         writercheckpointinfo                                                                         
-----------------+----------------+---------+----------+------------------------+------------------------+-------------+------------+--------------------+--------------------+-----------+------------+-------------+---------------+---------------+------------------+-------------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------
             142 |            127 |         | doChunk  | 2014-02-15 16:36:59.07 | 2014-02-15 16:36:59.27 | COMPLETED   | COMPLETED  |                    |                    |        11 |          9 |           5 |             1 |             1 |                0 |           0 |              0 | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b02000078700000000a | \xaced0005737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000005
(1 row)

動作の流れを見てみる

ざっくり

  1. 3件目までは普通に完走
  2. 6件目で例外が起きて、バッファリングされていた4, 5件目の処理結果は破棄
  3. item-count=1に設定されリトライが行われる
  4. 4, 5件目が1件ずつ処理されて結果がDBに書き込まれる
  5. 6件目で2回目の例外が起きる。6件目はあきらめてスキップされる
  6. 7件目以降が1件ずつ処理されて完走

備考

  • リトライの回数を指定できると嬉しいような気はするがまあこれはこれでいいのかも
  • アプリ側でリトライの回数を数えて、あきらめる時はスキップ用例外を投げる、みたいな感じで制御してもいいかも

参考文献

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

Comments [0]

Tags: jbatch

Hot tags

Below are the most often used tags in the blog. Hover over a tag to see a count of entries, click a tag to see the most recent posts with the tag.