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. See update note at the end of this post.
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.
Thanks
Suresh B. Kandoth
SQL Server Senior Escalation Engineer
Update [Nov 2009]:
We have observed in some cases where you can encounter these warnings even after SQL Server instance has finished the startup sequence and is ready for user connections. For example here is a sample from an error log we got:
<< start up messages >>
2009-11-16 14:22:22.240 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): 41608, committed (KB): 155840, memory utilization: 26%.
<< start up messages >>
2009-11-16 14:22:24.740 Server SQL Server is now ready for client connections. This is an informational message; no user action is required.
<< start up messages >>
2009-11-16 14:27:53.920 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 331 seconds. Working set (KB): 76524, committed (KB): 170992, memory utilization: 44%.
2009-11-16 14:32:25.130 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 602 seconds. Working set (KB): 76532, committed (KB): 170992, memory utilization: 44%.
2009-11-16 14:37:50.970 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 928 seconds. Working set (KB): 76504, committed (KB): 170992, memory utilization: 44%.
2009-11-16 14:43:22.660 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 1260 seconds. Working set (KB): 76516, committed (KB): 170992, memory utilization: 44%.
2009-11-16 14:47:48.020 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 1525 seconds. Working set (KB): 76480, committed (KB): 170992, memory utilization: 44%.
2009-11-16 14:53:19.720 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 1857 seconds. Working set (KB): 76496, committed (KB): 170992, memory utilization: 44%.
2009-11-16 15:23:10.860 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 3648 seconds. Working set (KB): 76368, committed (KB): 170992, memory utilization: 44%.
2009-11-16 16:22:55.820 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 7230 seconds. Working set (KB): 76296, committed (KB): 170992, memory utilization: 44%.
2009-11-16 18:23:26.360 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 14459 seconds. Working set (KB): 76244, committed (KB): 170992, memory utilization: 44%.
2009-11-16 22:23:22.730 spid1s A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 28853 seconds. Working set (KB): 76176, committed (KB): 170992, memory utilization: 44%.
On a server with no databases to recover and no activity, it is quite possible to see the above behavior. So before spending a lot of time investigating why this is happening, please look at the values for the Working Set and committed memory.