40 concurrent SQL Server parallel queries + (2 sockets * 10 cores per socket) = spinlock convoy

Here's a disclaimer: trace flags aren't toys - only deploy them in production environments after exploring and testing their behavior in the context of your critical workloads (including end user activity, backups, integrity checks, index maintenance, stats maintenance).  Be especially cautious with startup trace flags since it'll require a SQL Server restart to back them out.

Trace flag 8048 - I don't know of any bad side effects... and I've been looking.  Not a reason for you not to test... but I'll update this post and add a new post if I ever learn of trouble from trace flag 8048.

Trace flag 8015 - combined with trace flag 8048, disabling NUMA has been good medicine for the kinda-DSS/kinda data warehouse type workflows on the systems I'm involved with.  Its lead to more even CPU utilization across cores, more stable/predictable memory utilization, lower overall physical reads, higher scalability, and shorter execution times for batch workloads.  Your mileage WILL vary :)  Potential bad side effects to consider: loss of one independent buffer pool on each NUMA node, loss of "affinitize different SQL Server connections to different physical NUMA nodes" strategy, single lazy writer instead of one lazy writer per NUMA node.

Ok... is that good enough for the lawyers?  :)

A colleague sent me the perfmon spreadsheet snippet above today.  This is from a SQL Server with 2 Intel sockets of ten cores per socket, with hyperthreading enabled.  I know its hard to read :)  Don't bother trying to read the numbers - read the reds and the greens.  And if its 3 digit red - the logical CPU is 100% busy.  Report application servers send up to 40 concurrent queries to this SQL Server system.

Its about as good of a picture as you'll ever see of what can go wrong in SQL Server by default on a NUMA server: parallel query worker threads are stacking up on a single NUMA node instead of spreading out, and the worker threads on the busy NUMA node are hitting MAJOR spinlock contention in memory allocation.  My colleague just grabbed the per-CPU %busy stats from perfmon, stuffed them into excel, turned on conditional formatting and voila!  Its clear to me how much of a benefit trace flags 8048 and 8015 will be to this system.  Is it clear to other folks yet?

See - with NUMA enabled by default, all worker threads for parallelized queries tend to stay on the NUMA node which received the connection.  Connections are distributed round-robin among the NUMA nodes... but what if by happenstance one node gets all the quick queries, and the other node gets all the long, parallelized queries?  Ummm... this happens.

You end up with lots and lots and lots of worker threads executing tasks for parallelized queries - all stacked on the same poor cores, and the other CPU cores just might be loafing.

The other behavior to keep in mind is that, by default, query memory allocation (and some other memory allocations) for all threads on a NUMA node are serialized through a single chokepoint (!!). That's as well-defined bottleneck as you'll find, just waiting for enough concurrent activity on the NUMA node to 'poke the bear'.  In fact, when things start to look like they do above, it might not just be CPU overload coupled with spinlock contention.  It could even be a 'spinlock convoy', where numerous cores (in this case all CPU cores on at least 1 NUMA node) spend more cycles spinning for the same resource than accomplishing logical work.

So here's the deal - if you see this pattern on your SQL Server... and its a dedicated server so nothing else is chewing up your compute power... Check the waits.  Check the spins.  Plot logical reads, or some other measure of database work, against CPU utilization.  Consider disabling NUMA with trace flag 8015, and don't forget to also apply trace flag 8048 in order to promote query memory allocation to per-core serialization, eliminating the NUMA node serialization bottleneck.  Even if disabling NUMA with trace flag 8015 is not a good idea for your workload (maybe you need more than one lazywriter or you are affinitizing connections to a NUMA node?), I haven't yet found a disadvantage to promoting memory serialization to per-core and removing the bottleneck with trace flag 8048.

Oh yeah, I know about SQL Server 2012 kb hotfixes 2819662 and 2845380.  Neither one nor the combination will remedy this issue.  Nor will they address the stuff I talk about in the following post:
http://sql-sasquatch.blogspot.com/2013/08/sql-server-numa-servers-cpu-hotspot.html

