How does change processing tuning work when applying batched changes at intervals

[jbasile]

I am curious to know how the "Change Processing Tuning" parameters work when I have changes applied in "Batch optimized apply" mode.  My source is DB2 z/OS, writing to log stream and my target is Google Cloud BigQuery, storing the changes.  I am on Qlik Replicate version November 2023 (2023.11.0.159).

My business team wants changes applied every 30 minutes so currently my Batch Tuning parameters are "Longer than (seconds): 1779" and "But less than (seconds): 1800".

The other night a source table received over 60 million updates in four hours, which doesn't seem like a lot of updates in today's world but is a rare volume for our type of environment.  I noticed the next day the latency reached over 30 hours on the target apply side.  The table is in a task all by itself.  I did not notice any latency  with the source writing to log stream or any other tasks reading from the same log stream and writing to the same target.  I have since reloaded the target but am curious to know in the future if this happens again, how I can speed things up without reloading.

While watching the monitor tab of incoming changes, it seemed as if when changes were applied every 30 minutes, only a certain number of changes were applied each time.  With leaving the interval at 30 minutes, are there any parameter(s) that control how many changes get pushed at each interval?

[sureshkumar]

Hello @jbasile 

We need to check where the bottleneck i.e at the Source side or at the Target.

I would suggest enabling below component to TRACE when you face the latency next time

SOURCE_CAPTURE, TARGET_APPLY and PERFORMANCE, let the task run for 15 mins and check the log for any additional information.

Regards,

Suresh

[jbasile]

@sureshkumar

Thanks for the response. I created a test case and was able to re-create the scenario at a slightly smaller scale. For information purposes, my z/OS Cobol program performed 29,860,578 inserts into a table in about 20 minutes. The Qlik replication task from source to log stream was able to write everything within 10 minutes of the last insert, so I do not see a bottleneck at the source side. At the moment the task reading from log stream and applying to the target has about three hours latency (see screenshot). I have looked at the following two links below, but unfortunately, they are not helping me understand the tuning parameters as it relates to my case.

https://help.qlik.com/en-US/replicate/November2023/Content/Global_Common/Content/SharedEMReplicate/C...

https://community.qlik.com/t5/Official-Support-Articles/Understanding-Replicate-CDC-incoming-changes...

Below is a snippet of the log that that shows my two most recent thirty minute apply intervals, I removed any data that I deemed personal. From my perspective, it looks like a certain amount of data is getting pushed to the target every thirty minutes, but I am not sure how this is controlled.  Any help understanding what tuning parameters are viable to increase the amount of data pushed with each interval would greatly be appreciated. I am not too concerned with alleviating latency all together, just want the knowledge to tune on a case-by-case basis. Thanks.

