[CAIレシピ] アプリケーション接続(JDBC)の処理性能

はじめに

DBとのデータ連携をCAIで実装する場合、アプリケーション接続(JDBC)とDAS接続を利用する方法があることを以下の記事で紹介しています。

• DBを操作するためのアプリケーション接続設定
• DBデータの取得(SELECT)
• DBデータの登録(INSERT)
• DBデータの更新(UPDATE)
• DBデータの削除(DELETE)
• DASによるSQL実行
• DASによるストアドプロシージャ実行とストアドファンクションの実行

大量のデータ処理を実行する場はアプリケーション接続(JDBC)は処理性能が良くないと紹介していましたが、この記事では実際にアプリケーション接続(JDBC)を利用した場合にどの程度の時間を要するのかを確認したいと思います。

1000件のINSERT

以下のような形式のSQL －TABLE-BのデータをそのままTABLE-AにINSERTする処理－ を実行する場合、DAS接続による実装ではCAIプロセスの実行時間はSQLの実行時間に依存します。また、DBのデータはSecure Agent環境に一時的に取得されることもないので、CPU・メモリ負荷も低い実装となります。

• INSERT INTO TABLE-A SELECT *** FROM TABLE-B

一方で、アプリケーション接続を利用して同様の処理を実行する場合、次のようなSQLの実行が必要になります(主キーを有するテーブルを参照する場合)。

• データ取得処理のSQLとして SELECT <主キー項目> FROM TABLE-B を1回実行
• データ取得処理のSQLとして SELECT <主キー以外の項目> FROM TABLE-B を取得行数分実行
• データ登録処理のSQLとして INSERT INTO TABLE-A VALUES *** を取得行数分実行

たとえば、テーブル TABLE-B のデータが1000件あった場合、机上での計算では2001回のSQL実行が必要になります(対してDAS接続は1回のSQL実行で処理が完了する)。また、SQL実行に伴いCAIプロセス側では次のような状況が想定されます。

• 処理時間が長くなると想定される
• CPU使用率が高い状態が発生する可能性がある
• メモリ使用率が高い状態が発生する可能性がある
• ステップ数の増加

テストデータの用意

次のSQLを実行してテストデータを用意します。

SELECT用のテーブル+データ作成、INSERT用のテーブル作成

-- SELECT用テーブルの作成
create table recipeTest003pk(col1 varchar2(10), col2 char(10), col3 char(10), col4 char(10), col5 char(10)); 
-- INSERT用テーブルの作成
create table recipeTest004pk(col1 varchar2(10), col2 char(10), col3 char(10), col4 char(10), col5 char(10)); 
-- 各テーブルへの主キー制約の追加
alter table recipeTest003pk add constraint pk_recipeTest003pk primary key(col1); 
alter table recipeTest004pk add constraint pk_recipeTest004pk primary key(col1); 
-- テストデータ1000件の登録
insert into recipeTest003pk select level, level, level, level, level from dual connect by level <= 1000; 
commit; 

このSQLでは1つのVARCHAR2(10)型と4つのCHAR(10)型のフィールドを有するテーブル recipeTest003pk および recipeTest004pk を作成しています。更に、テーブル recipeTest003pkには、1000行のデータを作成しています。

後述するCAIプロセスでは以下のSQLに相当する処理をアプリケーション接続(JDBC)を利用して実装しています。

• INSERT INTO recipeTest004pk select col1, col2, col3, col4, col5 from recipeTest003pk

CAIプロセスの作成

1. 追加したテスト用のテーブルを参照できるようにするために アプリケーション接続 recipe-appConn-Jdbc の画面を開いて、必要に応じて Object Filter にエントリを追加した後にアセットのパブリッシュを実行します。
   

2. SQLINSERT INTO recipeTest004pk select col1, col2, col3, col4, col5 from recipeTest003pk に相当する処理として、CAIプロセスは次のように定義しています
   
   CAIプロセスの実装手順は次の記事で紹介しているので、詳細な手順は割愛させてください。

   • DBデータの取得(SELECT)
   • DBデータの登録(INSERT)

3. 保存してパブリッシュします。

このCAIプロセスを実行した際の動作を確認してゆきます。

