SLEEP_TASK and PAGELATCH_XX peaking after upgrade to R2 SP1

Question

I wanted to just add a comment to this question: SLEEP_TASK Wait Type in SQL Server - What does it indicate? But I'm having not only SLEEP_TASK wait but also PAGELATCH_SH and PAGELATCH_EX wait types. Also I've so much data that I believe I should ask a new question, although I know the risk exist to be considered as duplicated.

As on the referenced question, we too upgraded several of our servers couple of weeks ago from SQL Server 2008 SP3 to 2008R2 SP1 (10.52.2500.0). Since this point we began to notice some timeouts on our database requests. More and more, and last days its already a problem as we are having lot of timeouts. For monitoring I'm using Adam Machanic sp_whoisActive together with Kendra Little steps to log the results. I configured a job to run whoisactive each 4min using @delta_interval=2 and it runs 5 times each 20seconds. I've also settled up a job to pick up wait statistics on a table that runs each 2min.

From the results I'm posting below I noticed that there are lot of sleep_task and pagelatch_xx wait types. Nothing else has changed, no new releases on our development platform. Just update of SQL Server to 2008R2 SP1 and the sysadmin applied current windwos patches on WinSvr2012R2 Standard.

I've checked lot of references on tempd contention, wait types, etc:

• Wait statistics, or please tell me where it hurts
• Page 1,2,3 Contention
• Troubleshooting: Tempdb Contention
• tempdb should always have one data file per processor core (yes, we already have several of them)

I'm going crazy trying to figure out what could happend. Any idea?

Part of whoIsActive results:

| collection_time         | dd hh:mm:ss.mss | wait_info                         | host | db  | CPU | reads  | physical_io |
|-------------------------|-----------------|-----------------------------------|------|-----|-----|--------|-------------|
| 2014-05-20 14:25:30.253 | 00 00:00:00.080 | (1x: 8ms)SLEEP_TASK               | W2   | ss2 | 15  | 493    | 28          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.080 | (1x: 2ms)PAGELATCH_EX:tempdb:1(*) | W8   | ss2 | 16  | 1,541  | 1           |
| 2014-05-20 14:25:30.253 | 00 00:00:00.080 | (1x: 7ms)SLEEP_TASK               | W2   | ss2 | 16  | 489    | 34          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.083 | (4ms)PAGELATCH_EX:tempdb:1(*)     | W2   | ss2 | 16  | 1,429  | 2           |
| 2014-05-20 14:25:30.253 | 00 00:00:00.086 | (1x: 2ms)SLEEP_TASK               | W2   | ss2 | 47  | 488    | 36          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.100 | (5ms)PAGELATCH_EX:tempdb:1(*)     | W8   | ss2 | 15  | 4,347  | 1           |
| 2014-05-20 14:25:30.253 | 00 00:00:00.106 | (1x: 1ms)SLEEP_TASK               | W1   | ss2 | 78  | 530    | 34          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.110 | (2ms)PAGELATCH_EX:tempdb:1(*)     | W8   | ss2 | 15  | 853    | NULL        |
| 2014-05-20 14:25:30.253 | 00 00:00:00.110 | (1x: 7ms)SLEEP_TASK               | W1   | ss2 | 109 | 490    | 28          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.113 | (1x: 1ms)RUNNABLE                 | W3   | ss2 | 62  | 489    | 28          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.116 | (4ms)PAGELATCH_SH:tempdb:1(*)     | W1   | ss2 | 47  | 14,201 | 2           |
| 2014-05-20 14:25:30.253 | 00 00:00:00.116 | (1ms)IO_COMPLETION                | W3   | ss2 | 94  | 30,762 | 21          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.120 | (1x: 6ms)SLEEP_TASK               | W3   | ss2 | 16  | 507    | 30          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.120 | (12ms)SLEEP_TASK                  | W3   | ss2 | 62  | 513    | 31          |
| 2014-05-20 14:25:30.253 | 00 00:00:00.123 | (1x: 2ms)RUNNABLE                 | W1   | ss2 | 0   | 791    | 1           |

Here are part of the total wait results:

