Precision for average_disk_seconds_per_read?

Question

In SQL Server Extended Events, event = perfobject_logicaldisk, what is the actual unit of time for average_disk_seconds_per_read and average_disk_seconds_per_write?

All of the documentation I've found says "seconds", but my sample data includes values like these: 87708875, 1573358215, etc.

It's probably microseconds. I exported the target data to Excel and divided it by 1,000,000,000,000, which gives numbers that seem to be correct for microseconds, but I want confirmation before use such an xEvent query.

Answer 1

Extended Events are notorious for being poorly documented. Duration / units is especially so, see:

Extended event duration Millisecond or Microsecond?

Despite the fact that "seconds" is in the event field name, you're correct that the value being reported is nowhere near seconds. You mentioned that you have to divide the number by a trillion (a 1 with 12 zeroes after it). Rather than microseconds, that actually means the number is in picoseconds. Which sounds...crazy. But I think it's right.

To confirm this, I ran SELECT * from dbo.Posts; on the StackOverflow2010 database while running three different trace tools simultaneously and compared the results.

Extended Events: perfobject_logicaldisk

This event gets logged every 15 seconds.

For the "C:" instance_name at timestamp 09:44:43 (thus a span starting at 09:44:28), I got an average_disk_seconds_per_read of 3,839,009,107 during that 15 second interval.

For the "HarddiskVolume1" instance_name at that same timestamp, I got average_disk_seconds_per_read of 2,239,089.

There's also an entry for instance_name "HarddiskVolume3" with average_disk_seconds_per_read of 1,046,233.

I think those two volumes are system reservations and restore partitions respectively. For reference, here's the output from DiskPart on my machine

C:\WINDOWS\system32>diskpart

Microsoft DiskPart version 10.0.17134.1

Copyright (C) Microsoft Corporation.
On computer: *****************

DISKPART> list volume

  Volume ###  Ltr  Label        Fs     Type        Size     Status     Info
  ----------  ---  -----------  -----  ----------  -------  ---------  --------
  Volume 0     D                       DVD-ROM         0 B  No Media
  Volume 1         System Rese  NTFS   Partition    500 MB  Healthy    System
  Volume 2     C                NTFS   Partition    977 GB  Healthy    Boot

PerfMon.exe: LogicalDisk -> Avg. Disk sec/Read

This Windows performance counter object is documented as being reported in seconds. I only had it log the "C:" instance name. I see values around .002 seconds (2 milliseconds) on average during the period mentioned above.

PerfView: Windows Kernel/DiskIO/Read ETW event

PerfView samples much more aggressively than the other methods here (see screenshot with a snippet of the details below). Dumping that output (which is filtered to only include I/O done by the SQL Server process) into Excel indicates that the average seconds per read was 2.7 milliseconds over the entire sample.

What does it all mean?

ETW Tracing and Performance Counters, which are well known Windows components for measuring various performance metrics, indicate that reads were taking on average somewhere between .002 and .003 seconds (2-3 milliseconds).

Since the value we got from extended events was 3,839,009,107 I think we can assume it's trying to tell us .003 seconds (closer to .004). Backing in to that number, we'd have to divide by a trillion to get there.

I might be bad at math, but it looks like the number reported by this EE field is in picoseconds.

Terrible. Just...terrible.