none
Strange one-second delay with TCPConnections to localhost. RRS feed

  • Question

  • We use SharpSVN to programmatically access SVN repositories. Now we have the problem that the access to local repositories via svn:// or http:// urls is very slow - every access needs at least one second, and our app needs to fetch a bunch of properties and directory listings.

    We could reproduce the problem on two different machines, both are Windows 7 32 bit and are in the same domain. The SVN servers are VisualSVN 2.1.9 for http:// urls and the CollabNet 1.6.17 for svn:// urls. It appears for connections via "localhost" and via the host name. It appears in our C# application using SharpSVN, as well as a small SharpSVN testbed app using IronPython and when calling the SharpSvn svn.exe command.

    This problem does not happen when accessing when accessing remote repositories (Both a linux and a windows XP server) - here, each access is between 0.01 and 0.08 secs, which is expected due to network latency. The Problem also does not happen when acessing the local repositories via file:// urls or when accessing the repositories via "native" svn command line tools from CollabNet.

    With further testing, I found out that this limit also applies when connecting via a small C# test program using System.Net.Sockets.TcpClient:

    Server:

    using System;
    using System.IO;
    using System.Net;
    using System.Net.Sockets;
    
    namespace TcpSpeedServer
    {
      class Program
      {
        public static void Main()
        {
          Int32 port = 47011;
          IPAddress localAddr = IPAddress.Parse("127.0.0.1");
    
          var server = new TcpListener(localAddr, port);
          server.Start();
    
          Console.WriteLine("Listening on {0} : {1}", localAddr, port);
    
          ulong count = 0;
          // Enter the listening loop.
          while(true)
          {
            using (var client = server.AcceptTcpClient()) {
              Console.WriteLine("Connected: {0} {1}!", count, client.Client.RemoteEndPoint);
              count += 1;
    
              using (var stream = client.GetStream()) {
                using (StreamWriter writer = new StreamWriter(stream))
                  using (StreamReader reader = new StreamReader(stream))
                {
                  string query = reader.ReadLine();
                  writer.WriteLine("GET / HTTP/1.0");
                  writer.WriteLine();
                  writer.Flush();
                }
              }
            }
          }
        }
      }
    }
    

    Client:

    using System;
    using System.Collections.Generic;
    using System.IO;
    using System.Net.Sockets;
    using System.Threading;
    
    namespace TcpSpeedTest
    {
      class Program
      {
        const bool ASYNC = false;
        static DateTime s_now;
        public static void Main(string[] args)
        {
          var liste = new List<object>();
          s_now = DateTime.Now;
          for (int i=0; i < 100; i += 1) {
            if (ASYNC)
              ThreadPool.QueueUserWorkItem(connect, i);        
            else
              connect(i);
          }
    
          Console.WriteLine("outer: " + (DateTime.Now - s_now));
          Console.ReadLine();
        }
    
        private static void connect(object i)
        {
          DateTime now = DateTime.Now;
    
          using (TcpClient client = new TcpClient("localhost", 47011))
          {
            var stream = client.GetStream();
            using (StreamWriter writer = new StreamWriter(stream))
              using (StreamReader reader = new StreamReader(stream))
            {
              writer.WriteLine("GET / HTTP/1.0");
              writer.WriteLine();
              writer.Flush();
              string result = reader.ReadLine();
            }
          }
          Console.WriteLine(string.Format("inner: {0} - {1} - {2}", i, DateTime.Now - now, DateTime.Now - s_now));
        }
      }
    }
    


    So this problem seems not to be subversion specific.

    I also tested running the program using Mono 2.10 for windows - as soon as the client runs under mono, the delays disappear.

    Now my question is: Has .NET some built-in limit which only applies to localhost connections? And how can I programmatically suppress that limit?



    Thursday, July 14, 2011 8:23 AM

Answers

  • It is actually documented now that I knew what to look for.

    http://msdn.microsoft.com/en-us/library/115ytk56.aspx

    "If IPv6 is enabled and the TcpClient(String, Int32) method is called to connect to a host that resolves to both IPv6 and IPv4 addresses, the connection to the IPv6 address will be attempted first before the IPv4 address. This may have the effect of delaying the time to establish the connection if the host is not listening on the IPv6 address."

    Since the documentation for Connect(string, int) says the same that method is the one not working as documented.
    • Marked as answer by MarkusSchaber Friday, July 15, 2011 12:59 PM
    Friday, July 15, 2011 9:02 AM
    Moderator

