gotchasqlMajor
Why does a simple loop result in ASYNC_NETWORK_IO waits?
Viewed 0 times
resultwhysimplewaitsloopasync_network_iodoes
Problem
The following T-SQL takes about 25 seconds on my machine with SSMS v17.9:
It accumulates 532 ms of
In addition, I can get the call stacks that occur right before the
Finally, I noticed that SSMS uses a surprising amount of CPU during the loop (about half a core on average). I'm unable to figure out what SSMS is doing during that time.
Why does a simple loop cause `ASYN
DECLARE @outer_loop INT = 0,
@big_string_for_u VARCHAR(8000);
SET NOCOUNT ON;
WHILE @outer_loop < 50000000
BEGIN
SET @big_string_for_u = 'ZZZZZZZZZZ';
SET @outer_loop = @outer_loop + 1;
END;It accumulates 532 ms of
ASYNC_NETWORK_IO waits according to both sys.dm_exec_session_wait_stats and sys.dm_os_wait_stats. The total wait time increases as the number of loop iterations increases. Using the wait_completed extended event I can see that the wait happens roughly every 43 ms with a few exceptions: In addition, I can get the call stacks that occur right before the
ASYNC_NETWORK_IO wait:sqldk.dll!SOS_DispatcherBase::GetTrack+0x7f6c
sqldk.dll!SOS_Scheduler::PromotePendingTask+0x204
sqldk.dll!SOS_Task::PostWait+0x5f
sqldk.dll!SOS_Scheduler::Suspend+0xb15
sqllang.dll!CSECCNGProvider::GetBCryptHandleFromAlgID+0xf6af
sqllang.dll!CSECCNGProvider::GetBCryptHandleFromAlgID+0xf44c
sqllang.dll!SNIPacketRelease+0xd63
sqllang.dll!SNIPacketRelease+0x2097
sqllang.dll!SNIPacketRelease+0x1f99
sqllang.dll!SNIPacketRelease+0x18fe
sqllang.dll!CAutoExecuteAsContext::Restore+0x52d
sqllang.dll!CSQLSource::Execute+0x151b
sqllang.dll!CSQLSource::Execute+0xe13
sqllang.dll!CSQLSource::Execute+0x474
sqllang.dll!SNIPacketRelease+0x165d
sqllang.dll!CValOdsRow::CValOdsRow+0xa92
sqllang.dll!CValOdsRow::CValOdsRow+0x883
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x15d
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x638
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x2ad
sqldk.dll!SystemThread::MakeMiniSOSThread+0xdf8
sqldk.dll!SystemThread::MakeMiniSOSThread+0xf00
sqldk.dll!SystemThread::MakeMiniSOSThread+0x667
sqldk.dll!SystemThread::MakeMiniSOSThread+0xbb9Finally, I noticed that SSMS uses a surprising amount of CPU during the loop (about half a core on average). I'm unable to figure out what SSMS is doing during that time.
Why does a simple loop cause `ASYN
Solution
The documentation for
You are not running the statements in a stored procedure, so SQL Server sends
Note the
-
A
-
For execution of SQL statements within stored procedures,
You will see a dramatic reduction in
You could also use
Example stack trace captured just as an
An example TDS packet as seen in the inline function
Which decodes to:
Ultimately, the number of
The worst client by far for this test was Azure Data Studio. It ran for almost 6 hours:
SET NOCOUNT says:SET NOCOUNT ON prevents the sending of DONE_IN_PROC messages to the client for each statement in a stored procedure. For stored procedures that contain several statements that do not return much actual data, or for procedures that contain Transact-SQL loops, setting SET NOCOUNT to ON can provide a significant performance boost, because network traffic is greatly reduced.You are not running the statements in a stored procedure, so SQL Server sends
DONE tokens (code 0xFD) to indicate the completion status of each SQL statement. These messages are deferred, and sent asynchronously when the network packet is full. When the client does not consume network packets quickly enough, eventually the buffers fill up, and the operation becomes blocking for SQL Server, generating the ASYNC_NETWORK_IO waits.Note the
DONE tokens are different from DONEINPROC (code 0xFF) as the documentation notes:-
A
DONE token is returned for each SQL statement in the SQL batch except variable declarations.-
For execution of SQL statements within stored procedures,
DONEPROC and DONEINPROC tokens are used in place of DONE tokens.You will see a dramatic reduction in
ASYNC_NETWORK_IO waits using:CREATE PROCEDURE #P AS
SET NOCOUNT ON;
DECLARE
@outer_loop integer = 0,
@big_string_for_u varchar(8000);
WHILE @outer_loop < 5000000
BEGIN
SET @big_string_for_u = 'ZZZZZZZZZZ';
SET @outer_loop = @outer_loop + 1;
END;
GO
EXECUTE dbo.#P;You could also use
sys.sp_executesql to achieve the same result.Example stack trace captured just as an
ASYNC_NETWORK_IO wait begins:An example TDS packet as seen in the inline function
sqllang!srv_completioncode_ex had the following 13 bytes:fd 01 00 c1 00 01 00 00 00 00 00 00 00
Which decodes to:
- TokenType = 0xfd
DONE_TOKEN
- Status = 0x0001
DONE_MORE
- CurCmd = 0x00c1 (193)
- DoneRowCount = 0x00000001 (1)
Ultimately, the number of
ASYNC_NETWORK_IO waits depends on the client and driver, and what it does, if anything, with all the DONE messages. Testing with a loop 1/10th of the size given in the question (5,000,000 loop iterations) I found SSMS ran for about 4 seconds with 200-300 ms of waits. sqlcmd ran for 2-3 seconds with single digit ms waits; osql around the same run time with around 10 ms of waits.The worst client by far for this test was Azure Data Studio. It ran for almost 6 hours:
Code Snippets
CREATE PROCEDURE #P AS
SET NOCOUNT ON;
DECLARE
@outer_loop integer = 0,
@big_string_for_u varchar(8000);
WHILE @outer_loop < 5000000
BEGIN
SET @big_string_for_u = 'ZZZZZZZZZZ';
SET @outer_loop = @outer_loop + 1;
END;
GO
EXECUTE dbo.#P;Context
StackExchange Database Administrators Q#232816, answer score: 37
Revisions (0)
No revisions yet.