Hi all,

One of our client has a db server with about 10 production databases on.
The application issues jdbc queries that are not properly parametrized (although using prepared statements) resulting in a 5GB plan cache.
I noticed a lot of high compilation times for queries - 2 to 10 seconds. Sometimes the same query (with different parameters) will compile fast though.
The end users are complaining about performance issues and every time they will issue a dbcc freeproccache that will bring them back to decent performance for about an hour or so.
I have a perfmon trace running that collects most memory and other SQL specific events. Is this memory pressure? Stolen pages stays at about 10G.
I tried changing the "optimize for AdHoc" flag with no real improvements.
What should I check for?

Thanks

Hi, ever heard about "parameter sniffing"?

take a look at this useful link by Erland Sommarskog

http://www.sommarskog.se/query-plan-mysteries.html

hope will help you

Thanks,

wouldn't parameter sniffing be about slow query executions rather that taking too long to compile them?

My queries run in milliseconds, but if I look at the explain plan they show 10 seconds compile time

Ion,

First of all, sessions established by JDBC set the arithabort session property to 0 by default. This could result in the generation of bad query plans, with certain characteristics that could be causing a delay at compile time. Can you observe this same problem in management studio?

Secondly, you said the performance improves for a short time after you clear the plan cache. This is very weird because it should be the other way around. If this is true then your bottleneck isn't in the actual processing of compilations, but rather related to their storage past a certain point in time. It could be that the scanning for existing execution plans, when you run a query, may be taking more resources than usual for some reason. Have you checked the compilations/sec performance counter for this instance? Have you compared it to the number of requests? If the number of compilation/sec is low compared to the number of batches, this will further isolate the root cause.

Last but not least, check out this information available on an article about query plan cache:

"The algorithms to match new SQL statements to existing, unused execution plans in the cache require that all object references be fully qualified."

https://technet.microsoft.com/en-us/library/ms181055%28v=sql.105%29.aspx?f=255&MSPPError=-2147217396

This means that, if you do not specify the schema of a table (schema.table) within a query, a suitable cached plan will not be found and it will have to be recompiled.

After some digging, there are two other settings I would recommend you try changing:

1. If auto update statistics is on, statistics are updated as data or schema changes are made. Statistic updates cause plans which rely on them to recompile, possibly resulting in a high compile frequency. You might wanna try setting auto update statistics off and adding an update statistics task in your maintenance plan.

2. Enable forced parametrization in your database. This will increase the chance of existing plans being reused by widening the range of situations in which literal values can be implicitly converted to parameters. You said your prepared statements are not properly parametrized, so I suspect this could be of value.

https://technet.microsoft.com/en-us/library/ms175037%28v=sql.105%29.aspx?f=255&MSPPError=-2147217396

Thanks Samir,

I'll have to go through all these tomorrow. My initial thought was there is some cost in managing the relatively large cache - i.e. looking up a query or flushing others. I thought of forcing parametrization too, but it's a bit too risky trying that on a production server with users already peeved.

I suggested adding 64G RAM maybe this will help and is really cheap and easy to do. My other theory is that somehow SQL 2012 has some issues around managing large size query caches, as we have the same application running on 2008 at different sites and is fine. I will look at all your suggestions tomorrow and keep you posted, thanks a lot for your input.

Ultimately, the application needs to be fixed. That is, developers need to learn using parameterised statements. And, yes, rework the existing code.

Another thing that is important is that all table references should be in two-part notation, for instance dbo.customers. If the query goes "SELECT * FROM customers" without dbo, two users with different default schema, cannot share a cache entry.

In the meanwhile, I think forced parameterisation is what you should try. This option is the cover-up for poorly implemented applications like yours.

You should certainly have "optimize for ad hoc workloads" enabled, but if the application has the habit of submitting the same unparameterised query twice, it is not going to help you.

There was also advice to turn of auto-stats. From what you have told, I see absolutely no reason to do that.

There was also the statement set the arithabort session property to 0 by default. This could result in the generation of bad query plans. No, ARITHABORT does not affect the query plan, but for legacy reasons different settings of ARITHABORT produces different plan entries. With good odds that the plans are the same.

Enabling forced parametrization does have its risks. It can prevent the employment of indexes over views and indexes on computed columns for example, if your application relies on these for performance, but fortunately, enabling FP is an online operation and can be rolled back at any time. Read carefully the article I've sent you for more information. Knowledge of your application workload is strongly advised.

And yes, there is a cost in managing a large cache because the plan lookups will be more expensive, and this makes a lot of sense if you consider the fact that performance improves when you clear the plan cache, but this applies for any version of SQL Server, not just 2012.

