none
Extra ACK packet delaying each query with ~500 ms on Windows 8 RRS feed

  • Question

  • Hi!

    I've recently installed Windows 8 Enterprise on my box and now have a weird overhead when executing SQL queries against servers over TCP. Anything takes 500 ms consistently + whatever execution time it needs.

    I installed SS 2008 with SP2 first, but have now uninstalled client tools and server (just kept BIDS), and replaced it with 2012. No help in that, though.

    I traced the queries with WireShark, and see that my box sends an extra packet that other boxes (and my own win7 on same Box) doesn't send.

    Here's the test code I run:

    for (var i = 0; i < 10; i++)
    {
    	using (var cn = new OleDbConnection(connectionString))
    	{
    		openConnStart = DateTime.Now;
    		cn.Open();
    		openConnEnd = DateTime.Now;
    		using (var cmd = new OleDbCommand("SELECT @@VERSION", cn))
    		{
    			queryStart = DateTime.Now;
    			var result = cmd.ExecuteScalar();
    			queryEnd = DateTime.Now;
    		}
    	}
    	Console.WriteLine(@"{0,10:ss.fff}{1,1...") // more..
    }
    
     

    Output:
    cns = start open conn, cne = end open, cd = open conn duration
    qs = query start, qe = query end, qd = query duration

           cns       cne        cd        qs        qe        qd
        31.011    33.835    02.823    33.835    34.381    00.546
        34.381    34.381    00.000    34.381    34.912    00.530
        34.912    34.912    00.000    34.912    35.442    00.530
        35.442    35.442    00.000    35.442    35.972    00.530
        35.972    35.972    00.000    35.972    36.503    00.530
        36.503    36.503    00.000    36.503    37.033    00.530
        37.033    37.033    00.000    37.033    37.579    00.546
        37.579    37.579    00.000    37.579    38.110    00.530
        38.110    38.110    00.000    38.110    38.640    00.530
        38.640    38.640    00.000    38.640    39.170    00.530

    All other boxes have -500 ms duration. :)

    Here's my WireShark trace:

    "No.","Time","Source","Destination","Protocol","Length","Info","Delta"
    "16","2.247510000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=588 Ack=1109 Win=65132 Len=62","0.515033000"
    "17","2.272463000","172.18.166.116","10.29.84.127","TCP","474","sslp > 50853 [PSH, ACK] Seq=1109 Ack=650 Win=63591 Len=420","0.024953000"
    "18","2.325307000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=650 Ack=1529 Win=66240 Len=0","0.052844000"
    "19","2.779645000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=650 Ack=1529 Win=66240 Len=62","0.454338000"
    "20","2.805107000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=1529 Ack=712 Win=63529 Len=426","0.025462000"
    "21","2.855678000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=712 Ack=1955 Win=65812 Len=0","0.050571000"
    "22","3.309139000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=712 Ack=1955 Win=65812 Len=62","0.453461000"
    "23","3.334462000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=1955 Ack=774 Win=63467 Len=426","0.025323000"
    "24","3.386110000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=774 Ack=2381 Win=65388 Len=0","0.051648000"
    "25","3.839549000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=774 Ack=2381 Win=65388 Len=62","0.453439000"
    "26","3.864797000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=2381 Ack=836 Win=63405 Len=426","0.025248000"
    "27","3.916495000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=836 Ack=2807 Win=64960 Len=0","0.051698000"
    "28","4.369916000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=836 Ack=2807 Win=64960 Len=62","0.453421000"
    "29","4.395132000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=2807 Ack=898 Win=63343 Len=426","0.025216000"
    "30","4.446865000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=898 Ack=3233 Win=66240 Len=0","0.051733000"
    "31","4.900249000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=898 Ack=3233 Win=66240 Len=62","0.453384000"
    "32","4.925036000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=3233 Ack=960 Win=63281 Len=426","0.024787000"
    "33","4.977390000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=960 Ack=3659 Win=65812 Len=0","0.052354000"
    "34","5.430798000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=960 Ack=3659 Win=65812 Len=62","0.453408000"
    "35","5.455697000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=3659 Ack=1022 Win=63219 Len=426","0.024899000"
    "36","5.507647000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=1022 Ack=4085 Win=65388 Len=0","0.051950000"
    "37","5.961084000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=1022 Ack=4085 Win=65388 Len=62","0.453437000"
    "38","5.985919000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=4085 Ack=1084 Win=63157 Len=426","0.024835000"
    "39","6.038096000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=1084 Ack=4511 Win=64960 Len=0","0.052177000"
    "40","6.491659000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=1084 Ack=4511 Win=64960 Len=62","0.453563000"
    "41","6.516707000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=4511 Ack=1146 Win=63095 Len=426","0.025048000"
    "42","6.568557000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=1146 Ack=4937 Win=66240 Len=0","0.051850000"
    "43","7.023561000","10.29.84.127","172.18.166.116","TCP","116","50853 > sslp [PSH, ACK] Seq=1146 Ack=4937 Win=66240 Len=62","0.455004000"
    "44","7.048661000","172.18.166.116","10.29.84.127","TCP","480","sslp > 50853 [PSH, ACK] Seq=4937 Ack=1208 Win=63033 Len=426","0.025100000"
    "45","7.098987000","10.29.84.127","172.18.166.116","TCP","54","50853 > sslp [ACK] Seq=1208 Ack=5363 Win=65812 Len=0","0.050326000"
    

    Each third packet is only sent by my box, and obviously hangs everything for ~500 ms.
    It's an ACK for the packet from the server.

    Here's a trace from another (Win7) Box:

    "No.","Time","Source","Destination","Protocol","Length","Info","Delta"
    "12","0.168784000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=566 Ack=1109 Win=65024 Len=62","0.031770000"
    "13","0.193689000","172.18.166.116","10.29.84.125","TCP","474","sslp > 51756 [PSH, ACK] Seq=1109 Ack=628 Win=63613 Len=420","0.024905000"
    "14","0.210204000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=628 Ack=1529 Win=66048 Len=62","0.016515000"
    "15","0.234943000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=1529 Ack=690 Win=63551 Len=426","0.024739000"
    "16","0.235864000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=690 Ack=1955 Win=65792 Len=62","0.000921000"
    "17","0.260477000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=1955 Ack=752 Win=63489 Len=426","0.024613000"
    "18","0.261342000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=752 Ack=2381 Win=65280 Len=62","0.000865000"
    "19","0.286027000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=2381 Ack=814 Win=63427 Len=426","0.024685000"
    "20","0.286775000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=814 Ack=2807 Win=64768 Len=62","0.000748000"
    "21","0.311569000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=2807 Ack=876 Win=63365 Len=426","0.024794000"
    "22","0.312462000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=876 Ack=3233 Win=66048 Len=62","0.000893000"
    "23","0.337217000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=3233 Ack=938 Win=63303 Len=426","0.024755000"
    "24","0.338216000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=938 Ack=3659 Win=65792 Len=62","0.000999000"
    "25","0.362875000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=3659 Ack=1000 Win=63241 Len=426","0.024659000"
    "26","0.363619000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=1000 Ack=4085 Win=65280 Len=62","0.000744000"
    "27","0.388207000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=4085 Ack=1062 Win=63179 Len=426","0.024588000"
    "28","0.388994000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=1062 Ack=4511 Win=64768 Len=62","0.000787000"
    "29","0.414061000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=4511 Ack=1124 Win=63117 Len=426","0.025067000"
    "30","0.414767000","10.29.84.125","172.18.166.116","TCP","116","51756 > sslp [PSH, ACK] Seq=1124 Ack=4937 Win=66048 Len=62","0.000706000"
    "31","0.439419000","172.18.166.116","10.29.84.125","TCP","480","sslp > 51756 [PSH, ACK] Seq=4937 Ack=1186 Win=63055 Len=426","0.024652000"
    

    Goes without saying I'd really like to get rid of that dealy.
    I've tried several netsh options and several NIC configurations without Luck.

    Hope someone's able to help me. :)

    Lars-Erik


    Lars-Erik MCPD ASP.NET 2.0, MCTS ASP.NET 4.0

    Thursday, August 22, 2013 8:57 AM