処理時間

CAIプロセスを実行すると10分が経過したところで次のレスポンスが返ってきました。

{"error":{"code":500,"message":"Timeout waiting for reply from process ID 22461 (recipe-psa-jdbcInsert1000)."}}

実行時間が10分(600秒)を過ぎたためにタイムアウトと判断されているようです。CAIプロセス自体は43分ほど実行された結果、失敗(Fault)ステータスで終了していました。

SQLを記述してDAS接続で実行すれば一瞬で終わる処理ですが、43分かかったうえに失敗か・・・という気持ちですね・・・

詳細ビューによる動作確認

次の手順で詳細ビューからCAIプロセスの 実行ログ を確認すると1行あたりのINSERT処理の完了までに3秒程度を要している状況が確認できました。

1. アプリケーション統合コンソール > CAIプロセスの実行結果 の画面右上3点リーダーオプションより 詳細ビュー を選択します。
   

2. Outline タブの虫メガネアイコンをクリックします。
   

3. 実行ログ より Assignment_to_tmpRow_tmpRows(2つ目の割り当てステップ) がおおよそ、3秒間隔で実行されている動作を確認できます。
   

更に 実行ログ の最後には次の出力(Activity execution limit exceeded)があることからジャンプステップによる実行制御で紹介している プロセスアクティビティ実行制限 によりCAIプロセスが失敗(Fault)ステータスで終了していることがわかります。

[22461][2025-12-17 03:40:06.647] Assign Perform_Output_Mapping: Completed with fault: 
AeBusinessProcessException 
(Error executing activity /process/flow/scope[@name='RECIPETEST004PK']/sequence/assign[@name='Perform_Output_Mapping'].  
Reason: (Terminating non-persistent process, unable to suspend. Tenant: $public
, Process ID: 22461, Suspend reason: Activity execution limit exceeded)) : 

CPU使用率

CAIプロセスの実行中に、次のAWKスクリプトを利用して1秒毎にprocess engine(pgrep -f bootstrap.jar)のCPU使用率を確認します。

top -b -d 1 | awk -v PID=`pgrep -f bootstrap.jar` '
{
   if($0 ~ "^top"){time=$3;}
   if($0 ~ "^ *" + PID){printf("%s, %s\n", time, $0);}
}
'

以下、実行結果です。%CPUが瞬間的に100を超える(1コア分を使い切る)状況は見えますが、想像より静かに実行されているように見えます。

※列補足※    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
02:58:00,   10330 infaUSW5  20   0 7465888   1.5g  37632 S  11.8   4.8  31:40.17 java
02:58:01,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:40.18 java
02:58:02,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   7.9   4.8  31:40.26 java
02:58:03,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:40.27 java
02:58:04,   10330 infaUSW5  20   0 7465888   1.5g  37632 S  10.9   4.8  31:40.38 java
02:58:05,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   7.9   4.8  31:40.46 java
02:58:06,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:40.47 java
02:58:07,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   9.9   4.8  31:40.57 java
02:58:08,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:40.58 java
02:58:09,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   8.8   4.8  31:40.67 java
02:58:10,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   2.0   4.8  31:40.69 java
02:58:11,   10330 infaUSW5  20   0 7465888   1.5g  37632 S  20.8   4.8  31:40.90 java ★%CPUは1-20%を上下する動作が殆どでした
02:58:12,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   9.9   4.8  31:41.00 java
02:58:13,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:41.01 java
02:58:14,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   8.9   4.8  31:41.10 java
02:58:15,   10330 infaUSW5  20   0 7465888   1.5g  37632 S   1.0   4.8  31:41.11 java
02:58:17,   10330 infaUSW5  20   0 7463784   1.5g  35528 S  22.8   4.8  31:41.34 java
02:58:18,   10330 infaUSW5  20   0 7463784   1.5g  35528 S   7.9   4.8  31:41.42 java
02:58:19,   10330 infaUSW5  20   0 7463784   1.5g  35528 S 120.6   4.8  31:42.65 java ★%CPUが100を超える動作はとても稀でした
02:58:20,   10330 infaUSW5  20   0 7465888   1.5g  38884 S 112.9   4.8  31:43.79 java
02:58:21,   10330 infaUSW5  20   0 7465888   1.5g  38884 S 101.0   4.8  31:44.81 java
02:58:22,   10330 infaUSW5  20   0 7465888   1.5g  38884 S 110.8   4.8  31:45.94 java
02:58:23,   10330 infaUSW5  20   0 7465888   1.5g  38884 S  86.1   4.8  31:46.81 java
02:58:24,   10330 infaUSW5  20   0 7465888   1.5g  38884 S   1.0   4.8  31:46.82 java
02:58:25,   10330 infaUSW5  20   0 7465888   1.5g  38884 S  58.8   4.8  31:47.42 java
02:58:26,   10330 infaUSW5  20   0 7465888   1.5g  38884 S   1.0   4.8  31:47.43 java