00006420: 2024-10-14T13:31:10 [SORTER ]I: Task is running (sorter.c:714)
00004456: 2024-10-14T13:31:25 [PERFORMANCE ]T: Source latency 8413.97 seconds, Target latency 8485.09 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:31:55 [PERFORMANCE ]T: Source latency 8444.11 seconds, Target latency 8515.22 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:32:25 [PERFORMANCE ]T: Source latency 8474.19 seconds, Target latency 8545.30 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Finish bulk because stream timeout (bulk_apply.c:1024)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Bulk finished. First record 24800501. Last Record Id 32400645. Skip until record Id 0 (bulk_apply.c:2251)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Bulk finished. Total sequential events #0 (bulk_apply.c:2253)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Tables with PK #1, (bulk_apply.c:2365)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Going to start applying bulk changes for tables with PK and inserts for tables without PK (bulk_apply.c:5727)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Truncate table statement: TRUNCATE TABLE `sa_control_attrep`.`attrep_changes86D30419D0E00467` (provider_syntax_manager.c:2324)
00005376: 2024-10-14T13:32:36 [TARGET_APPLY ]T: Truncate net changes table. 'TRUNCATE TABLE `sa_control_attrep`.`attrep_changes86D30419D0E00467`' (odbc_bulk.c:793)
00005376: 2024-10-14T13:32:38 [TARGET_APPLY ]T: Start handling table 2000002 which is in the bulk (bulk_apply.c:5257)
00004456: 2024-10-14T13:32:55 [PERFORMANCE ]T: Source latency 8504.30 seconds, Target latency 8575.41 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00005376: 2024-10-14T13:33:12 [TARGET_APPLY ]T: bulk_map: seq 1:1900000 INSERT 'DB1005'.'TDBREPL' (id=2000002) (bulk_apply.c:6890)
00005376: 2024-10-14T13:33:12 [TARGET_APPLY ]T: Going to load file 'D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000002.csv' (csv_target.c:1979)
00004456: 2024-10-14T13:33:25 [PERFORMANCE ]T: Source latency 8534.43 seconds, Target latency 8605.54 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00005376: 2024-10-14T13:33:34 [TARGET_APPLY ]T: File D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000002.csv compressed to gzip (csv_target.c:1783)
00005376: 2024-10-14T13:33:34 [TARGET_APPLY ]T: Going to run load statement, 'D:\Program Files\Attunity\Replicate\bin/arepbq.exe' (csv_target.c:1254)
00005376: 2024-10-14T13:33:34 [TARGET_APPLY ]T: Before wait for command (csv_target.c:1033)
00004456: 2024-10-14T13:33:55 [PERFORMANCE ]T: Source latency 8564.52 seconds, Target latency 8635.63 seconds, Handling latency 71.11 seconds (replicationtask.c:3879)
00005376: 2024-10-14T13:34:05 [TARGET_APPLY ]T: Load command output: insert a JSON key