Here's a bibliography if you want a fuller understanding of task distribution with default SQL Server NUMA behavior, memory management with default SQL Server NUMA behavior, memory allocation with default SQL Server serialization, etc.  Or maybe you want to double check that I actually know what I'm talking about :) You could also follow the tags to my other posts on NUMA, TF8048, TF8015 :)

Selected SQL Server 2012 NUMA and Memory Management Hotfixes

kb2819662: SQL Server Performance Issues in NUMA Environments

http://bit.ly/Z9C25x

kb2845380: You may experience performance issues in SQL Server 2012

http://bit.ly/13LADVq

Selected Trace Flag 8048 Sources 

CSS SQL Server Engineers - SQL Server 2008/2008 R2 on Newer Machines with More Than 8 CPUs Presented per NUMA Node May Need Trace Flag 8048

http://bit.ly/15Wjdmn

CSS SQL Server Engineers - CMemThread and Debugging Them

http://bit.ly/X9BsDW

Selected SQL Server NUMA Sources

CSS SQL Server Engineers - SQL Server (NUMA Local, Foreign and Away Memory Blocks)

http://bit.ly/VuNebm

CSS SQL Server Engineers - SQL Server 2008 NUMA and Foreign Pages

http://bit.ly/W2Nh0x

CSS SQL Server Engineers - SQL Server 2005 Connection and Task Assignments 

http://bit.ly/Xe2sz3

CSS SQL Server Engineers - NUMA Connection Affinity and Parallel Queries

http://bit.ly/15iRlv8

CSS SQL Server Engineers - Soft NUMA, I/O Completion Thread, Lazy Writer Workers and Memory Nodes

http://bit.ly/YyLZGW

MSDN - Growing and Shrinking the Buffer Pool Under NUMA 

http://bit.ly/ZiWDBe

qdpma.com - NUMA Systems and SQL Server 

http://bit.ly/XcXanp

SQL Server: NUMA servers CPU hotspot liability by default

This post is long overdue.  I still don't like the graphs I have... although they kinda tell the story, they still don't quite capture the risk/reward in an intuitive way.  But I don't want to hold off anymore on getting something out in the wild.

I talk a lot about hotspots, and usually its about storage.  Balanced resource utilization typically provides the most predictable performance, and that's what I shoot for by default.

Its important to realize that hotspots are not only a storage resource concept - they can apply to CPU or other resources as well.  In fact, for SQL Server on NUMA servers, by default there is a CPU hotspot liability.

Imagine you have a server with 8 NUMA nodes, 6 cores on each NUMA node(think old school AMD, 12 cores per socket, 2 NUMA nodes per socket one logical CPU per physical core).  Parallel queries start stacking up their workers.  Once the 6 cores on NUMA node 0 have enough active worker threads threads to stay busy - it would seem like a good idea to start giving some threads to the other cores... right?  In fact - once those 6 cores are all at or near 100% CPU utilized - if any more active threads are added the available cycles on those CPUs are just going to be spread among a larger number of active workers, with each of them accomplishing less than previously.  (In fact, the growing number of context switches also represents a growing management cost, so less of the CPU total cycles will be available for dividing among the growing number of threads.)  And in fact, that's exactly what happens in SQL Server by default.  Hotspot jambalaya!

Here's the deal: client connections are round-robin distributed among NUMA nodes.  But when a connection requests a parallel query, there is a strong tendency for all of the query workers to remain on the NUMA node.  Hmmmm.... so on my 8 NUMA node server if a single query spins up a worker thread per CPU, each of the cores in the NUMA node would have 8 active worker threads.  While the other 40 cores get no work to do for the query.  Well.... shoot....

See - this is a huge part of the recommendation to set maxdop to the number of cores in the NUMA node... or half of the cores in the NUMA node... or...

But that's a losing game, let me tell you.  Because if a query starts with multiple data paths, you can easily end up right back where you started. If all queries were simple and had a single stream of processing, setting maxdop to the number of logical CPUs in a NUMA node might make sense.  Each parallel query would result in one thread per logical CPU.  But complex, multi-stream queries toss that idea out the window.  Use a stored procedure or complex query with 8 separate processing streams - you are right back where you started: 8 active worker threads per logical core on one NUMA node, and no work associated with that query for anyone else.

