Out of memory exception with high exceptions rate in multi threaded environment

[sanjaysingh]

Describe the bug
Rollbar seems to be causing out of memory issues when a multi threaded application causes burst of exceptions in short span of time.

To Reproduce
We were able to write a .Net console app with just the enough code to show the behavior that we think is affecting us. The memory usage keeps growing up when application is continuously pumping exceptions from multiple threads. In this example we only used 5 threads but in the real application where we use Rollbar we have 100s of threads. Understand that following example is just a representation of the issue to simplify reproducing of the problem; it does not depict how the Rollbar is being used in the application. In actual application, Rollbar is used with Log4Net using an appender.

The error can also be reproduced if you use incorrect access code that you might want to do so that Rollbar is not flooded with all these dummy exceptions.

using System;
using System.Threading.Tasks;
using System.Configuration;
using Rollbar;
using System.Diagnostics;

namespace ConsoleApp1
{
    class Program
    {
        static void Main(string[] args)
        {
            var config = new RollbarConfig(ConfigurationManager.AppSettings["Rollbar.AccessToken"])
            {
                Environment = "Development"
            };
            var rollBar = RollbarFactory.CreateNew().Configure(config);
            int threadsCount = 5;
            Console.WriteLine($"Enter to start sending stream of messages on {threadsCount} threads.");
            Console.ReadLine();
            for (int i = 0; i < threadsCount; i++)
            {
                Task.Run(() =>
                {
                    while (true)
                    {
                        rollBar.Error(new System.Exception("A dummy exception occurred".PadRight(1024, 'Z')));
                    }
                });

            }
            Task.Run(() => 
            {
                while (true)
                {
                    Console.WriteLine($"Memory used: {Process.GetCurrentProcess().PrivateMemorySize64 / (1024 * 1024) }MB");
                    Task.Delay(1000).Wait();
                }
            });
            Console.WriteLine("Done creating tasks. Enter to exit");
            Console.ReadLine();
        }
    }
}

Expected behavior
Flooding of exceptions should not cause extra memory pressure on the application just because we are trying to send those errors to Rollbar. Seems like the errors get cached in memory and it cannot keep with the rate of exceptions being generated. If the application is already under pressure because of some issues in downstream dependencies, the logger (Rollar) should not aggravate that situation. There might be a possibility of implementing some rate limiting / buffer limiting on the client side if it is not already there.

Screenshots
Memory graph taken from Visual Studio 2017 in-built memory profiler

Console log showing how memory usage is increasing

Rollbar Client - Rollbar.NET Hosting Environment

• Rollbar.NET Host type: Azure Worker Role, Console Application

• OS and its version: Windows Server 2012, Windows 10

• .NET flavor and its version: .Net Framework 4.6.2

• Rollbar.NET Version: 2.1.0

• Applicable custom third party logging library/framework integration (if any): Log4Net

[akornich]

@sanjaysingh , thanks for reporting the issue.
I'll look into the attached sample application a bit later today. But for now, I want to make sure there is a clear understanding of the basic concepts of Rollbar.NET inner structure.
Every instance of the logger has a payload queue associated with it. It is a fixed depth queue (of 20 items by default and can be overwritten in RollbarConfig). All the active instances of the queues are grouped by their Rollbar access tokens. When the queues are processed the processor makes sure it does not transmit the payloads in excess of the allowed rate per each unique access token (60 payloads per min per access token, by default but could be reduces within RollbarConfig). Also, if there are any network issues to transmit a payload it might take up to 3 retries to get it out of a queue. Also, keep in mind that even already transmitted payload objects could hang around in memory long enough until they the .NET garbage collector kicks in.
So, in short, some memory usage increase is expected but to a limited level based on payloads rate and size, amount of queues, their depths, and their transmission rate limits.

[sanjaysingh]

@akornich Thanks for prompt reply. In our case, we are using a single instance of the logger for the lifetime of the application. It also then uses a single access key that is configured when logger is created. Let us know if we are using the the Rollbar logger incorrectly causing this memory issue.

[akornich]

@sanjaysingh , what happens if you periodically invoke garbage collector while the test app running?

[sanjaysingh]

Haven't tried that. But i don't think it will make any difference. When running the memory profiler i see that the issue is with RollbarLogger class maintaining the dictionary of pending tasks. With flood of messages, these tasks just don't get scheduled fast enough and eventually cause out of memory.

The queue depth of 20 does not really matter in this case because, the tasks itself are piling up to get scheduled to queue those messages. I think the depth smartness needs to be shifted little bit up the stack so that these unnecessary tasks don't get created in the first place.

[akornich]

@sanjaysingh , i just briefly looked at your test application code and it looks like you are starting 5 threads pumping exceptions into a single logger instance without any "sleep"/breath time left. How realistic is this scenario in the first place?
I understand you are trying to simulate a busy server application. If your real application does something similar to this, you probably need to take close look into why it generates such a flood of exceptions (with virtually infinitely high rate). Also, when .NET runs on Windows server it runs its garbage collection in the server mode as opposed to running in the workstation mode (I am not saying it can fix the problem you are facing but it does make them as very different use cases). Another thing to keep in mind, in server environment .NET has (at least it used to be some time ago) much larger thread pool than in non-server environment, and I think there is a way to increase even that number.
The point I am trying to make is that when you need to, for example, test your defense line, throwing a nuke on it and evaporating the whole thing does not provide you with any learning experience about how good or not it was as a defense line regardless of what purpose it was created for.

[sanjaysingh]

