Nservicebus: In Memory saga persistence degrades very fast over time

[ramonsmits]

The in-memory saga persistence degrades very fast over time. In the beginning message processing is fast but degrades as can be seen in the following graph.

Affected versions are:

• V5
• V6 RC

The test that is running:

• Creates only new saga instances, no congestion
• Max concurrency level = 512
• Memory used by the process is max several 100's of MB's

Looking at the following source files I see a helper class but didn't spot

• https://github.com/Particular/NServiceBus/blob/release-6.0.0/src/NServiceBus.Core/Persistence/InMemory/SagaPersister/InMemorySagaPersister.cs#L66-L77
• https://github.com/Particular/NServiceBus/blob/release-6.0.0/src/NServiceBus.Core/Persistence/InMemory/InMemoryTransactionalStorageSession.cs

Also note that the file name doesn't have the same name as the class (InMemorySynchronizedStorageSession )

[danielmarbach]

removing the bug label. Adding Bug is a bit of a stretch. The way the saga persister is designed it will decrease in performance. Pretty sure if you'd attach a profiler to it you would see https://github.com/Particular/NServiceBus/blob/release-6.0.0/src/NServiceBus.Core/Persistence/InMemory/SagaPersister/InMemorySagaPersister.cs#L93 shining in colorful lights in your profiler. The data we have in https://github.com/Particular/NServiceBus/blob/release-6.0.0/src/NServiceBus.Core/Persistence/InMemory/SagaPersister/InMemorySagaPersister.cs#L123 the slower this algorithm will be because of https://github.com/Particular/NServiceBus/blob/release-6.0.0/src/NServiceBus.Core/Persistence/InMemory/SagaPersister/InMemorySagaPersister.cs#L97-L103

Not sure we want to address this though since the persistence is not production ready and will probably never be.

[Scooletz]

Are these sagas completed in any stage, or are they just created and left forever?

[ramonsmits]

@Scooletz The scenario is never ending sagas. It's just a test case testing saga creation ingestion performance.

The graph only shows the first 1 minute. It's not like this is running for hours.

Maybe it is by design as @danielmarbach seems to suggest but than it's not suitable to use in the performance tests to use as a 'baseline'.

[danielmarbach]

@Particular/nservicebus-maintainers we need to fix this as we have users that are using the persistence in production for short-lived sagas. Especially now that we no longer support callbacks in the handlers coordination sagas for callbacks become more relevant. For those types of sagas InMemoryPersistence would be a good fit since you can live with the data being wiped after an endpoint restart.

[timbussmann]

why is this assigned to 6.1? Couldn't this be fixed on a patch release?

[danielmarbach]

we could yes.

[ramonsmits]

@timbussmann Because it's a refactoring and not a bug? The refactoring would be classified as a substantial improvement and that implies it can be seen as

Minor......... It MAY be incremented if substantial new functionality or improvements are introduced within the private code.

[timbussmann]

Because it's a refactoring and not a bug?

I'd say that heavily depends on the degree of performance impact. If it makes the system so slow that it can be classified as an "outtake", it would apply for a critical patch release.

[dbelcham]

After some investigation the initial spike that @ramonsmits noted can be attributed to the startup with a concurrency of 512 (or any other suitably large concurrency number). At startup the system needs to pull out a large volume of messages to initially create all of the threads for that level of concurrency. Once that initial pull of messages has occurred, the messages are retrieved from the queue at the speed they are being processed at which will be slower than the first loading.

When observed over a longer period of time the persister does continue to slow down at an almost linear rate. When observed over 20+ minutes and 50,000+ messages the processing speed dropped by over 50%. This steady decline in performance is what I'm going to look into to see if it can be remedied.

[ramonsmits]

@dbelcham The concurrency does not have a lot to do with it. When there are a lot of saga instances that the current implementation does a linear search on the collection. That, on average, requires to compare 50% of the objects in the collection. The solution is to do either a binary/tree search on the property values by button those values in separate Dictionary objects.

[timbussmann]

The concurrency does not have a lot to do with it.

@ramonsmits yes it does have a lot to do with the initial spike you can see when observing the #consumed messages performance counter when starting the endpoint. Once we picked up the amount of messages which can be handled concurrently, the endpoint only consumes as many new messages as it successfully processes. @dbelcham is still investigating this issue and we're not talking about solutions yet.

