SQL Server 性能问题—等待RESOURCE_SEMAPHORE
转自 http://blogs.msdn.com/b/apgcdsd/archive/2011/07/06/sql-server-resource-semaphore.aspx
SQL Server 有 两类RESOURCE_SEMAPHORE 等待事件：
- RESOURCE_SEMAPHORE
- RESOURCE_SEMAHPORE_QUERY_COMPILE
Resource_SEMAPHORE 是指一条或多条语句在执行的时候等待memory的分配。
RESOURCE_SEMAHPORE_QUERY_COMPILE是指一条语句在编译的时候等待memory的情况。
问题描述，用户反应所有SQL Server有关的操作都很慢。
第一次收集性能日志的方式跟通常的性能问题是没有什么区别的：
- 手工收集系统性能日志，包含system, physical disk, process, processor, memor以及所有的SQL Server相关的计数器。
- 收集sys.dm_exec_connections, sys.dm_exec_sessions 和sys.dm_exec_requests的信息(每5-10秒打印一次)。
- 如果允许的话，收集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里面的表做关联，就解决了这个问题。
