The Rare, Simple SQL Wait Fix

A "power user" reported some slowness on one of our big servers today while it was being pummeled by about 60 simultaneous executions of the same script. The wait type was PAGELATCH_UP, which I vaguely recalled to mean something about allocation contention. The Microsoft Waits and Queues tuning guide confirmed that, so I checked the wait resources. They all started with 2:6 and 2:9, so it definitely had to do with tempdb.

This server is pretty beefy, a 4-socket quad-core with Xeon 7350s, but tempdb only had 8 files. I know that the rule of thumb of 1 file per core is no longer quite so hard and fast, but I figured it probably wouldn't hurt here. Created an extra 8 files, equalized the file sizes on the current ones, and had the user kick off the process again.

No waits! Or at least, no PAGELATCH_UP waits. Some SOS_SCHEDULER_YIELDs and CXPACKETs, but I took that to mean that we had successfully shifted the bottleneck off of allocations and onto CPU, where it should be.

It's rare that 5 minutes of configuration change can effect a significant gain in process speed, but it's pretty satisfying when it happens.

CPU Affinity Masking plus High CPU = Login Timeouts

Recently we saw an alarming issue with one of our database servers. Under heavy but not prohibitive load (60-80% CPU), it stopped accepting new connections intermittently. Obviously this is bad for any server, especially one that handles thousands of client connections simultaneously.

Some of the hard drives were under heavy load, especially tempdb, but another anomaly was a long-running query using many linked server connections (11!) that had been killed but was stuck in rollback several hours later. It was consuming near 100% of the cycles on one CPU core. We tried a variety of the usual DBA tricks to get rid of this spid, but nothing worked. It wasn't clear to us how this could cause the server to stop accepting connections, however.

Another oddity was the appearance in the System logs of messages like this:

The time stamp counter of CPU on scheduler id 2 is not synchronized with other CPUs.

I asked our Systems guys about this, and they said that this had been noticed a few months ago and a workaround had been put in place as per KB 931279 - the CPU affinity mask had been set in SQL Server.

Hmm.

This happened again a week later, minus the spid stuck in rollback, but with one CPU slammed at 100% again. We had engaged Microsoft PSS to assist with the problem, but so far all they had told us was that we had tempdb IO issues, which we knew. (DVNation, please finish the Windows drivers for your IODrives so we can use them for tempdb!)

So here's my theory, cooked up with one of the other DBAs: the login issues are being caused by the combination of affinity masking and one CPU at 100%. This could happen because schedulers are affinitized by the mask to a single CPU, making them unable to hop CPUs when one is under heavy load. User logins round-robin between schedulers, so if a scheduler is stuck to a single CPU and that CPU is not making enough cycles available to log someone in, eventually the login will timeout and fail.

Plausible? Anyone else seen this kind of issue?

UPDATE:

I was right. After removing the affinity masking, we no longer saw login timeouts, even when the server was near 100% CPU load. Be careful with those affinity masks.

Lists vs. temp tables

Dynamic SQL is in heavy use at my new office, and I'm not sure how I feel about a lot of it. For example, one of my coworkers showed me a neat trick by which one can append to a string with each successive row returned in a select statement, like so:

select @list = @list + cast(foo as varchar(10)) + ',' from #test2

But I noticed that this technique was used in many pieces of code in our system, and it bothered me, because I was pretty sure that creating and joining to temp tables would be faster than assembling long strings and then using them with "in" clauses. I wasn't positive, however, so I assembled this test script:

SET NOCOUNT ON

if OBJECT_ID('tempdb..#timing') is not null
drop table #timing

if OBJECT_ID('tempdb..#test1') is not null
drop table #test1

if OBJECT_ID('tempdb..#test2') is not null
drop table #test2

declare
@i int
, @items int

set @items = 1022

create table #timing
(
testrun varchar(100)
, setupStartTime datetime
, setupEndTime datetime
, setupElapsed as datediff(ms, setupStartTime, setupEndTime)
, queryStartTime datetime
, queryEndTime datetime
, queryElapsed as datediff(ms, queryStartTime, queryEndTime)
, totalElapsed as datediff(ms, setupStartTime, setupEndTime) + datediff(ms, queryStartTime, queryEndTime)
)

select
identity(int, 10403, 96) as foo
, cast('some text' as varchar(20)) as bar
into
#test1

set @i = 0

while @i < @items begin insert into #test1 select 'cowabunga' set @i = @i + 1 end insert into #timing (testRun, setupStartTime) values ('Temp Table', getDate()) select foo into #test2 from #test1 create clustered index ix on #test2 (foo) update #timing set setupEndTime = getDate() where testRun = 'Temp Table' create clustered index ix on #test1 (foo) insert into #timing (testRun, setupStartTime) values ('List', getDate()) declare @list varchar(7000), @curID int set @list = '(' select @curID = min(foo) from #test2 --while @curID is not null --begin -- select @list = @list + cast(@curId as varchar(10)) + ',' -- select @curId = min(foo) from #test2 where foo > @curID
--end

select @list = @list + cast(foo as varchar(10)) + ',' from #test2


set @list = substring(@list, 0, len(@list) - 1) + ')'

declare @sql varchar(8000)
set @sql = 'select * from #test1 where foo in ' + @list

update #timing
set setupEndTime = getDate()
where testRun = 'List'

print(@sql)


update #timing
set queryStartTime = getDate()
where testRun = 'List'

exec (@sql)

update #timing
set queryEndTime = getDate()
where testRun = 'List'



update #timing
set queryStartTime = getDate()
where testRun = 'Temp Table'

select t1.* from #test1 t1
inner join #test2 t2
on t1.foo = t2.foo

update #timing
set queryEndTime = getDate()
where testRun = 'Temp Table'

select * from #timing

The results of this test vary somewhat, so it would be best to run the whole thing in a loop to assemble a statistically valid set of data, but the difference between the two methods is so pronounced that the SD doesn't really matter. Ready for the (approximate) difference?

Temp tables are 3x faster then strings.

Here's a typical result of this script running on our QA server, an 8-CPU 20-GB box running SQL 2000 build 2171:


Running it repeatedly yielded similar results with some higher outliers, but very few lower ones. The next problem will be how to propose changing our coding practices and re-writing a lot of stored procs. Stay tuned for that one, and possibly an entry about my subsequent de-hiring.