If that type of activity takes place on a DSS or DW system with a high concurrency of batched queries, query throughput can be horrible.  Check it out.  I'm sorry its ugly.  The numbers in the graph are from a 48 physical core system with 8 NUMA nodes, and MAXDOP set to 6.  I averaged the CPU busy along NUMA node boundaries, and those are the results below for Node0 to Node7.  While some NUMA nodes are maxed out, others are loafing.

  

This isn't a secret, although almost no-one ever talks about it.  There are details about task assignment at the following locations.

How It Works: SQL Server 2005 Connection and Task Assignments

http://blogs.msdn.com/b/psssql/archive/2008/02/12/how-it-works-sql-server-2005-connection-and-task-assignments.aspx

NUMA Connection Affinity and Parallel Queries
http://blogs.msdn.com/b/psssql/archive/2007/06/28/numa-connection-affinity-and-parallel-queries.aspx

So... what to do, what to do?

Well, SQLCAT pursued one avenue.  They wrapped queries in a "terminate - reconnect" strategy.

Resolving scheduler contention for concurrent BULK INSERT

http://sqlcat.com/sqlcat/b/technicalnotes/archive/2008/04/09/resolving-scheduler-contention-for-concurrent-bulk-insert.aspx

I'm not very fond of that solution, but it is an acknowledgement of the problem, if nothing else :)

