More on SSRS 2008 memory management

  • [アーティクル]

This is a continuation of a previous posting that I made which introduced some of the memory management functionality in SSRS 2008.  In this post, I wanted to dig a bit more into the details of the system in order to illuminate some of the decisions that are happening under the covers. 

In order to get the system into a memory constrained state, I have configured the server to only use ~256MB of memory.  You can read about how to do this in this books online article entitled Configuring Available Memory for Report Server Applications.  I also set the "appdomainmanager" trace level to 4, which is the "Verbose" setting.  I wouldn't recommend having a production system run with this tracelevel since the memory management output can get pretty spammy when the system is under pressure and notifications are firing rapidly. 

I then ran a pretty simple report that has 100K rows.

So lets dig into the log file a bit.  The first couple of lines look like this:

appdomainmanager!DefaultDomain!aec!03/11/2008-16:56:17:: v VERBOSE: Received NotifyMemoryPressure(pressureLevel=MediumPressure, kBytesToFree=6056)
appdomainmanager!WindowsService_1!aec!03/11/2008-16:56:18:: v VERBOSE: Memory Statistics: 0 items, 0KB Audited, 0KB Freeable, 295544KB Private Bytes
appdomainmanager!DefaultDomain!aec!03/11/2008-16:56:18:: v VERBOSE: Appdomain (WindowsService) attempted to free 0 KB.
appdomainmanager!ReportServer_0-2!aec!03/11/2008-16:56:18:: v VERBOSE: Memory Statistics: 3 items, 83654KB Audited, 78534KB Freeable, 296900KB Private Bytes

This is basically telling the state of the current system.  We have two worker appdomains (WindowsService and ReportServer).  WindowsService is used for background processing (subscriptions) and the ReportServer appdomain handles all of the interactive requests from our HTTP endpoint (including all management operations such as publishing reports, creating folders, etc...)  In my test, I wasn't running any subscriptions, and you can tell that there were "0 items" reported.  However, I was running a single report interactively in the ReportServer appdomain.  You can see there that we indicated that there were "3 items."  What are these items?  As you might remember from the previous post, there is not a direct 1:1 mapping between "memory consumers" and requests.  Typically there are 3 "memory consumers" per request... this is a bit of an implementation detail about how out report processing and rendering engine divides up the large memory consuming components.  Additionally, you can see that a total of ~84MB was discovered as being used by these consumers, of which ~79MB is considered freeable.  We also report that we are currently using ~289MB private bytes.

appdomainmanager!DefaultDomain!aec!03/11/2008-16:56:18:: v VERBOSE: Appdomain (ReportServer) attempted to free 6056 KB.

This line is telling us that some consumer in the ReportServer domain agreed to try to release ~6MB of memory (which is equal to the amount we were trying to free in the previous request).  Some additional time passes, and we recieve another memory notification.

appdomainmanager!DefaultDomain!aec!03/11/2008-16:56:19:: v VERBOSE: Received NotifyMemoryPressure(pressureLevel=HighPressure, kBytesToFree=25120)
appdomainmanager!WindowsService_1!aec!03/11/2008-16:56:19:: v VERBOSE: Skipping shrink request for appdomain (WindowsService_1) because no memory consuming requests are registered.
appdomainmanager!ReportServer_0-2!aec!03/11/2008-16:56:19:: v VERBOSE: 1057 ms has elapsed since last memory shrink attempt for this appdomain (ReportServer_0-2-128497526482384832)
appdomainmanager!ReportServer_0-2!aec!03/11/2008-16:56:19:: v VERBOSE: Memory Statistics: 3 items, 77765KB Audited, 72645KB Freeable, 313648KB Private Bytes
processing!ReportServer_0-2!aec!03/11/2008-16:56:19:: w WARN: Processing Scalability -- Memory Shrink Request Received
appdomainmanager!DefaultDomain!aec!03/11/2008-16:56:19:: v VERBOSE: Appdomain (ReportServer) attempted to free 25120 KB.

From this, we can determine that the original memory shrink was not aggressive enough, and there are other consumers which are still allocating memory.  Note that the memory pressure is now "High."  However, note that the audited memory has actually been reduced from the previous iteration.  In general, the reason why this happens is that there are memory allocations that happen outside of the areas which are strictly controlled and audited (remember the CLR shares a single global heap for all code running in all appdomains).  Since we are in a high pressure state, in addition to requesting the large consumers to reduce memory usage, we will also instruct all memory consumers to freeze their current allocation so they do not grow larger.

As time passes, the processing and rendering engines continue to work on the report, the log shows additional memory shrink notifications which I am not going to duplicate here.  The majority of them look like this:

appdomainmanager!ReportServer_0-2!aec!03/11/2008-16:56:50:: v VERBOSE: Skipping shrink request for appdomain (ReportServer_0-2-128497526482384832) because no memory consuming requests have been added.

Indicating that we are not taking additional action because we have detected that no additional requests have been added to the system.  Internally, we use a time based heuristic here to basically bail out of the shrink notification early if we believe that we are not going to do any productive activity.

Eventually, about 30 seconds after starting execution of the report, we finish rendering it, and the following line is output to the log file:

webserver!ReportServer_0-2!9d0!03/11/2008-16:56:52:: i INFO: Processed report. Report='/homeadvisor_rowparameters', Stream=''

Ok, well hopefully that has given a little bit of insight into the system that we are using, and shows how you can examine the log file to get some details into the decisions that are happening.

Comments