topic Re: TARGET_APPLY: Finish bulk because stream timeout in Qlik Replicate

TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 16:56:26 GMT

I have been investigating high latency in my solution and it seems to be caused by a specific, high activity table (RESB in SAP db).

I noticed this message in the log and wondered if could point me to a more specific cause that I could investigate:

00018076: 2022-12-28T09:39:44 [TARGET_APPLY ]T: Finish bulk because stream timeout (bulk_apply.c:1012)

Thanks

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 16:58:01 GMT

A few other points to clarification:

The task that shows noted message has only the one high activity table (RESB) and is showing 3 hours latency but with zero incoming changes.

And even with zero incoming changes, the apply throughput graph is showing 6-10 records / second being applied.

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 16:59:26 GMT

....I have 4 other tasks all reading from the same source and writing to the same target but they all have latency < 10 seconds.

Re: TARGET_APPLY: Finish bulk because stream timeout

Dana_Baldwin — Wed, 28 Dec 2022 18:12:56 GMT

Hi @Martin11

This log entry doesn't indicate a problem, it just informs you that the batch of data it was processing was applied to the target based on the length of time rather than the amount of data. Batches can be applied based on either time or amount of data. This is controlled based on what settings are in Task Settings \ Change Processing \ Change Process Tuning. More information can be found here:

Change Processing Tuning #Change Processing Tuning ‒ Qlik Replicate

When you select "Incoming Changes" on the Monitor tab, are you seeing changes in memory or on disk waiting for target commit? If you select Apply Latency are you seeing source or target latency?

Here's some general information about latency:

Latency is the time interval in seconds
between the time a change was
committed in the source system and the
time it is applied and committed in the
target system.

Source Latency: The gap in seconds
between the original change in the
source endpoint and capturing it.

Target Latency: The gap in seconds between the
original change in the source endpoint
and applying it to the target endpoint.

Apply Latency: The gap in seconds
between capturing the change in the
source endpoint and applying it to the target
endpoint.

Note During data capture, the target latency will always be equal to the source latency (even
though no data has reached the target yet). This is simply because target latency is the sum of
source latency + apply latency, and can therefore never be less than the source latency.

Latency when applying large transactions:
For example, when the most recent latency value was 10 seconds and now a transaction
of one million rows gets committed at the source endpoint, Attunity Replicate starts to
apply that transaction to the selected target and it will take some time to write all the
changes to the target (for example 60 seconds). During the next 60 seconds, the latency
value gradually grows to 70 seconds for the last change in the transaction. Once the
transaction is committed, the latency drops back to the 'regular' latency (10 seconds in
this case).

Latency when no transactions are being applied:
When a time period passes with no changes applied to the target, the latency calculation
is based on the time difference between the current time and the timestamp of the last
change event read from the transaction log. This could happen if, for example, there is
high activity on tables which are not selected for replication in the current task.

Thanks,

Dana

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 18:38:31 GMT

Hi Dana,

With regards to Latency when no transactions are being applied:

I witnessed a situation where 1 of my 5 tasks had 3 hours of latency and the other 4 tasks all had less than 10 seconds of latency.

(All 5 tasks are reading from the same source and writing to the same target.)

If latency can be the difference between current time and last change event read from the transaction log (even if not for task tables), shouldn't all 5 tasks have a similar latency ?

Thanks,

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Dana_Baldwin — Wed, 28 Dec 2022 20:29:54 GMT

Hi @Martin11

Were there no incoming changes or pending changes for the target for any of the 5 tasks?

Thanks,

Dana

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 20:39:27 GMT

HI Dana,

There were but none had latency associated with those changes of more than 10 seconds.

So if latency is also representative of changes for tables not selected for replication by the task, I'm struggling to understand how the latency is so wildly different among these 5 tasks that have common source/target endpoints.

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Dana_Baldwin — Wed, 28 Dec 2022 21:06:04 GMT

Hi @Martin11

Latency is only based on activity in tables not selected in the task when there is no activity in the tables that do belong to the task.

Thanks,

Dana

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Wed, 28 Dec 2022 23:18:35 GMT

Hi Dana,

Is there any way to configure so that if there is no activity for the tables selected in the task that latency shows zero ?

Thanks,

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Heinvandenheuvel — Wed, 28 Dec 2022 23:25:27 GMT

@Dana_Baldwin provided some good information on Latency. Please be sure to enable logging for PERFORMANCE set to TRACE (in the current version VERBOSE does not add additional info beyond TRACE) and let us know which latency we are dealing with. Are there 'waiting for source commit' pending TX's?

You reported "Finish bulk because stream timeout" in the opening writing and subject for the topic. It may be good to explain that a little to understand whether it is relevant at all and is so whether, a cause, or an effect.

First, what does it mean to "finish a bulk", well it is very much an intermediate stage. It means that the 'bulk_apply' engine inside the 'TARGET_APPLY' threat decided is gathered enough changes (from the SORTER threat) for them to be applied and thus to START sending them to the target. That decision is based on task-settings - Change Processing Tuning - Batch tuning - choices.

