SQL Server 性能问题—等待RESOURCE_SEMAPHORE

Artikel
07/06/2011

SQL Server 性能问题 — 等待RESOURCE_SEMAPHORE

SQL Server 有两类RESOURCE_SEMAPHORE 等待事件： RESOURCE_SEMAPHORE 和 RESOURCE_SEMAHPORE_QUERY_COMPILE.

Resource_SEMAPHORE是指一条或多条语句在执行的时候等待memory的分配。RESOURCE_SEMAHPORE_QUERY_COMPILE是指一条语句在编译的时候等待memory的情况。

问题描述，用户反应所有SQL Server有关的操作都很慢。

第一次收集性能日志的方式跟通常的性能问题是没有什么区别的：

1. 手工收集系统性能日志，包含system, physical disk, process, processor, memor以及所有的SQL Server相关的计数器。

2. 收集sys.dm_exec_connections, sys.dm_exec_sessions 和sys.dm_exec_requests的信息(每5-10秒打印一次)。

3. 如果允许的话，收集profiler trace。

这三个步骤要同时收集。如果有PSSDIAG 工具，可以用PSSDIAG工具代替以上的三个步骤。

接下来我们首先从步骤2收集的信息入手检查，看看数据库连接在当时的运行状况和等待事件，动态视图sys.dm_exec_requests显示的结果如下：

session_id start_time status command blocking_session_id wait_type wait_time

---------- ----------------------- ------------ ---------- ------------------- --------------------- ---------

51 2011-04-06 18:00:00.220 suspended INSERT 0 RESOURCE_SEMAPHORE 6156

58 2011-04-06 18:00:06.973 suspended INSERT 0 RESOURCE_SEMAPHORE 265

66 2011-04-06 18:00:03.763 running SELECT 0 NULL 0

76 2011-04-06 17:59:54.533 runnable INSERT 0 NULL 0

78 2011-04-06 18:00:01.217 suspended INSERT 0 RESOURCE_SEMAPHORE 5046

81 2011-04-06 17:59:54.523 runnable INSERT 0 NULL 0

82 2011-04-06 17:59:54.553 runnable INSERT 0 NULL 0

83 2011-04-06 17:59:56.410 suspended SELECT 0 RESOURCE_SEMAPHORE 15

87 2011-04-06 17:59:56.343 runnable INSERT 0 NULL 0

89 2011-04-06 17:59:58.403 suspended INSERT 0 RESOURCE_SEMAPHORE 7984

90 2011-04-06 18:00:00.530 suspended INSERT 0 RESOURCE_SEMAPHORE 5640

91 2011-04-06 18:00:00.567 suspended INSERT 0 RESOURCE_SEMAPHORE 5562

92 2011-04-06 17:59:59.300 suspended INSERT 0 RESOURCE_SEMAPHORE 6937

93 2011-04-06 17:59:58.517 suspended INSERT 0 RESOURCE_SEMAPHORE 7906

94 2011-04-06 18:00:00.567 suspended INSERT 0 RESOURCE_SEMAPHORE 5453

95 2011-04-06 18:00:00.550 suspended INSERT 0 RESOURCE_SEMAPHORE 5562

96 2011-04-06 17:59:58.550 suspended INSERT 0 RESOURCE_SEMAPHORE 7953

97 2011-04-06 18:00:00.577 suspended INSERT 0 RESOURCE_SEMAPHORE 5375

99 2011-04-06 18:00:00.610 suspended INSERT 0 RESOURCE_SEMAPHORE 5468

102 2011-04-06 18:00:00.640 suspended INSERT 0 RESOURCE_SEMAPHORE 5453

103 2011-04-06 18:00:02.473 suspended INSERT 0 RESOURCE_SEMAPHORE 4046

104 2011-04-06 18:00:00.780 suspended INSERT 0 RESOURCE_SEMAPHORE 5437

106 2011-04-06 18:00:00.847 suspended INSERT 0 RESOURCE_SEMAPHORE 5359

107 2011-04-06 18:00:00.877 suspended INSERT 0 RESOURCE_SEMAPHORE 5390

108 2011-04-06 18:00:00.880 suspended INSERT 0 RESOURCE_SEMAPHORE 5359

109 2011-04-06 18:00:06.450 suspended INSERT 0 RESOURCE_SEMAPHORE 781

110 2011-04-06 18:00:00.920 suspended INSERT 0 RESOURCE_SEMAPHORE 5125

111 2011-04-06 17:59:59.733 suspended INSERT 0 RESOURCE_SEMAPHORE 6093

112 2011-04-06 18:00:00.910 suspended INSERT 0 RESOURCE_SEMAPHORE 5312