| wait_type                        | wait_time_s | pct   | running_pct |
|----------------------------------|-------------|-------|-------------|
| SLEEP_TASK                       | 301.00      | 41.58 | 41.58       |
| LAZYWRITER_SLEEP                 | 151.00      | 20.88 | 62.46       |
| CHECKPOINT_QUEUE                 | 65.00       | 9.00  | 71.46       |
| SQLTRACE_INCREMENTAL_FLUSH_SLEEP | 32.00       | 4.42  | 75.88       |
| LOGMGR_QUEUE                     | 30.00       | 4.14  | 80.02       |
| XE_TIMER_EVENT                   | 30.00       | 4.14  | 84.16       |
| REQUEST_FOR_DEADLOCK_SEARCH      | 30.00       | 4.14  | 88.30       |
| WAITFOR                          | 23.00       | 3.18  | 91.47       |
| OLEDB                            | 17.00       | 2.40  | 93.87       |
| BROKER_TO_FLUSH                  | 14.00       | 1.99  | 95.87       |

Running wait percentages:

| wait_type                         | diff          | wait_time | max_wait | diff_signal  | diff_elapsed | last_time_stamp         | previous_time_stamp     |
|                                   | waiting tasks | ms        | time_ms  | wait_time_ms | time_ms      |                         |                         |
|                                   | count         |           |          |              |              |                         |                         |
|-----------------------------------|---------------|-----------|----------|--------------|--------------|-------------------------|-------------------------|
| SLEEP_TASK                        | 25100         | 301554    | 1698     | 7891         | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| OLEDB                             | 24161         | 17416     | 15061    | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| MSQL_DQ                           | 2229          | 8111      | 2023     | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PREEMPTIVE_COM_QUERYINTERFACE     | 2229          | 8109      | 2023     | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| SOS_SCHEDULER_YIELD               | 40102         | 4929      | 1954     | 4900         | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| ASYNC_NETWORK_IO                  | 81            | 3053      | 2013     | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PAGELATCH_EX                      | 5348          | 988       | 1927     | 535          | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PREEMPTIVE_OS_CRYPTACQUIRECONTEXT | 2229          | 654       | 40       | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PREEMPTIVE_OS_REVERTTOSELF        | 6699          | 630       | 38       | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PREEMPTIVE_OS_CRYPTIMPORTKEY      | 6687          | 500       | 30       | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PAGEIOLATCH_SH                    | 88            | 491       | 4855     | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PREEMPTIVE_OS_SECURITYOPS         | 6687          | 451       | 46       | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| PAGELATCH_SH                      | 4633          | 438       | 1933     | 276          | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| IO_COMPLETION                     | 474           | 74        | 237      | 2            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |
| WRITELOG                          | 38            | 62        | 1624     | 0            | 30013        | 2014-05-20 17:36:30.933 | 2014-05-20 17:36:00.920 |

Yes, we have lot of inserts on one of the databases, logging stuff (trying to log less but impossible for the moment). We have main db, log file and tempDB on a Fusion IO drive and all the other stuff on RAID10.

The OLEDB is a call to a linked server and for the moment is unavoidable. My main concern is that couple of weeks ago there were no such big timeouts and now suddenly they are. Found the referenced question and made me think that maybe server upgrade could trigger some weird behaviour that we are not aware of.

Answer 1

_{Community wiki answer:}

Please ignore the sleep and queue waits. These should be filtered out as they are always going to be high, by definition. They collect a minute of wait every minute. PAGELATCH tells me it can't keep up. That said, I don't see that as your major problem here.

For latch contention, you might consider this whitepaper. However, I'd be much more concerned about the OLEDB and MSQL_DQ waits. Are you doing a ton of cross-server stuff? Can any of this be consolidated, or are these things communicating with non-SQL Server RDBMS platforms?

I don't think 2008 -> 2008 R2 should cause any severe issues, but you may want to be sure that you have updated statistics everywhere (with FULLSCAN, preferably during a maintenance window), as this is a common cause for plan/perf degradation after an upgrade or migration.

But I would also strongly consider getting on the most recent branch and installing the most recent CU available. You should also keep in mind that mainstream support for 2008R2 ends in two months.

And while I hesitate to advocate Thomas' line of thinking that a clustered GUID is always better than an IDENTITY column, given that you have Fusion IO and your latches are still occasionally exceeding 2 seconds, you may need to consider redesign, because obviously throwing fast I/O at the problem isn't solving anything.

See this post and this post for some edge case enlightenment (again, please don't consider this an endorsement of "heaps > clustered index" or "GUID > identity").