Partitions gets unhealthy if many timers are scheduled

[ChrisKujawa]

Describe the bug

We deployed the following process

There were two bugs in the process:

• an parallel sequence flow to the call activity, causing endless recursion
• the timer expression was not optimal =date and time(today(), time("16:00:00@Europe/Berlin")) - now() it caused an negative duration after reaching the time.

When we deploy the model, we create endless new process instances and fill the timer column. If the specific time is reached we have to trigger a lot of timers, might be millions depending how long the recursion was running and how many instances have initially be started. The recursion continues and adds more and more due timers to the timer column.

The problem here is that the processing is completely blocked, since the timer checker is running in the same actor.. Furthermore, it causes to produces an endless backlog, which the processor is not able to catch up. The processor will become unhealthy and the backpressure wents up to 100% since the requests are not answered.

To Reproduce

Deploy this model
gamedayprocess.bpmn.txt and start new instances watch out, you can throw your cluster away afterwards.

Expected behavior
As a user I'm not able to completely f** up my cluster, or at least there is some way to recover from this.

[npepinpe]

Seems like we did not triage this, and this was marked as critical. Let's talk about it tomorrow - I guess the board switch caused me to miss this one.

[pihme]

This also occurred in a simpler process. E.g. in Roman's benchmark he wants to have a certain load on the system. He starts a number of process instance e.g. 10/s. Each process waits at two points for 20 minutes. Because of the continuous creation of process instances, at any point in time, there are a couple of timers ready to be triggered.

Depending on the load the performance is heavily degraded.

[pihme]

Roman's workflow looked like this:

I guess it can be simplified to:

But maybe the other elements are necessary to add latency between the time a command is written to the log and the time a record is processed.

This is just to say it can also happen without specially crafted process from Game days.

Looking at the code I can see the following:

• Timer Records are added to the database when the timer element is activated
• Timer records are removed after the TimerIntent.TRIGGER has been processed.

This also means that the DueDateTimeChecker might visit the same timer multiple times, and create multiple trigger commands for it. This is because the DueDateTimeChecker does not alter the database, and only writes to the log.

So my working hypothesis is that the there is an escalating feedback loop.

• DueDateTimeChecker visits a couple of timers once, writes commands for these timers
• DueDateTimeChecker is triggered again before these commands have been processed, thus revisit the same events and also new events which have come due since the last run. Then it writes duplicate commands for the old timers and new commands for new timers it found
• Thus, if we cannot process all commands than the DueDateTimeChecker wrote in the last run, before DueDateTimeChecker is running again, we will write more and more duplicate records to the commit log and revisit certain timers again and again.
• Sine the db table is chronological, the commands are also chronological. So in the second round we encounter the duplicate commands first and waste time on those, which means we make even less progress in terms of removing the new events from the database
• This can then escalate until we are totally blocked, because thousands of timers have not been removed yet, and thousands of timers lead to thousands of follow up records

Could also be that this happens more prominently after a broker resumes, because much time has passed since the last run. This could also explain Romans observation that one some days he can get stable performance and on others not.

/cc @Zelldon @saig0 wdyt?

[saig0]

@pihme yes. That sounds correct.

But there is one more aspect. If the DueDateTimeChecker visits many timers on a check then it blocks the actor thread and other actor jobs can't be executed (e.g. sending heartbeats).

A solution could be to limit the number of timers for one check (e.g. only 100 timers at once).

[pihme]

Not sure this would be a valid solution. My fear is that it will just always be falling further and further behind.

Right now the highest possible frequency of DueDateTimeChecker runs seems to be 10 Hertz. If we only allow to trigger 100 timers per invocation, but we create 200 timers each 100ms, then we will just fall further and further behind. And this build up would not be reflected in the back pressure mechanism.

My hope is that if we always trigger all due timers, this will cause delay, which will influence back pressure. The way the system is set up now, I see no other way than to let back pressure dial in to sustained throughput to the speed of the slowest link in the processing chain.

[ChrisKujawa]