想像よりもCPU使用率は静か・・・、3秒で1行のINSERTを実行している点を踏まえると、オーバーヘッドがかかっている状況も見えます(3秒の中では非主キーフィールドを取得するためのSELECT文も実行されています)。

メモリ使用率

CAIプロセスを実行中に、次のAWKスクリプトを利用して1秒毎にprocess engine(pgrep -f bootstrap.jar)のヒープメモリの使用状況を確認します。

jstat -gc `pgrep -f bootstrap.jar` 1000 | awk '
NR==1 {next}   # 1行目（ヘッダ）をスキップ
{
  S0C=$1; S1C=$2; S0U=$3; S1U=$4;
  EC=$5; EU=$6; OC=$7; OU=$8; FGC=$15;

  heap_total = S0C + S1C + EC + OC;
  heap_used = S0U + S1U + EU + OU;
  heap_available = heap_total - heap_used;

  printf("合計(MB):%d", heap_total/1024);
  printf(", 空き(MB):%d", heap_available/1024);
  printf(", Full GC:%d\n", FGC);
}'

以下、実行結果です。ヒープメモリの空きは上下するものの、Full GCは発生せず、メモリリークも発生してなさそうです。健康的にヒープメモリが利用されている状況が伺えます(健康的と言ってもメモリ消費は激しく行われているる動作です)。

合計(MB):979, 空き(MB):734, Full GC:6 ★FULLではないGC直後、空きが734MB
合計(MB):979, 空き(MB):715, Full GC:6
合計(MB):979, 空き(MB):680, Full GC:6
合計(MB):979, 空き(MB):680, Full GC:6
合計(MB):979, 空き(MB):647, Full GC:6
合計(MB):979, 空き(MB):615, Full GC:6
合計(MB):979, 空き(MB):615, Full GC:6
合計(MB):979, 空き(MB):580, Full GC:6
合計(MB):979, 空き(MB):547, Full GC:6
合計(MB):979, 空き(MB):547, Full GC:6
合計(MB):979, 空き(MB):514, Full GC:6
合計(MB):979, 空き(MB):514, Full GC:6
合計(MB):979, 空き(MB):482, Full GC:6
合計(MB):979, 空き(MB):447, Full GC:6
合計(MB):979, 空き(MB):447, Full GC:6
合計(MB):979, 空き(MB):415, Full GC:6
合計(MB):985, 空き(MB):739, Full GC:6 ★FULLではないGC直後、空きが739MB
合計(MB):985, 空き(MB):724, Full GC:6 ★メモリリークはなさそう
合計(MB):985, 空き(MB):690, Full GC:6
合計(MB):985, 空き(MB):689, Full GC:6
合計(MB):985, 空き(MB):657, Full GC:6

総評

実際に動作確認をしてみた結果、次のポイントが確認できました。

• 思っていた以上に処理に時間を要している
• 思っていたよりもCPU使用率は高くない
• メモリは健康的に解放されている動作が確認できた点は安心できた

おわりに

1行あたりのINSERT処理に3秒・・・感情的に許容できない動作でしたね・・・もちろん、感情論ではなく業務要件やプロジェクトメンバーのスキルセット(SQLを書けるエンジニアの割合など)に応じて、今回のようなアプリケーション接続(JDBC)を利用する実装とするか、DAS接続を利用する実装とするかを決めていただくと良いと思います。

• Qiita - IICS CAIの実装レシピ - マスターページ