3

We have a third-party Microsoft Access application that uses SQL Server 2012 as its data store. It is a well known issue that Access often does not tell SQL Server that it has received the results of a query, causing sessions to sit in ASYNC_NETWORK_IO wait for minutes or even hours although the application screen displays the result of the query almost instantly. In some cases, this can cause blocking. I want to find sessions that are in that state for a long period of time. Eventually, I may want to create a procedure that will automatically kill them.

For each session that is currently in an ASYNC_NETWORK_IO wait, I want to find out how long it has been waiting. However, dm_exec_requests.wait_time is never as high as 2,000 even though the difference between GETDATE() and last_request_end_time is much longer. last_request_end_time equals GETDATE() minus total_elapsed_time (CalculatedStartTime in the query below) if both are rounded to the nearest second. This is also true of dm_exec_sessions.start_time and dm_exec_requests.last_request_end_time.

In the results of this query:

SELECT  SPID            = s.session_id
        ,Program        = s.[program_name]
        ,StartTime      = r.start_time
        ,ElapsedTime    = CONVERT(TIME, DATEADD(SECOND, DATEDIFF(SECOND, r.start_time, GETDATE()), 0), 114)
        ,s.last_request_end_time
        ,r.wait_time
        ,CalculatedStartTime = DATEADD(MILLISECOND, -r.total_elapsed_time, GETDATE())
  FROM  sys.dm_exec_sessions s
        JOIN sys.dm_exec_requests r ON s.session_id = r.session_id
 WHERE  s.open_transaction_count    = 0
   AND  r.[status]                  = 'suspended'
   AND  r.wait_type                 = 'ASYNC_NETWORK_IO'
   AND  r.last_wait_type            = 'ASYNC_NETWORK_IO'
   AND  r.command                   = 'SELECT'
   AND  r.blocking_session_id       = 0
   AND  r.total_elapsed_time        > 10000 -- 10 seconds
 ORDER BY r.wait_time DESC

I must be misunderstanding the definition of some of these DMV columns. Note that in the result, row 9 shows a wait_time of only 629 ms, yet the ElapsedTime (time since the last_request_end_time) is over 28 minutes:

Typical result

How can I get the results I intend (a row for each session_id that shows how long it has been waiting on ASYNC_NETWORK_IO)?

  • have a look at sp_whoisactive. You can even log that to a table as well. Also, In some cases, this can cause blocking. -> You can set up event notification for blocking and then perform the action you need to do. – Kin Shah Sep 2 '15 at 20:25
  • 2
    Books Online for sys.dm_exec_requests.wait_time says "If the request is currently blocked, this column returns the duration in milliseconds, of the current wait. Is not nullable." Therefore, you are seeing an elapsed time of 28 minutes, and the last wait (not sum of all waits) is 629ms. Paul Randal has a nice blog post on capturing wait stats over a period of time that may be useful: sqlskills.com/blogs/paul/capturing-wait-statistics-period-time – Geoff Patterson Sep 2 '15 at 20:45
  • @Kin, sp_whoisactive is a wonderful thing for diagnostics, but way too heavyweight for what I need, which has to run pretty much continuously in a production environment. I took a look to see if I could hack it down to just what I needed, but that's a lot of complex code! – Mark Freeman Sep 3 '15 at 19:22
  • @Geoff Patterson: Paul's code only captures aggregate waits without any link to the sessions. It's great to find out what the most significant waits are for an instance, but not applicable to my problem. His approach doesn't lend itself well to adaptation to a continuous monitoring situation like mine, as he captures to two temp tables and then compares the results. I appreciate your taking the time to comment though. – Mark Freeman Sep 3 '15 at 19:32
  • @Mark: Fair enough, it's true that the "wait stats over a period of time" would require you to create a copy of your server if you wanted to completely isolate this specific workload. And that probably isn't feasible :) Paul does have another post about using extended events to capture the wait stats for a single process. I'll include the link here just in case that's something you didn't come across previously and is helpful: sqlskills.com/blogs/paul/… – Geoff Patterson Sep 3 '15 at 20:30
2

I see a lot of this from MS Office apps as well.

What is probably happening is that there are multiple ASYNC_NETWORK_IO waits per request while the clients slowly fetch and acknowledge subsets of the result set. Multiple wait events per request would explain why the current wait time is lower than the time elapsed since the last request ended. As Geoff mentioned, wait_time is only the time spent in the current wait event, not the total time the session has spent waiting.

