AWS DMS のタスクモードをサーバーレスで試した際にフルロードが完了しなかったように見えた原因を CloudWatch Logs から調査する
DMS のタスクログは CloudWatch Logs に出力できます。CPUUtilization や WriteIOPS などのメトリクスも CloudWatch で確認できます。
2025.10.01
コーヒーが好きな emi です。最近はカフェインを控えています。
以下のブログで DMS でサーバレスモードの移行を試しました。
しかし、実は一回うまくいかないタイミングがありました。今回はうまくいかなかった事象の整理と、原因究明のために各種をログを確認してみましたので共有します。
タスク実行開始からの時系列
1 回目のタスク実行は不具合で停止し、2 回目に再実行してうまくいったという流れです。
| 大体の時刻（JST） | マネジメントコンソール上の表示・事象 |
|---|---|
| 20:07 | サーバーレスタスクの作成ボタン押下、タスクのステータスが 初期化中 となる |
| 20:27 | キャパシティのプロビジョニングが終了し、タスクのステータスが 開始中 となる |
| 20:29 | フルロードの進行状況が 0% のまま、タスクのステータスが stopped になる |
| 「テーブルの統計」タブを確認するも 0、Sumary もすべて 0 | |
| 「モニタリング」タブを確認するも、キャパシティの使用率は最大で 25% 程度で余裕がある | |
| タスクを再ロードしてみるも、エラーで再ロードできない | |
| 20:39 | タスクを再ロードすると、タスクのステータスが「初期化中」となり、タスクが進行する |
| 20:58 | キャパシティのプロビジョニングが終了し、タスクのステータスが 開始中 となる |
タスクのステータスが ロード完了 となり、フルロードの進行状況が 100% となる |
（参考）時系列キャプチャ
20:07～
サーバーレスタスクの作成ボタン押下、タスクのステータスが 初期化中 となる
20:27～
キャパシティのプロビジョニングが終了し、タスクのステータスが 開始中 となる
20:29～
フルロードの進行状況が 0% のまま、タスクのステータスが stopped になる
「テーブルの統計」タブを確認するも 0、Sumary もすべて 0
「モニタリング」タブを確認するも、キャパシティの使用率は最大で 25% 程度で余裕がある
タスクを再ロードしてみるも、エラーで再ロードできない
Replication for Replication Config, 'P2NOQMBK3BDJVNSQ3SCECW22HI' is in provision state 'deprovisioning' and cannot start
（機械翻訳）レプリケーション構成 『P2NOQMBK3BDJVNSQ3SCECW22HI』 のレプリケーションは 『deprovisioning』 状態であり、開始できません
20:39～
タスクを再ロードすると、タスクのステータスが「初期化中」となり、タスクが進行する
20:58～
キャパシティのプロビジョニングが終了し、タスクのステータスが 開始中 となる
タスクのステータスが ロード完了 となり、フルロードの進行状況が 100% となる
ちなみに、一度再ロードを実行した際に出た以下のエラーは、一度タスクが終わって使わなくなったコンピューティングリソースを縮退（deprovisioning）している最中にタスクを再実行しようとしたことが原因のようです。
Replication for Replication Config, 'P2NOQMBK3BDJVNSQ3SCECW22HI' is in provision state 'deprovisioning' and cannot start
（機械翻訳）レプリケーション構成 『P2NOQMBK3BDJVNSQ3SCECW22HI』 のレプリケーションは 『deprovisioning』 状態であり、開始できません
If your replication is not using its resources at full capacity, AWS DMS will gradually deprovision resources to save you costs. However, since provisioning and deprovisioning resources takes time, we recommend that you set your MinCapacityUnits setting to a value that can handle any sudden spikes you expect in your replication workload. This will keep your replication from being under-provisioned while AWS DMS provisions resources for the higher workload level.
レプリケーションがリソースをフルに活用していない場合、AWS DMSはコスト削減のためリソースを段階的にプロビジョニング解除します。ただし、リソースのプロビジョニングとプロビジョニング解除には時間がかかるため、レプリケーションワークロードで予想される急激な増加に対応できる値をMinCapacityUnits設定に指定することを推奨します。これにより、AWS DMSがより高いワークロードレベル向けにリソースをプロビジョニングしている間も、レプリケーションがリソース不足に陥ることを防げます。
CloudWatch Logs で調査
タスク作成時に CloudWatch Logs にログを出力するよう設定しておいたので、CloudWatch Logs を確認してみます。タスクログの「CloudWatch ログを表示」から該当の CloudWatch Logs に遷移できます。
dms-serverless-replication-P2NOQMBK3BDJVNSQ3SCECW22HI というロググループに遷移しました。
このままログストリームを見てもいいのですが、ログ全体を眺めたいので「ログのインサイト（CloudWatch Logs Insights）」から時間帯を絞り込んで検索します。
ローカルタイムゾーンと時刻を指定し、ロググループ dms-serverless-replication-P2NOQMBK3BDJVNSQ3SCECW22HI を選択して以下クエリを実行します。
fields @timestamp, @message, @logStream
| sort @timestamp asc
| limit 10000
タイムスタンプ、ログメッセージ、ログストリームを昇順（古い→新しい）で 10000 行取得するクエリです。
結果はコピーすることもダウンロードすることもできます。CSV でダウンロードすると、logs-insights-results.csv という名前の CSV がダウンロードできました。
以下トグル内に CSV を貼ります。
logs-insights-results.csv 全量（エラーで Stopped になるまで）
logs-insights-results.csv
@timestamp,@message,@logStream
2025-09-30 11:10:02.793,"{'replication_state':'fetching_metadata', 'message': 'Fetching metadata from your source endpoint to calculate workload capacity.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:10:02.996,"{'replication_state':'failed', 'message': 'Failed to fetch metadata.', 'failure_message': 'Internal failure.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:10:03.116,"{'replication_state':'failed', 'message': 'Failed to fetch metadata.', 'failure_message': 'Internal failure.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:10:33.360,"{'replication_state':'fetching_metadata', 'message': 'Fetching metadata from your source endpoint to calculate workload capacity.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:11:03.854,"{'replication_state':'fetching_metadata', 'message': 'Fetching metadata from your source endpoint to calculate workload capacity.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:11:59.496,"{'replication_state':'calculating_capacity', 'message': 'Calculating workload capacity for your replication based on table mappings and source metadata.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:12:36.594,"{'replication_state':'provisioning_capacity', 'message': 'Fetching workload capacity to provision your replication.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:12:38.984,"{'replication_state':'provisioning_capacity', 'message': 'Provisioning 2 capacity units to perform the replication. This can take some time.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:27:18.197,"{'replication_state':'replication_starting', 'message': 'Starting replication from source arn:aws:dms:ap-northeast-1:123456789012:endpoint:5SBTLOTFTVFQHL7MDMN5HV3SUU to target arn:aws:dms:ap-northeast-1:123456789012:endpoint:NX3KDSKKNFBG5JPVZEQVSLN3II in FULL_LOAD mode.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
2025-09-30 11:27:25.000,"2025-09-30T11:27:25 [AT_GLOBAL ]I: Task Server Log - serv-res-id-1759231542299-krss (V3.5.3.R2373 ip-172-23-1-209 Linux 4.14.355-280.695.amzn2.x86_64 #1 SMP Tue Sep 23 00:22:57 UTC 2025 x86_64 64-bit, PID: 16156) started at Tue Sep 30 11:27:25 2025 (at_logger.c:3250)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [DATA_STRUCTURE ]I: SQLite version is 3.31.1 (at_sqlite.c:178),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TARGET_APPLY ]I: Lob lookup mutex created successfully (bulk_apply.c:888),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [VALIDATOR ]I: validation_util_class_initialize (validation_util.c:85),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [VALIDATOR ]I: Creating Table Def Mutex (validation_util.c:89),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [VALIDATOR ]I: ==> Success Creating Table Def Mutex (validation_util.c:97),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Execute Request Task 'serv-res-id-1759231542299-krss' running full load only with flags fresh start with cdcPosition null and stop_at null (replicationtask.c:993),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,"2025-09-30T11:27:25 [TASK_MANAGER ]I: ""BatchApplyPreserveTransaction"" is turned off because Batch optimized apply mode is disabled in the task settings. (replicationtask.c:1400)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,"2025-09-30T11:27:25 [TASK_MANAGER ]I: Note: the 'SQL Server' target endpoint does not support ""BatchApplyPreserveTransaction"" option in ""Batch optimized apply"" mode. Therefore, this option is disabled even if you enable in the task settings. (replicationtask.c:1407)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Task 'serv-res-id-1759231542299-krss' starting full load only in fresh start mode (replicationtask.c:1621),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Serverless enhanced throughput is Disabled. (replicationtask.c:1821),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [VALIDATOR ]I: bValidationFreshStart = '1' (validation_manager.c:170),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Task Id: d6dfa149-347a-4bb0-b11b-93cfb70a2dbc (replicationtask.c:3911),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: LOB support on the task has been enabled (endpointshell.c:1915),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Task is running in Limited LOB Mode. MaxLobSize is set to '32768' Bytes (endpointshell.c:1918),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,"2025-09-30T11:27:25 [METADATA_MANAGE ]I: Going to connect to ODBC connection string: DRIVER={ODBC Driver 17 for SQL Server};SERVER=source-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;Trusted_Connection=no;; (sqlserver_endpoint_util.c:242)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [METADATA_MANAGE ]I: Source endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:894),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: SQL server version: Microsoft SQL Server 2016 (SP3-GDR) (KB5063762) - 13.0.6465.1 (X64) Jul 14 2025 21:50:50 Copyright (c) Microsoft Corporation Standard Edition (64-bit) on Windows Server 2016 Datacenter 10.0 <X64> (Build 14393: ) (Hypervisor) (sqlserver_log_queries.c:8466),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Database is RDS SQL Server (sqlserver_log_queries.c:8518),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Sampled server version: 2016 (sqlserver_endpoint_imp.c:2372),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property forceloblookup: false (sqlserver_endpoint_imp.c:2386),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property lobLookupNoDataRetry: 0 (sqlserver_endpoint_imp.c:2387),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property lobLookupNodataPollingSec: 1 (sqlserver_endpoint_imp.c:2388),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property forceDataRowLookup: false (sqlserver_endpoint_imp.c:2390),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property rowLookupNoDataRetry: 0 (sqlserver_endpoint_imp.c:2391),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Internal property rowLookupNoDataPollingSec: 1 (sqlserver_endpoint_imp.c:2392),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: NLS configuration sampled: Associated code page=932 (sqlserver_endpoint_imp.c:2426),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Bulk is set to ignore max row size warnings (sqlserver_endpoint_imp.c:1656),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Working with collated columns (sqlserver_endpoint_imp.c:1713),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Working with BCPKeepNull set to TRUE (sqlserver_endpoint_imp.c:1717),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Target endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:900),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Loaded SQLServer Driver: 'ODBC Driver 17 for SQL Server' (sqlserver_endpoint_imp.c:472),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [METADATA_MANAGE ]I: Going to connect to SQL Server Target : DRIVER={ODBC Driver 17 for SQL Server};SERVER=target-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;UID=target_db_admin; (ar_odbc_conn.c:354)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [METADATA_MANAGE ]I: Going to connect to SQL Server Target : DRIVER={ODBC Driver 17 for SQL Server};SERVER=target-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;UID=target_db_admin; (ar_odbc_conn.c:354)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [METADATA_MANAGE ]I: Target endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:900),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Preparing all components (replicationtask.c:2279),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STARTING state, updating starting status to AR_PREPARING_COMPONENTS (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Creating threads for all components (replicationtask.c:2312),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STARTING state, updating starting status to AR_CREATING_TREADS (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STARTING state, updating starting status to AR_CREATING_TABLES_LIST (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TABLES_MANAGER ]I: Calling for get capture table list from the Metadata Manager started. (tasktablesmanager.c:963),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TABLES_MANAGER ]I: Calling for get capture table list from the Metadata Manager ended. (tasktablesmanager.c:970),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in RUNNING state, updating starting status to AR_RUNNING (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: All stream components were initialized (replicationtask.c:3648),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Starting the validation process... (replicationtask.c:3725),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Starting subtask #1 (replicationtask_util.c:521),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Threads for all components were created (replicationtask.c:2499),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Task initialization completed successfully (replicationtask.c:3968),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [SOURCE_UNLOAD ]I: Going to connect to ODBC connection string: DRIVER={ODBC Driver 17 for SQL Server};SERVER=source-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;Trusted_Connection=no;; (sqlserver_endpoint_util.c:242)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [SOURCE_UNLOAD ]I: Source endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:894),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [SOURCE_UNLOAD ]I: NLS configuration sampled: Associated code page=932 (sqlserver_endpoint_imp.c:2426),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Bulk is set to ignore max row size warnings (sqlserver_endpoint_imp.c:1656),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Working with collated columns (sqlserver_endpoint_imp.c:1713),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Working with BCPKeepNull set to TRUE (sqlserver_endpoint_imp.c:1717),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Target endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:900),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Loaded SQLServer Driver: 'ODBC Driver 17 for SQL Server' (sqlserver_endpoint_imp.c:472),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TARGET_LOAD ]I: Going to connect to SQL Server Target : DRIVER={ODBC Driver 17 for SQL Server};SERVER=target-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;UID=target_db_admin; (ar_odbc_conn.c:354)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TARGET_LOAD ]I: Going to connect to SQL Server Target : DRIVER={ODBC Driver 17 for SQL Server};SERVER=target-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;UID=target_db_admin; (ar_odbc_conn.c:354)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TARGET_LOAD ]I: Target endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:900),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [SOURCE_CAPTURE ]I: Going to connect to ODBC connection string: DRIVER={ODBC Driver 17 for SQL Server};SERVER=source-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;Trusted_Connection=no;; (sqlserver_endpoint_util.c:242)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [SOURCE_CAPTURE ]I: Source endpoint 'SQL Server' is using provider syntax 'SQLServer' (provider_syntax_manager.c:894),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [SOURCE_CAPTURE ]I: NLS configuration sampled: Associated code page=932 (sqlserver_endpoint_imp.c:2426),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Starting component st_1_NX3KDSKKNFBG5JPVZEQVSLN3II (subtask.c:1449),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Starting component st_1_5SBTLOTFTVFQHL7MDMN5HV3SUU (subtask.c:1449),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TARGET_LOAD ]I: No records received to load or apply on target , waiting for data from upstream (streamcomponent.c:2013)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TABLES_MANAGER ]I: Next table to load 'dbo'.'user' ID = 1, order = 0 (tasktablesmanager.c:1918)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Start loading table 'dbo'.'user' (Id = 1) by subtask 1. Start load timestamp 0006400309600B6D (replicationtask_util.c:755),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Sent unloaded record 1 to internal queue (streamcomponent.c:3015),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Calculated batch used for UNLOAD size is 1000 rows per fetch. (sqlserver_endpoint_unload.c:222),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Unload finished for table 'dbo'.'user' (Id = 1). 3 rows sent. (streamcomponent.c:3875),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TARGET_LOAD ]I: Target starts loading table 'dbo'.'user'. (sqlserver_endpoint_imp.c:4229),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TARGET_LOAD ]I: Load finished for table 'dbo'.'user' (Id = 1). 3 rows received. 0 rows skipped. Volume transferred 1344. (streamcomponent.c:4168),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [PERFORMANCE ]I: End load handler time for dbo.user = 2790 microseconds (endpointshell.c:3062),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [PERFORMANCE ]I: Total load time for dbo.user = 4580 microseconds (endpointshell.c:3064),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TASK_MANAGER ]I: Loading finished for table 'dbo'.'user' (Id = 1) by subtask 1. 3 rows affected. Time taken: 72658 micro seconds (replicationtask.c:2958),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TASK_MANAGER ]I: All tables are loaded. Full load only task is stopped (replicationtask.c:4383),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TASK_MANAGER ]I: Subtask #1 ended (replicationtask_util.c:595),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,"2025-09-30T11:27:27 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STOPPED state, updating starting status to AR_NOT_APPLICABLE (repository.c:5483)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:27.000,"2025-09-30T11:27:27 [TASK_MANAGER ]I: Updated Task, serv-res-id-1759231542299-krss, info with TaskState - 0 (replicationtask.c:4543)",dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:27:35.000,2025-09-30T11:27:35 [TASK_MANAGER ]I: Task management thread terminated (replicationtask.c:4623),dms-serverless-serv-res-id-1759231542299-krss
2025-09-30 11:28:38.180,"{'replication_state':'running', 'message': 'Replication is now running in FULL_LOAD mode.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
ブログの文字数制限の関係でエラーになるまでのログしか貼れませんでしたが、成功時のログは AWS DMS で Amazon RDS for SQL Server のデータ移行を行う～ Serverless 編～ | DevelopersIO - CloudWatch Logs のログ に貼りましたのでそちらを参照ください。
ログの詳細確認
ダウンロードして気づいたのですが、CloudWatch Logs のログは結果をコピーしたりダウンロードしたりすると UTC タイムゾーンになってしまうんですね。ローカルタイムゾーンのままかと思っていました。
ログの詳細の見方のドキュメントはこの辺りを参照します。
'replication_state' は同期状況のようで、サーバレスのコンピューティングリソースのデプロイ状態などを表すようです。
サーバーレスタスクのステータスは以下ドキュメントに遷移図があります。
2025-09-30 11:27:18.197,"{'replication_state':'replication_starting', 'message': 'Starting replication from source arn:aws:dms:ap-northeast-1:123456789012:endpoint:5SBTLOTFTVFQHL7MDMN5HV3SUU to target arn:aws:dms:ap-northeast-1:123456789012:endpoint:NX3KDSKKNFBG5JPVZEQVSLN3II in FULL_LOAD mode.'}",dms-serverless-replication-orchestrator-P2NOQMBK3BDJVNSQ3SCECW22HI
11:27（20:27 JST）ソースエンドポイントからターゲットエンドポイントへのレプリケーションを FULL_LOAD モードで開始しています。
2025-09-30 11:27:25.000,2025-09-30T11:27:25 [TASK_MANAGER ]I: Task 'serv-res-id-1759231542299-krss' starting full load only in fresh start mode (replicationtask.c:1621),dms-serverless-serv-res-id-1759231542299-krss
タスクは新規起動モードでフルロードのみを開始しています。
2025-09-30 11:27:25.000,"2025-09-30T11:27:25 [METADATA_MANAGE ]I: Going to connect to ODBC connection string: DRIVER={ODBC Driver 17 for SQL Server};SERVER=source-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;Trusted_Connection=no;; (sqlserver_endpoint_util.c:242)",dms-serverless-serv-res-id-1759231542299-krss
ソース DB の test_db に SQL 認証で接続開始しています。
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [METADATA_MANAGE ]I: Going to connect to SQL Server Target : DRIVER={ODBC Driver 17 for SQL Server};SERVER=target-db.colw41khta5t.ap-northeast-1.rds.amazonaws.com,1433;DATABASE=test_db;UID=target_db_admin; (ar_odbc_conn.c:354)",dms-serverless-serv-res-id-1759231542299-krss
同様にターゲット DB の test_db に SQL 認証で接続開始しています。
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STARTING state, updating starting status to AR_CREATING_TABLES_LIST (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
テーブルのリストを作成しています。
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in RUNNING state, updating starting status to AR_RUNNING (repository.c:5491)",dms-serverless-serv-res-id-1759231542299-krss
タスクのステータスが RUNNING に遷移し、実行フェーズに入ったようです
データ検証をしたり、処理スレッドがスタートしたりというログが続きます。
2025-09-30 11:27:26.000,"2025-09-30T11:27:26 [TABLES_MANAGER ]I: Next table to load 'dbo'.'user' ID = 1, order = 0 (tasktablesmanager.c:1918)",dms-serverless-serv-res-id-1759231542299-krss
フルロードの対象テーブルが dbo.user（ID=1） と決定され、
2025-09-30 11:27:26.000,2025-09-30T11:27:26 [TASK_MANAGER ]I: Start loading table 'dbo'.'user' (Id = 1) by subtask 1. Start load timestamp 0006400309600B6D (replicationtask_util.c:755),dms-serverless-serv-res-id-1759231542299-krss
dbo.user の ロードが開始しました。
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Sent unloaded record 1 to internal queue (streamcomponent.c:3015),dms-serverless-serv-res-id-1759231542299-krss
ソース DB 側で読み出した 1 件目のレコードを内部キューへ送出しています。
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Calculated batch used for UNLOAD size is 1000 rows per fetch. (sqlserver_endpoint_unload.c:222),dms-serverless-serv-res-id-1759231542299-krss
アンロード（抽出）の フェッチ単位は 1 回あたり最大 1000 行でチューニングされています。
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [SOURCE_UNLOAD ]I: Unload finished for table 'dbo'.'user' (Id = 1). 3 rows sent. (streamcomponent.c:3875),dms-serverless-serv-res-id-1759231542299-krss
dbo.user の 抽出が完了し合計 3 行が内部キューへ送信されました。
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TARGET_LOAD ]I: Target starts loading table 'dbo'.'user'. (sqlserver_endpoint_imp.c:4229),dms-serverless-serv-res-id-1759231542299-krss
ターゲット DB 側で dbo.user のロード処理が開始され、
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TARGET_LOAD ]I: Load finished for table 'dbo'.'user' (Id = 1). 3 rows received. 0 rows skipped. Volume transferred 1344. (streamcomponent.c:4168),dms-serverless-serv-res-id-1759231542299-krss
dbo.user を 3 行受信しロードが完了しています。スキップなしで転送量は 1344 Byte です。
2025-09-30 11:27:27.000,2025-09-30T11:27:27 [TASK_MANAGER ]I: All tables are loaded. Full load only task is stopped (replicationtask.c:4383),dms-serverless-serv-res-id-1759231542299-krss
全テーブルのフルロードが完了し、タスクは停止しました。
2025-09-30 11:27:27.000,"2025-09-30T11:27:27 [TASK_MANAGER ]I: Task - serv-res-id-1759231542299-krss is in STOPPED state, updating starting status to AR_NOT_APPLICABLE (repository.c:5483)",dms-serverless-serv-res-id-1759231542299-krss
タスクが STOPPED に更新され、開始ステータスが「AR_NOT_APPLICABLE（該当なし）」 になりました。
2025-09-30 11:27:35.000,2025-09-30T11:27:35 [TASK_MANAGER ]I: Task management thread terminated (replicationtask.c:4623),dms-serverless-serv-res-id-1759231542299-krss
タスクマネジメントスレッドが終了しました。
………特に問題なさそうですね？？？
デフォルトの粒度で出力されたログを見る限り、原因は掴めませんでした。一時的にマネジメントコンソール上に反映されなかっただけなのかもしれません。
詳細なデバックログを出しておけば良かったと思いましたが、事象がすぐに再現できなさそうなので今回は一旦ここまでとします。
DMS の CloudWatch メトリクス
DMS に関する CloudWath メトリクスは AWS Database Migration Service メトリクス に記載があるので確認すると良いです。CPUUtilization や WriteIOPS などのメトリクスが確認できます。
以下の種類のメトリクスがあります。
- [Host Metrics] (ホストメトリクス)
- レプリケーションホストのパフォーマンスおよび使用状況の統計
- [Replication Task Metrics] (レプリケーション タスク メトリクス)
- 受信した変更とコミットされた変更、レプリケーション ホストとソースおよびターゲットデータベースの間のレイテンシーなど、レプリケーション タスクの統計
- [Table Metrics] (テーブルメトリクス)
- 挿入、更新、削除、完了した DDL ステートメントの数など、移行が進行中のテーブルの統計
DMS 移行ログを CloudWatch Logs に出力する設定
DMS タスクでは コンテキストログ を出力できます。これを ON にすると、コンテキストのログ記録がタスクの CloudWatch Logs に書き込まれます。書き込まれる情報には以下が含まれます。
- ソースデータベースとターゲットデータベースへのタスクの接続に関する情報
- レプリケーションタスクの動作
- このタスクログからレプリケーションの問題を診断する
- DMS がソース DB およびターゲット DB で実行する、データを含まないSQLステートメント
- この SQL ログから予期しない移行の動作を診断する
- 各 CDC（change data capture、変更データキャプチャ）イベントのストリーム位置の詳細
また、CloudWatch Logs の設定は以下のように粒度が選択できます。
ロギングタスク設定 を見ると、ログ収集粒度は以下のようになっています。原因が突き止められず、より詳細なログが必要な場合は「詳細なデバッグ」を選ぶと良さそうです。
- LOGGER_SEVERITY_DEFAULT (デフォルト)：情報メッセージ、警告、エラーメッセージを含む
- LOGGER_SEVERITY_ERROR (エラー)：エラーメッセージを含む
- LOGGER_SEVERITY_WARNING (警告)：警告とエラーメッセージを含む
- LOGGER_SEVERITY_INFO (情報)：情報メッセージ、警告、エラーメッセージを含む
- LOGGER_SEVERITY_DEBUG (デバッグ)：デバッグ メッセージ、情報メッセージ、警告、エラーメッセージを含む
- LOGGER_SEVERITY_DETAILED_DEBUG (詳細なデバッグ) - すべての情報を含む
おわりに
今回は原因究明まで至らなかったのですが、DMS にどのようなログがあって、どこを見たらよいのかということが分かって良かったです。
本記事への質問やご要望については画面下部のお問い合わせ 「DevelopersIO について」 からご連絡ください。記事に関してお問い合わせいただけます。
