Why does a simple loop result in ASYNC_NETWORK_IO waits?

Question

The following T-SQL takes about 25 seconds on my machine with SSMS v17.9:

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+0xbb9

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 ASYNC_NETWORK_IOwaits when executed through SSMS? The only output that I appear to get from the client from this query execution is the "Commands completed successfully." message.

Answer 1

The documentation for 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<1> 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: