SQL Server 2008 性能调优 session级别 wait event

最新推荐文章于 2021-08-30 16:38:48 发布

dida4700

最新推荐文章于 2021-08-30 16:38:48 发布

阅读量140

点赞数

文章标签：数据库开发工具

原文链接：http://www.cnblogs.com/Amaranthus/archive/2012/02/14/2350874.html

版权

SQL Server 2008 性能调优 session级别 wait event

Investigating perfomance bottlenecks in SQL Server 2008 by looking at wait events using the XE trace system

Introduction.

In my previous articles SQL Server Wait Events: Taking the Guesswork out of Performance Profiling, and Taking the Guesswork out of SQL Server Performance Profiling Part 2, I introduced the concepts of performance analysis based on wait events.

In short, the idea behind this concept is to take the response time of a SQL statement (or a batch or a user session) and split it up into CPU time and Wait time..

Earlier versions of SQL Server only maintain wait time (aggregated) on the server level, or you can see the wait times and the wait reasons, and when they actually occur in views like sysprocesses orsys.dm_os_waiting_tasks. Starting with SQL Server 2005, the wait events are finally documented in the SQL Server BOL, and more and more background is provided in blogs, KB Articles, forums etc.

A wait event ‘happens’ when the SQL Server scheduler (implemented in the SQLOS) decides to suspend a running task.

This can be because a ‘long’ operation starts, such as disk, network I/O, or lock. It can also happen when the allotted time quantum that a task can be active on the CPU ends. At this moment this seems to be a hard-coded 4 ms. This is the means by which that the SQL Server scheduler makes sure that every task in SQL Server gets its turn running on the CPU. By carefully looking at the way the response time is build up, one can make intelligent decisions on where to look for possible optimizations, or capacity planning: For instance, if on your SQL Server box 90% of the total used (response) time consists of I/O waits and only 10% of the time is spend on the CPU, then adding CPU capacity or upgrading to faster CPUs is unlikely to have a very large impact on response times. The same is true for individual queries. If one query spends 90% of its time waiting for I/O, then speeding up the CPU will only impact the other 10% of the response time picture.

SQL Server 2008 introduces Extended Events (XE) a new event handling system. XE is a flexible and lightweight event trace system.

The SQL Server engine is instrumented with tracing code in many locations. It is possible to trace ‘traditional’ events as existed in older SQL Trace versions, events like ‘RPC:Completed’. ‘sp_completed’, ‘lock timeout’ etc.

An exciting new tracing feature, is the means by which one can trace information about SQL Server OS (SQLOS) wait events

Each event contains a set of interesting columns that will be logged to a ‘target’. In this example, we have chosen a file. Next to the ‘default’ set of columns for an event, extra information can be logged as well. This is done by defining ‘actions’ on a traced event. Below is an example of standard columns that are logged for the event‘wait_info’ in the package ‘sqlos’, and for the event, ‘sql_statement_completed’ in the sqlserver package, which will also be used in the example:

name column_id object_name

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

wait_type 0 wait_info

opcode 1 wait_info

duration 2 wait_info

max_duration 3 wait_info

total_duration 4 wait_info

signal_duration 5 wait_info

completed_count 6 wait_info

…

source_database_id 0 sql_statement_completed

object_id 1 sql_statement_completed

object_type 2 sql_statement_completed

cpu 3 sql_statement_completed

duration 4 sql_statement_completed

reads 5 sql_statement_completed

writes 6 sql_statement_completed

Next is an example on how to setup wait event tracing and collecting information from an ‘asynchronous file target’. Only specific events are collected for session_id=53.

First we create the ‘event session’, and start it.

After this, we can run an example query from a session with session_id=53, a count(*) query was run on a 1 million row (unindexed) table.

Example 1:

create event session test1

on server

add event sqlserver.sql_statement_starting

(action

(sqlserver.session_id, package0.collect_system_time,

package0.collect_cpu_cycle_time,sqlserver.sql_text,

sqlserver.plan_handle, sqlos.task_address, sqlos.worker_address)

where sqlserver.session_id = 53),

add event sqlserver.sql_statement_completed

(action

(sqlserver.session_id, package0.collect_system_time,package0.collect_cpu_cycle_time, sqlserver.sql_text,

sqlserver.plan_handle, sqlos.task_address, sqlos.worker_address)

where sqlserver.session_id = 53),

add event sqlos.wait_info

(action

(sqlserver.session_id, package0.collect_system_time,package0.collect_cpu_cycle_time, sqlos.task_address, sqlos.worker_address)

where sqlserver.session_id = 53)

-- async file, read with: sys.fn_xe_file_target_read_file

ADD TARGET package0.asynchronous_file_target

(SET filename = N'C:\temp\wait.etx', metadatafile = N'C:\temp\wait.mta',

max_file_size = 50, max_rollover_files = 10)

WITH (max_dispatch_latency = 2 seconds)

alter event session test1 on server state = start

Example 2:

The next example shows how to collect the trace information from the trace files for further processing. As you can see from the example, the files is read ‘through’ a virtual function, ‘sys.fn_xe_file_target_read_file‘, and the rows are returned in XML form.

The insert into the xTable counted 4938 rows. For the next summary I only collected the ‘wait_info’ ‘end’ events (1560 rows) and the ‘sql_statement_completed’ event (1 row):

drop table xTable

CREATE TABLE xTable

(

xTable_ID INT IDENTITY

PRIMARY KEY,

xCol XML

) ;

INSERT INTO xTable ( xCol )

select cast(event_data as xml) waitinfo from sys.fn_xe_file_target_read_file

('c:\temp\wait_*.etx',

'c:\temp\wait_*.mta',

null,null)