Someone more familiar with the relevant client libraries and protocols could probably confirm whether this behavior is expected. You could probably get more detail on the internals with an extended event session capturing callstacks combined with a network packet capture, but I'm not sure that I'd want to do that in production.

The following extended event session would at least help you confirm that there are multiple ASYNC_NETWORK_IO waits occurring per query:

CREATE EVENT SESSION [async_network_io_waits] ON SERVER 
ADD EVENT sqlos.wait_info(
    ACTION(sqlserver.client_app_name,
      sqlserver.client_hostname,
      sqlserver.client_pid,
      sqlserver.database_id,
      sqlserver.database_name,
      sqlserver.server_principal_name,
      sqlserver.session_id,
      sqlserver.sql_text,
      sqlserver.username)
    --ASYNC_NETWORK_IO waits
    --See SELECT * FROM sys.dm_xe_map_values WHERE map_value = '%NETWORK_IO%';
    WHERE (([wait_type]=(99)) 
      -- Waits of more than 100 ms only
      AND [duration]>(100)
      AND ([sqlserver].[database_id]>(4)) 
      AND ([sqlserver].[database_id]<>(32767))))
-- Change the path to something reasonable
-- Up to 4 128MB files
ADD TARGET package0.event_file(SET filename=N'C:\temp\async_network_io_waits.xel',
  max_file_size=(128),
  max_rollover_files=(4))
WITH (MAX_MEMORY=16384 KB,EVENT_RETENTION_MODE=ALLOW_MULTIPLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=300 SECONDS)
GO
ALTER EVENT SESSION async_network_io_waits ON SERVER STATE=START;

If you run something like SELECT * FROM BigTable UNION ALL SELECT * FROM BigTable ... in SSMS you'll see the EE session showing multiple ASYNC_NETWORK_IO events firing for the same query. You might need to change the duration predicate in the EE session to something much lower to capture that in a test scenario with SSMS (again, not something I'd want to do in prod).

I don't have SQL Server 2012 around right now, so I can't test this on the same version you're using.

Extended event sessions can have performance overhead, so I'd probably filter that session more restrictively if I used it in production.

What I would probably monitor for in your situation (using a modified version of your query, not the EE session) is a large difference between the current time and last_request_end_time where the current wait type is ASYNC_NETWORK_IO. I'd probably want to gather data about what is being matched for a long while before automatically killing anything.

I also like the suggestion about exploring dumping the output of sp_WhoIsActive to a table and have had good success with that approach to troubleshooting issues generally.

  • The application does things like SELECT SKU FROM Inventory ORDER BY SKU to populate drop-downs and other such horrors. If we have 20,000 SKUs and the user picks one of the first SKUs in the list, Access will never fetch the rest of the rows and the session will just sit in ASYNC_NETWORK_IO for a long, long time. I want to kill the sessions that seem to have received all the results they are really ever going to fetch, as they end up blocking other users. The application was designed for 10 users. We have 200. My solution needs to run in production every 5 seconds, so I need light weight. – Mark Freeman Sep 3 '15 at 19:19
  • Then I would probably look for queries where there is a large difference between the current time and last_request_end_time where the current wait type is ASYNC_NETWORK_IO. – James L Sep 3 '15 at 19:30
  • So you're thinking that I should just ignore wait_time altogether, as it is only measuring a small part of the consecutive wait for a session? I want to be sure that DATEDIFF(SECOND, last_request_end_time, GETDATE()) will really get me the time since the last subset of the result set data was requested by the application. I can't find a definitive reference for that. BOL is a bit vague: "Time of the last completion of a request on the session." could be interpreted as request means the last subset or request means the entire statement. – Mark Freeman Sep 3 '15 at 19:45
  • I probably would, since it can't show the cumulative time for lots of fairly short back-to-back waits, or maybe you could combine it with another condition like wait_time > 1000 AND wait_type = 'ASYNC_NETWORK_IO'. Maybe you could log what your query is capturing for a while to see how many false-positives it picks up before you start automatically killing queries? – James L Sep 3 '15 at 19:55
  • There are probably some oddities with last_request_end_time to watch out for -- one example here. – James L Sep 3 '15 at 19:57

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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