analysis of the problem of spinlocks in SQL Server

Summarizing the useful conclusions from the publication of colleagues, I highlight several key observations:

High CPU consumption. One of the key aspects of this problem was the significant CPU consumption of TRUNCATE operations.

Specifics of SQL Server 2019. This is unusual behavior. I assume that it is specific only to SQL Server 2019 and newer versions. Previous versions of SQL Server did not exhibit this anomaly, indicating version specific or changes in the new release.

Workaround. The temporary solution was to restart SQL Server, which mitigated the problem, but only temporarily. A few days later everything repeated itself.

Independence of the size of the table being cleared. The number of rows in the temporary table did not affect the duration of the TRUNCATE command, suggesting that the problem is not related to the amount of data being processed.

Reproduction difficulties. The article also describes the difficulties in reproducing the problem in testing conditions, where changes in the intensity and number of rows in temporary tables did not allow the problem to be consistently recreated, making diagnosis more difficult. By the way, I also could not reproduce the problem in its pure form.

Research the problem

Problem Confirmation

When encountering an abnormal performance issue in SQL Server, it is important to take a systematic troubleshooting approach. The first step in the troubleshooting process is to confirm that a problem exists. To do this, you should use Extended Events (XE), a flexible logging system that allows you to monitor and collect data about the operation of SQL Server at different levels.

XE session code used:

CREATE EVENT SESSION [truncate] ON SERVER ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1) ACTION(package0.callstack,sqlos.cpu_id,sqlos.scheduler_id,sqlos.task_time,sqlserver.session_id,sqlserver.username) WHERE ([sqlserver].[like_i_sql_unicode_string]([statement],N'TRUNCATE TABLE%') AND [cpu_time]>=(100000))) ADD TARGET package0.event_file(SET filename=N'truncate.xel',max_rollover_files=(0)) WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB, MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF) GO

A session can last from a few minutes to several hours, depending on your goals. It is important to remember that collecting 'sql_statement_completed' data can impact performance, especially when collecting data over a long period of time on heavily loaded systems. More details about working with XE can be found in the official documentation Quickstart: Extended Events – SQL Server | Microsoft Learn.

The event collection results are below:

Spinlocks or where we get high CPU utilization from

The next step in troubleshooting the TRUNCATE TABLE operation performance issue is to investigate the possible impact of spinlocks. Spinlocks are low-level synchronization primitives used by SQL Server to control access to its internal structures. Competition for these spinlocks can result in increased CPU load.

Below is the XE code to capture the spinlock_backoff events that occur when a thread backs off after a failed spinlock attempt. By collecting this data, you can determine whether spinlock contention occurs during TRUNCATE TABLE operations and whether this is a factor in high CPU utilization.

CREATE EVENT SESSION [spin_lock_backoff] ON SERVER ADD EVENT sqlos.spinlock_backoff( ACTION(package0.callstack,sqlserver.sql_text) WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N'truncate table%'))) ADD TARGET package0.event_file(SET filename=N'spin_lock_backoff.xel',max_rollover_files=(0)), ADD TARGET package0.histogram(SET filtering_event_name=N'sqlos.spinlock_backoff',source =N'package0.callstack',source_type=(1)) WITH (MAX_MEMORY=51200 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=PER_NODE,TRACK_CAUSUPALITY=OFF,START_STATE =OFF) GO

The result is below:

Let's look at the result from the XE histogram for spinlock_backoff. The screenshot shows a list of values, each representing a unique call stack in the SQL Server process, along with the number of times an attempt to acquire a spinlock lock has failed.

The data obtained shows the dominance of one call stack over all others. To accurately identify the spinlock responsible for this contention, you can match the call stack to the corresponding spinlock name. In this case, after examining the collected event file, I identified the spinlock lock as 'OPT_IDX_STATS'.

The XE call stack decryption was performed using SQLCallstackResolver, which revealed the sequence of operations within SQL Server that led to spinlock contention. The stack trace includes several functions. Note 'CQSIndexStatsMgr::DropIndexStatsWithWildcards.'

Decrypted call stack:

sqllang!XeSqlPkg::CollectSqlText
sqllang!XeSqlPkg::CollectSqlTextActionInvoke
sqldk!XeSosPkg::spinlock_backoff::Publish
sqldk!SpinlockBase::Sleep
sqldk!SpinlockBase::Backoff
sqllang!Spinlock<287,1,257>::SpinToAcquireWithExponentialBackoff
sqllang!CQSIndexStatsMgr::PqsisAdvanceInBucket
sqllang!CQSIndexStatsMgr::DropIndexStatsWithWildcards
sqllang!CQSIndexRecMgr::InvalidateMissingIndexes
sqllang!QPEvent::ModifyObject
sqllang!CStmtTruncateTable::XretExecute
sqllang!CMsqlExecContext::ExecuteStmts<1,0>
sqllang!CMsqlExecContext::FExecute
sqllang!CSQLSource::Execute
sqllang!process_request
sqllang!process_commands_internal
sqllang!process_messages
sqldk!SOS_Task::Param::Execute
sqldk!SOS_Scheduler::RunTask
sqldk!SOS_Scheduler::ProcessTasks
sqldk!SchedulerManager::WorkerEntryPoint
sqldk!SystemThreadDispatcher::ProcessWorker
sqldk!SchedulerManager::ThreadEntryPoint
KERNEL32+0x17974

The call stack shows that after the TRUNCATE TABLE operation, SQL Server begins invalidating cache entries for MissingIndexes clauses. This process requires access to the OPT_IDX_STATS spinlock to update the cache. When multiple TRUNCATE TABLE operations are running concurrently, it can result in contention for this spinlock because each transaction is trying to update the same cache at the same time.

Solution

The solution to this problem is to use Trace Flag (TF) 2392, which disables collection of data about missing indexes.

This trace flag is mentioned in KB4042232 – FIX: Access violation when you cancel a pending query if the missing indexes feature is enabled in SQL Server – Microsoft Support.

After applying flag 2392, I resumed monitoring using XE for TRUNCATE TABLE. Now no TRUNCATE TABLE event exceeds 100 ms in CPU time. In addition, as a positive side effect on a highly loaded system, I noted a decrease in CPU usage during working hours, from an average value of ~40% to ~30%.

Personal view of the problem

The behavior observed in SQL Server is similar to the behavior by Design. Personally, I doubt the need to call 'InvalidateMissingIndexes' when clearing a temporary table. When considering potential solutions, Microsoft SQL Server developers might explore the following options:

Confirmation of need. Determine whether there is a real need to invalidate the cache of missing indexes during temporary table cleanup. If this turns out to be unnecessary, then this step can be skipped to avoid the problem.
Using trace flag 2392: This flag currently disables missing index collection for the entire SQL Server instance. A more flexible approach would be to apply this behavior to a specific database.
Spinlock sectioning. If avoiding the 'InvalidateMissingIndexes' call is not possible and database level control is not a valid option, another option would be to partition the OPT_IDX_STATS spinlock. This can reduce competition and improve performance.

This article was first published by me in English at the link Slow TRUNCATE: Diagnosing SQL Server Spinlock Contention – SQL Peak Performance

In the comments I invite you to ask questions, I am ready to answer them, discuss the problem and solution.