通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？

Posted lonelyxmas

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？相关的知识，希望对你有一定的参考价值。

原文:通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？

问题就是，一个很简单的语句，在不同的服务器上执行，所需要的时间相差很大，特别提到在性能差的服务器上反而快，在性能好的服务器上反而慢，他想知道这是为什么？

 

对这个问题，我的回答是：

 

从表面看，很难分析出为什么多台机器执行同一个简单的sql语句，速度有差异，甚至好的服务器反而花了更多的时间，而看上去相对较差的机器反而更快，这些都是表面现象。


我们可以分析一下整个SQL语句执行的大致过程：

1、语句发送到SQL Server服务器端。

2、SQL Server会找这个语句是否已经缓存在内存中，如果能找到，这样就不用重新编译，这样就会节省时间。
如果不在缓存中，那么就需要经过语法检查、语义检查、权限检查、编译，这个过程需要内存；再进行优化，生成执行计划，优化时也需要内存；然后把这个执行计划放进行缓存，这个也需要内存。

3、在执行的时候，如果所要访问的数据都在内存，也就是数据也缓存在内存中了，那么就不用从硬盘读取数据，也就是没有物理IO，只有逻辑操作，速度也会快。

4、在执行的时候，需要申请相关锁，如果所要访问的数据上已经加了锁，那么需要等待。

5、上面几点中，还有一个问题是，系统的负载，如果系统本来就很忙，那么上面的整个过程，可能任何一步，都有可能会等待一会。另外，内存和IO非常重要，如果你的系统存在内存压力，此外，磁盘经常满负荷运转，那么计算是执行一个简单的语句，也会比负载比较低时慢。

你的开发机器和你的服务器，负载是否一样。


6、非常重要的一点，语句运行完成后的结果集，通过网络发送到客户端程序，所以网络是否通畅以及速度的快慢，决定了你的语句的快慢。

对比，你的多张图片，之所以慢的原因应该不是在分析编译、执行时的cpu时间，而是执行时的占用时间，应该是花在IO上的，扫描次数和逻辑读取次数都一样，lob的逻辑读取差了2个，lob预读次数一样，很有可能就是这点差别，当然还有系统的负载，也会导致从硬盘读数据变慢。

另外，如果是直接连接远程，可能会有网络问题，如果是像你上面，直接通过远程连接登录到数据库服务器，再直接连数据库，那么应该不是网络的问题。



下面通过 这个帖子所描述的方法： http://blogs.msdn.com/b/sqlsakthi/archive/2011/02/20/sql-query-slowness-troubleshooting-using-extended-events-wait-info-event.aspx

通过扩展事件来跟踪一个语句，在运行时到底把时间消耗在哪儿了，比如说是PAGEIOLATCH_EX。