Now in order to extract the CPU and Wait information and match it with the total response time, we run the following queries:

SELECT

-- for some reason wait type name is not logged with synch target. bug?

(select map_value from sys.dm_xe_map_values

where name = 'wait_types'

and map_key = xCol.value('(event/data/value)[1]', 'int')

)AS wtype,

xCol.value('(event/data/value)[3]', 'int') --wait time

AS tottime,

xCol.value('(event/data/value)[6]', 'int') --sig wait time

AS sigtime

into #mywaits

FROM xTable

where xCol.value('(/event/@name)[1]', 'varchar(30)') = 'wait_info'

and xCol.value('(event/data/value)[2]', 'int') = 1 --opcode end

select wtype,

count(*) as wcount,

sum(tottime) as total_time,

sum(sigtime) as signal_time

from #mywaits group by wtype

-- stmt completed:

SELECT

xCol.value('(event/data/value)[4]', 'int')

AS cputime,

xCol.value('(event/data/value)[5]', 'int')

AS duration,

xCol.value('(event/action/value)[4]', 'varchar(MAX)')

AS sql_text

into #mysql

FROM [xTable]

where xCol.value('(/event/@name)[1]', 'varchar(30)') ='sql_statement_completed'

select sql_text,

count(*) as count,

SUM(cputime) as cputime,

SUM(duration) as duration from #mysql group by sql_text

drop table #mywaits

drop table #mysql

This is the result of the above queries:

wtype wcount total_time signal_time

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

PWAIT_SOS_SCHEDULER_YIELD 20 45 0

PWAIT_SLEEP_TASK 1 10 0

PWAIT_PAGEIOLATCH_SH 1539 59163 674

(1 row(s) affected)

sql_text count cputime duration

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

select COUNT(*) from t1m 1 1892 61560364

So what we can see here is that the statement response time (duration) was 6156 ms (apparently, the sqlserver.sql_statement_completed.duration is measured in microseconds)

The CPU time used was 1892 ms and the wait time for the three different wait events was 45+10+59163 ms = 59218 ms. Including the measured signal_time (the time between the end of the actual wait and the resumption of work) this nicely adds up to the total duration of the query.

For more information on the specific wait events, search the SQL Server BOL for the sys.dm_os_wait_stats view. All wait events are documented here.

It is also possible to look at each individual wait event. This can be useful to detect skew in wait durations for example. If you detect that certain I/O operations take longer than others, it might be interesting to add other XEvents to trace. Events like ‘file_read_completed’ will show which file was read and which offset within the file. The event ‘physical_page_read’, can tell which page for which file. These events can help detecting if you might be reading from slow disks or doing random I/O while you were expecting to do sequential I/Os.

-- first: sql_statement_starting

SELECT xTable_ID,

xCol.value('(event/action/value)[1]', 'int')

AS session_id,

xCol.value('(/event/@timestamp)[1]', 'varchar(24)')

AS EventTime,

xCol.value('(/event/@name)[1]', 'varchar(30)')

AS EventType,

xCol.value('(event/action/value)[2]', 'varchar(30)')

AS system_time,

xCol.value('(event/action/value)[3]', 'varchar(30)')

AS cpu_cycle_time,

xCol.value('(event/data/value)[5]', 'varchar(30)')

AS data1,

xCol.value('(event/data/value)[6]', 'varchar(30)')

AS data2,

xCol.value('(event/action/value)[4]', 'varchar(MAX)')

AS sql_text

FROM [xTable]

where xCol.value('(/event/@name)[1]', 'varchar(30)') = 'sql_statement_starting'

union --now collect: statement_completed

SELECT xTable_ID,

xCol.value('(event/action/value)[1]', 'int')

AS session_id,

xCol.value('(/event/@timestamp)[1]', 'varchar(24)')

AS EventTime,

xCol.value('(/event/@name)[1]', 'varchar(30)')

AS EventType,

xCol.value('(event/action/value)[2]', 'varchar(30)')

AS system_time,

xCol.value('(event/action/value)[3]', 'varchar(30)')

AS cpu_cycle_time,

xCol.value('(event/data/value)[4]', 'varchar(30)')

AS data1,

xCol.value('(event/data/value)[5]', 'varchar(30)')

AS data2,

xCol.value('(event/action/value)[4]', 'varchar(MAX)')

AS sql_text

FROM [xTable]

where xCol.value('(/event/@name)[1]', 'varchar(30)') = 'sql_statement_completed'

union

SELECT xTable_ID,

xCol.value('(event/action/value)[1]', 'int')

AS session_id,

xCol.value('(/event/@timestamp)[1]', 'varchar(24)')

AS EventTime,

-- for some reason wait type name is not logged with synch target. bug?

(select map_value from sys.dm_xe_map_values

where name = 'wait_types'

and map_key = xCol.value('(event/data/value)[1]','int')

) as Event_name,

xCol.value('(event/action/value)[2]', 'varchar(30)')

AS system_time,

xCol.value('(event/action/value)[3]', 'varchar(30)')

AS cpu_cycle_time,

xCol.value('(event/data/value)[3]', 'varchar(30)') --wait time

AS data1,

xCol.value('(event/data/value)[6]', 'varchar(30)') --sig wait time

AS data2,

AS sql_text

FROM [xTable]

where xCol.value('(/event/@name)[1]', 'varchar(30)') = 'wait_info'

and xCol.value('(event/data/value)[2]', 'int') = 1 -- opcode end

This article, submitted in May, was originally scheduled for publication as part of Simple-Talk's celebration of the launch of SQL Server 2008 next month, but has been brought forward in view of the current interest in the subject