You can add more RAM, but make sure you are using the enterprise edition of SQL Server. The standard edition supports only 64 GB.

Besides, if compile performance only starts to degrade as the cachestore starts to grow, its not clear to me how adding more memory could be helpful, but its worth a shot.

I would add that, we have a lot of guesses here, good guesses, but we still lack a little data. I wonder what your CPU stats look like overall. I wonder what your wait stats look like.

Could be you have some SQL that creates or modifies schemas, and that you have locking and blocking at the schema level going on, and lots of recompiles.

Josh

Thank you all for the suggestions. I will give it a try with FP.

Th application uses only one user under the covers, so fully qualifying the table names will not make a difference.

The cpu rarely goes over 15%, there's a lot of cpu power on that box although I wished it uses parallelism more. It does, but the application uses fast forward cursors and I noticed warnings in the query plans saying that the query can only use one cpu because of that type of cursor.The application doesn't do any schema modifications except occasionally creating temp tables but not often. I've seen locking and blocking but they are isolated to certain processes that will ave to be optimized, but they cannot explain the general poor performance. The database has no indexed views as it has to also support a legacy app that needs SQL 2005 so SQL runs in SQL 2005 legacy mode which I believe has a lot of restrictions on the indexed views.

What puzzles me is that flushing the cache has an instant huge impact on the app, or at least that is what the users report. We have the same app running at a different customer, about the same db size and they do not have this issue, and the only significant difference is that they run 2008R2 instead of 2012.

Ion,

Post the results of:

SELECT @@VERSION

And please let us know if any of the suggestions above helped solve your problem. It may be of further reference to anyone who encounters a similar situation.

Good info, Ion, thanks.  Cursors, hmm?  Always a bad sign. 

And I'd still like those wait stats, if you can search out how to do those. 

Josh

We plan to try forced parmetrization in the next couple of days.

Version: Microsoft SQL Server 2012 - 11.0.2218.0 (X64)
    Jun 12 2012 13:05:25
    Copyright (c) Microsoft Corporation
    Standard Edition (64-bit) on Windows NT 6.2 <X64> (Build 9200: )

Working to get customer to apply patches.

Waits - using a script I found on the Web