Going to load dataset id: sa_control_attrep table id attrep_changes86D30419D0E00467 from D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000002.csv.gz
Loaded 1900000 rows to dev-gold-core.sa_control_attrep.attrep_changes86D30419D0E00467 (csv_target.c:1098)
00005376: 2024-10-14T13:34:05 [TARGET_APPLY ]T: Start applying of 'INSERT (1)' events for table 'DB1005'.'TDBREPL' (2000002). (bulk_operations_applier.c:343)
00005376: 2024-10-14T13:34:05 [TARGET_APPLY ]T: Going to run insert statement, from seq 1 to seq 1900000
~{AwAAAPigjx9oBHZ+22G8vQrveTLNgimQje7t4XQ==}~ (odbc_util.c:4487)
00005376: 2024-10-14T13:34:17 [TARGET_APPLY ]T: Finished applying of 1900000 'INSERT (1)' events for table 'DB1005'.'TDBREPL' (2000002). (bulk_operations_applier.c:375)
00005376: 2024-10-14T13:34:17 [TARGET_APPLY ]T: Finished applying bulk changes for tables with PK and inserts for tables without PK (bulk_apply.c:6440)
00005376: 2024-10-14T13:34:17 [TARGET_APPLY ]T: The current bulk was applied. The last confirmed record id = 1900000, the last record id = 32400645 (bulk_apply.c:2501)
00005376: 2024-10-14T13:34:17 [TARGET_APPLY ]T: First bulk event: record_id = 32400653, stream_position ='2622;638645154735728340;20240229125837965062|0000000006C3B4DA17730001' (bulk_apply.c:1200)
00004456: 2024-10-14T13:34:25 [PERFORMANCE ]T: Source latency 8526.82 seconds, Target latency 8594.26 seconds, Handling latency 67.44 seconds (replicationtask.c:3879)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: get_target_schema return target 'sa_qlik_issue' (odbc_endpoint_imp.c:10844)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Adding columns to table_def sa_qlik_issue.tdbqlik (odbc_util.c:1069)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Column col_int added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Column col_char added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Column col_bigint added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Column col_dec added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Column col_char_exst_pii added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Added all columns to table_def successfully (odbc_util.c:1164)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Got table indexes successfully (odbc_util.c:1177)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Got table PK successfully (odbc_util.c:1207)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: No Index or PK added to table_def (odbc_util.c:1332)
00005376: 2024-10-14T13:34:37 [TARGET_APPLY ]T: Check if column on table tdbqlik is clustered by 'SELECT column_name , clustering_ordinal_position, is_nullable FROM `sa_qlik_issue`.INFORMATION_SCHEMA.COLUMNS WHERE table_name = 'tdbqlik'' (odbc_endpoint_metadata.c:1079)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: get_target_schema return target 'sa_qlik_issue' (odbc_endpoint_imp.c:10844)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Adding columns to table_def sa_qlik_issue.tdbqlik_cdc (odbc_util.c:1069)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column header_change_seq added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column header_change_oper added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column header_transaction_id added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column header_timestamp added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column col_int added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column col_char added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column col_bigint added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column col_dec added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Column col_char_exst_pii added to table_def (odbc_util.c:1153)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Added all columns to table_def successfully (odbc_util.c:1164)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Got table indexes successfully (odbc_util.c:1177)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Got table PK successfully (odbc_util.c:1207)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: No Index or PK added to table_def (odbc_util.c:1332)
00005376: 2024-10-14T13:34:39 [TARGET_APPLY ]T: Check if column on table tdbqlik_cdc is clustered by 'SELECT column_name , clustering_ordinal_position, is_nullable FROM `sa_qlik_issue`.INFORMATION_SCHEMA.COLUMNS WHERE table_name = 'tdbqlik_cdc'' (odbc_endpoint_metadata.c:1079)
00004456: 2024-10-14T13:34:55 [PERFORMANCE ]T: Source latency 8551.08 seconds, Target latency 8624.36 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:35:26 [PERFORMANCE ]T: Source latency 8581.23 seconds, Target latency 8654.51 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:35:56 [PERFORMANCE ]T: Source latency 8611.31 seconds, Target latency 8684.60 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:36:26 [PERFORMANCE ]T: Source latency 8641.44 seconds, Target latency 8714.72 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:36:56 [PERFORMANCE ]T: Source latency 8671.58 seconds, Target latency 8744.86 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:37:26 [PERFORMANCE ]T: Source latency 8701.73 seconds, Target latency 8775.01 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:37:56 [PERFORMANCE ]T: Source latency 8731.86 seconds, Target latency 8805.14 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:38:26 [PERFORMANCE ]T: Source latency 8761.97 seconds, Target latency 8835.25 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:38:56 [PERFORMANCE ]T: Source latency 8792.04 seconds, Target latency 8865.32 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:39:27 [PERFORMANCE ]T: Source latency 8822.15 seconds, Target latency 8895.44 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:39:57 [PERFORMANCE ]T: Source latency 8852.27 seconds, Target latency 8925.56 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:40:27 [PERFORMANCE ]T: Source latency 8882.40 seconds, Target latency 8955.69 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:40:57 [PERFORMANCE ]T: Source latency 8912.52 seconds, Target latency 8985.80 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00006420: 2024-10-14T13:41:11 [SORTER ]I: Task is running (sorter.c:714)
00004456: 2024-10-14T13:41:27 [PERFORMANCE ]T: Source latency 8942.62 seconds, Target latency 9015.91 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:41:57 [PERFORMANCE ]T: Source latency 8972.69 seconds, Target latency 9045.97 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:42:27 [PERFORMANCE ]T: Source latency 9002.80 seconds, Target latency 9076.08 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:42:57 [PERFORMANCE ]T: Source latency 9032.91 seconds, Target latency 9106.19 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:43:27 [PERFORMANCE ]T: Source latency 9063.07 seconds, Target latency 9136.35 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:43:58 [PERFORMANCE ]T: Source latency 9093.20 seconds, Target latency 9166.48 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:44:28 [PERFORMANCE ]T: Source latency 9123.31 seconds, Target latency 9196.60 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:44:58 [PERFORMANCE ]T: Source latency 9153.42 seconds, Target latency 9226.70 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:45:28 [PERFORMANCE ]T: Source latency 9183.55 seconds, Target latency 9256.83 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:45:58 [PERFORMANCE ]T: Source latency 9213.68 seconds, Target latency 9286.96 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:46:28 [PERFORMANCE ]T: Source latency 9243.78 seconds, Target latency 9317.07 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:46:58 [PERFORMANCE ]T: Source latency 9273.91 seconds, Target latency 9347.20 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:47:28 [PERFORMANCE ]T: Source latency 9304.00 seconds, Target latency 9377.29 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:47:58 [PERFORMANCE ]T: Source latency 9334.11 seconds, Target latency 9407.39 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:48:29 [PERFORMANCE ]T: Source latency 9364.21 seconds, Target latency 9437.49 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:48:59 [PERFORMANCE ]T: Source latency 9394.30 seconds, Target latency 9467.59 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:49:29 [PERFORMANCE ]T: Source latency 9424.44 seconds, Target latency 9497.72 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:49:59 [PERFORMANCE ]T: Source latency 9454.53 seconds, Target latency 9527.81 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:50:29 [PERFORMANCE ]T: Source latency 9484.65 seconds, Target latency 9557.93 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:50:59 [PERFORMANCE ]T: Source latency 9514.76 seconds, Target latency 9588.04 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00006420: 2024-10-14T13:51:11 [SORTER ]I: Task is running (sorter.c:714)
00004456: 2024-10-14T13:51:29 [PERFORMANCE ]T: Source latency 9544.86 seconds, Target latency 9618.15 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:51:59 [PERFORMANCE ]T: Source latency 9574.97 seconds, Target latency 9648.25 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:52:30 [PERFORMANCE ]T: Source latency 9605.11 seconds, Target latency 9678.40 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:53:00 [PERFORMANCE ]T: Source latency 9635.21 seconds, Target latency 9708.50 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:53:30 [PERFORMANCE ]T: Source latency 9665.31 seconds, Target latency 9738.60 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:54:00 [PERFORMANCE ]T: Source latency 9695.41 seconds, Target latency 9768.69 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:54:30 [PERFORMANCE ]T: Source latency 9725.56 seconds, Target latency 9798.85 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:55:00 [PERFORMANCE ]T: Source latency 9755.72 seconds, Target latency 9829.00 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:55:30 [PERFORMANCE ]T: Source latency 9785.79 seconds, Target latency 9859.08 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:56:00 [PERFORMANCE ]T: Source latency 9815.91 seconds, Target latency 9889.20 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:56:30 [PERFORMANCE ]T: Source latency 9846.05 seconds, Target latency 9919.34 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:57:01 [PERFORMANCE ]T: Source latency 9876.16 seconds, Target latency 9949.45 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:57:31 [PERFORMANCE ]T: Source latency 9906.27 seconds, Target latency 9979.56 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:58:01 [PERFORMANCE ]T: Source latency 9936.39 seconds, Target latency 10009.67 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:58:31 [PERFORMANCE ]T: Source latency 9966.52 seconds, Target latency 10039.80 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:59:01 [PERFORMANCE ]T: Source latency 9996.63 seconds, Target latency 10069.91 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T13:59:31 [PERFORMANCE ]T: Source latency 10026.72 seconds, Target latency 10100.00 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:00:01 [PERFORMANCE ]T: Source latency 10056.85 seconds, Target latency 10130.13 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:00:31 [PERFORMANCE ]T: Source latency 10086.97 seconds, Target latency 10160.25 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:01:02 [PERFORMANCE ]T: Source latency 10117.12 seconds, Target latency 10190.40 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00006420: 2024-10-14T14:01:11 [SORTER ]I: Task is running (sorter.c:714)
00004456: 2024-10-14T14:01:32 [PERFORMANCE ]T: Source latency 10147.22 seconds, Target latency 10220.51 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:02:02 [PERFORMANCE ]T: Source latency 10177.39 seconds, Target latency 10250.67 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:02:32 [PERFORMANCE ]T: Source latency 10207.53 seconds, Target latency 10280.81 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:03:02 [PERFORMANCE ]T: Source latency 10237.65 seconds, Target latency 10310.93 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:03:32 [PERFORMANCE ]T: Source latency 10267.74 seconds, Target latency 10341.02 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Finish bulk because stream timeout (bulk_apply.c:1024)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Bulk finished. First record 32400653. Last Record Id 40400817. Skip until record Id 0 (bulk_apply.c:2251)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Bulk finished. Total sequential events #0 (bulk_apply.c:2253)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Tables with PK #2, (bulk_apply.c:2365)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Current net changes table needs to be recreated (bulk_apply.c:6247)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Going to start applying bulk changes for tables with PK and inserts for tables without PK (bulk_apply.c:5727)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Drop table statement: DROP TABLE `sa_control_attrep`.`attrep_changes86D30419D0E00467` (provider_syntax_manager.c:2290)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Create table statement: CREATE TABLE `sa_control_attrep`.`attrep_changes86D30419D0E00467` ( `seq` INT64 NOT NULL, `col1` STRING, `col2` STRING, `col3` STRING, `col4` STRING, `col5` STRING, `col6` STRING, `col7` STRING, `col8` STRING, `col9` STRING, `seg1` STRING, `seg2` STRING, `table_id` INT64 NOT NULL, `replicate_op` INT64 NOT NULL ) (provider_syntax_manager.c:1790)
00005376: 2024-10-14T14:03:57 [TARGET_APPLY ]T: Create net changes table.
~{NIcAId8HyB4wSAcKWYQ1a1zyvvVY6sn0JKkgFAdtRc}~ (odbc_bulk.c:697)
00005376: 2024-10-14T14:03:58 [TARGET_APPLY ]T: Start handling table 2000001 which is in the bulk (bulk_apply.c:5257)
00005376: 2024-10-14T14:03:58 [TARGET_APPLY ]T: Start handling table 2000002 which is in the bulk (bulk_apply.c:5257)
00004456: 2024-10-14T14:04:02 [PERFORMANCE ]T: Source latency 10297.86 seconds, Target latency 10371.14 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00005376: 2024-10-14T14:04:28 [TARGET_APPLY ]T: bulk_map: seq 1:1 INSERT 'DB1005'.'TDBQLIK' (id=2000001) (bulk_apply.c:6890)
00005376: 2024-10-14T14:04:28 [TARGET_APPLY ]T: bulk_map: seq 2:2000001 INSERT 'DB1005'.'TDBREPL' (id=2000002) (bulk_apply.c:6890)
00005376: 2024-10-14T14:04:28 [TARGET_APPLY ]T: Going to load file 'D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000003.csv' (csv_target.c:1979)
00004456: 2024-10-14T14:04:32 [PERFORMANCE ]T: Source latency 10327.98 seconds, Target latency 10401.27 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00005376: 2024-10-14T14:04:51 [TARGET_APPLY ]T: File D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000003.csv compressed to gzip (csv_target.c:1783)
00005376: 2024-10-14T14:04:51 [TARGET_APPLY ]T: Going to run load statement, 'D:\Program Files\Attunity\Replicate\bin/arepbq.exe' (csv_target.c:1254)
00005376: 2024-10-14T14:04:51 [TARGET_APPLY ]T: Before wait for command (csv_target.c:1033)
00004456: 2024-10-14T14:05:02 [PERFORMANCE ]T: Source latency 10358.09 seconds, Target latency 10431.38 seconds, Handling latency 73.28 seconds (replicationtask.c:3879)
00005376: 2024-10-14T14:05:16 [TARGET_APPLY ]T: Load command output: insert a JSON key