1、建立扩展事件，注意下面的session_id为你要跟踪的语句的会话id，要改过来。

  1. -- *** Change the Session ID values as per your need *** 
  2.  
  3.  
  4.  
  5. -- Check for existing session
  6.  
  7. IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=‘Waits_of_Particular_Session‘)
  8.  
  9.   DROP EVENT session Waits_of_Particular_Session ON SERVER;
  10.  
  11. GO
  12.  
  13.  
  14.  
  15. -- Create a session and add events and actions
  16.  
  17. CREATE EVENT SESSION Waits_of_Particular_Session 
  18.  
  19. ON SERVER
  20.  
  21. ADD EVENT sqlserver.sql_statement_starting
  22.  
  23. (
  24.  
  25. 	ACTION (sqlserver.session_id,
  26.  
  27. 		sqlserver.sql_text,
  28.  
  29. 		sqlserver.plan_handle)
  30.  
  31. 	WHERE 
  32.  
  33. 		sqlserver.session_id > 52 AND sqlserver.session_id < 54
  34.  
  35. ),
  36.  
  37. ADD EVENT sqlos.wait_info 
  38.  
  39. (
  40.  
  41. 	ACTION (sqlserver.session_id,
  42.  
  43. 		sqlserver.sql_text,
  44.  
  45. 		sqlserver.plan_handle)
  46.  
  47. 	WHERE 
  48.  
  49. 		sqlserver.session_id > 52 AND sqlserver.session_id < 54
  50.  
  51. ),
  52.  
  53. ADD EVENT sqlos.wait_info_external
  54.  
  55. (
  56.  
  57. 	ACTION (sqlserver.session_id,
  58.  
  59. 		sqlserver.sql_text,
  60.  
  61. 		sqlserver.plan_handle)
  62.  
  63. 	WHERE 
  64.  
  65. 		sqlserver.session_id > 52 AND sqlserver.session_id < 54
  66.  
  67. ),
  68.  
  69. ADD EVENT sqlserver.sql_statement_completed
  70.  
  71. (
  72.  
  73. 	ACTION (sqlserver.session_id,
  74.  
  75. 		sqlserver.sql_text,
  76.  
  77. 		sqlserver.plan_handle)
  78.  
  79. 	WHERE 
  80.  
  81. 		sqlserver.session_id > 52 AND sqlserver.session_id < 54
  82.  
  83. )
  84.  
  85. ADD TARGET package0.asynchronous_file_target
  86.  
  87.     (SET filename=N‘C:TempWaits_of_Particular_Session.xel‘)
  88.  
  89. WITH (MAX_DISPATCH_LATENCY = 5 SECONDS, EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS, TRACK_CAUSALITY=ON)
  90.  
  91. GO
  92.  
  93.  
  94.  
  95. -- Start the Session
  96.  
  97. ALTER EVENT SESSION Waits_of_Particular_Session ON SERVER
  98.  
  99. STATE = START
  100.  
  101. GO
  102.  
  103.  
  104.  
  105. -- Run the query from the SPID 
  106.  
  107.  
  108.  
  109. -- Code to stop the session once the query execution completes
  110.  
  111. ALTER EVENT SESSION Waits_of_Particular_Session ON SERVER
  112.  
  113. STATE = STOP
  114.  
  115. GO


2、然后，运行你的语句：select  *  from  dbo.ttt


3、最后，运行下面的语句，获取各类操作所消耗的时间：

  1. -- Parse the XML to show wait details
  2.  
  3. SELECT
  4.  
  5.     event_xml.value(‘(./@name)‘, ‘varchar(1000)‘) as Event_Name,
  6.  
  7.     event_xml.value(‘(./data[@name="wait_type"]/text)[1]‘, ‘nvarchar(max)‘) as Wait_Type,
  8.  
  9.     event_xml.value(‘(./data[@name="duration"]/value)[1]‘, ‘int‘) as Duration,
  10.  
  11.     event_xml.value(‘(./data[@name="opcode"]/text)[1]‘, ‘varchar(100)‘) as Operation,
  12.  
  13.     event_xml.value(‘(./action[@name="session_id"]/value)[1]‘, ‘int‘) as SPID,
  14.  
  15.     event_xml.value(‘(./action[@name="sql_text"]/value)[1]‘, ‘nvarchar(max)‘) as TSQLQuery,
  16.  
  17.     event_xml.value(‘(./action[@name="plan_handle"]/value)[1]‘, ‘nvarchar(max)‘) as PlanHandle
  18.  
  19. FROM    
  20.  
  21. 	(SELECT CAST(event_data AS XML) xml_event_data FROM sys.fn_xe_file_target_read_file(‘C:TempWaits_of_Particular_Session*.xel‘, ‘C:TempWaits_of_Particular_Session*.xem‘, NULL, NULL)) AS event_table
  22.  
  23. 	CROSS APPLY xml_event_data.nodes(‘//event‘) n (event_xml)
  24.  
  25. WHERE  
  26.  
  27. 	event_xml.value(‘(./@name)‘, ‘varchar(1000)‘) IN (‘wait_info‘,‘wait_info_external‘)   
  28.  
  29. 	
  30.  
  31. -- Code to drop the session
  32.  
  33. DROP EVENT SESSION Waits_of_Particular_Session ON SERVER;

这段监控的语句，在网友的服务器上执行，最后发现，时间主要消耗在了NETWORK_IO上，也就是网络。


技术图片 技术图片
不想长大啊
发布了416 篇原创文章 · 获赞 135 · 访问量 94万+
他的留言板 关注

以上是关于通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？的主要内容，如果未能解决你的问题，请参考以下文章

如何查看SQL Server2000执行过的SQL语句

如何跟踪SQL SERVER 正在执行的语句

sql server profiler 是啥文件

如何用sqlserver 2000事件查探器查询sql

如何诊断SQL数据？

如何使用SQL Server Profiler跟踪数据库