WaitType    Wait_S    Resource_S    Signal_S    WaitCount    Percentage    AvgWait_S    AvgRes_S    AvgSig_S
CXPACKET    18111570.50    17528713.89    582856.61    5722458318    78.13    0.0032    0.0031    0.0001
TRACEWRITE    3069921.14    3069385.19    535.95    1538841    13.24    1.9950    1.9946    0.0003
LATCH_EX    893596.94    881628.44    11968.50    43982229    3.85    0.0203    0.0200    0.0003
PAGEIOLATCH_SH    375854.34    372325.42    3528.93    58634993    1.62    0.0064    0.0063    0.0001
SOS_SCHEDULER_YIELD    268422.53    525.37    267897.16    500582520    1.16    0.0005    0.0000    0.0005
IO_COMPLETION    145468.01    145159.43    308.58    36548257    0.63    0.0040    0.0040    0.0000
WRITELOG    69986.46    57784.74    12201.72    106011256    0.30    0.0007    0.0005    0.0001
ASYNC_IO_COMPLETION    39865.10    39852.52    12.58    9090    0.17    4.3856    4.3842    0.0014
BACKUPIO    31493.56    31445.15    48.41    6748509    0.14    0.0047    0.0047    0.0000
BACKUPBUFFER    28258.51    27873.40    385.11    5074733    0.12    0.0056    0.0055    0.0001
LCK_M_S    28208.71    28203.07    5.64    5057    0.12    5.5782    5.5770    0.0011
PAGEIOLATCH_EX    25147.11    24740.25    406.86    73240568    0.11    0.0003    0.0003    0.0000
ASYNC_NETWORK_IO    23922.55    23056.93    865.61    4534331    0.10    0.0053    0.0051    0.0002
CMEMTHREAD    21165.06    20018.28    1146.79    44288120    0.09    0.0005    0.0005    0.0000
LCK_M_IS    10997.07    10996.82    0.25    824    0.05    13.3460    13.3457    0.0003
PAGELATCH_EX    9380.70    8224.18    1156.52    13226761    0.04    0.0007    0.0006    0.0001
MSQL_XP    6189.06    6189.06    0.00    457177    0.03    0.0135    0.0135    0.0000
PAGELATCH_SH    4252.25    3479.34    772.92    4360671    0.02    0.0010    0.0008    0.0002
PREEMPTIVE_OS_AUTHENTICATIONOPS    4110.71    4110.71    0.00    7934684    0.02    0.0005    0.0005    0.0000
LATCH_SH    1823.63    1778.34    45.29    682593    0.01    0.0027    0.0026    0.0001
LOGBUFFER    1628.35    1599.83    28.53    9798    0.01    0.1662    0.1633    0.0029
LCK_M_U    1623.77    1621.87    1.90    2555    0.01    0.6355    0.6348    0.0007
LCK_M_X    1465.12    1464.55    0.57    1761    0.01    0.8320    0.8317    0.0003
PREEMPTIVE_OS_DELETESECURITYCONTEXT    1073.12    1073.12    0.00    2623681    0.00    0.0004    0.0004    0.0000
PREEMPTIVE_OS_WAITFORSINGLEOBJECT    979.32    979.32    0.00    2272477    0.00    0.0004    0.0004    0.0000
LCK_M_SCH_S    760.40    760.36    0.04    231    0.00    3.2918    3.2916    0.0002
PREEMPTIVE_OS_CRYPTACQUIRECONTEXT    724.57    724.57    0.00    2604437    0.00    0.0003    0.0003    0.0000
PREEMPTIVE_OS_CRYPTOPS    700.19    700.19    0.00    2603432    0.00    0.0003    0.0003    0.0000
PREEMPTIVE_OS_WRITEFILE    668.43    668.43    0.00    259527    0.00    0.0026    0.0026    0.0000
CXROWSET_SYNC    651.29    614.79    36.50    568470    0.00    0.0011    0.0011    0.0001
THREADPOOL    396.68    396.67    0.00    7565    0.00    0.0524    0.0524    0.0000
PAGELATCH_UP    356.90    347.11    9.80    115196    0.00    0.0031    0.0030    0.0001
PREEMPTIVE_OS_AUTHORIZATIONOPS    316.27    316.27    0.00    2625195    0.00    0.0001    0.0001    0.0000
SQLTRACE_FILE_BUFFER    303.62    303.39    0.23    2948    0.00    0.1030    0.1029    0.0001
PREEMPTIVE_OS_CRYPTIMPORTKEY    296.67    296.67    0.00    2608074    0.00    0.0001    0.0001    0.0000
BACKUPTHREAD    294.27    293.46    0.82    7806    0.00    0.0377    0.0376    0.0001
DEADLOCK_ENUM_MUTEX    219.41    217.83    1.58    6510    0.00    0.0337    0.0335    0.0002
PREEMPTIVE_OS_WRITEFILEGATHER    160.38    160.38    0.00    242    0.00    0.6627    0.6627    0.0000
PREEMPTIVE_OS_DECRYPTMESSAGE    116.85    116.85    0.00    2624556    0.00    0.0000    0.0000    0.0000
PAGEIOLATCH_UP    78.82    78.49    0.34    34312    0.00    0.0023    0.0023    0.0000
PREEMPTIVE_XE_CALLBACKEXECUTE    68.99    68.99    0.00    18901774    0.00    0.0000    0.0000    0.0000
LCK_M_SCH_M    60.58    60.00    0.57    21641    0.00    0.0028    0.0028    0.0000
PREEMPTIVE_OS_QUERYREGISTRY    14.90    14.90    0.00    51093    0.00    0.0003    0.0003    0.0000
LCK_M_IX    14.41    14.36    0.05    166    0.00    0.0868    0.0865    0.0003
LOGMGR_FLUSH    13.51    13.50    0.01    1469    0.00    0.0092    0.0092    0.0000
PREEMPTIVE_OS_FILEOPS    12.84    12.84    0.00    14118    0.00    0.0009    0.0009    0.0000
PREEMPTIVE_OS_DISCONNECTNAMEDPIPE    7.81    7.81    0.00    38349    0.00    0.0002    0.0002    0.0000
PREEMPTIVE_OS_REPORTEVENT    6.36    6.36    0.00    808    0.00    0.0079    0.0079    0.0000
WRITE_COMPLETION    4.55    4.53    0.01    3666    0.00    0.0012    0.0012    0.0000
FFT_RECOVERY    3.69    3.69    0.00    15    0.00    0.2459    0.2459    0.0000
PREEMPTIVE_OS_GETVOLUMEPATHNAME    3.27    3.27    0.00    4348    0.00    0.0008    0.0008    0.0000
PREEMPTIVE_OS_GETPROCADDRESS    2.68    2.68    0.00    457177    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_OS_LOOKUPACCOUNTSID    2.42    2.42    0.00    463    0.00    0.0052    0.0052    0.0000
PREEMPTIVE_OS_GENERICOPS    2.41    2.41    0.00    848    0.00    0.0028    0.0028    0.0000
PREEMPTIVE_OS_REVERTTOSELF    1.39    1.39    0.00    20949    0.00    0.0001    0.0001    0.0000
PREEMPTIVE_OS_QUERYCONTEXTATTRIBUTES    1.33    1.33    0.00    20865    0.00    0.0001    0.0001    0.0000
PREEMPTIVE_OS_CREATEFILE    1.24    1.24    0.00    4280    0.00    0.0003    0.0003    0.0000
PREEMPTIVE_XE_GETTARGETSTATE    1.06    1.06    0.00    14    0.00    0.0757    0.0757    0.0000
PREEMPTIVE_OS_LIBRARYOPS    0.57    0.57    0.00    1    0.00    0.5730    0.5730    0.0000
PREEMPTIVE_XE_TARGETINIT    0.42    0.42    0.00    102    0.00    0.0041    0.0041    0.0000
PREEMPTIVE_XE_SESSIONCOMMIT    0.37    0.37    0.00    289    0.00    0.0013    0.0013    0.0000
SQLTRACE_FILE_WRITE_IO_COMPLETION    0.36    0.36    0.00    61    0.00    0.0058    0.0058    0.0000
LCK_M_IU    0.34    0.34    0.00    54    0.00    0.0064    0.0063    0.0000
FT_IFTS_RWLOCK    0.27    0.25    0.02    1701    0.00    0.0002    0.0001    0.0000
PREEMPTIVE_OS_COMOPS    0.27    0.27    0.00    1    0.00    0.2700    0.2700    0.0000
PREEMPTIVE_OS_DELETEFILE    0.26    0.26    0.00    59    0.00    0.0044    0.0044    0.0000
PREEMPTIVE_OS_AUTHZINITIALIZECONTEXTFROMSID    0.22    0.22    0.00    74    0.00    0.0030    0.0030    0.0000
PREEMPTIVE_OS_GETFILEATTRIBUTES    0.17    0.17    0.00    2085    0.00    0.0001    0.0001    0.0000
PREEMPTIVE_OS_ENCRYPTMESSAGE    0.17    0.17    0.00    1410    0.00    0.0001    0.0001    0.0000
PREEMPTIVE_OS_LOADLIBRARY    0.14    0.14    0.00    3    0.00    0.0467    0.0467    0.0000
DEADLOCK_TASK_SEARCH    0.11    0.11    0.00    47    0.00    0.0024    0.0024    0.0000
PREEMPTIVE_OS_PIPEOPS    0.11    0.11    0.00    1    0.00    0.1120    0.1120    0.0000
PREEMPTIVE_OS_DOMAINSERVICESOPS    0.10    0.10    0.00    1    0.00    0.1040    0.1040    0.0000
PREEMPTIVE_OS_CLOSEHANDLE    0.07    0.07    0.00    495    0.00    0.0001    0.0001    0.0000
PREEMPTIVE_OS_GETDISKFREESPACE    0.06    0.06    0.00    212    0.00    0.0003    0.0003    0.0000
PARALLEL_BACKUP_QUEUE    0.05    0.05    0.00    3    0.00    0.0167    0.0167    0.0000
PREEMPTIVE_OS_NETVALIDATEPASSWORDPOLICY    0.05    0.05    0.00    9    0.00    0.0051    0.0051    0.0000
PREEMPTIVE_OS_FLUSHFILEBUFFERS    0.04    0.04    0.00    222    0.00    0.0002    0.0002    0.0000
PREEMPTIVE_XE_TARGETFINALIZE    0.04    0.04    0.00    96    0.00    0.0004    0.0004    0.0000
SNI_CRITICAL_SECTION    0.02    0.02    0.00    26    0.00    0.0008    0.0008    0.0000
PREEMPTIVE_FILESIZEGET    0.01    0.01    0.00    313    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_OS_SQMLAUNCH    0.01    0.01    0.00    37    0.00    0.0002    0.0002    0.0000
CLR_CRST    0.01    0.01    0.00    6    0.00    0.0010    0.0010    0.0000
XE_BUFFERMGR_ALLPROCESSED_EVENT    0.01    0.01    0.00    18    0.00    0.0003    0.0003    0.0001
PREEMPTIVE_OS_AUTHZINITIALIZERESOURCEMANAGER    0.01    0.01    0.00    74    0.00    0.0001    0.0001    0.0000
CLR_TASK_START    0.00    0.00    0.00    9    0.00    0.0004    0.0004    0.0000
SOS_SYNC_TASK_ENQUEUE_EVENT    0.00    0.00    0.00    8    0.00    0.0005    0.0000    0.0005
PREEMPTIVE_OS_AUTHZGETINFORMATIONFROMCONTEXT    0.00    0.00    0.00    148    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_OS_GETVOLUMENAMEFORVOLUMEMOUNTPOINT    0.00    0.00    0.00    16    0.00    0.0002    0.0002    0.0000
DAC_INIT    0.00    0.00    0.00    1    0.00    0.0020    0.0020    0.0000
EE_PMOLOCK    0.00    0.00    0.00    61    0.00    0.0000    0.0000    0.0000
BROKER_MASTERSTART    0.00    0.00    0.00    1    0.00    0.0010    0.0010    0.0000
LCK_M_SIX    0.00    0.00    0.00    1    0.00    0.0010    0.0010    0.0000
LATCH_UP    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PAGELATCH_KP    0.00    0.00    0.00    13    0.00    0.0000    0.0000    0.0000
SNI_TASK_COMPLETION    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_OS_NETVALIDATEPASSWORDPOLICYFREE    0.00    0.00    0.00    9    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_SB_STOPENDPOINT    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_XE_DISPATCHER    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PERFORMANCE_COUNTERS_RWLOCK    0.00    0.00    0.00    5    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_XE_TIMERRUN    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_LOCKMONITOR    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
PREEMPTIVE_SP_SERVER_DIAGNOSTICS    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000
SECURITY_CRYPTO_CONTEXT_MUTEX    0.00    0.00    0.00    1    0.00    0.0000    0.0000    0.0000