@akornich The sample code above as I had clearly mentioned was an attempt to replicate the issue that we faced in production and had to turn off Rollbar. So yes it is very much possible. I am shocked that you are doubting this whole issue that we spent many man hours to figure out and then spending time to reproduce it and trying to get it addressed. Thread starvation can happen. It is not about increasing the thread count because no number of threads would be enough with the current structure that you have if the exceptions are flooded. We for sure are working on fixing the issues that caused the flooding and will be implementing the Circuit breaker there. The important thing is we will fix what we find. What we don't know what we don't know and the things can repeat and we in no way want the the logger to be a bottleneck. Here is the lay of the land. It is unnecessary distraction in my opinion but just it case it is going to help you visualize better.

• An Azure Worker Role with multiple nodes has 10+ jobs running off .Net Tasks (not classic threads).

• All the jobs subscribes to Rabbit queues with PrefetchCount of 50.

• When there are too many messages in queues, there can be as many as 50 tasks per subscriptions so total of 500+ tasks in play.

• We currently have Splunk and Azure AppInsight configured. We are additionally adding Rollbar for some important insight into exception it provides and also to add redundancy on the logging and monitoring.

• Flooding of exceptions can happen for many reasons and we are improving on those as we learn. Splunk works off of Log4Net throgh file appender and Splunk forwarder out-of-process executable pumping the logs. AppInsight has something similar and so we never faced any issues with flooding of the logs causing the logger itself to choke. In fact, Spunk is how we triaged this issue in the first place.

I am just trying to help myself and you figuring out a solution to this problem, but from the tone of your response I don't think you are interested in listening.

Let me know if you need any other data from me. I have given most of the details that matters here and am also clear on where the issue is in the code as i have shown above.

[akornich]

@sanjaysingh , I appreciate the effort you put into tracking down and reporting the issue. No doubt here.
That is exactly my point, starvation of the pool thread is a real issue that could happen in any application. That is why .NET provides a way to increase default thread count in the application thread pool as needed. Although you potentially may run into some other types of issues (like doing more thread context switching than actual useful work) while trying to increase the thread pool limit, the approach does work to some reasonable amount of threads in the pool.
Based on what you just reported, I believe the real cause of the issues you are facing is the thread starvation. According to your own estimates the application might use over 500 threads by design. If each of the threads generates even one exception around the same time, the Rollbar logger might need another 500+ threads to schedule payloads. Now in total we are already over 1K threads down in the pool. A couple of more async calls within the application threads during the same processing per thread and we are over 2K threads down in the pool.
Now, I just checked default value for worker threads limit in .NET console application on my machine - it is 2,047. Under .NET Core it is 32,767. Why? .NET Core is geared towards server/service applications in the first place. That explains much higher default limit.
It looks like your application already places huge demand for threads from the pool, so adding into it a component that does rely on thread pool as well and proportionally to demands of the hosting applications - it does not help the situation.
What are possible solutions?
A few that come to mind:

1. try to allow more threads in the pool.
2. partition your application across multiple hardware hosts (with less message processing per host, hence less demand for pool threads)
3. make other third party libraries to watch their demand
4. TBD?
   You are essentially suggesting to implement solution N3. Problem with this approach that a third party library has less application context about what is happening than the hosting application itself. Is it just a short spike in payload reports or a consistent pounding with payloads forever? What component/layer has better chance to know the reason.
   Now, we can stop scheduling payloads if we see that we are getting close or over the current thread pool max limit and start ignoring (throwing away) subsequent reports. That is a possibility. But what if it was a short term spike in activity that could be eventually recoverable - while we actually lost the data by then. Also, what would be the condition to restart collection of payloads?
   I just checked a payload scheduling performance on my ultra-portable laptop: it normally stays under 1 [msec] per payload (and we are talking about an exception with around 200 data rich stack frames to parse). A very small price to pay - assuming it was given a chance (i.e. a thread) to do so. That means 1000 payloads per second could be successfully scheduled if (again) were given a chance. Before any signs of "choking". While any finite time "choking" would be recoverable with time.
   And now somewhat relevant point about the situation without going into any technical details. Rollbar.NET has built in maximum payload reporting limit per access token. It is 60 per minute. So, if you have 500 processing tasks generating even one exception per task not many of them will get delivered. And even if you increase the queue depth it could take long time to get them all to the Rollbar service. But even then if the 500 tasks, that are still present, consistently keep adding new ones - a lot of payloads will be discarded. You may want to consider allocating something like a different access token per job.

[sanjaysingh]

@akornich if you notice the sample code, you will see that things break even with 5 Tasks. During triage process, we had reduced the PrefetchCount to 5 and Rollbar still seemed to hog memory. It has mainly to do with continuous pump of exceptions rather than number of threads. I am afraid we are not discussing the main issue but rather going around these unnecessary thread limitation issues in .Net.

Today even with these bursty loads and exceptions, things will eventually be back to normal after few seconds of errors exhausting the retries. As soon as we bring Rollbar in, it causes out of memory just within few seconds of those bursty load and thus we don't have chance to recover. That is the crux of the issue we should be focusing on. If Rollbar was not creating these infinite Tasks one per log message, i think these issues would not have happened. Don't you think, it is wasteful to create more Tasks that the queue depth specified? I am going to make that change and try to see how that works. If application is working fine without Rollbar, i don't have a justification to make any design change or anything at this time. Rollbar logger and related code can be changed as required.

One more thing that we have tried and it seems to work with linear memory growth rather than exponential is just adding 1 millisecond of delay after each Rollbar call and we are testing this currently.

Task.Delay(1).Wait();

[sanjaysingh]

@akornich I made this change at sanjaysingh@17b3836 to limit creating tasks and only have statically configurred consumers. It seems to work fine in local testing.