All replies

  • I can confirm your results. I rewrote the code a bit and managed to get good performance again. 

          using (TcpClient client = new TcpClient())
          {
            client.Connect("localhost", 47011);
            // ...
            client.Close();
          }

    Does this change also work better for you?

    I will see if the answer to why is in the MSIL.

     

    Thursday, July 14, 2011 9:51 AM
    Moderator
  • Hi, Andreas,

    Yes, this change works better for me. But I think we will have to dig for the reason of this behaviour, as I'm not shure whether I can apply a similar change to the internals of SharpSVN.

    Thanks,
    Markus

    Thursday, July 14, 2011 11:22 AM
  • SharpSVN is open source so nothing stopping you from changing it at least.

    I enabled logging of System.Net and noticed that the version that takes one second gets that server refused connection. Not sure why but I would guess the timeout is 1 second.

    http://msdn.microsoft.com/en-us/library/bb203855(BTS.70).aspx

    Maybe debug into the framework will give info why.

    http://blogs.msdn.com/b/sburke/archive/2008/01/16/configuring-visual-studio-to-debug-net-framework-source-code.aspx

     EDIT: Too bad I don't get the stepping to work.

    Refused attempt:

    System.Net.Sockets Verbose: 0 : [5560] TcpClient#39785641::Connect(localhost)
    System.Net.Sockets Verbose: 0 : [5560] DNS::GetHostAddresses(localhost)
    System.Net.Sockets Verbose: 0 : [5560] DNS::GetHostByName(localhost)
    System.Net.Sockets Verbose: 0 : [5560] Exiting DNS::GetHostByName()  -> IPHostEntry#45523402
    System.Net.Sockets Verbose: 0 : [5560] Exiting DNS::GetHostAddresses()  -> IPAddress[]#35287174
    System.Net.Sockets Verbose: 0 : [5560] Socket#44419000::Socket(InterNetwork#2)
    System.Net.Sockets Verbose: 0 : [5560] Exiting Socket#44419000::Socket()
    System.Net.Sockets Verbose: 0 : [5560] Socket#52697953::Socket(InterNetworkV6#23)
    System.Net.Sockets Verbose: 0 : [5560] Exiting Socket#52697953::Socket()
    System.Net.Sockets Verbose: 0 : [5560] Socket#52697953::Connect(::1#609340884)
    System.Net.Sockets Verbose: 0 : [5560] Socket#52697953::Connect([::1]:47011#609319543)
    System.Net.Sockets Error: 0 : [5560] Exception in the Socket#52697953::Connect - No connection could be made because the target machine actively refused it [::1]:47011
    System.Net.Sockets Verbose: 0 : [5560] Socket#44419000::Connect(1#16777343)
    System.Net.Sockets Verbose: 0 : [5560] Socket#44419000::Connect(1:47011#16824284)
    System.Net.Sockets Information: 0 : [5560] Socket#44419000 - Created connection from 127.0.0.1:57417 to 127.0.0.1:47011.
    System.Net.Sockets Verbose: 0 : [3488] Socket#7307551::Socket()
    System.Net.Sockets Verbose: 0 : [5560] Exiting Socket#44419000::Connect()
    System.Net.Sockets Verbose: 0 : [3488] Exiting Socket#7307551::Socket()
    System.Net.Sockets Verbose: 0 : [5560] Exiting Socket#44419000::Connect()
    System.Net.Sockets Information: 0 : [3488] Socket#7307551 - Accepted connection from 127.0.0.1:57417 to 127.0.0.1:47011.

    Not refused attempt:

    System.Net.Sockets Verbose: 0 : [5560] TcpClient#22597652::Connect(localhost)
    System.Net.Sockets Verbose: 0 : [5560] DNS::GetHostAddresses(localhost)
    System.Net.Sockets Verbose: 0 : [5560] DNS::GetHostByName(localhost)
    System.Net.Sockets Verbose: 0 : [5560] Exiting DNS::GetHostByName()  -> IPHostEntry#59109011
    System.Net.Sockets Verbose: 0 : [5560] Exiting DNS::GetHostAddresses()  -> IPAddress[]#42659827
    System.Net.Sockets Verbose: 0 : [5560] TcpClient#22597652::Connect(1:47011#16824284)
    System.Net.Sockets Verbose: 0 : [5560] Socket#10261382::Connect(1:47011#16824284)
    System.Net.Sockets Information: 0 : [5560] Socket#10261382 - Created connection from 127.0.0.1:57418 to 127.0.0.1:47011.
    System.Net.Sockets Verbose: 0 : [5560] Exiting Socket#10261382::Connect()
    System.Net.Sockets Verbose: 0 : [5560] Exiting TcpClient#22597652::Connect()
    System.Net.Sockets Verbose: 0 : [5560] Exiting TcpClient#22597652::Connect()
    System.Net.Sockets Verbose: 0 : [3488] Socket#30018436::Socket()
    System.Net.Sockets Verbose: 0 : [3488] Exiting Socket#30018436::Socket()
    System.Net.Sockets Information: 0 : [3488] Socket#30018436 - Accepted connection from 127.0.0.1:57418 to 127.0.0.1:47011.

    Thursday, July 14, 2011 12:37 PM
    Moderator
  • Now I know what the difference between

    new TcpClient("localhost", 5000); // Slow

    and

    (new TcpClient()).Connect("localhost", 5000); // Fast

    In the first case a private initialize method isn't called and it makes the whole difference.

    The reason why it is slow is because it tries IPv6 first and fails and then tries IPv4 and succeeds, when it is fast it tries IPv4 first. The reason it decides IPv4 is because what happens in the initialize method.



    Thursday, July 14, 2011 2:25 PM
    Moderator
  • It is actually documented now that I knew what to look for.

    http://msdn.microsoft.com/en-us/library/115ytk56.aspx

    "If IPv6 is enabled and the TcpClient(String, Int32) method is called to connect to a host that resolves to both IPv6 and IPv4 addresses, the connection to the IPv6 address will be attempted first before the IPv4 address. This may have the effect of delaying the time to establish the connection if the host is not listening on the IPv6 address."

    Since the documentation for Connect(string, int) says the same that method is the one not working as documented.
    • Marked as answer by MarkusSchaber Friday, July 15, 2011 12:59 PM
    Friday, July 15, 2011 9:02 AM
    Moderator
  • Hi, Andreas,

    Thanks for the analysis!

    I just tried: new TcpClient("127.0.0.1", 47011) also results in the fast calls. The same works for SharpSVN - giving the IP address and it works fast.

    Now I just have to find a way to convince SharpSVN to prefer IPV4 when I pass a host name, without breaking the hosts actually supporting IPV6.

    (AFAICS, SharpSVN internally uses native code based on APR instead of TCPClient, so it is not straight forward.)

    Although my problem is not finally solved yet, I mark your last message as answer. It brought enough light and insight about things I never would have found on my own, and now I know in which direction to investigate further.

    Friday, July 15, 2011 12:42 PM