113 2011-04-06 18:00:01.247 suspended INSERT 0 RESOURCE_SEMAPHORE 3906

在这里我们发现所有的连接等待的资源都是RESOURCE_SEMAPHORE ，状态都是suspended，等待的事件大部分超过了5秒钟。

既然确定了所有的连接都在等待RESOURCE_SEMAPHORE,那么以上收集的这些信息就不足够来检查和定位具体的问题了。我们使用如下脚本收集更多的信息:

write the script to collect DMV info:

while (1=1)

begin

print '****************'

print getdate()

print '*********sys.dm_exec_query_resource_semaphores info**********'

select * from sys.dm_exec_query_resource_semaphores

print '*********sys.dm_exec_query_memory_grants info**********'

select * from sys.dm_exec_query_memory_grants

print '*********sys.dm_exec_requests info**********'

select * from sys.dm_exec_requests where session_id>50

DBCC MEMORYSTATUS

print '****************'

waitfor delay '00:00:10'

end

从再次收集到的DMV的结果我们可以看到：

session_id request_time grant_time requested_memory_kb granted_memory_kb required_memory_kb wait_time_ms plan_handle

---------- ----------------------- ----------------------- -------------------- -------------------- -------------------- -------------------- --------------------------------------------------

83 2011-04-06 17:59:57.360 NULL 80688 NULL 4864 6453 0x050006003A1F0067B8211D44000000000000000000000000

174 2011-04-06 18:00:00.417 NULL 80688 NULL 4864 3390 0x050006003A1F0067B8211D44000000000000000000000000

91 2011-04-06 18:00:01.667 NULL 80688 NULL 4864 2140 0x050006003A1F0067B8211D44000000000000000000000000

108 2011-04-06 18:00:01.870 NULL 80688 NULL 4864 1937 0x050006003A1F0067B8211D44000000000000000000000000

112 2011-04-06 18:00:01.920 NULL 80688 NULL 4864 1890 0x050006003A1F0067B8211D44000000000000000000000000

145 2011-04-06 18:00:03.070 NULL 114688 NULL 38912 734 0x050006003A1F0067B8211D44000000000000000000000000

163 2011-04-06 18:00:03.070 NULL 109872 NULL 34048 734 0x050006003A1F0067B8211D44000000000000000000000000

103 2011-04-06 18:00:03.187 NULL 80688 NULL 4864 625 0x050006003A1F0067B8211D44000000000000000000000000

131 2011-04-06 18:00:03.700 NULL 7424 NULL 1024 109 0x050006003A1F0067B8211D44000000000000000000000000

168 2011-04-06 17:59:55.233 2011-04-06 18:00:02.247 80688 80688 4864 NULL 0x050006003A1F0067B8211D44000000000000000000000000

165 2011-04-06 17:59:57.020 NULL 80688 NULL 4864 6797 0x050006003A1F0067B8211D44000000000000000000000000

137 2011-04-06 17:59:59.297 NULL 80688 NULL 4864 4515 0x050006003A1F0067B8211D44000000000000000000000000

180 2011-04-06 18:00:03.020 NULL 1328 NULL 1280 781 0x05000600F9038615B8C1FF53000000000000000000000000

173 2011-04-06 18:00:03.110 NULL 6208 NULL 512 703 0x05000600AC67E868B8412F21000000000000000000000000

这些数据库连接都在等待分配数据库内存，每个连接都要求80688KB的内存，绝大部分连接都没有获得内存。从系统性能日志也可以看到这样的现象：

从上面DMV的信息除了发现这些数据库连接每个都要求分配80MB左右的内存，我们还可以看到这个连接的plan_handle 都是一样的。这说明所有的数据库连接都在调用同样的语句或者存储过程。那么我们就可以很容易从profiler trace里面定位到具体的语句，然后检查语句的执行计划，看看为什么这个语句在执行的时候要求这么多内存。

在这个案例中，我们最终发现了导致问题的存储过程中包含了这样的语句：

INSERT INTO #Trustees

SELECT Trustee.TrusteeIdentity FROM OPENXML(@hDoc, '/ROOT/SID') WITH (SID [EVMoniker] '.') XMLDATA

INNER JOIN Trustee ON Trustee.SID = XMLDATA.SID collate database_default

这个语句读取了一个XML文件并和SQL Server里面的一个表做关联查询，如果xml文件很大，这条语句会需要分配较多内存来执行。修改这条语句，直接将XML文件的数据写入临时表，然后再来和SQL Server里面的表做关联，就解决了这个问题。

Freigeben über

SQL Server 性能问题—等待RESOURCE_SEMAPHORE

Zusätzliche Ressourcen