Sorry for the late response. Interesting observation you made @pihme and sounds right. In my case it was more like @saig0 described that the actor didn't stop to write due timers, I had many many write records per second but no processing at all.

I agree with the argument from @pihme. Not sure whether it would really help to just limit it, sounds like a band-aid 🩹 I guess optimal would be to have a separate actor, which writes to the log. This would at least help here with not blocking processing. Still it can happen that we write many many timers at once. We could solve that then maybe via writing over the command API or something such that back pressure is taken into account like @pihme said. 🤷

[pihme]

@Zelldon Could you comment on the prioritization of actor tasks with respect to time based tasks vs. ordinary tasks?

More precisely: Supposing the DueDateTimeChecker is scheduled every 100ms, but runs more than 100ms each time. What will happen? Will the actor schedule always and only schedule the DueDateTimeChecker or will some progress be made by other tasks before DueDateTimeChecker is scheduled again?

[pihme]

And the second question: What happens when you schedule a task with a negative delay? Because I think this can happen

[ChrisKujawa]

Hey @pihme

as always it depends. In general, the timers and "ordinary" tasks are at the end scheduled the same. We have the fastlane and the queue, for "less" priority. So we have kind of an implicit priority. What I understand from the code is that if there are jobs in the fastlane already they are executed first and due timers are added to the fastlane as well. I guess the issue is even more problematic if we use runAtFixedRate and the execution takes longer than the rate.

To get to your example: If the DueDateTimeChecker is scheduled via runAtFixedRate with 100ms as the rate and takes longer than 100ms then a new job will already be added. Normally we use runDelayed, which means we schedule the next job only after we are done. AFAIK this is how it's done in the DueDateTimeChecker.

So in the above-described example and scenario, which I used in the gameday was that the DueTimerchecker had thousand or millions of Timers, which are due at the same time. It blocked the actor thread completely because it iterated over the whole column family to write a timer trigger command. I guess due to the subscription logic and "priority" that timers are scheduled in fast-lane the processing was not happening for a long time. This is my current assumption.

Regarding the negative duration, this happened to me accidentally in the gameday. This means the timer is immediately due.

Does this help?

[pihme]

Summary of Preliminary Findings

There are two problems we need to solve:

• Huge backlog of accumulated timers
• Steady state with high throughput of process instances

The first problem was the focus of the original description of the issue. This could for example occur when a company wants to send their customers a thank you email on Christmas. Throughout the year timers are collected, which all fire on Christmas day simultaneously.

Here we see the following issues:

• DueDateTimeChecker will block progress if many timers are due #9238 Timers are iterated over in full without ever giving yield. During this time, no other processing can take place

The second problem was observed by Roman in benchmarks. Here it is just a steady load which leads to indeterministic blocking of the processing thread.

Here we see the following issues:

• Due timers may be visited several times by the DueDateTimeChecker. Each time it will write a new TriggerTimer command. Only when the command is processed will the timer be removed. So then we run into a difference in the speed in which timers are created, and the speed in which timers are removed. And writing duplicate commands makes this worse for reasons outline above.
• DueDateTimeChecker may be scheduled with a negative delay #9236 The DueDateTimeChecker may be scheduled with a negative delay to run next, which means it runs pretty much immediately.

[romansmirnov]

Just want to share my thoughts 😄

@Zelldon,

Maybe a comment on your #8991 (comment) 😄

I guess due to the subscription logic and "priority" that timers are scheduled in fast-lane the processing was not happening for a long time. This is my current assumption.

In the described scenario, with millions of timers being due simultaneously, I think the problem is not with how the actor schedules the jobs. In my opinion, this whileTrue-loop is the problem:

https://github.com/camunda/zeebe/blob/dd3e9fb653e04223e4fe64b88b3273231efa6c6e/engine/src/main/java/io/camunda/zeebe/engine/state/instance/DbTimerInstanceState.java#L90-L105

This means it will remain in this loop as long as there is a next timer event being due. With millions of timers being due simultaneously, it will execute that loop until it visits all the millions of timer events...and this may take some time and block processing on that partition in the meantime.