[ramonsmits]

@timbussmann No, it does not and here is a graph to prove it:

Each spike shows the configured max concurrency level and you see that this also happens with a max concurrency level of 1.

The following graph shows how the performance is when there is only a single item in the dictionary:

[dbelcham]

@ramonsmits did you restart the endpoint just before each of those spikes? I'm assuming you did since that's the only way I know of changing the concurrency

[ramonsmits]

@dbelcham Yes, each one is a new process.

[dbelcham]

@ramonsmits if each one is the start of a new process then what you are seeing is the ramp up of all the Task needed to get to the level of concurrency configured. Each on of the 512 (given your sample config earlier) concurrencies will start a new Task and add that to the processing pool. Not all 512 will be started, that number will be controlled by the TaskScheduler. It's safe to say that on a multi core/processor system, multiple Tasks will be started though.

Each one of those started tasks will pull a message off the queue. This happens almost simultaneously (yay parallel processing!) as the Tasks spin up. This rapid and simultaneous retrieval of messages is reflected as a spike in the chart.

The processing of multiple messages will not complete at the same time which results in the starting of new Tasks in more of a trickle than a big bang like the initial loading of the concurrency limits. As such, subsequent messages are fetched in a trickle by those newly starting Tasks. This is reflected in the charts by a flatter line of messages being pulled from the queue. As the Task execution and completion falls into a more predictable pattern of completion and new Task initialization and execution, the number of pulled messages per second will stabilize as well. This is why we see a flat-ish line the longer we look at these charts. As it currently stands, the line is not actually flat, but slowly declines over time. Watching it for 20-30 minutes will show that the line can actually drop 50% during that period.

The "table-top" effect that you see when running at a concurrency of 1 is because of the existence of only one Task at any given time. Because only one Task exists, only 1 message can be pulled from the queue at start up. This "1" represents the peak of messages being retrieved during the endpoint initialization process. Unlike a scenario with a concurrency of > 1, there is no "stabilization" of the frequency that Tasks are finished and created, and that also means that there is no stabilization of the frequency of messages pulled from the queue. As such, the initial startup faze represents both the peak frequency of messages pulled as well as the stabilized frequency of messages pulled. This means that the frequency is, in effect, flat while there are messages to process. This is what presents the "table-top" graph.

As I said, in a concurrency > 1 configuration the stabilized frequency will slowly decline over time. This is not what we would like and it is that performance problem that I'm investigating at the moment. The spike when concurrency > 1 is to be expected because of the initial surge of messages pulled as the pool of Tasks is created during endpoint start up.

[dbelcham]

Update on what is being tried:

• Finished: optimization of two different tight loops to move functionality outside the loop and reduce the number of looping operations performed. In both cases the results were very minor improvements.
• Tried & Failed: _unable to properly keep two collections in sync in the Update method on the persister. No information about the CorellationProperty was available_ -- Removal of the loop over ConcurrentDictionary in the Get method. The locking performed on inside the ConcurrentDictionary class is consuming a large amount of processing. This would be replaced by a custom data structure that has custom locking surrounding a simple Dictionary<SagaId, Saga> and a Dictionary containing indexed lookups by the correlation property of the saga. This approach will initially be very coarse in its locking strategy to see if the use of the indexing yields any performance gains.
• WIP: change the loop to use foreach(var entity in data) instead of foreach(var entity in data.Values). Was pointed at this possible solution while reading up on the inner workings of ConcurrencyDictionary. It appears that using GetEnumerator is lock free reading of the data while iterating over .Values (or .Keys for that matter) requires collection level locking. Initial testing looks promising.
• To Try: Change the concurrency settings for the current ConcurrentDictionary to be better for reading

[ramonsmits]

https://github.com/Particular/NServiceBus/issues/4158#issuecomment-256703766

I'm sorry @dbelcham but that just isn't true. Again, it doesn't matter if concurrency is 1 or 1000. If the collection contains more and more saga instances that will make it slower. To retrieve a single saga instance we perform a linear search and that is an O(n) operation.

Maybe you are looking at something completely different than that I'm making clear in this issue.

As my test only creates saga instances it is clear that this doesn't have anything to do with concurrency or ramping up of tasks.

[dbelcham]

Fixed in #4300

[Scooletz]

I'm so 😄 seeing it closed 💃