The easy one is when there are more changes than the <Force apply a batch when processing memory exceeds (MB):> allowed for and the resulting message in the reptask log will be "Bulk finished because memory usage has exceeded the limit". After that message the tasks will start sending that bulk to the target which involves filling a 'atterp_changes' table and perhaps first stuffing them in a CVS file to be transferred over the network and applies after which the SQL apply statements start. "the bus is full"

Timeout is trickier because there are two!

Parameter "Longer than (seconds): " (default 1). This roughly maps to a formula : "now" > BulkStartTime + ApplyTimeoutMin and results in --> "Finish bulk because stream timeout". This is where the 'bulk_apply' code has been provided a change and waits around some to see it can put more changes in the bulk. Low values improve 'near realtime' behavior. Higher values allow for larger bulks which reduces resource use on targets. This is a bus driver keeping the door open to see if there is someone coming in running.

Parameter "But less than (seconds):" (default 30). This roughly maps to a formula : "now" > BulkStartTime + ApplyTimeout AND NOT EmptyBulk and results in --> "Finish Bulk because Bulk timeout"). The sorter keeps providing changes. Perhaps a steady stream of unrelated events, perhaps lots of changes for a single table in a transaction. They are added to the pile while there is still room. But eventually they have to be released to the target. Again low values improve 'near realtime' behavior. Higher values allow for larger bulks which reduces resource use on targets and very high values will lead to bulk filling up memory. This is a bus driver closing the door in your face 'sorry folks I gotta go I have a schedule to try to maintain and those on the bus already have been more than patient.'

Hope this helps understanding whether the "Finish bulk because stream timeout" is just fine or not.

For further help please clarify whether those other tasks truly work on the same source and target (and why more than 1 task?) and perhaps provide a bit of reptask log, with at least 'performance trace' and hopefully 'target_apply trace, for at least a minute but better 10 or more minutes and ideally showing a good task versus a bad task, where the 'bad' task log is most important of course. Oh, and how about a bad task JSON?

Cheers,

Hein.

Re: TARGET_APPLY: Finish bulk because stream timeout

Dana_Baldwin — Wed, 28 Dec 2022 23:44:58 GMT

Hi @Martin11

Not that I am aware of. I encourage you to submit a feature request here if this is something you would like to see in the product: https://community.qlik.com/t5/Ideas/idb-p/qlik-ideas

Thanks,

Dana

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Thu, 29 Dec 2022 19:02:10 GMT

Thanks for all the great info, Hein !

I'm going to wait for a time when the latencies diverge and provide the documentation that you suggest.

Thanks,

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Tue, 03 Jan 2023 19:16:15 GMT

Hi Hein

Apologize for the delay.

I can confirm that these tasks are using the same source and target systems.

We have multiple tasks in an effort to troubleshoot / isolate latency issues.

I have attached a file with the JSON of the 'good' and 'bad' tasks as well as their respective logs for about a 15 minute timeframe. During this time the latency of the 'bad' task was 7+ hours and the 'good' task was less than 5 minutes.

Thank,

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Heinvandenheuvel — Thu, 05 Jan 2023 06:01:25 GMT

Thanks for the detailed info.

At first glance it is strictly volume related where the source change reading for the RESB table cannot keep up.

The 'bad' task runs at 1000+ changes/sec, frequently running out of its default 500 MB memory for batches of 72,000+ changes.

The 'good' task runs ar 70 changes/sec, never running out of its 1800 MB 'tuned' memory with no more than 2500 changes/batch.

Summary of TARGET_APPLY log lines for BAD:

Task <bad__PE3-3 RESB_to_QLIK.txt> from 01/03 11:34:38 thru 01/03 11:50:01. (923 seconds) Total 37 Batches in log, largest 72508, longest duration 60 1125.1 changes/second overall. 1038481 total, gap 63 @ 01/03 11:48:08. 35 Statement not found. no_bulk:0, no pk:0, 69 applies, 0 singles, max 36254. noPK-time=0 35 truncates for attrep_changes tables taking 0 seconds "Start Handling Table" took 17 times more than 1 second. Total 86 seconds LATENCY| Begin| End| Min| Max| Net| -------|-------|-------|-------|-------|-------| Source | 29490| 29761| 29490| 29770| 271| Target | 285| 418| 0| 525| 133| Elapsed| | | | | 923|

Summary of TARGET_APPLY log lines for GOOD:

Task <good__PE3_to_QLIK_NOSQL.txt> from 01/03 11:34:00 thru 01/03 11:49:45. (945 seconds) Total 158 Batches in log, largest 2504, longest duration 13 72.8 changes/second overall. 68767 total, gap 12 @ 01/03 11:36:30. 4339 Statement not found. no_bulk:0, no pk:0, 8953 applies, 3396 singles, max 509. noPK-time=0 157 truncates for attrep_changes tables taking 4 seconds LATENCY| Begin| End| Min| Max| Net| -------|-------|-------|-------|-------|-------| Source | 4| 7| 2| 22| 3| Target | 4| 7| 0| 9| 3| Elapsed| | | | | 945|