@pihme,

Here it is just a steady load which leads to indeterministic blocking of the processing thread.

I don't think my scenario is much different from Chris's scenario in the gameday. The only difference is there are more than 20k timer events on one partition, whereby the timer's due date is distributed over the next 20 minutes. So, not all of them are due at the same time.

What can happen (and happens) is that it will remain in the whileTrue-loop for the next 20 minutes because there is always a next timer event being due. Also, it may happen that in between, it reaches a moment when the next timer event is not due at that moment (but the timer event would get due at the very next moment). Then it will schedule the next run accordingly, but because of how the actor schedules the jobs (as described by @Zelldon), it will immediately go into the whileTrue-loop and continue visiting the timers.

[ChrisKujawa]

Hey @romansmirnov yes this is what I wrote the sentence before 😅 It blocked the actor thread completely because it iterated over the whole column family to write a timer trigger command. and the subscription is the addition to it which makes the problem even worse.

[romansmirnov]

I guess optimal would be to have a separate actor, which writes to the log.

I agree with that point. I even tried that but it failed with the exception in #9187 - but I haven't investigated it further.

Besides that, the only concern I may have, if there is only one CPU thread configured 😉

[ChrisKujawa]

Besides that, the only concern I may have, if there is only one CPU thread configured wink

@romansmirnov you mean because it would block the thread again and the other actor can't run? Might be then the yield or backpressure would help here? 🤔

[romansmirnov]

@Zelldon, yes, exactly.

Might be then the yield or backpressure would help here?

I think yield would help but haven't thought it through yet.

[pihme]

Update before handover:

There were three problems found in DueDateChecker

• Tasks to check for due timers was sometimes rescheduled immediately - fixed DueDateTimeChecker may be scheduled with a negative delay #9236
• DueDateTimeChecker did not yield - fixed DueDateTimeChecker will block progress if many timers are due #9238
• DueDateTimeChecker will visit the same timer more than once and write duplicate trigger event records - open (no issue created yet)

With the two fixes, I was unable to repeatedly recover a cluster which was unresponsive. I was able to recover it once, by also implementing a quick fix for the third issue, but I was unable to reproduce the success.

There were a couple of problems found unrelated to DueDateChecker

• Request time out in JobActivation request (and others) is ignored #9276 In discussion. Behavior seems to be expected, but is not really useful
• Consider adding deploy workflow / cancel process instance to whitelisted commands (which will be accepted when backpressure is high) #9283 open. Could help in this case and would be an easy fix

Another issue not needed for the fix, but to make it better to diagnose issue:
#9282

From what I could see from the logs of the server it seems to be stuck at some other place as well. It makes good progress, intermitted by long breaks. I don't know what is causing the breaks. The data set is linked in one of the comments above.
I did add timer watch guards around the call to process a command:

        final long now = System.currentTimeMillis();
        processCommand(currentRecord);
        final long elapsedTime = System.currentTimeMillis() - now;
        if (elapsedTime > 1000) {
          System.out.println("Elapsed Time:" + Duration.ofMillis(elapsedTime).toString());
        }

However, I have not observed any commands that exceeded 1 s.

Another thing to consider is whether the same issues of DueDateTimerChecker would also need to be implemented for job timeouts. (in the logs I saw a lot of jobs timing out)

[saig0]

Summary

A partition gets unhealthy if many timers are scheduled for the same time (or in a short time frame).
The number of timers depends on the available resources.

@romansmirnov ran into this issue with a process that has two timers after each other (including some service tasks in between). The timers are scheduled for 20 minutes.

With cluster plan S: if more than 17 instances are created per second
With cluster plan M: if more than 27 instances are created per second

The partition got unhealthy but it recovered after a while (20 minutes - 1 hour).

---

We will not work on this issue immediately because

• it is not likely to have so many timers that are scheduled for the same time
• it is a general issue about processing large data from the database (also for job time outs and message TTL) that requires a bigger effort to fix it

[korthout]

Updated severity to reflect current team opinion described here. Issue is moved into backlog.