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

时间：2022-06-26 07:29:22

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


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


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


   
  
    

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

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


通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？通过SQL Server的扩展事件来跟踪SQL语句在运行时，时间都消耗到哪儿了？ 不想长大啊 发布了416 篇原创文章 · 获赞 135 · 访问量 94万 他的留言板 关注

相关文章