SQL Server gives 110%!! (And sometimes a little more...)

Perfmon "Resource Pool Stats" sometimes shows CPU utilization in excess of 100% - sometimes approaching 120%.
I can't explain it.  But I can eliminate an explanation.   This is a an older Intel X5675 (6 cores per socket, dual socket), due for refresh.

http://ark.intel.com/products/52577/Intel-Xeon-Processor-X5675-12M-Cache-3_06-GHz-6_40-GTs-Intel-QPI

I trust the utilization reported by "Processor Info".  Note that the greatest reported "Resource Pool Stats" utilization (approaching 120%) is when total "Processor Info" utilization is near 100% across all 12 physical/24 logical cores.  Nominal rating of the core is 3.06 GHz, top SpeedStep is 3.46 GHz.  That would give a maximum ratio of 3.46/3.06 = 113%, which is still under the number reported by SQL Server (for Default pool alone, I'll add).  Even if the numbers made it seem possible that SpeedStep was responsible for more than 100% utilization reported by SQL Server, I don't think SpeedStep is the culprit.  The older Intel processors were by default conservative with SpeedStep, to stay well within power and heat envelope.  And no-one's been souping this server up for overclocking :-)

So... if my database engine will give 110% (and sometimes more...) I guess I better, too.  :-)

Even though the CPU utilization reported by SQL Server Resource Pool Stats can't be strictly compared to Processor Info, it can still be valuable.  If there are other user Resource Pools, comparing CPU utilization among them can still be useful.  (On this particular server there is only Default and Internal.)  It is also very helpful to me to compare CPU utilization reported for the resource pool to number of active requests and number of active parallel workers in the resource pool.

When I see this graph...





In light of the low efficiency of CPU utilized in terms of lookups/sec (below - this relationship is of course not static across workloads but is meaningful when familiar with a particular workload), I suspect that either there are spinlocks to be mitigated with a trace flag (ie 8048, 9024, 1236) or the workload is overthreaded and would work more efficiently with a lower total number of parallel threads.


 

High DiskSpd Activity in VMware VMs - Part 2: More Questions

In my most recent previoust blog post I showed some perfmon graphs, with 1 second collection interval, from some tests I was running with DiskSpd in an 8 vcpu VMware VM, against a guest LUN managed by the pvscsi vHBA.

High DiskSpd Activity in VMware VMs - Part 1: Start of an investigation
http://sql-sasquatch.blogspot.com/2015/11/high-diskspd-activity-in-vmware-vms.html 

In that particular test run, the main concern was the high privileged time on vCPU 0, which is also the location of the SQL Server logwriter.

Although most of my tests showed high CPU utilization on vcpu 0, there was some variability.  Sometimes it would be a different single vcpu bearing the cost of handling the vHBA.  Sometimes the work would be shared among a few vcpus.

Here are some results of a separate test, mere minutes away from the last test I shared, on the same system.  These results show another concern I have about high SQL Server disk IO within VMware VMs.

In this case, cost of managing disk IO has been balanced across vCPUs 0, 1, 2, and 3.  The remaining 4 vcpus have little involvement in managing the disk IO.

That presents an interesting question - why is the cost dispersed in this case?  It may be extremely preferable to disperse the cost over 4 vcpus, rather than keep vcpu 0 (*especially* vcpu 0) nearly fully consumed with privileged time.

But there's another important question - and one which may be familiar to lots of other folks running SQL Server in VMware VMs by the time I'm done.  What's going on in the nearly 6 second valley?

If I look at IOPs (reads/sec since this was a read-only test) the valley is evident, too.



Was the test running?  Oh, yeah.  In fact, this test had a target queue length (total outstanding IO against the tested Windows volume) of 16 - and the valley was the only sustained time that the target was achieved constantly. (As an aside: I still see folks - performance experts even!! - proclaim 'current disk queue length' as a metric without value.  They're wrong.)




But... if there was a constant queue length of 16 reads while IOPs dropped really low...

Yep.  Really high latency. So that valley in activity and utilization is really a performance divot.  (That's one of my favorite terms.  You might end up seeing it a lot if you read my blog regularly.)



Sometimes a chart of the values over time put performance divots with extreme outlier values into better perspective.

	Disk Reads/sec	Current Disk Queue Length	Avg. Disk sec/Read
14:50:18	65389.65	12	0.00022
14:50:19	58861.78	16	0.00024
14:50:20	42.96	16	0.31733
14:50:21	18.98	16	0.71181
14:50:22	8.96	16	0.50111
14:50:23	272.43	16	0.09647
14:50:24	0.00	16	0.00000
14:50:25	25.35	16	1.24708
14:50:26	54419.92	11	0.00039
14:50:27	65439.81	12	0.00022

So - average read latency of under a millisecond at roughly 60,000 read IOPs with a divot to under 300 read IOPs at average read latency from 96 milleseconds to over 1 full second.  And one second ending at 14:50:24 with NO reads completed at all.

That raises some serious questions.  I've seen this behavior numerous times on numerous systems.  Hopefully in the next couple of weeks I'll be able to get to the bottom of it, so I can share some answers rather than just more questions.  :-)