Sample Header Ad - 728x90

Stored procedure times out despite very low cpu_time and logical reads/writes

2 votes
1 answer
558 views
I'm developing a service locally that uses SQL Server Express as a database. I'm seeing strange behavior where a stored procedure is executing several times in a row (with different parameters), and after a few successful calls that take ~1 sec each, it starts timing out. The rpc_completed events show the following info: | cpu_time | logical_reads | duration | result | | --------:| -------------:| --------:|:------ | | 984000 | 15244 | 1048445 | OK | | 63000 | 8543 | 75841 | OK | | 531000 | 1782 | 30036796 | Abort | | 0 | 2 | 30003296 | Abort | | 15000 | 820 | 29995839 | Abort | | 0 | 2 | 30010495 | Abort | The four aborted events were retries of the exact same command + parameters. There are several odd things going on here: - cpu_time is always under 1 sec, even when duration jumps to 30 sec - two aborted events show 0 cpu_time and only 2 logical reads (should be thousands) This is just a simple SQL Express instance running on a development machine with nothing else going on. The entire database is only a few MB, so it's hard to image any of these commands being even mildly expensive. So I'm not sure why the server suddenly starts timing out on these commands (while apparently doing almost no work). Any idea what's going on here? **UPDATE 1:** - I ran the failed command a bit later from a query window and it executed successfully in ..." StatementType="SELECT" QueryHash="0x358148098B8FEF90" QueryPlanHash="0xF78E3AAD5E94ED14" RetrievedFromCache="true" SecurityPolicyApplied="false"> ... --> ... --> ``` I can see there's a small (269 ms) ASYNC_NETWORK_IO wait, probably just SSMS being a bit slow pulling/displaying the query results, but I don't see where the other 14 seconds came from. Query elapsed time in the actual plan is only 375 ms, while the connection elapsed time 15 sec. **UPDATE 3:** I checked sys.dm_exec_session_wait_stats for info on the SPID for the above execution (63), and got these numbers: |session_id|wait_type|waiting_tasks_count|wait_time_ms|max_wait_time_ms|signal_wait_time_ms| |--|--|--|--|--|--| |63|PAGELATCH_SH|2|0|0|0| |63|PAGELATCH_EX|4|0|0|0| |63|SOS_SCHEDULER_YIELD|194|1|0|1| |63|MEMORY_ALLOCATION_EXT|9189|21|3|0| |63|RESERVED_MEMORY_ALLOCATION_EXT|390|0|0|0| |63|**ASYNC_NETWORK_IO**|**219**|**13787**|**1307**|**8**| Looks like I found the missing 14 sec for the manual execution from SSMS (not sure why this wasn't mentioned in the actual query plan WaitStats), but I'm not sure if the original timeouts when the service was trying to execute this command had the same cause. I'm suspicious of some obscure SQL Server Express limit being the cause, but I can't find any limits that looks relevant. **UPDATE 4:** Red herring. Looks like the ~15 sec execution time in SSMS is just due to requesting the actual execution plan. Happens every time. Disable that option and the execution time is consistently < 1 sec.
Asked by Bob Meyers (121 rep)
Feb 13, 2023, 04:31 AM
Last activity: Feb 13, 2023, 05:02 PM