7

I've run into a problem on our production sql server where temp table objects take a long time to drop (obvious when small and synchronous drop is used). I can't reproduce this on other sql servers (similarly spec'd with same numbers of spindles serving tempdb data files (split in same number of files (1 per physical core)). On SQL 2005 Enterprise (SP2 - 3042).

Update: one more factor - which is looking the most likely. this server has >500 databases on it. Another server with > 800 also runs these drops slow. That's the only other server I've got with a lot of dbs on it.

Second Update: restart of the problem servers will allow the create and drop statements to execute instantaneously. Performance of the test degrades over the next few hours (while application is running) until it hits (what appears to be) a plateau. I've got a job running in the background that is testing this every 30 mins. I'll see what results are after a few days and see if execution times are the same. I think they will be.

Third Update: While none of the executing statements have shown latch waits on CPU resources, using sp_whoisactive I see that during a delta_interval = 30 (seconds) run, running query the CPU_delta reports roughly 30,000 (milliseconds?) and when I watch perf during execution there appears to be one core worth of cpu spike during the execution time. these are on 16 cpu boxes so it can be a bit tough to see via perfmon when other traffic is occurring, but it appears to be spiking a cpu worth during execution of drop statements.

Create and destruction of 20 tiny temp tables with unique names (one column, no rows) takes less than 20ms on most servers I test it on. On one server it takes > 5 seconds. The vast majority (>95%) of the time is spent on the drop statements.

During execution there are no explicit waits, and no blocking being reported, and perfmon doesn't show any load on the I/O subsystem for either data or log files.

I've looked at peak and low usage times, when high number of tables marked for destruction and low. The operation takes 5 seconds or so to handle the 20 drop statements, no matter what. The issue is causing perceivable (by clients) slowdown to responsiveness.

Sample code, I created 20 like objects to get the 5 second timing. It appears to be about 300ms per drop. 

PRINT CONVERT(varchar(30),GETDATE(),113)


CREATE TABLE [#Objects1]
(
  [Id] uniqueidentifier NOT NULL
)


CREATE TABLE [#Objects12]
(
  [Id] uniqueidentifier NOT NULL
)
...
DROP TABLE [#Objects1]
DROP TABLE [#Objects12]
...
PRINT CONVERT(varchar(30),GETDATE(),113)

Timing consistently 5 to 6 seconds to execute

11 Nov 2011 12:56:52:073 - Begin temp table creation

11 Nov 2011 12:56:52:090 - End temp table creation

11 Nov 2011 12:56:52:090 - Begin temp table drop

11 Nov 2011 12:56:57:230 - Complete temp table drop

Could you also run USE tempdb; DBCC LOGINFO; and record the number of rows returned. Please add all output from the scripts to your original question.

I noticed originally that I had about 271 vlogs, so I shrank and regrew to see if fragmentation was a problem. Made no difference. Current DBCC Loginfo

FileId,FileSize,StartOffset,FSeqNo,Status,Parity,CreateLSN
2,253952,8192,101603,2,64,0
2,262144,262144,101604,2,64,0
2,262144,524288,101605,2,64,85000000038300574
2,262144,786432,101606,2,64,85000000038300574
2,262144,1048576,101578,2,128,86000000001600001
2,262144,1310720,101579,2,128,86000000001600001
2,262144,1572864,101580,2,128,86000000001600001
2,262144,1835008,101581,2,128,86000000001600001
2,262144,2097152,101582,2,128,86000000001600001
2,262144,2359296,101583,2,128,86000000023400002
2,262144,2621440,101584,2,128,86000000023500756
2,327680,2883584,101585,2,128,86000000023500756
2,327680,3211264,101586,2,128,86000000023500756
2,393216,3538944,101587,2,128,86000000023500756
2,393216,3932160,101588,2,128,86000000023500756
2,458752,4325376,101589,2,128,86000000023500756
2,253952,4784128,101590,2,128,86000000023500756
2,270336,5038080,101591,2,128,86000000023500756
2,253952,5308416,101592,2,128,86000000023500756
2,270336,5562368,101593,2,128,86000000023500756
2,253952,5832704,101594,2,128,86000000023500756
2,335872,6086656,101595,2,128,86000000023500756
2,253952,6422528,101596,2,128,86000000023500756
2,401408,6676480,101597,2,128,86000000023500756
2,253952,7077888,101598,2,128,86000000023500756
2,466944,7331840,101599,2,128,86000000023500756
2,253952,7798784,101600,2,128,86000000023500756
2,253952,8052736,101601,2,128,86000000023500756
2,278528,8306688,101602,2,128,86000000023500756
2,133627904,8585216,101607,2,64,101336000000013600462
2,133627904,142213120,101563,0,128,101336000000013600462
2,133627904,275841024,101564,0,128,101336000000013600462
2,133627904,409468928,101565,0,128,101336000000013600462
2,133627904,543096832,101566,0,128,101336000000013600462
2,133627904,676724736,101567,0,128,101336000000013600462
2,133627904,810352640,101568,0,128,101336000000013600462
2,133627904,943980544,101569,0,128,101336000000013600462
2,133627904,1077608448,101570,0,128,101336000000013600462
2,133627904,1211236352,101571,0,128,101336000000013600462
2,133627904,1344864256,101572,0,128,101336000000013600462
2,133627904,1478492160,101573,0,128,101336000000013600462
2,133627904,1612120064,101574,0,128,101336000000013600462
2,133627904,1745747968,101575,2,128,101336000000013600462
2,133627904,1879375872,101576,2,128,101336000000013600462
2,134479872,2013003776,101577,2,128,101336000000013600462

IO stats output:

Database Name,physical_name,io_stall_read_ms,num_of_reads,avg_read_stall_ms,io_stall_write_ms,num_of_writes,avg_write_stall_ms,io_stalls,total_io,avg_io_stall_ms
msdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\MSDBData.mdf,47691565,817329,58.4,10747142,533509,20.1,58438707,1350838,43.3
tempdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\templog.ldf,54457,30177,1.8,145691717,8235651,17.7,145746174,8265828,17.6
model,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\modellog.ldf,547,122,4.4,2273,239,9.5,2820,361,7.8
tempdb,P:\tempdb_data3.mdf,2606066,1112043,2.3,17829023,1919954,9.3,20435089,3031997,6.7
tempdb,P:\tempdb_data2.mdf,2484793,1111808,2.2,17270161,1922735,9.0,19754954,3034543,6.5
tempdb,P:\tempdb_data5.mdf,2514469,1112086,2.3,17066589,1919802,8.9,19581058,3031888,6.5
tempdb,P:\tempdb_data7.mdf,2542070,1112551,2.3,17049649,1920204,8.9,19591719,3032755,6.5
tempdb,P:\tempdb_data6.mdf,2517767,1112237,2.3,17043756,1924983,8.9,19561523,3037220,6.4
tempdb,P:\tempdb_data0.mdf,2476811,1113570,2.2,17084779,1926333,8.9,19561590,3039903,6.4
tempdb,P:\tempdb_data4.mdf,2462179,1111649,2.2,17073336,1920058,8.9,19535515,3031707,6.4
tempdb,P:\tempdb_data1.mdf,2456317,1111859,2.2,16997589,1922438,8.8,19453906,3034297,6.4
model,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\model.mdf,5194,798,6.5,612,240,2.5,5806,1038,5.6
master,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\master.mdf,40640,7326,5.5,2868,1548,1.9,43508,8874,4.9
msdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\MSDBLog.ldf,8015,950,8.4,1012107,312084,3.2,1020122,313034,3.3
master,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\mastlog.ldf,640,141,4.5,198283,99134,2.0,198923,99275,2.0

Waitstats output:

wait_type,wait_time_s,pct,running_pct

PAGEIOLATCH_EX,0.02,100.00,100.00

TokenAndPermUserStore size is 2952kb.

SELECT SUM(single_pages_kb + multi_pages_kb) AS "SecurityTokenCacheSize(kb)" FROM sys.dm_os_memory_clerks WHERE name = 'TokenAndPermUserStore'
Improve this question
  • tempdb is 8 data files on a raid 10 SAN lun. Nowhere near space pressure on data files (usually somewhere around 500MB of 48GB...)SQL box has 4 quad core procs. Log file is on separate spindles. Unfortunately, temp tables can't be worked around without massive rearchitecting and is an artifact of a bulk insert strategy for getting data into the temp tables to make available to stored procs to work on. – JorgeSandoval Nov 11 '11 at 2:24
  • 1
    Same @@VERSION on all SQL Servers? Then check startup switches for trace flags on all servers – gbn Nov 11 '11 at 5:21
  • 3
    Now check trace flags... which is not code – gbn Nov 11 '11 at 8:54
  • 4
    If you TRUCATE the temp tables first it will speed up the DROP. Ha, just kidding. – Nick Chammas Nov 11 '11 at 17:25
  • 1
    Only when the table is > 8MB. For stored proc temp tables there is a cache of the meta data. This is where my suspicions lie... But I'm not sure where to look for these cached tables. If its just sys.objects in tempdb there are only 2k objects or so. I can't imagine why that would be so slow to add/drop. – JorgeSandoval Nov 11 '11 at 23:37
8

You didn't mention the IOPS used by the tempdb LUN. Are you seeing any IO waits on the LUN device? Is anything else on that LUN? Is another system using the disk group/pool that the LUN is carved from?

Ditto master db -- same q's.

Also, are you using local temp tables (#tablename) or global temp tables (##tablename)? If global could another SPID be keeping the shared lock on the global temp tables when you're trying to delete them?

Improve this answer
  • Tempdb data files are on LUN that is on its own 4 disk raid 10 group (i.e. dedicated spindles). No i/o load shown (i.e. 98% or greater idletime on the logical disk). temp tables are local temp tables, (as in my example in original post). Can be reproduced when it does not appear to be under load. – JorgeSandoval Nov 11 '11 at 18:27
  • Also tempdb ldf is on raid 5 – JorgeSandoval Nov 11 '11 at 18:52
  • I think @bretlowery is on to something. Can you ALTER tempdb into a different LUN, restart, see if anything changes. Also, I wouldn't have LDFs on RAID 5: they are 100% write and are suited better for R1 or R10. Finally, check disk + controller settings (caching, raid status etc) – gbn Nov 14 '11 at 8:38
  • Would I not have seen some contention for disk there, usage in idletime % of the luns was near 98/99%? I mean we are talking about a drop of a temp table with one column. This should be two maybe three write operations at most, but it takes 300 ms after the server runs for an extended period of time with the application running. Restart of the instance and you get super fast drops that slow down over the first few hours of the application running against it. – JorgeSandoval Nov 14 '11 at 17:52
7

The answer to my perf problem is a little known (though I had seen it a long time ago) issue related to collection of dmv statistics on systems with many databases where code uses temp tables a lot (or presumably you have a lot of tables). On our slowest servers sys.dm_db_index_usage_stats had > 200k records, with servers returning 10k records still having a measureable lag.

KB article describes the problem. http://support.microsoft.com/kb/2003031

Query performance decreases when sys.dm_db_index_usage_stats has large number of rows

Consider the following scenario:

  • In Microsoft SQL Server 2005, you frequently perform DDL operation that involve dropping and recreation of lot of tables (especially temporary tables in tempdb database).
  • You have a large number of entries (100,000 or more) in the sys.dm_db_index_usage_stats dynamic management view (DMV).

This issue is fixed in SQL 2008, but can only be alleviated in 2005 by code changes to reduce dependence on temp tables or by enabling trace flag 2330.

This KB has saved my bacon. Restarting after adding this trace flag to start up params has reduced drop times down to <100 ms levels (from 40000 ms!), and I can expect other perf gains on these servers as well!

Additional reading that led me to the conclusion that this was the problem

http://www.pythian.com/news/5211/sql-server-more-light-shed-on-non-yielding-scheduler-and-indexes-stats/

Thanks to all who contributed to this question, I've gained quite a few very useful tools for diagnosing perf issues in the process.

Improve this answer
  • 1
    Pleased to hear you found a solution and thanks for posting the details. – Mark Storey-Smith Nov 18 '11 at 15:59
  • 1
    Thanks a lot for your help, the problem seemed (rightfully) like voodoo. A single thread taking up a cpu is hardly even noticeable on a big box, and without any waits, it really was just chugging through the massive memory cache for these stats. Glad they've fixed this in SQL 2008, now just have to wait out the long period between now and when we actually get to upgrade... – JorgeSandoval Nov 19 '11 at 7:54
6

When a drop-table is waiting for more than a second or two, run Adam Machanic's sp_WhoIsActive. It's a great tool to find out why any query is running slow. In the waits column, you'll see the waits for the specific task, and if it's stuck waiting on CPU (which won't show up in sys.dm_os_wait_stats) you'll see that too.

Also, I'd be remiss if I didn't point out that your build is out of support. As a consultant, I tell my clients, "I would hate to do hours of troubleshooting only to find that it's been fixed in a service pack - and end up billing you thousands of dollars for something you could have fixed for free. Plus you're out of support anyway." You can find the most recent SQL Server service packs & cumulative updates at http://sqlserverbuilds.blogspot.com. Build 3042 is way out of date - the supported version is SP4.

Improve this answer
  • Yeah, I wish it was a simple as just updating to a later service pack... I've already scanned the cumulative updates and sp notes and didn't see anything related to this issue. Unfortunately, dept policy prevents us from installing SQL SPs without a full regression test of the application which can take months. Unit tests on this app cover about 20%... its painful. Its a slow train to get moving and we're gearing up for just that activity to support he migration to Denali (or if not released soon SQL2008 R2) – JorgeSandoval Nov 14 '11 at 17:44
  • I downloaded the sp_whoisactive proc, but in order to get any meaningful stats I have to widen the execution to creating 50 temp tables and dropping them. Total execution of the batch took 43 seconds. I started the sp_whoisactive and ran with delta=30 seconds to make sure start and stop included this batch. It appears that the statements are putting CPU under some pressure (well, one core) during the execution time. – JorgeSandoval Nov 14 '11 at 20:56
  • Its not clear if cpu time of sp_whoisactive is milliseconds or microseconds. It looks like milliseconds in that it correlates with the delta interval, but when I look up a lot of the DMVs they report in microseconds – JorgeSandoval Nov 14 '11 at 21:21
  • Yeha, Adam's got it reporting in milliseconds. Don't use the delta - you just want to run sp_WhoIsActive as I show in the video, and you want to catch it while it's waiting on the temp table drop. That means running it in a tight loop, like every second, and capturing the output to a temp table each time. Then go back and examine the temp tables to see what the spid was waiting on each time, and if there's any blocking. Also about the notes - they won't cover every fix that's included in the SP/CU, and remember, you're on an unsupported version. – Brent Ozar Nov 16 '11 at 13:57
  • Thanks for the input, problem was a management view's collection of stats (see my answer for more info). – JorgeSandoval Nov 17 '11 at 19:19
5

Edit: 2011-11-12 13:00

As TokenAndPermStore looks to be a "normal" size, it's unlikely to be a factor. Next place to look is probably spinlock stats. Can you also (as I mentioned in chat) determine if the problem persists if you remove the explicit drop statements and let the tables fall out of scope instead.

Edit: 2011-11-12 01:00

As you're on 2005SP2, I'm starting to wonder if this might be a TokenAndPermUserStore issue. It would explain why the problem is alleviated by a restart of the instance and why the problem is prevalent on servers with large numbers of database.

Can you run the following query and add the output to your question.

SELECT SUM(single_pages_kb + multi_pages_kb) AS "SecurityTokenCacheSize(kb)"
FROM sys.dm_os_memory_clerks
WHERE name = 'TokenAndPermUserStore'

The quick hack fix for this is to create a job that monitors the size of the cache and runs DBCC FREESYSTEMCACHE ('TokenAndPermUserStore') when it exceeds a certain size. IIRC (I'll check tomorrow and update) I've set the limit at 100MB on servers where this caused a problem. SP3 introduces a mechanism to control the cache size, without having to brute force clear it.

Original answer:

Might take a bit of to and fro but can we start with a look at the IO and wait statistics? (scripts in GIST)

Modify your create/drop script to run DBCC SQLPERF("sys.dm_os_wait_stats",CLEAR); at the start, followed by the wait stats script after your final drop. Result will probably be easier to read if you post them as CSV (so they can be copied to Excel).

Could you also run USE tempdb; DBCC LOGINFO; and record the number of rows returned.

Improve this answer
  • FYI after about 6 or 7 executions it seems waits only on PAGEIOLATCH_SH PAGEIOLATCH_SH 0.02 100.00 100.00 – JorgeSandoval Nov 11 '11 at 18:45
  • 6.5 or so average for data files, and 17.6 for log file don't seem like they'd contribute to the 300ms per dropped table. – JorgeSandoval Nov 11 '11 at 19:14
  • Interestingly, the test script (creating/dropping the temp tables) doesn't return any waits on other servers. (Waits CTE actually reports divide by zero error). – JorgeSandoval Nov 11 '11 at 19:27
  • @JorgeSandoval could you add the data to your original question as an edit please. That way it's easier for everyone to see (and work on). – Mark Storey-Smith Nov 11 '11 at 19:54
  • results have been added – JorgeSandoval Nov 11 '11 at 21:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.