Mind you, I don't think giving the 'bad' tasks more memory will help it significantly, as the delay appears to be gathering the changes.

Another way to see the the source reader delay is to see in the log the timestamp for which change is currently being read as committed.

GOOD: 03T11:39:11 [SOURCE_CAPTURE ]T: > txn_id: 00065B58071E, timestamp: 2023-01-03 16:39:08

BAD: 03T11:39:11 [SOURCE_CAPTURE ]T: > txn_id: 00065AD8B438, timestamp: 2023-01-03 08:24:56

GOOD shows 5 hours and 3 seconds difference between replicate log time and the source time stamp. Surely 5 hour due to time-zone and 3 seconds latency. BAD shows 8 hours 15 mintes earlier than GOOD matching the latency reported by 03T11:39:01 [PERFORMANCE ]T: Source latency 29656: 29656/3600 = 8.24

On the SOURCE_CAPTURE side the BAD task with no 'stream_buffer' tuning reports 1127 'FULL STREAM ' messages, whereas the GOOD task which has 'stream_buffer' tuning never reports that. Mind you considering the frequency and sub-second 'recovery time I again do not expect a significant improvement is those FULL STREAM events are tuned away, but one should attempt to tune that just in case so to speak.

Could the source server have 'punished' (Linux NICE) the source reader tasks/thread for the RESB task because it was consuming disproportional resources?

I think it is worth your while to check out LOG_STEARM to have 1, well tuned, source reader task and you can still have your 'control' with multiple slave tasks reading the logstream each selecting their own tables.

I would also be tempted to run the RESB (aka BAD) task in isolation with no other source change log reading and with a NUL target to see what it's absolute max change throughput is.

hth,

Hein.

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Sun, 08 Jan 2023 17:26:18 GMT

Hi Hein,

Some questions:

1. Can you give a brief explanation of how you created the charts for Source and Target rows ?

2. The logs uploaded for this thread contain the message "[SOURCE_CAPTURE ]T: Transactions in progress counter is negative". Does this indicate a problem ?

3. GOOD shows 5 hours and 3 seconds difference between replicate log time and the source time stamp. Surely 5 hour due to time-zone and 3 seconds latency. BAD shows 8 hours 15 mintes earlier than GOOD matching the latency reported by 03T11:39:01 [PERFORMANCE ]T: Source latency 29656: 29656/3600 = 8.24

Since both tasks are reading the same source, wouldn't they both have the same offset of time zone ?

Thanks,

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Heinvandenheuvel — Mon, 09 Jan 2023 04:53:21 GMT

>> 1. Can you give a brief explanation of how you created the charts for Source and Target rows ?

Just to clear, I think you know this, those are LATENCY numbers, not row numbers. They are just from a (perl) scripts parsing the [PERFORMANCE] lines. I'll attach the script. It also created the other summary statements.

>> 2. The logs uploaded for this thread contain the message "[SOURCE_CAPTURE ]T: Transactions in progress counter is negative".

I noticed those but have no good explanations. It feels like a 'start by timestamp' failing to 'wait for transaction consistency'. I that case the source reader could easily, in fact is guaranteed, to see more commits than TX created and thus the count would be negative. I don't recall having seen source drivers do not seem to report this. I don't think they are critical warnings just 'debug' observations.

>> 3. wouldn't they both have the same offset of time zone ?

Yes, that's why I wrote "BAD shows 8 hours 15 mintes earlier than GOOD" so relative to one another, both being 5 hours away from the Replicate server (can you confirm that?)

Re: TARGET_APPLY: Finish bulk because stream timeout

kishetty03 — Tue, 30 May 2023 05:56:31 GMT

@Martin11
HI Martin,
Just wanted to get your input/suggestion on this.
Were you able to solve the issue.

We are facing same issue on same Table RESB due to high Transaction on Source.
Latency is reaching over 24 hours in my case.

Thanks,

Kiran

Re: TARGET_APPLY: Finish bulk because stream timeout

Steve_Nguyen — Thu, 01 Jun 2023 17:40:31 GMT

@kishetty03 see hein comment #20782345

Re: TARGET_APPLY: Finish bulk because stream timeout

Martin11 — Thu, 01 Jun 2023 19:25:04 GMT

Hi Kiran,

We still have sporadically high latency on our RESB table. We have 5 tasks all pointed to the same db source and sometimes they are all at about the same latency - but often RESB (which is in it's own dedicated task), is several hours latent and the other 4 tasks are near zero or at much lower latencies.

Martin

Re: TARGET_APPLY: Finish bulk because stream timeout

Steve_Nguyen — Fri, 02 Jun 2023 12:29:55 GMT

@Martin11 try to enable verbose logging on source and target to see what is slowing, is on the source or target . and then try to narrow down to exact cause of slow.