Sql-server – Understanding sys.dm_exec_query_stats execution_count vs creation_time

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 view returns one row for each cached stored procedure plan, and the lifetime of the row is as long as the stored procedure remains cached.

NOTE: An initial query of sys.dm_exec_procedure_stats might produce inaccurate results if there is a workload currently executing on the server. More accurate results may be determined by rerunning the query.

Resource

Is sp_recompile or WITH RECOMPILE being used? Those can cause the stored procedure to be removed. Also, it could be in regards to the name of the procedure. This answer talks about that.