Ion,

Your customer is using the RTM version of SQL Server, which is very outdated. I recommend you instruct them to apply service pack 2, as it fixes countless problems. Their instance should be much more stable after that.

Waits - using a script I found on the Web

Despite what you said about wishing that parallelism was used more, CXPACKET is your top wait and by far - 78%.

I notice that TRACEWRITE is your second wait, and this is worrisome. This indicates that someone is running SQL Server Profiler a lot. One should be very restrictive on using Profiler on a production system, as it can have quite a performance impact. It is much better to run traces server-side.

WaitType	Wait_S	Resource_S	Signal_S	WaitCount	Percentage	AvgWait_S
CXPACKET	18,111,571	17,528,714	582,857	5,722,458,318	78.13	0.003
TRACEWRITE	3,069,921	3,069,385	536	1,538,841	13.24	1.995
LATCH_EX	893,597	881,628	11,969	43,982,229	3.85	0.020
PAGEIOLATCH_SH	375,854	372,325	3,529	58,634,993	1.62	0.006
SOS_SCHEDULER_YIELD	268,423	525	267,897	500,582,520	1.16	0.001

Pretty amazing count of cxpackets!

If you're running more than 8 cores and still have maxdop=0 (default) you might look at setting that down to a smaller number, 8 or 4 or something, I wonder if the whole problem could be an artifact of lots of big parallel plans and the big cache.

