Tell me more ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.
up vote 4 down vote favorite
1

We have an Agent job that runs every morning at 2a.m. to defrag the top 5 biggest tables. Usually it takes around 20 mins to complete. It has stayed this way for several years. However, recently (last week or so) I've noticed that it's been taking significantly longer (2-7 hours). This morning, I had to terminate the job because it had been running for a good 8 and a half hours.

I took a look at its log and it looks like it hadn't even finished with the indices from the first table by the time I cancelled the job:

Job '02.00 am - Index defrag' : Step 1, 'run index defrag' : Began Executing 2012-06-27 02:00:05

DBCC: Defrag phase of index 'table1_pk_index' is 27% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 27% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 27% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 27% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 28% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 29% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 30% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 31% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 31% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 32% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 33% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 33% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 34% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 34% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 35% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 35% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 36% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 43% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 43% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 43% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 44% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 44% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 44% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 45% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 45% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 45% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 45% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 46% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 46% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 47% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 47% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 48% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 48% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 49% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 49% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 50% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 50% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 51% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 52% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 52% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 52% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 53% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 53% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 53% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 54% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 54% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 54% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 55% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 55% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 55% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 56% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 56% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 57% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 57% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 58% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 59% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 59% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 60% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 60% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 61% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 62% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 63% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 63% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 64% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 65% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 65% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 66% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 67% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 73% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 77% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 79% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 80% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 82% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 84% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 86% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 88% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 90% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 91% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 94% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 96% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_pk_index' is 98% complete. [SQLSTATE 01000]
Index Name                                                                                                                       Pages Scanned        Pages Moved          Pages Removed       
-------------------------------------------------------------------------------------------------------------------------------- -------------------- -------------------- --------------------
table1_pk_index                                                                                                           2145739              1546226              236
DBCC: Defrag phase of index 'table1_index1' is 66% complete. [SQLSTATE 01000]
Index Name                                                                                                                       Pages Scanned        Pages Moved          Pages Removed       
-------------------------------------------------------------------------------------------------------------------------------- -------------------- -------------------- --------------------
subscription_orders_idx1                                                                                                         434585               374095               768
DBCC: Compaction phase of index 'table1_index2' is 93% complete. [SQLSTATE 01000]
DBCC: Defrag phase of index 'table1_index2' is 38% complete. [SQLSTATE 01000]
Msg 0, Sev 0, State 1: Operation canceled [SQLSTATE HY008]

Query cancelled.

Judging by the numerous lines of 'DBCC: Defrag phase of index...', I can tell that the primary key index in particular had taken much longer than usual (just a side question, does anyone know the interval at which these messages are generated, since SQL Server is very sparing when it comes to timestamps.)

Looking at the index fragmentation information, it appears that all three indices have really low average fragmentation percentage, which is expected as they are defragged every day:

  • table1_pk_index: 0.103168974377375%
  • table1_index1: 0.100508753691454%
  • table2_index2: 0.734118693782182%

These figures look normal to me, so I am a little stumped. What could've caused these indices to take so much longer to defrag? What else should I be looking out for?

Update: I drilled down on the problem a bit more as Remus recommended and discovered that the disc queue length was through the roof around the time when the defrag took place. It turned out that this started happening after we moved the restore time on the reporting server a few days ago (which restores from a backup file on the production server using Litespeed), so it coincided with the scheduled time of the defrag. Even though the two jobs read/write files from two different logical drives, both drives happen to sit on the same LUN which couldn't take the amount of concurrent IO requests. The problem disappeared as soon as we moved the time for the defrag to another time slot.

share|improve this question
How many rows do these indexes have? Are you actually using the DBCC INDEXDEFRAG command? Have you tried using an ALTER INDEX ... REBUILD? What is that duration? DBCC INDEXDEFRAG is deprecated, you should be utilizing the latter. And to rebuild indexes with that low of fragmentation is virtually useless. It's a good rule of thumb that anything more than 5% and less than 30% should be reorganized, and any index with fragmentation greater than 30% should be rebuilt. – Thomas Stringer Jun 27 '12 at 2:46
1  
I think @Shark meant REORGANIZE. If these indexes have such low fragmentation, why are you blindly defragging all of them every night? – Aaron Bertrand Jun 27 '12 at 2:55
This is a legacy Agent job left over from previous DBAs. I will give reorganize a try tonight. It still doesn't explain why all of sudden it's taking more than 20x longer for the defrag to complete though. The clustered index has 2,146,312 pages in total and the table has 234,001,728 rows. – deutschZuid Jun 27 '12 at 3:44

1 Answer

up vote 8 down vote accepted

You should approach index reorganize performance troubleshooting problems the same way you approach any performance troubleshooting problem: identify the waits and resources, using a methodology like waits and queues for example. Once you do the due diligence and collect the data (perf counters, wait stats etc), if you are still unable to find the issue we can help, rather than ask us to roll the 8 ball and guess (and more importantly, rather than you working by guess).

Next, there are many maintenance scripts out there that are a heck of a lot better than reorganizing ad-nauseam every night, like Ola Hallengren or Michelle Ufford just to give two examples.

share|improve this answer
+1 For Ola's scripts. Used those to seriously reduce the index reorg/rebuild in my shop. – swasheck Jun 28 '12 at 21:46
2  
I give you the credits for sound advice which helped me resolve the problem. I will start looking at other options than reorging the indexes every night. Have updated my answer with the resolution. – deutschZuid Jun 28 '12 at 22:01
Thanks for posting back the resolution. – Remus Rusanu Jun 28 '12 at 22:08

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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