Extended Events PerfObject Events

SQL Server 2008 R2 Service Pack 1 provides a new set of Events in Extended Events to collect performance counter data from the Windows OS that would be really useful to monitoring SQL Server.  The first place I can find that they were mentioned is on a blog post by Mark Weber, a PFE for SQL and SAP at Microsoft.  However, a few weeks ago a question was asked about these counters one of the forums and the question was around how to use them.  I looked at the Events and found out that they aren’t really useable in their current implementation, something that is disappointing since being able to collect the data provided by these Events would really benefit most DBA’s out there. 

If you look at the Events and columns, these events collect information about the Logical Disk, Processor, Process for the SQL instance, and System at 15 second intervals and makes the data available through Extended Events.

SELECT name, description
FROM  sys.dm_xe_objects
WHERE name like 'perfobject_%'

name

description

perfobject_process

Returns a set of counters associated with the Process performance object. The event occurs once every 15 seconds for both the SQL Server and SQL Agent processes.

perfobject_system

Returns a set of counters associated with the System performance object. The event occurs once every 15 seconds.

perfobject_logicaldisk

Returns a set of counters associated with the Logical Disk performance object. The event occurs once every 15 seconds for each hard or fixed disk drive.

perfobject_processor

Returns a set of counters associated with the Processor performance object. The event occurs once every 15 seconds for each processor in the system.

If we look at the columns, we’ll see that the columns actually represent the individual counters under the categories exposed by the Event names. For example, the perfobject_logicaldisk event returns the following columns:

SELECT
    object_name, 
    name AS column_name, 
    description
FROM  sys.dm_xe_object_columns
WHERE object_name = 'perfobject_logicaldisk'
  AND column_type = 'data'
ORDER BY object_name, name

object_name

column_name

description

perfobject_logicaldisk

average_disk_bytes_per_read

Shows the average number of bytes transferred from the disk during read operations.

perfobject_logicaldisk

average_disk_bytes_per_transfer

Shows the average number of bytes transferred to or from the disk during write or read operations.

perfobject_logicaldisk

average_disk_bytes_per_write

Shows the average number of bytes transferred to the disk during write operations.

perfobject_logicaldisk

average_disk_queue_length

Shows the average number of both read and write requests that were queued for the selected disk during the sample interval.

perfobject_logicaldisk

average_disk_read_queue_length

Shows the average number of read requests that were queued for the selected disk during the sample interval.

perfobject_logicaldisk

average_disk_seconds_per_read

Shows the average time, in seconds, of a read operation from the disk.

perfobject_logicaldisk

average_disk_seconds_per_transfer

Shows the time, in seconds, of the average disk transfer.

perfobject_logicaldisk

average_disk_seconds_per_write

Shows the average time, in seconds, of a write operation to the disk.

perfobject_logicaldisk

average_disk_write_queue_length

Shows the average number of write requests that were queued for the selected disk during the sample interval.

perfobject_logicaldisk

current_disk_queue_length

Shows the number of requests outstanding on the disk at the time that the performance data is collected.

perfobject_logicaldisk

disk_bytes_per_second

Shows the rate at which bytes are transferred to or from the disk during write or read operations.

perfobject_logicaldisk

disk_read_bytes_per_second

Shows the rate at which bytes are transferred from the disk during read operations.

perfobject_logicaldisk

disk_reads_per_second

Shows the rate at which read operations are performed on the disk.

perfobject_logicaldisk

disk_transfers_per_second

Shows the rate at which read and write operations are performed on the disk.

perfobject_logicaldisk

disk_write_bytes_per_second

Shows the rate at which bytes are transferred to the disk during write operations.

perfobject_logicaldisk

disk_writes_per_second

Shows the rate at which write operations are performed on the disk.

perfobject_logicaldisk

free_megabytes

Shows the unallocated space, in megabytes, on the disk drive. One megabyte is equal to 1,048,576 bytes.

perfobject_logicaldisk

instance_name

The logical disk drive name

perfobject_logicaldisk

percent_disk_read_time

Shows the percentage of time that the selected disk drive is busy servicing read or write requests.

perfobject_logicaldisk

percent_disk_time

Shows the percentage of time that the selected disk drive is busy servicing read requests.

perfobject_logicaldisk

percent_disk_write_time

Shows the percentage of time that the selected disk drive is busy servicing write requests.

perfobject_logicaldisk

percent_free_space

Shows the percentage of the total usable space on the selected logical disk drive that is free.

perfobject_logicaldisk

percent_idle_time

The percentage of time during the sample interval that the disk was idle.

perfobject_logicaldisk

split_io_per_second

The rate at which I/Os to the disk were split into multiple I/Os.

This all seems good, until we actually use the Events in an Event Session and take a look at the data being returned.

CREATE EVENT SESSION [XE_PerfCounters] 
ON SERVER 
ADD EVENT sqlserver.perfobject_logicaldisk 
ADD TARGET package0.ring_buffer;
GO

image

Unfortunately, the counters are returning Raw values for the Event and the necessary Base counters that are required to give these values any useful meaning have been left out of the Events data.  Looking at this in my test environment, it appears the counter values pulled for the perfobject_ Events are pulled directly from Win32_PerfRawData_PerfDisk_LogicalDisk, but if you look at the CookingType requirements for the counters in Win32_PerfFormattedData_PerfDisk_LogicalDisk the raw values have to be calculated by their base values for them to have meaning:

