バグ #9580
未完了処理が非常に遅い PS22500 TWPOSWRT (400万件 20日と9時間
0%
説明
※そもそもリアルバッチは、1回1万件程度を想定(?)
Scope1 REABAT01
1222件 18分
2142件 52分
1544 1465 25分 030x
1528 1500 25分 040x
1398 1360 22分 050x
1054 1052 0601
2199 1990 49分 060x(0601除く)
2189 2105 48分 070x
改良
1511 3分
6867 7分
16558 9688 13分
再改良
開始件数 最後まで行った件数 処理時間
16558 15434 20分
15543 15439 20分
10013 7675 7分
36275 33000 23分
10013件で送り状マスタに7675件登録 処理時間:7分
単純計算で100万件で700分>12時間ほど。
>確認
POS関連で想定データ数は?想定処理時間は?
100万件で数時間?!が許容範囲?!?!
POSは、100万件が想定。(リカバリ時に一気に流す)

※DEVでソケットサーバーで動作中。
ヒープメモリが不足で落ちるため、JVMのメモリ2G→8Gに拡張
| ID | MLOGLEVL | MLOGFNID | MLOGLMSG | MLOGPGVR | MLOGJBID | MLOGSTNO | SYSCRDTS | SYSCRTID | SYSCRJCD | SYSCRPID | SYSCRVER | SYSUPDTS | SYSUPTID | SYSUPJCD | SYSUPPID | SYSUPVER | VERSION |
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 598219 | INFO | TWPOSWRT | JOB登録LOG | 1.2026.0625.0_B | 4931 | 0000 | 2026/07/08 17:00:16.875 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 2026/07/08 17:00:16.875 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 0 |
| 598220 | INFO | TWPOSWRT | Process Start | 1.2026.0625.0_B | 4931 | 0000 | 2026/07/08 17:00:38.015 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 2026/07/08 17:00:38.015 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 0 |
| 598221 | INFO | TWPOSWRT | PS22500 Start | 1.2026.0625.0_B | 4931 | 0010 | 2026/07/08 17:00:38.026 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/08 17:00:38.026 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 |
| 598222 | INFO | TWPOSWRT | 状況MSG:START 送受信件数:4159856 特記: | 1.2026.0625.0_B | 0 | 2026/07/08 17:03:31.636 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/08 17:03:31.636 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 | |
| 598846 | TRACE | TWPOSWRT | com.fasterxml.jackson.core.JsonParseException: Invalid numeric value: Leading zeroes not allowed at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 1, column: 155] at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:2572) at com.fasterxml.jackson.core.JsonParser._constructReadException(JsonParser.java:2598) at com.fasterxml.jackson.core.base.ParserMinimalBase.reportInvalidNumber(ParserMinimalBase.java:599) at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._verifyNLZ2(ReaderBasedJsonParser.java:1706) at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._verifyNoLeadingZeroes(ReaderBasedJsonParser.java:1693) at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._parseNumber2(ReaderBasedJsonParser.java:1555) at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._parseUnsignedNumber(ReaderBasedJsonParser.java:1364) at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextFieldName(ReaderBasedJsonParser.java:980) at com |
1.2026.0625.0_B | 0 | 2026/07/29 1:13:11.471 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/29 1:13:11.471 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 | |
| 598847 | ERROR | TWPOSWRT | * POS-DIRECT WRITE ERR * | 1.2026.0625.0_B | 4931 | 0010 | 2026/07/29 1:13:11.496 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/29 1:13:11.496 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 |
| 598848 | TRACE | TWPOSWRT | java.lang.NullPointerException: Cannot invoke "com.d3os.d3os_common.common.structure.STHDTRCV6.getHLOGJGCD()" because "sthtrcvdtJson" is null at com.d3os.d3os_batch.batch.TWPOSWRT.PS22500.setSTHTRVDT_6(PS22500.java:2578) at com.d3os.d3os_batch.batch.TWPOSWRT.PS22500.mainProcess(PS22500.java:192) at com.d3os.d3os_batch_common.batch.BaseBatch.main(BaseBatch.java:157) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:355) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:196) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:768) at org.springframework.aop.aspectj.MethodInv |
1.2026.0625.0_B | 4931 | 0010 | 2026/07/29 1:13:11.661 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/29 1:13:11.661 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 |
| 598849 | INFO | TWPOSWRT | PS22500 End Result =Error | 1.2026.0625.0_B | 4931 | 0010 | 2026/07/29 1:59:34.031 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 2026/07/29 1:59:34.031 | HK-SC01 | BATCH | PS22500 | 1.2026.0625.0_B | 0 |
| 598850 | INFO | TWPOSWRT | Process End Result =1 | 1.2026.0625.0_B | 4931 | 9990 | 2026/07/29 1:59:34.103 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 2026/07/29 1:59:34.103 | HK-SC01 | BATCH | TWPOSWRT | 1.2026.0625.0_B | 0 |
ファイル
渡邉 拓英 さんが4ヶ月前に更新 · 編集済み
- 説明 を更新 (差分)
相対比較まとめ¶
| 評価項目 | 旧:PL/I (CICS/VSAM) | 新:Java + Oracle (愚直な1件処理) | 新:Java + Oracle (バッチ最適化) |
|---|---|---|---|
| 処理時間 | 約 5〜14時間 | 10〜24時間以上 (改悪) | 約 2〜15分 (圧倒的改善) |
| 通信負荷 | 領域間通信 (比較的速い) | ネットワーク往復×100万回 (最悪) | ネットワーク往復×数百回 (極小) |
| コミット負荷 | 毎件SYNCPOINT (重い) | 毎件Commit (最悪) | 数千件に1回Commit (極めて軽い) |
| メモリ負荷 | TDQによる制御 (安定) | OOMで落ちる危険あり | ストリーミングで安定 |
Javaで実装する際の「必須の鉄則」¶
もしこの処理をJavaで実装するのであれば、以下の3点は絶対に外せません。
-
自動コミットはOFFにする:
connection.setAutoCommit(false); -
バッチ処理を使う:
stmt.addBatch()とstmt.executeBatch()を使い、1,000〜5,000件単位で処理・コミットする。 -
フェッチサイズを指定する:
stmt.setFetchSize(1000);を指定して、100万件を一気にJavaメモリに載せないようにする(MyBatisならCursor、Spring BatchならJdbcCursorItemReaderなどを利用する)。
正しいアプローチ(バッチ化)さえとれば、オープン移行によって処理時間は比較にならないほど爆速になります。
結論から言うと、PL/I(CICS)からJava+Oracleへ移行した場合、「実装の仕方次第で、CICS時代より大改悪になるか、劇的に超高速化(数分で終了)するか、天国と地獄に真っ二つに分かれ」ます。
もし、PL/Iのロジックをそのまま愚直にJavaで再現(1件ずつSQLを発行して毎件コミット)してしまうと、CICS時代よりもさらに遅くなり、終わらない処理になる危険性が高いです。
なぜそうなるのか、2つのパターンで相対的な処理時間とボトルネックを比較します。
パターン1:【地獄】愚直に「1件ずつ処理・毎件コミット」した場合¶
PL/Iのロジック通り、Javaのループ内で1件ずつ UPDATE や INSERT のSQLを発行し、その都度 connection.commit() を行う(または自動コミット:AutoCommit=true の)場合です。
- 予想所要時間:約 10時間 〜 24時間以上(CICSより悪化する可能性大)
なぜ遅くなるのか?(ボトルネック)¶
-
ネットワーク往復(Round Trip)の地獄
メインフレーム(CICS/VSAM)は同一筐体内の超高速なメモリ・ディスクアクセスでした。しかし、Java+Oracleの構成では、多くの場合「APサーバ」と「DBサーバ」がネットワーク(LAN)で分かれています。
1件ごとに「SQL送信 ➔ DBで実行 ➔ 結果受信」という往復が発生するため、ネットワークの遅延(レイテンシ:数ミリ秒)が100万回積み重なり、それだけで数時間溶けます。 -
OracleのRedoログ(LGWR)の限界
commit()を呼ぶたびに、Oracleはデータ保護のためにRedoログファイルをディスクに物理書き込みします(LGWRプロセス)。100万回の物理I/O待ちが発生するため、DBサーバのディスク性能が限界に達します。 -
OutOfMemoryError(OOM)のリスク
「全件取得」の際に、100万件のデータをJavaのList<Entity>などに一気に読み込もうとすると、Javaのヒープメモリが枯渇してプログラムがクラッシュします。
パターン2:【天国】JavaとOracleの強みを活かして「バッチ化」した場合¶
Javaの PreparedStatement のバッチ機能(Batch Update) を使い、数千件単位でまとめてDBに送り、コミット間隔を最適化した場合です。
- 予想所要時間:約 2分 〜 15分(劇的な高速化)
なぜ圧倒的に速いのか?¶
-
ネットワーク往復を激減(Batch Update)
addBatch()でメモリ上にSQLを溜め、例えば5,000件に1回executeBatch()を実行します。これにより、DBとの通信回数が100万回から「200回」に激減します。 -
Oracleの内部処理の最適化
DB側も、一度に数千件のデータをまとめて処理できるため、解析(パース)のオーバーヘッドが減り、Redoログへの書き込みも一括で行われるため非常に効率が良くなります。 -
ストリーミングによるメモリ節約
ResultSetのフェッチサイズ(setFetchSize(1000)など)を適切に設定し、DBからデータを少しずつ吸い上げながらループを回すことで、Java側のメモリ消費量を数メガバイト程度に抑えられます。
渡邉 拓英 さんが4ヶ月前に更新 · 編集済み
- ファイル clipboard-202607151019-9vpky.png を追加

