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.
Best Answer
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.