image

I’ve submitted Connect Item 725167 for this and I really hope that this one gets fixed in a future Cumulative Update or Service Pack.

Does filing bugs on Microsoft Connect for SQL Server work?

In a word; YES! In a lot more words, not always in the way that we want it to, but there are plenty of cases where it actually works and changes are made to the product as a result.

Now with that said, it doesn’t work all the time, and it helps to realize that what is important to us as an individual user might not be important to the product as a whole.  Before you post comments, I am sure that there are plenty of cases out there where people can say that Microsoft Connect for SQL Server is broken.  I have personally been irritated to the point of posting negative comments on Twitter about the whole Connect process.  I feel that it is about time that I show the other side of the story as well and talk about some Connect successes that have occurred in the past year, and of course what better topic to do this with than Extended Events.  Over the next few weeks, I’ll post a couple of different examples of Connect actually working and bringing about changes to the product that are beneficial to the community, starting with this post.

Extended Events does not track insert statements

This Connect item is actually incorrectly titled and is based on some confusion about what the sqlserver.plan_handle action actually returns when executed in the engine.  I blogged about this with much more detail last year in my blog post; What plan_handle is Extended Events sqlserver.plan_handle action returning?

If we revisit the Connect item there is a note that the sql_statement_completed event in SQL Server 2012 now includes a parameterized_plan_handle customizable column that can be used to retrieve the parameterized plan handle for statements that are auto-parameterized by SQL Server during their execution.  Taking the same original demo code from my previous blog post, we can now see how this Connect item has improved the ability to find information about plan caching in SQL Server 2012:

-- Create the Event Session
IF EXISTS(SELECT * 
          FROM sys.server_event_sessions 
          WHERE name='SQLStmtEvents')
    DROP EVENT SESSION SQLStmtEvents 
    ON SERVER;
GO
CREATE EVENT SESSION SQLStmtEvents
ON SERVER
ADD EVENT sqlserver.sql_statement_completed(
    SET collect_parameterized_plan_handle = 1
    ACTION (sqlserver.client_app_name,
            sqlserver.plan_handle,
            sqlserver.sql_text,
            sqlserver.tsql_stack,
            package0.callstack,
            sqlserver.request_id)
--Change this to match the AdventureWorks, 
--AdventureWorks2008 or AdventureWorks2008 SELECT DB_ID('AdventureWorks2008R2')
WHERE sqlserver.database_id=9
)
ADD TARGET package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)
GO
 
-- Start the Event Session
ALTER EVENT SESSION SQLStmtEvents 
ON SERVER 
STATE = START;
GO
 
-- Change database contexts and insert one row
USE AdventureWorks2008R2;
GO
INSERT INTO [dbo].[ErrorLog]([ErrorTime],[UserName],[ErrorNumber],[ErrorSeverity],[ErrorState],[ErrorProcedure],[ErrorLine],[ErrorMessage])
VALUES(getdate(),SYSTEM_USER,-1,-1,-1,'ErrorProcedure',-1,'An error occurred')
GO 10
 
-- Drop the Event
ALTER EVENT SESSION SQLStmtEvents
ON SERVER
DROP EVENT sqlserver.sql_statement_completed;
GO

-- Retrieve the Event Data from the Event Session Target
SELECT
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    event_data.value('xs:hexBinary((event/data[@name="parameterized_plan_handle"]/value)[1])', 'varbinary(64)') as parameterized_plan_handle,
    event_data.value('xs:hexBinary((event/action[@name="plan_handle"]/value)[1])', 'varbinary(64)') as plan_handle,
    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text
FROM(    SELECT evnt.query('.') AS event_data
        FROM
        (   SELECT CAST(target_data AS xml) AS TargetData
            FROM sys.dm_xe_sessions AS s
            JOIN sys.dm_xe_session_targets AS t
                ON s.address = t.event_session_address
            WHERE s.name = 'SQLStmtEvents'
              AND t.target_name = 'ring_buffer'
        ) AS tab
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS split(evnt) 
     ) AS evts(event_data)

If we look at the output of this, we will get the parameterized plan handle for each subsequent call of the statement after the initial call caches the parameterized plan into the cache.

image

If we plug one of the original plan_handle values from the sqlserver.plan_handle action into a query of sys.dm_exec_cached_plans() it will return nothing, but using the new parameterized_plan_handle value from the customizable column will give us the appropriate cached plan for the statement from cache:

-- Use the plan_handle from one of the Events action to get the query plan
DECLARE @plan_handle varbinary(64) = 0x06000900DFC9DD12608B18EE0100000001000000000000000000000000000000000000000000000000000000
SELECT * 
FROM sys.dm_exec_query_plan(@plan_handle)
GO

-- Use the parameterized_plan_handle from the same Events to get the query plan
DECLARE @plan_handle varbinary(64) = 0x06000900DD8D6D08601E70EE01000000010000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
SELECT * 
FROM sys.dm_exec_query_plan(@plan_handle)
GO

image

Now, you might point out the different lengths of the plan handles in the above two queries.  If you look back at the source, the same code is being used to perform the xhexBinary conversion in the XML so the values are exactly the same as what was originally provided by the event and the action.  The non-parameterized plan is not cached because it is not likely to be reused, which is why we have the auto-parameterized plan in cache.