CSS SQL Server Engineers

SQL Server reports working set trim warning message during early startup phase

In the previous posts we have discussed the working set trim message “A significant part of sql server process memory has been paged out” that gets written to the SQL Server Error log. You can find the details about the various parameters that determine when this message is written to the error log in the KB Article. You might be very familiar with this message and the steps needed to troubleshoot and find the root cause of these memory issues when they appear during the regular lifespan of a SQL Server instance.

You may also have noticed the working set trim messages logged in the SQL Server Error log when SQL Server is starting up. We had several customers report this to us. Here is a sample error log where this working set trim message is reported very early.

2009-02-06 11:48:59     Server          Microsoft SQL Server 2005 - 9.00.3294.00 (X64)
2009-02-06 11:48:59     Server              Oct  3 2008 00:51:23
2009-02-06 11:48:59     Server              Copyright (c) 1988-2005 Microsoft Corporation
2009-02-06 11:48:59     Server              Enterprise Edition (64-bit) on Windows NT 5.2 (Build 3790: Service Pack 2)
2009-02-06 11:48:59     Server          (c) 2005 Microsoft Corporation.
2009-02-06 11:48:59     Server          All rights reserved.
2009-02-06 11:48:59     Server          Server process ID is 2104.
2009-02-06 11:48:59     Server          Authentication mode is MIXED.
2009-02-06 11:48:59     Server          Logging SQL Server messages in file 'C:\MSSQL.1\MSSQL\LOG\ERRORLOG'.
2009-02-06 11:48:59     Server          This instance of SQL Server last reported using a process ID of 3772 at 3/28/2009 10:14:10 AM (local) 3/28/2009 2:14:10 PM (UTC). This is an informational message only; no user action is required.
2009-02-06 11:48:59     Server          Registry startup parameters:
2009-02-06 11:48:59     Server          -d C:\MSSQL.1\MSSQL\DATA\master.mdf
2009-02-06 11:48:59     Server          -e C:\MSSQL.1\MSSQL\LOG\ERRORLOG
2009-02-06 11:48:59     Server          -l C:\MSSQL.1\MSSQL\DATA\mastlog.ldf
2009-02-06 11:48:59     Server          SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2009-02-06 11:48:59     Server          Detected 8 CPUs. This is an informational message; no user action is required.
2009-02-06 11:48:59     Server          Cannot use Large Page Extensions:  lock memory privilege was not granted.
2009-02-06 11:48:59     Server          Using dynamic lock allocation.  Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node.  This is an informational message only.  No user action is required.
2009-02-06 11:48:59     Server          Attempting to initialize Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
2009-02-06 11:48:59     spid1s          A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 0 seconds. Working set (KB): 39416, committed (KB): 351872, memory utilization: 11%.
2009-02-06 11:49:00     Server          Attempting to recover in-doubt distributed transactions involving Microsoft Distributed Transaction Coordinator (MS DTC). This is an informational message only. No user action is required.
2009-02-06 11:49:00     Server          Database mirroring has been enabled on this instance of SQL Server.
2009-02-06 11:49:00     spid5s          Starting up database 'master'.
2009-02-06 11:49:00     spid5s          Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
2009-02-06 11:49:00     spid5s          CHECKDB for database 'master' finished without errors on 2008-11-22 23:00:33.537 (local time). This is an informational message only; no user action is required.
2009-02-06 11:49:00     spid5s          SQL Trace ID 1 was started by login "sa".
2009-02-06 11:49:00     spid5s          Starting up database 'mssqlsystemresource'.
2009-02-06 11:49:00     spid5s          The resource database build version is 9.00.3294. This is an informational message only. No user action is required.
2009-02-06 11:49:00     spid9s          Starting up database 'model'.

In almost all of these reports, we have seen these warnings appear very close to the MSDTC initialization. Also you will notice that the committed and working set values reported will normally be very low numbers compared to your “max server memory” settings or peak memory usages under regular load.

What causes these warnings? 

During the startup phase, several components allocate memory based on the anticipated needs for the various structures. These allocations are not used immediately and hence do not get accounted under the working set. Until these allocations are used and brought into the working set, they will be backed by the paging file. So this sets up a scenario where the working set can be well below 50% of the committed bytes for the sqlservr.exe process. Once such a condition is detected the working set trim warning messages are reported in the SQL Server Error log. When the databases start recovery and then user/application load kicks in, the working set and committed bytes will come close to each other.

You would normally notice this message reported during startup when you see neither of the following messages earlier in the log:

            Using locked pages for buffer pool.

            Large Page Extensions enabled.

SQL Server 2008 SP1 included some changes to address this situation. These changes touch the allocated memory immediately so they are now accounted for in the working set. As a result the working set stays above 50% of the committed bytes. So you will not notice the working set trim warnings.

In SQL Server 2005 SP2, SQL Server 2005 SP3 and SQL Server 2008 RTM, if this warning message appears during the early startup phase, you can safely ignore it. On the other hand, if you encounter this warning message after the server finishes its startup sequence, then use the regular troubleshooting steps to attack the problem, find the root cause and resolve it.

I did a comparison of the memory counters [committed bytes and working set] between SQL Server 2008 RTM and SQL Server 2008 SP1.

SQL Server 2008 RTM

SQL Server 2008 SP1

You will notice that the working set does not climb as fast as the committed bytes in SQL Server 2008 RTM. The changes done in SQL Server 2008 SP1 keeps the working set / committed bytes ratio higher than 50%.

Note: I captured this perfmon while SQL Server was started under a debugger and halted the startup at various phases of importance. Under normal circumstances, you may not be able to see this with such detail. It might show up as a sudden growth in memory allocations.