Also as Erland says you might look into that tracewrite, you don't want that on a production box, though I doubt it accounts for the problem here.

Other than that things look remarkably healthy, not much registered as official locks, anyway.

Josh

Ok, I love this forum, you guys are awesome :)

So, for tracing I have no clue what is going on there, I noticed they have a Spotlight application that shows up in my queries but other that that I'm not aware of any profiler trace. I traced blocked processes (5seconds), rpc completed and batch completed and  for a couple of days using extended events, and that filtered by duration grater that 2 seconds, which didn't really result in any big trace files.  I noticed Spotlight regularly resulting in long queries and blocked processes reports, but I don't yet have a solid case against it

The CXPacket waits I suspect come from the fact that they rebuild indexes and run stats every night on 10 production databases that live on that server. Or from other applications that share those databases  (there are I believe 3 or 4), or maybe from long cognos reporting queries run usually off hours.

Parallelism is indeed a big issue, but not the way you expect it: I noticed that the cpu NEVER goes above 4% during regular business hours. That means not much parallelism really, and here's what I saw: while looking at explain plans I noticed that most of them use fast forward cursors, and the plan had a warning saying that because of this cursor stuff parallelism cannot be used. I traced that back to the jdbc connection string where we force server side cursors (selectMethod=cursor), and I have no clue why this was done. We changed the setting and are testing it, I really hope to see faster queries and a healthier cpu usage. I also hope to see the tempdb write latency going down from 100 ms on average - it's all cursors. All other i/o latency is under 5ms. So cxpacket waits seem to be a red herring here or I am missing something. We are also testing bringing the server to the last fix pack.