Instead, for the DSS systems and workloads I work with, I recommend disabling NUMA support at the database level with startup trace flag 8015.   All schedulers are treated as a single pool, then - no preferential treatment for parallel query workers along NUMA node boundaries.  (All memory is treated as a single pool as well, which leads to a separate set of benefits for the workloads I deal with.  Guess I'll have to return to that another day.)

Its important to note that on these systems we already use trace flag 8048 to eliminate spinlock contention among schedulers in the same group during concurrent memory allocation.  Increase the number of schedulers in the group by disabling NUMA with TF8015, and if you haven't also put TF8048 in place you could invoke a spinlock convoy with enough concurrent activity.  That would NOT be cool.

Anyway... time for the big finish.  Here's another graph that's better than nothing, although I'm still not completely happy with it.  It takes forever to explain what is being measured... but at least it makes the difference very evident :)

So, the blue line is the control workflow - trace flag 8048 is in place to eliminate spinlock contention, but the database NUMA support is enabled.  The Y axis counts occurrences of qualifying 15 second interval perfmon samples.  The X axis is the difference between the CPU% for the busiest NUMA node and the average of the remaining 7 NUMA nodes.  The graph displays the level of balance in CPU utilization across NUMA nodes.  The more balanced the CPU use of a workload is, the more samples there will be in the lower end of the graph.  See -- the control workflow is not very balanced.  The most popular level of difference was 68% - so the busiest NUMA node was 68% busier than the average of the remaining 7 nodes well over 600 times (more than 2.5 hours).  

Contrast that with the same workload on the same system, with trace flag 8015 added to trace flag 8048, to disable database NUMA support.  Now the most popular position is about 4% difference, with over 2.5 hours spent at that level.

AIX hotspot hunting and potential benefit of tier 0 cache: lvmstat overtime data

Recently I posted a method for tacking on a timestamp to lvmstat output with awk.  Maybe you think that's not a big deal.  In my world, it is :)

The graph above is a heat map of a logical volume with a JFS2 filesystem on top.  Its cio mounted, and has tons of database files in it.  With this particular database engine, all reads and writes to a cio filesystem are 8k (unlike Oracle and SQL Server which will coalesce reads and writes when possible).  Also, all database reads go into database cache, unlike Oracle which can elect to perform direct path reads into PGA rather than into the SGA database cache.  Those considerations contribute to the nice graph above.

The X axis is the logical partition number - the position from beginning to end in the logical volume.
The left primary axis represents the number of minutes in out of 360 elapsed minutes that the logical partition was ranked in the top 32 for the logical volume by iocnt.  (Easy to get with the -c parameter for the lvmstat command.)

So... what use is such a graph?  Together with data from lslv, you can map hot logical partitions back to their physical volumes (LUNs)... that is invaluable when trying to eliminate QFULL occurrences at the physical volume level.  For another thing, together with database cache analysis (insertion rates at all insertion points, expire rates, calculated cache hold time, etc) heat maps like these can help to estimate the value of added database cache.  They can also help to estimate the value of a tier 0 flash automated tiering cache - whether the flash is within the storage array, or in an onboard PCIe flash device.  I've worked a bit with EMC xtremsw for x86 Windows... looking forward to working with it for IBM Power and PCIe flash form factor.  Hoping to test with the QLogic Mt Rainier/FabricCache soon, too.  If the overall IO pattern looks like the graph above, as long as the flash capacity together with the caching algorithm results in good caching for the logical partitions on the upward swing of the hockey stick, you can expect good utilization of the tier 0 cache.  I personally prefer onboard cache, because I like as little traffic getting out of the server as possible.  In part for lower latency... in part to eliminate queuing concerns... but mostly to be a good neighbor to other tenants of shared storage.

So... in reality, the system I'm staring at today isn't as simple as a single logical volume heat map.  There are more than 6 logical volumes that contain persistent database files.  All of those logical volumes have hockey stick shaped graphs as above.  Its easy to count the number of upswing logical partitions across all of those LVs, and find out how much data I really want to see in the flash cache.  Now... if the flash cache transfer size is different than the logical partition size that should be considered.  If my logical partition size is 64mb, and the flash tiering always promotes contiguous 1 GB chunks from each LUN, that could lead to requiring a lot more flash capacity to contain all of my hot data.  On the other hand, if the transfer size into tier 0 cache is 1 mb, and the heat is very uneven among 1 mb chunks within each hot LP... the total flash cache size for huge benefit might be a lot smaller than the aggregate size of all hot LPs.  Something to think about.  But I can't give away all of my secrets. Keeping at least some secrets is key to sasquatch survival :)

IBM Power AIX hotspot hunting - About that lvmstat date timestamp...

So a few posts ago I cavalierly wrote how easy it was to add a timestamp to lvmstat for unattended data gathering when hotspot hunting. (Hotspot hunting ain't easy unless you can time-align lvmstat and iostat data.)  I was overconfident, in my own awk abilities at the very least.

Sure, I found the hot logical partitions when I was reviewing data.  But every single one of my timestamps in the log had the same value!  Criminey!  It took me forever to spreadsheet-mod my way out of that in order to create some decent looking spreadsheet and graph data.

If you McGoogle "lvmstat", "awk", and "timestamp" I don't think you'll find very much that is helpful in allowing time-aligning of unattended lvmstat logs with iostat logs.  Maybe there's a compact answer somewhere, but I didn't find it... don't wanna brag but I'm a pretty good McGoogler.  Most of the responses in various forums resulted in the same stale date timestamp values, collected at the beginning of script execution and repeated throughout.  Eventually I was able to get a date timestamp value that was updated throughout execution... but then I had extra linebreaks that I didn't want.

My pain... your gain.  Here's what I ended up with*.

# ###find top 4 partitions, 5 second interval, 4 iterations
# lvmstat -s -l sasquatch_lv -c4 5 4 | awk -u '{ORS=" ";} {print $0 ; system("date") ; close("date") ; }'
 Wed Jul 31 16:40:16 CDT 2013
Log_part  mirror#  iocnt   Kb_read   Kb_wrtn      Kbps Wed Jul 31 16:40:16 CDT 2013
      45       1   39773        16    340312      0.02 Wed Jul 31 16:40:17 CDT 2013
       1       1   16298         0    425208      0.02 Wed Jul 31 16:40:17 CDT 2013
       3       1    5428         0    685612      0.03 Wed Jul 31 16:40:17 CDT 2013
       2       1    4528         0    480760      0.02 Wed Jul 31 16:40:17 CDT 2013
... Wed Jul 31 16:40:26 CDT 2013

Yay!  A small victory, but I'll take it.

*This isn't really the end of course... there's a bit more cleanup.  The empty first line can be removed, the lines that represent no change in values and have only periods and timestamps can be removed.  Those are left as exercises for the reader.  :)


***** Update sql_sasquatch 10/03/2013 *****
I pulled this out today to make sure it really works and that I wasn't just conveniently ignoring timestamps that weren't updating as desired.  Nope, its working like I thought. 
# lvmstat -s -l lv_unicorn -c4 5 20 | awk -u '{ORS=" ";} {print $0 ; system("date") ; close("date") ; }'
 Thu Oct  3 15:00:45 CDT 2013
Log_part  mirror#  iocnt   Kb_read   Kb_wrtn      Kbps Thu Oct  3 15:00:45 CDT 2013
      77       1     146         0       592      0.06 Thu Oct  3 15:00:45 CDT 2013
      75       1      91       144       240      0.04 Thu Oct  3 15:00:45 CDT 2013
      78       1      88         4       348      0.04 Thu Oct  3 15:00:45 CDT 2013
      85       1      80         4      2412      0.26 Thu Oct  3 15:00:45 CDT 2013
. Thu Oct  3 15:00:55 CDT 2013
      85       1       2         0        52     11.11 Thu Oct  3 15:00:55 CDT 2013
....... Thu Oct  3 15:01:35 CDT 2013
      75       1       7         0        28      5.80 Thu Oct  3 15:01:35 CDT 2013
      85       1       7         0       148     30.67 Thu Oct  3 15:01:35 CDT 2013
      77       1       5         0        20      4.15 Thu Oct  3 15:01:35 CDT 2013
      40       1       4         0        16      3.32 Thu Oct  3 15:01:35 CDT 2013
........ Thu Oct  3 15:02:15 CDT 2013
      85       1       2         0       124     21.96 Thu Oct  3 15:02:15 CDT 2013

IBMPower AIX Hotspot hunting - lvmstat

So, maybe you think there are hotspots in disk IO queuing.  I often think that when looking at #Oracle 11GR2 on #AIX #IBMPower servers.  The lvmstat command can be your best friend in tracking down host side LVM hotspots.  Believe me, sometimes you can get a big benefit by moving a small amount of data.  But, usually you end up proving some known best practices - like keeping Oracle redo logs on separate logical and physical volumes from Oracle database .dbf files, and keeping ETL flat files on separate logical/physical volumes from both redo logs and dbf database files :)

At any rate, lvmstat is a mega-useful tool.    A few references for your reading enjoyment.
http://pic.dhe.ibm.com/infocenter/aix/v6r1/topic/com.ibm.aix.prftungd/doc/prftungd/lvm_perf_mon_lvmstat.htm
http://poweritpro.com/performance/if-your-disks-are-busy-call-lvmstat

Root privileges are required for lvmstat, and unlike iostat there isn't a parameter to timestamp its output.  Easily remedied with awk.


Here's some iostat info from mountainhome, a server chosen totally at random. :)
# iostat -DlRTV hdisk0

System configuration: lcpu=24 drives=6 paths=10 vdisks=2

Disks:                     xfers                                read                                write                                  queue                    time
-------------- -------------------------------- ------------------------------------ ------------------------------------ -------------------------------------- ---------
                 %tm    bps   tps  bread  bwrtn   rps    avg    min    max time fail   wps    avg    min    max time fail    avg    min    max   avg   avg  serv
                 act                                    serv   serv   serv outs              serv   serv   serv outs        time   time   time  wqsz  sqsz qfull
hdisk0           0.6  44.3K   6.3  11.7K  32.6K   2.5   5.3    0.1  215.6     0    0   3.8   1.8    0.2  165.3     0    0  11.8    0.0  130.5    0.0   0.0   2.8  12:10:08

My eagle-sharp eyes train in on the serv qfull number - a rate of 2.8 per second for the monitoring period!  Time for intervention!  At least for me - I hate qfulls.

Lets try to be scientifical about this.


Enable the volume groups/logical volumes for stats collection.
A script I've got for that - ain't pretty but it works. (execute as root)
#enable lvmstat stats
for vg in `lsvg | /usr/bin/awk -u '{print $1 ;}'`;
   do
   lvmstat -v $vg -e
   for lv in `lsvg -l $vg | /usr/bin/awk -u 'NR <= 2 { next } {print $1 ;}'`;
      do
         lvmstat -l $lv -e ;
      done ;
   done ;


Once stats are enabled for the volume groups/logical volumes that you care about... start collecting!  (execute as root)
./sasquatch_lvmstat_script 3 3 $(pwd) 4 &


#sasquatch_lvmstat_script
# Begin Functions
lvmon_cmd(){
/usr/sbin/lvmstat -s -l $1 -c$2 $3 $4 | /usr/bin/awk -u '{print $0, date}' date="`date '+%D %H:%M:%S'`" >> $5/$(hostname)_$6_$1_$(date +%Y%m%d)
}
# End functions

interval=${1:-2}
count=${2:-2}
logdir=${3:-/tmp}
top=${4:-32}
for vg in `lsvg | /usr/bin/awk -u '{print $1 ;}'`;
   do
   for lv in `lsvg -l $vg | /usr/bin/awk -u 'NR <= 2 { next } {print $1 ;}'`;
      do
         lvmon_cmd $lv $top $interval $count $logdir $vg $lv &
      done ;
   done ;


Lets pretend I've looked at enough of the output files to determine that lvmcore is the heavy hitter logical volume in rootvg.

The output files from the lvmstat script look kinda like this:

cat mountainhome_rootvg_lvcore_20130722
 07/22/13 11:42:47
Log_part  mirror#  iocnt   Kb_read   Kb_wrtn      Kbps 07/22/13 11:42:47
      56       1      53       212         0      0.00 07/22/13 11:42:47
       1       1      52       208         0      0.00 07/22/13 11:42:47
      53       1      10        40         0      0.00 07/22/13 11:42:47
       2       1       7        28         0      0.00 07/22/13 11:42:47
.. 07/22/13 11:42:47


Log_part are the logical partitions of the logical volume.  Match them up to physical partitions and physical volumes based on the output of something like 'lslv -m'.
# lslv -m lvcore | grep -e 0056 -e 0053 -e 0001 -e 0002
0001  0704 hdisk0
0002  0705 hdisk0
0053  0756 hdisk0
0056  0759 hdisk0

So... what are the lines with nothing but periods and a timestamp?  Those are quiet collection intervals - lvmstat collapsed them for you.  That was nice!  Kinda like including -V in iostat -DlRTV you only get what you need.

OK.  So Logical partitions 0056 and 0001 are the busiest in logical volume lvcore.  They are both on hdisk0.  And we supposedly compared the output across our logical volumes in rootvg and saw that, while hdisk0 is under qfull pressure, lvmcore is the heavy hitter in rootvg volume group.  If there's a quiet hdisk in rootvg, moving one of those logical partitions - or both of them... could relieve the pressure.  Or, maybe you know the contents.  (The fileplace command can assist by mapping individual file fragments to logical partitions of the logical volume - that's a lesson for another day.)  Sometimes its easiest to say "golly!  I guess I could put such-n-such into a different filesystem on a different volume group!  It wouldn't put any pressure on filesystem buffers or any pressure on those physical volume IO queues then!"  That kinda stuff requires negotiation, though.  And I'm not a negotiator, just a sasquatch.

When you are done with lvmstat monitoring, disable the stats collection.  Its a small amount of overhead, but if you aren't baselining or investigating... no need to have the stats enabled. (execute as root)

#disable lvmstat stats
for vg in `lsvg | /usr/bin/awk -u '{print $1 ;}'`;
   do
   /usr/sbin/lvmstat -v $vg -d
   for lv in `lsvg -l $vg | /usr/bin/awk -u 'NR <= 2 { next } {print $1 ;}'`;
      do
         /usr/sbin/lvmstat -l $lv -d ;
      done ;
   done ;