Chunk方式のStepの再実行時の挙動を確かめてみる
TweetPosted 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でもそのうち試してみる。たぶん同じだろうけど
Tags: jbatch
WildFly8.0.0.Finalで出るGuavaのNoClassDefFoundErrorの対処
TweetPosted 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=#
単純に書き漏れたのだろうか。次のリリースでは直っていることを祈る
Tags: jbatch
Logging with log4j appenders
TweetPosted on Thursday Feb 13, 2014 at 10:59AM in Technology
- We can use WildFly's logging mechanism with log4j appenders.
Environment
- WildFly 8.0.0.Final
- Oracle JDK7u51
- OS X 10.9.2
Precondition
- Ensure we already have a logger named “hoge.logger1”.
- I will use this servlet to logging test.
package logger;
import java.io.IOException;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
@WebServlet("/")
public class LogServlet extends HttpServlet {
private static final org.slf4j.Logger SLF4J_LOGGER1 = org.slf4j.LoggerFactory.getLogger("hoge.logger1");
protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
StringBuilder sb = new StringBuilder(1200);
for(int i=0; i<1200; i++){
sb.append(i%10);
}
SLF4J_LOGGER1.info("0-1199: {}", sb);
SLF4J_LOGGER1.info("exception logging test", new AssertionError("test"));
}
}
- Log4j is shipped with out-of-box WildFly8 so we don't need any preparation about log4j.
Defining with org.apache.log4j.FileAppender
Create an custom-handler named “LOG4J_FILE”
/subsystem=logging/custom-handler=LOG4J_FILE:add( \
class="org.apache.log4j.FileAppender", \
module="org.apache.log4j", \
named-formatter=PATTERN, \
level=INFO, \
properties={ \
File="/tmp/log4jtest.log", \
Append=true})
Assign the handler to a logger
/subsystem=logging/logger=hoge.logger1:assign-handler(name=LOG4J_FILE)
Output
2014-03-07 14:57:46,538 INFO [hoge.logger1] (default task-10) 0-1199: 012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789
2014-03-07 14:57:46,538 INFO [hoge.logger1] (default task-10) exception logging test: java.lang.AssertionError: test
at logger.LogServlet.doGet(LogServlet.java:22) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [jboss-servlet-api_3.1_spec-1.0.0.Final.jar:1.0.0.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:113) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.AuthenticationCallHandler.handleRequest(AuthenticationCallHandler.java:52) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:61) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:240) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:227) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:73) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:146) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:168) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:687) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
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]
Defining with org.apache.log4j.net.SyslogAppender
Create an custom-handler named “LOG4J_SYSLOG”
/subsystem=logging/custom-handler=LOG4J_SYSLOG:add( \
class="org.apache.log4j.net.SyslogAppender", \
module="org.apache.log4j", \
formatter="%-5p [%c] (%t) %s%E%n", \
level=INFO, \
properties={ \
Header=true, \
syslogHost="localhost:514", \
facility="local1", \
facilityPrinting=false})
Assign the handler to a logger
/subsystem=logging/logger=hoge.logger1:assign-handler(name=LOG4J_SYSLOG)
Output
Mar 7 15:02:33 kyle-no-MacBook.local INFO [hoge.logger1] (default task-1) 0-119]: 0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456...
Mar 7 15:02:33 kyle-no-MacBook.local Unknown: ...78901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789
Mar 7 15:02:33 kyle-no-MacBook.local INFO [hoge.logger1] (default task-1) exception logging tes]: java.lang.AssertionError: test
at logger.LogServlet.doGet(LogServlet.java:22) [classes:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [jboss-servlet-api_3.1_spec-1.0.0.Final.jar:1.0.0.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
Mar 7 15:02:33 kyle-no-MacBook.local ...est(SecurityContextAssociationHandler.java: 78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:113) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.AuthenticationCallHandler.handleRequest(AuthenticationCallHandler.java:52) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:61) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
Mar 7 15:02:33 kyle-no-MacBook.local ...Handler.handleRequest(CachedAuthenticatedSessionHandler.java: 70) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:240) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
Mar 7 15:02:33 kyle-no-MacBook.local ...ertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java: 227) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:73) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:146) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:168) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:687) [undertow-core-1.0.0.Final.jar:1.0.0.Final]
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]
Conclusion
- Anyway, we can use log4j appenders with custom-handler surely.
- But something goes wrong with exception logging with SyslogAppender.
- Some parts of stacktraces were lost.
- The last digit of message strings are replaced by ']'.
References
- [AS7-4925] Log4j appenders should also be allowed for custom handlers - JBoss Issue Tracker
- Log4jAppenderHandler usage | Community
- #8059525 - Pastie
- Use Log4j appender as custom-handler in AS 7.1…. | Community
- Magnus K Karlsson: How to setup log4j Syslog Appender in JBoss EAP 6
- Programming fun at startup: log4j TCP SyslogAppender
Tags: wildfly
WildFly8でPostgreSQLをジョブレポジトリにしてみる
TweetPosted 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にはインデックスがほとんどないので、履歴が増えてきたときに備えていくつか作っておいたほうが良いような気もする。
参考文献
Tags: jbatch
Chunk方式のStepでJDBCを使ってみる
TweetPosted 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()使えばちょっと楽になりそう
参考文献
Tags: jbatch