Answers

  • Purp identified.

    It was Trend Micro Worry Free (!) Business Security.

    Upgraded it, and problem gone.

    Lars-Erik


    Lars-Erik MCPD ASP.NET 2.0, MCTS ASP.NET 4.0

    Wednesday, August 28, 2013 9:51 AM

All replies

  • First of all: Use a high resolution timer, e.g. the Stopwatch class.

    Then I'm currently not using Windows 8. So what SQL Server driver is used? The same as on your old box?

    Wireshark should be able to interpret TDS. Maybe this gives us more insight..

    Thursday, August 22, 2013 9:25 AM
  • I've tried SQLOLEDB.1, SQLNCLI10.1 and SQLNCLI11.1 using OleDbConnection, and no provider (Sql Server Native) with SqlConnection.

    Having high resolution on the time in my little test app has no obvious advantage as far as I can see. The point here is that there IS an extra dealy on my box, not how long it is. The Wireshark log also proves that my box does something extra.

    I have no idea how to interpret TDS, and if I did, how to resolve any issue I find. :(
    (Which netsh setting, which registry setting, which deep config value etc.)

    Any specific fields I should log?

    [edit] I was able to log TDS stuff also, but it doesn't help much. The ACK packet I have isn't connected to TDS, and TDS does no transaction, end message in both query and response.


    Lars-Erik MCPD ASP.NET 2.0, MCTS ASP.NET 4.0


    Thursday, August 22, 2013 9:33 AM
  • New "discovery"..

    In the "nice" WS trace, the queries are tagged as ACK for previous frame (response).
    In my WS trace, the queries are not tagged as ACK, even though they include the ACK bit.
    The extra packet I have is tagged as ACK to the response.

    Here's an example:

    (my trace)

    "19","2.949616000","10.29.84.127","172.18.166.116","TDS","116","SQL batch"
    "20","2.974706000","172.18.166.116","10.29.84.127","TDS","480","Response"
    "21","2.974793000","10.29.84.127","172.18.166.116","TCP","54","50457 > sslp [ACK] Seq=775 Ack=1955 Win=65792 Len=0"
    -- 21 is ack for 20

    -- 22 is not ack for 20, although ack bit is set
    "22","3.494747000","10.29.84.127","172.18.166.116","TDS","116","SQL batch"
    "23","3.520266000","172.18.166.116","10.29.84.127","TDS","480","Response"
    "24","3.520363000","10.29.84.127","172.18.166.116","TCP","54","50457 > sslp [ACK] Seq=837 Ack=2381 Win=65280 Len=0"

    (Nice trace)

    "20","0.286775000","10.29.84.125","172.18.166.116","TDS","116","SQL batch"
    "21","0.311569000","172.18.166.116","10.29.84.125","TDS","480","Response"
    -- 22 is ack for 21
    "22","0.312462000","10.29.84.125","172.18.166.116","TDS","116","SQL batch"
    "23","0.337217000","172.18.166.116","10.29.84.125","TDS","480","Response"

    Dunno where to go from here, though. :)

    [edit] Just to clarify - the SQL server this log is for runs on port 1750, not 1433 - hence SSLP instead of MS-SQL-S. Same behavior no matter which server, so never mind it. ;)


    Lars-Erik MCPD ASP.NET 2.0, MCTS ASP.NET 4.0


    • Edited by Lars-Erik Aabech Thursday, August 22, 2013 12:17 PM clarified port in log
    Thursday, August 22, 2013 10:34 AM
  • Purp identified.

    It was Trend Micro Worry Free (!) Business Security.

    Upgraded it, and problem gone.

    Lars-Erik


    Lars-Erik MCPD ASP.NET 2.0, MCTS ASP.NET 4.0

    Wednesday, August 28, 2013 9:51 AM