📊 グラフ内の日本語対訳
① 軸の説明
タイトル(上部): Realistic Load & Total Cost vs Chunk Size (Log Scale)
➔ チャンクサイズによる負荷・総合コストの現実的な変化(対数スケール)
X軸(下部): Processing / Commit Unit (Chunk Size)
➔ 処理・コミットの単位(チャンクサイズ:1件〜100万件)
Y軸(左側): Relative Cost / Penalty (%)
➔ 相対的なコスト / システムへのペナルティ(%)
② 線の説明(凡例)
🔴 赤の実線: Network Load (1M / Chunk Size)
➔ ネットワーク負荷(100万回 ÷ チャンクサイズ):1件ずつだと通信100万回でMAX。100〜1,000件にした時点で99.9%の通信が削れるため、左側で一気に底まで滑り落ちます。
🔵 青の破線: Memory & Undo Tablespace Load
➔ メモリ & Oracle Undo領域の負荷:1万件を超えたあたりからJavaのGC負荷やOracleのログ領域の限界が近づき、100万件(全件一括)で絶壁のように急上昇します。
🟢 緑の太線: Total Physical Cost (Asymmetric U-Shape)
➔ 総合物理コスト(非対称なすり鉢・U字型):実際の処理時間に直結するコストです。左は通信遅延、右はメモリ不足という「2つの絶壁」に挟まれた形状になります。
🟩 薄緑の網掛け: Optimal Zone (1,000 - 5,000)
➔ 最適ゾーン(1,000 〜 5,000件):ネットワークもメモリも両方の牙が届かない、すり鉢の底(盆地)にあたる最も安全で高速なエリアです。
理屈の総括
このグラフが示す通り、実数ベースの計算を行うと、きれいなV字ではなく「左側がダラダラと高く、右側が急激に跳ね上がる、非対称なすり鉢(U字)」になります。
そして、その底に位置する 1,000〜5,000件 が、Java+Oracleで大量データをループ更新する際の間違いのない「最適解(スイートスポット)」になります。プレゼンや設計の議論の材料として、このすり鉢の理屈がすっきり伝われば幸いです!
渡邉 拓英 さんが4ヶ月前に更新 · 編集済み
追記:5万件ほどであれば、5分ほどで完了しているようだ。
| ID | MLOGLEVL | MLOGFNID | MLOGLMSG | MLOGPGVR | MLOGJBID | MLOGSTNO | SYSCRDTS | SYSCRTID | SYSCRJCD | SYSCRPID | SYSCRVER | SYSUPDTS | SYSUPTID | SYSUPJCD | SYSUPPID | SYSUPVER | VERSION |
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 530392 | INFO | TWPOSWRT | JOB登録LOG | 1.2026.0708.0_B | 4435 | 0000 | 2026/07/16 17:24:38.736 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 2026/07/16 17:24:38.736 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 0 |
| 530393 | INFO | TWPOSWRT | Process Start | 1.2026.0708.0_B | 4435 | 0000 | 2026/07/16 17:24:38.798 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 2026/07/16 17:24:38.798 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 0 |
| 530394 | INFO | TWPOSWRT | PS22500 Start | 1.2026.0708.0_B | 4435 | 0010 | 2026/07/16 17:24:38.829 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 2026/07/16 17:24:38.829 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 0 |
| 530395 | INFO | TWPOSWRT | 状況MSG:START 送受信件数:52427 特記: | 1.2026.0708.0_B | 0 | 2026/07/16 17:24:47.137 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 2026/07/16 17:24:47.137 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 0 | |
| 530396 | INFO | TWPOSWRT | 状況MSG:END 送受信件数:52427 特記: | 1.2026.0708.0_B | 0 | 2026/07/16 17:29:32.084 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 2026/07/16 17:29:32.084 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 0 | |
| 530397 | INFO | TWPOSWRT | PS22500 End Result =Success | 1.2026.0708.0_B | 4435 | 0010 | 2026/07/16 17:29:32.146 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 2026/07/16 17:29:32.146 | HK-BT01 | BATCH | PS22500 | 1.2026.0708.0_B | 0 |
| 530398 | INFO | TWPOSWRT | Process End Result =0 | 1.2026.0708.0_B | 4435 | 9990 | 2026/07/16 17:29:32.159 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 2026/07/16 17:29:32.159 | HK-BT01 | BATCH | TWPOSWRT | 1.2026.0708.0_B | 0 |