January 19, 2016 at 4:42 am
Had an issue yesterday which caused a backlog of queries, very high CPU, application slowdown - all from the start of the business day at about 6.30am. This was fixed almost immediately by running a job which creates+drops a snapshot as this was known to clear the cache (a hunch by someone that this was the issue).
What I can't understand is WHY this occurred at the time it did, since just prior to it at 6am there is a job which changes 'degree of parallelism' and also has an explicit step to (after a wait of 2 mins') run DBCC FREEPROCCACHE.
It is almost like the freeproccache didn't do its job at the time specified, and had to be run via the snapshot job a bit later - is this a bug with SQL 2005 SP4 that the command doesn't do what is required??
Incidentally, the wait of 2 mins and explicit running of DBCC FREEPROCCACHE was introduced because during load testing in the pre-production environment a similar patter was found. The first run of the day had CPU issues etc, and after some deduction it was found that the command needed to be specified, despite there being other jobs (snapshots and the like) which should have cleared the cache automatically themselves. This 'fix' has kept things sweet in both pre and production up until yesterday.
One further bit of info is that between 4am and 5:30am there was an update stats job using the 'UPDATE STATISTICS' command. But surely the 6am FREEPROCCACHE should have taken care of any out of date stats in query plans?
Also, here are the relevant things recorded by SQL:
Snapahot created and MAXDOP changed:
2016-01-18 00:00:01.130spid109Configuration option 'show advanced options' changed from 0 to 1. Run the RECONFIGURE statement to install.
2016-01-18 00:00:01.130spid109Configuration option 'max degree of parallelism' changed from 1 to 4. Run the RECONFIGURE statement to install.
2016-01-18 00:00:01.230spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 00:00:01.230spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 00:00:08.050spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 00:00:08.050spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 00:00:08.050spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 00:00:08.050spid109SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 00:00:08.080spid109Configuration option 'show advanced options' changed from 1 to 0. Run the RECONFIGURE statement to install.
Snapshot dropped after use:
2016-01-18 02:36:03.520spid70SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 02:36:05.840spid70SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 02:36:05.840spid70SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
MAXDOP changed, 2 minute wait and then DBCC FREEPROCCACHE command run:
2016-01-18 06:00:00.150spid62Configuration option 'show advanced options' changed from 0 to 1. Run the RECONFIGURE statement to install.
2016-01-18 06:00:00.160spid62Configuration option 'max degree of parallelism' changed from 4 to 1. Run the RECONFIGURE statement to install.
2016-01-18 06:00:00.230spid62SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 06:00:00.480spid62SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 06:00:00.490spid62SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 06:00:00.510spid62Configuration option 'show advanced options' changed from 1 to 0. Run the RECONFIGURE statement to install.
Manual running of the earlier snapshot creation and drop jobs to try and fix the performance issue:
2016-01-18 10:51:35.070spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 10:51:35.160spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 10:52:17.740spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 10:52:17.830spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 10:52:18.010spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to 'DBCC FREEPROCCACHE' or 'DBCC FREESYSTEMCACHE' operations.
2016-01-18 10:52:18.100spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2016-01-18 10:56:50.200spid549SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
January 19, 2016 at 12:19 pm
This sounds less like FREEPROCCACHE didn't work and more like you just had some queries get compiled with poor plans. After a subsequent clearing of the cache, they happened to get compiled with better plans.
If it happens again, I'd dig more into which queries are driving the CPU utilization and check their execution plans; those can be compared to the execution plans for the same queries when performance is acceptable.
From there it'll just be some tuning work based on what you see.
Cheers!
EDIT: Fixed a couple typos. Also, I should point out that unless you have very good reasons (and maybe not even then), clearing the entire procedure cache and changing MAXDOP for the instance on a schedule is probably not a good idea. I'd revisit the reasons for doing so, since there are likely better ways to do address any issues you might be seeing.
January 19, 2016 at 3:54 pm
rarara,
What you are saying makes no sense to me. I would strongly suggest you to review your maintenance tasks, because it feels like you have no idea what you are doing with the server, just trying random things hoping that it will magically resolve all the issues.
Why do you need to change MAXDOP back and force every day? There must be a better way to do whatever you are trying to achieve.
Calling FREEPROCCACHE to clear the cache completely in order to fix some performance issues? Have you ever tried to identfy what processes, procedures or queries are causing these problems?
Create and drop snapshot in order to clear the cache? That's simply a nonsense. And even if it works in SQL 2005 it doesn't mean this will work in 2008+, so I would strongly suggest you to refrain from such practices in the future.
I can try to guess that you have parameter sniffing issues, and I would look into it rather then wondering why FREEPROCCACHE may or may not work correctly. Assume, for now, that all the functionality of SQL Server works as designed, you simply need to learn how actually it was designed.
January 20, 2016 at 3:30 am
Hi guys, thanks for your input. i didn't include every detail for fear of getting bogged-down in process. In terms of what is currently running through the night we have:
Snapshot creation which is used to populate an MI database. This snapshot is then dropped after the export completes.
Maxdop is changed as the performance of the MI population is improved, and it is changed back again after that.
Obviously as part of the above operations the cache is cleared, and that in itself isn't an issue - we are comfortable with that and there is no noticeable performance hit when queries are getting compiled again. I agree that "Create and drop snapshot in order to clear the cache?" was a lazy way to achieve an aim, but it wasn't me who did this step at the time.
Unfortunately I don't have the execution plan info as the issue hasn't occurred again before or since. To my mind this points towards a primary cause of:
1) At some point between the 6am FREEPROCCACHE running and the ramp-up of poor performance shortly afterwards, something caused the queries to be compiled with poor plans. There are a couple of small jobs but I believe that they use different queries to the type of ones that were performing poorly via general user access/tasks.
I am still confused as to why this happened in isolation - would I not expect to see this problem regularly if that was the case??
January 20, 2016 at 3:40 am
rarara (1/20/2016)
Snapshot creation which is used to populate an MI database. This snapshot is then dropped after the export completes.
Maxdop is changed as the performance of the MI population is improved, and it is changed back again after that.
Quick suggestion, leave the MAXDOP setting for the server alone, set the Cost Threshold for Parallelism to a proper value and run the MI population with OPTION (MAXDOP X)
😎
January 20, 2016 at 6:42 am
rarara (1/20/2016)
Hi guys, thanks for your input. i didn't include every detail for fear of getting bogged-down in process. In terms of what is currently running through the night we have:Snapshot creation which is used to populate an MI database. This snapshot is then dropped after the export completes.
Maxdop is changed as the performance of the MI population is improved, and it is changed back again after that.
Obviously as part of the above operations the cache is cleared, and that in itself isn't an issue - we are comfortable with that and there is no noticeable performance hit when queries are getting compiled again. I agree that "Create and drop snapshot in order to clear the cache?" was a lazy way to achieve an aim, but it wasn't me who did this step at the time.
Unfortunately I don't have the execution plan info as the issue hasn't occurred again before or since. To my mind this points towards a primary cause of:
1) At some point between the 6am FREEPROCCACHE running and the ramp-up of poor performance shortly afterwards, something caused the queries to be compiled with poor plans. There are a couple of small jobs but I believe that they use different queries to the type of ones that were performing poorly via general user access/tasks.
I am still confused as to why this happened in isolation - would I not expect to see this problem regularly if that was the case??
You wouldn't necessarily expect to see the problem regularly. To use the typical sort of parameter sniffing problem as an example, if some procedures just got plans generated for an atypical value that is used, say, 1/10000 calls, then it would be relatively rare for a recompile of that query to result in a plan optimized for that atypical value.
Of course, that's just one possible reason; without any data it's hard to say for sure what actually happened.
I second Eirikur's suggestion. There's no need to change MAXDOP for the entire server; use the MAXDOP query hint on the queries you have determined benefit from a particular MAXDOP.
Cheers!
Viewing 6 posts - 1 through 5 (of 5 total)
You must be logged in to reply to this topic. Login to reply