March 31, 2016 at 1:54 am
Hi
I' ve a database used to a gaming application. 99% of procedure called by the application are 2 stored procedure called 'new_transaction' and 'upd_trandaction'. Those stored are called usually 30-40 times in a second and have a medium execution time of 10 millisecond. But...
Using profiler, i've seen that every 4 minutes i have a few case (10-15) where these procedure take 4-5 SECONDS to be executed. I've no job with that schedulation, no locks are generated, no log shipping is used.
What could be?? Every 4 minutes PRECISE (no 1 second more no 1 second less)
Thanks
Andrea
March 31, 2016 at 7:23 am
For it to be that precise, something is running a process I'd guess. Do you have monitoring in place to capture query executions? If not, try trace (since you're still on 2008) or extended events to capture the calls for a period of time to see what's up. Also, try capturing the execution plan when the query is running normally and during that period when it's running slowly. See if there's a difference.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
March 31, 2016 at 8:12 am
andrea.dimaio (3/31/2016)
HiI' ve a database used to a gaming application. 99% of procedure called by the application are 2 stored procedure called 'new_transaction' and 'upd_trandaction'. Those stored are called usually 30-40 times in a second and have a medium execution time of 10 millisecond. But...
Using profiler, i've seen that every 4 minutes i have a few case (10-15) where these procedure take 4-5 SECONDS to be executed. I've no job with that schedulation, no locks are generated, no log shipping is used.
What could be?? Every 4 minutes PRECISE (no 1 second more no 1 second less)
Thanks
Andrea
What are the growth settings on the database? And what is the Recovery Model of the database and are you doing any backups?
--Jeff Moden
Change is inevitable... Change for the better is not.
April 1, 2016 at 8:27 am
Recovery model is simple and filegrouth is 1mb but ther's enough space pre allocated so it never happen that needs to grouth file
April 1, 2016 at 8:35 am
You might want to capture wait stats as well. Since they're cumulative since SQL Server started, you'll need to subtract one set of figures from the next in order to get the numbers for the period you're interested in. Try trapping them every five seconds and see whether they look any different for the periods in which you have your slow-downs. Once you've gathered enough information, stop capturing, or at least reduce the frequency of capture.
John
April 1, 2016 at 9:02 am
I've a tool that monitor lock/waits > 1000 ms but it never happens.
I've seen this is not a problem of single database but is relative to the instance. Other procedure that usually take from 0 to 20 ms to be executed, in that precise second (every 4 minutes) take from 1000 to 6000 ms to be executed... It could be an i/o problem?
April 1, 2016 at 9:32 am
It could be, but until you capture the wait stats, you're just speculating. Also, see whether you can capture sys.dm_os_waiting_tasks during that single second of slowness. If you suspect it's IO, have you spoken to your system admin to see whether there are any scheduled tasks that run every four minutes?
John
April 1, 2016 at 9:35 am
I've a lot of writelog waits. I've seen running this query:
WITH Waits AS
(SELECT wait_type, wait_time_ms / 1000. AS wait_time_s,
100. * wait_time_ms / SUM(wait_time_ms) OVER() AS pct,
ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS rn
FROM sys.dm_os_wait_stats
WHERE wait_type NOT IN( 'SLEEP_TASK', 'BROKER_TASK_STOP',
'SQLTRACE_BUFFER_FLUSH', 'CLR_AUTO_EVENT', 'CLR_MANUAL_EVENT',
'LAZYWRITER_SLEEP')) -- filter out additional irrelevant waits
SELECT W1.wait_type,
CAST(W1.wait_time_s AS DECIMAL(12, 2)) AS wait_time_s,
CAST(W1.pct AS DECIMAL(12, 2)) AS pct,
CAST(SUM(W2.pct) AS DECIMAL(12, 2)) AS running_pct
FROM Waits AS W1
INNER JOIN Waits AS W2
ON W2.rn <= W1.rn
GROUP BY W1.rn, W1.wait_type, W1.wait_time_s, W1.pct
HAVING SUM(W2.pct) - W1.pct < 95;
this is the result
WRITELOG20604758.7715.8115.81
XE_TIMER_EVENT10382008.337.9723.78
REQUEST_FOR_DEADLOCK_SEARCH10381684.647.9731.75
XE_DISPATCHER_WAIT10380443.217.9739.71
ONDEMAND_TASK_QUEUE10374754.687.9647.67
BROKER_EVENTHANDLER10336495.207.9355.60
FT_IFTS_SCHEDULER_IDLE_WAIT10296174.047.9063.51
WAITFOR10243021.577.8671.37
LOGMGR_QUEUE10207724.787.8379.20
CHECKPOINT_QUEUE9856517.917.5686.76
BROKER_TO_FLUSH5191021.823.9890.75
IO_COMPLETION2323702.871.7892.53
ASYNC_NETWORK_IO1852131.581.4293.95
SQLTRACE_LOCK1151670.040.8894.83
BACKUPIO1097395.760.8495.68
April 1, 2016 at 9:42 am
Good. Is that normal? In other words, do you see those WRITELOG waits all the time, or only while the system is running slow?
John
April 4, 2016 at 1:33 am
These are total waits time so writelog is always to the top. How can i monitor real time non cumulative waits time?
April 4, 2016 at 1:54 am
I've seen with perfmon, at the time we have the problems, we also have a peak of disk/writes on disk where is located the log...
April 4, 2016 at 2:18 am
andrea.dimaio (4/4/2016)
These are total waits time so writelog is always to the top. How can i monitor real time non cumulative waits time?
Since they're cumulative since SQL Server started, you'll need to subtract one set of figures from the next in order to get the numbers for the period you're interested in. Try trapping them every five seconds and see whether they look any different for the periods in which you have your slow-downs. Once you've gathered enough information, stop capturing, or at least reduce the frequency of capture.
andrea.dimaio (4/4/2016)
I've seen with perfmon, at the time we have the problems, we also have a peak of disk/writes on disk where is located the log...
Do you have anything else other than transaction log files on that disk? If not, it sounds as if some process is running every four minutes and doing a lot of writing to your database(s). Is there a SQL Server Agent job with such a schedule? Are there any Windows scheduled tasks? If not, you'll need to do some detective work and find out what is connecting every four minutes and from where, and what it's doing.
John
April 4, 2016 at 2:25 am
It could be some settings relative to checkpoints? It's very strange! Every database have the same problem with log disk. Exactly every 4 minutes!
April 4, 2016 at 9:25 am
Now i've checked perfmon counter log bytes flushed/sec and i've seen that when the mistrious event happens,
this counter GO DOWN. So it means that :
- we have an external process that generate I/O every 4 minutes (it could be a windows process??)
- when this process is active, sql server can't write flush log on disk so generate WRITELOG wait and slow performance
- when process ends everything comeback normal
Do u think is a reasonable explanation?
April 4, 2016 at 11:14 am
Possibly, but SQL Server isn't going to flush the log in a clockwork, every four minutes, fashion. So I can see how external I/O issues can lead to the log flush problem, yes. I don't see how it equates to every four minutes exactly within SQL Server. I still think some query is being run every four minutes on the nose. Have you monitored using trace or exevents?
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
Viewing 15 posts - 1 through 15 (of 19 total)
You must be logged in to reply to this topic. Login to reply