Going to load dataset id: sa_control_attrep table id attrep_changes86D30419D0E00467 from D:\Program Files\Attunity\Replicate\data\tasks\Qlik_Issue_GBQ\data_files\0\LOAD00000003.csv.gz
Loaded 2000001 rows to dev-gold-core.sa_control_attrep.attrep_changes86D30419D0E00467 (csv_target.c:1098)
00005376: 2024-10-14T14:05:16 [TARGET_APPLY ]T: Start applying of 'INSERT (1)' events for table 'DB1005'.'TDBQLIK' (2000001). (bulk_operations_applier.c:343)
00005376: 2024-10-14T14:05:16 [TARGET_APPLY ]T: Bulk INSERT statement for table 'sa_qlik_issue.tdbqlik_cdc' was not found in the pool, going to allocate a new statement (statement_manager.c:2016)
00005376: 2024-10-14T14:05:17 [TARGET_APPLY ]T: Going to run insert statement, from seq 1 to seq 1
~{NAtCIDo0k5d+pBdV0YtMhyIWUW38k6JoZEdv9qKEle9MtFCFatzA}~ (odbc_util.c:4487)
00005376: 2024-10-14T14:05:19 [TARGET_APPLY ]T: Finished applying of 1 'INSERT (1)' events for table 'DB1005'.'TDBQLIK' (2000001). (bulk_operations_applier.c:375)
00005376: 2024-10-14T14:05:19 [TARGET_APPLY ]T: Start applying of 'INSERT (1)' events for table 'DB1005'.'TDBREPL' (2000002). (bulk_operations_applier.c:343)
00005376: 2024-10-14T14:05:19 [TARGET_APPLY ]T: Bulk INSERT statement for table 'sa_qlik_issue.tdbrepl_cdc' was not found in the pool, going to allocate a new statement (statement_manager.c:2016)
00005376: 2024-10-14T14:05:20 [TARGET_APPLY ]T: Going to run insert statement, from seq 2 to seq 2000001
~{U0sbKDCHPQuDgGRSR/7g6N4v9hjvbZjUC1aemyrWWll/LSN3U}~ (odbc_util.c:4487)
00005376: 2024-10-14T14:05:25 [TARGET_APPLY ]T: Finished applying of 2000000 'INSERT (1)' events for table 'DB1005'.'TDBREPL' (2000002). (bulk_operations_applier.c:375)
00005376: 2024-10-14T14:05:25 [TARGET_APPLY ]T: Finished applying bulk changes for tables with PK and inserts for tables without PK (bulk_apply.c:6440)
00005376: 2024-10-14T14:05:25 [TARGET_APPLY ]T: The current bulk was applied. The last confirmed record id = 2000001, the last record id = 40400817 (bulk_apply.c:2501)
00005376: 2024-10-14T14:05:26 [TARGET_APPLY ]T: First bulk event: record_id = 40400825, stream_position ='2623;638645155528322420;20240229125837965062|0000000006C3EC86C0000001' (bulk_apply.c:1200)
00004456: 2024-10-14T14:05:33 [PERFORMANCE ]T: Source latency 10332.28 seconds, Target latency 10385.05 seconds, Handling latency 52.78 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:06:03 [PERFORMANCE ]T: Source latency 10345.43 seconds, Target latency 10415.18 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:06:33 [PERFORMANCE ]T: Source latency 10375.57 seconds, Target latency 10445.32 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:07:03 [PERFORMANCE ]T: Source latency 10405.72 seconds, Target latency 10475.47 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:07:33 [PERFORMANCE ]T: Source latency 10435.85 seconds, Target latency 10505.60 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:08:03 [PERFORMANCE ]T: Source latency 10465.94 seconds, Target latency 10535.69 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:08:33 [PERFORMANCE ]T: Source latency 10496.03 seconds, Target latency 10565.78 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)
00004456: 2024-10-14T14:09:03 [PERFORMANCE ]T: Source latency 10526.15 seconds, Target latency 10595.90 seconds, Handling latency 69.75 seconds (replicationtask.c:3879)

[sureshkumar]

Hello @jbasile 

Looks like the there is a Source Latency, please open a support ticket to analyze further.

Regards,

Suresh