Re: [go-nuts] net.Conn read slow ?

[Dave Cheney]

Hello,

Which operating system, which version of Go?

I guessing windows/32bit and go 1.0.3. 

Looking at your data, each packet is about 100ms apart which may point to nagle and/or delayed acks. 

As an aside your program is not correct and you may loose the last packet. The contract of io.Reader says you should always process the n bytes of data from the Read call before processing the error. 

Dave

On 29/12/2012, at 19:24, rahe...@gmail.com wrote:

Hi,

I am using net.Listen("tcp", addr) for a small server program which is to accept data and STORE it on the server.
On the client side, I have a c++ program and I have simply written 4096000 BYTES to the socket (connected to my server program)
The write on the client side finishes in less than a second.
When using the Read() funtions of the connection net.Conn, the read happens very slow.

Following is the Read() for loop :
      // Handle the reads

   var tbuf [81920]byte

      for {

        n, err := c.rwc.Read(tbuf[0:])

        // Was there an error in reading ?

        if err != nil {

            log.Printf("Could not read packet : %s", err.Error())

            break

        }

        log.Println(n)

    }

    return

c.rwc is of type net.Conn

The output of the above code is as follows :
2012/12/29 13:45:12 16384
2012/12/29 13:45:12 16018
2012/12/29 13:45:12 16384
2012/12/29 13:45:12 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:13 16016
2012/12/29 13:45:13 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:14 16384
2012/12/29 13:45:14 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:15 16016
2012/12/29 13:45:15 16384
2012/12/29 13:45:16 16016
2012/12/29 13:45:16 16384
2012/12/29 13:45:16 16016
2012/12/29 13:45:16 16384
2012/12/29 13:45:16 16016
2012/12/29 13:45:16 16384
2012/12/29 13:45:16 16016
2012/12/29 13:45:16 16384
2012/12/29 13:45:16 16016
2012/12/29 13:45:18 16384
2012/12/29 13:45:18 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:19 16016
2012/12/29 13:45:19 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:20 16384
2012/12/29 13:45:20 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:21 16016
2012/12/29 13:45:21 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:22 16384
2012/12/29 13:45:22 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:23 16384
2012/12/29 13:45:23 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:24 16016
2012/12/29 13:45:24 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:25 16016
2012/12/29 13:45:25 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:26 16384
2012/12/29 13:45:26 16016
2012/12/29 13:45:27 16384
2012/12/29 13:45:27 16016
2012/12/29 13:45:27 16384
2012/12/29 13:45:27 16016
2012/12/29 13:45:27 16384
2012/12/29 13:45:27 16016
2012/12/29 13:45:27 16384
2012/12/29 13:45:27 16016
2012/12/29 13:45:27 16384
2012/12/29 13:45:28 16016
2012/12/29 13:45:28 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:29 16016
2012/12/29 13:45:29 16384
2012/12/29 13:45:30 16016
2012/12/29 13:45:30 16384
2012/12/29 13:45:30 16016
2012/12/29 13:45:30 16384
2012/12/29 13:45:30 16016
2012/12/29 13:45:30 16384
2012/12/29 13:45:30 16016
2012/12/29 13:45:30 16384
2012/12/29 13:45:30 16016
2012/12/29 13:45:31 16384
2012/12/29 13:45:31 16016
2012/12/29 13:45:31 16384
2012/12/29 13:45:31 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:32 16016
2012/12/29 13:45:32 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:33 16016
2012/12/29 13:45:33 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:34 16016
2012/12/29 13:45:34 16384
2012/12/29 13:45:35 16016
2012/12/29 13:45:35 16384
2012/12/29 13:45:35 16016
2012/12/29 13:45:35 16384
2012/12/29 13:45:35 16016
2012/12/29 13:45:35 16384
2012/12/29 13:45:35 16016
2012/12/29 13:45:36 16384
2012/12/29 13:45:36 16016
2012/12/29 13:45:36 16384
2012/12/29 13:45:36 16016
2012/12/29 13:45:37 16384
2012/12/29 13:45:37 16016
2012/12/29 13:45:37 16384
2012/12/29 13:45:37 16016
2012/12/29 13:45:37 16384
2012/12/29 13:45:37 16016
2012/12/29 13:45:37 16384
2012/12/29 13:45:37 16016
2012/12/29 13:45:37 16384
2012/12/29 13:45:37 16016
2012/12/29 13:45:37 4048

As you can see the read operation is taking nearly 21-25 seconds to read 4096000 bytes, 
which is very slow as the server and the client are on the same computer.
Is the read operation wrong ? I am unable to understand why is this so slow ?

--
 
 

[Rémy Oudompheng]

On 2012/12/29 <rahe...@gmail.com> wrote:
>>> Which operating system, which version of Go?
>

> Win 7 64 Bit and Go 1.0.3

>
>
>>> Looking at your data, each packet is about 100ms apart which may point to
>>> nagle and/or delayed acks.
>

> I am a little new to this. Why would there be delayed ACKS ? and how can I
> improve this ?
> I would like speeds to touch atleast 10MB/s

>
>
>>> As an aside your program is not correct and you may loose the last
>>> packet. The contract of io.Reader says you should always process the n bytes
>>> of data from the Read call before processing the error.
>

> Are you saying I should check the error after doing something with the
> "tbuf" ? I guess you are referring to the io.EOF error.
> I checked that and the following is the changes :

>
> // Was there an error in reading ?
>
> if err != nil {
>

> if err != io.EOF {
>
> log.Printf("Could not read the Length of the Packet : %s",
> err.Error())
>
> break
>
> }
>
> }
>
>
> But the main issue is the slowness of the data.

Can you show the client code too?

Rémy.

[Raheel Gupta]

The client code is a simple loop :
for(int i = 1; i <= 1000; i++){

            // Was the login successful ?

            if(unconnected){

                qDebug() << socket->state();

                return;

            }

            socket->write("A 4096 BYTE string")           

            written++;

 }

[Nick Craig-Wood]

On 29/12/12 10:21, Raheel Gupta wrote:
> The client code is a simple loop :

> for(inti=1;i<=1000;i++){

> // Was the login successful ?
> if(unconnected){
> qDebug() << socket->state();
> return;
> }
> socket->write("A 4096 BYTE string")
> written++;
>
> }

Did something actually check the write was successful?

--
Nick Craig-Wood <ni...@craig-wood.com> -- http://www.craig-wood.com/nick

[Rémy Oudompheng]

Your source code extracts are not really helpful. You didn't explain
neither on the Go side, neither on the C++ side, where your connection
comes from. In your Go extract, the rwc thing could pretty well be a
ArtificiallySlowedDownReader, and same thing on the C++ side.

Did you investigate how to turn off delayed ACKs as mentioned by Dave ?

Rémy.

[Raheel Gupta]

>> You didn't explain  neither on the Go side, neither on the C++ side, where your connection comes from.

The Go side gets the connection from the net/http package connection.

I modified the net/http package function readRequest() in server.go as follows :
// Read next request from connection.

func (c *conn) readRequest() (w *response, err error) {

    if c.hijacked {

        return nil, ErrHijacked

    }

    c.lr.N = int64(c.server.maxHeaderBytes()) + 4096 /* bufio slop */

    var req *Request

    if req, err = ReadRequest(c.buf.Reader); err != nil {

        if err.Error() == "STOREDATA" {

            c.storedata()

        }

        if c.lr.N == 0 {

            return nil, errTooLarge

        }

        return nil, err

    }

    c.lr.N = noLimit

    req.RemoteAddr = c.remoteAddr

    req.TLS = c.tlsState

    w = new(response)

    w.conn = c

    w.req = req

    w.header = make(Header)

    w.contentLength = -1

    c.body = c.body[:0]

    return w, nil

}

// Function to handle the request of STOREDATA

func (c *conn) storedata() {

    // Is this a secure connection

    if c.tlsState == nil {

        fmt.Fprintf(c.rwc, "Connection not secure")

        return

    }

   var tbuf [81920]byte

   for {
        n, err := c.rwc.Read(tbuf[0:])

        // Was there an error in reading ?
        if err != nil {

            log.Printf("Could not read packet : %s", err.Error())
            break
        }

        log.Println(n)

    }
    return

}

On the C++ (client side) its a QSslSocket connection :
     QSslSocket * socket = new QSslSocket;
      socket->connectToHostEncrypted("127.0.0.1", 8080);
     
      // Wait for it to reach the encryted and connected state

    if (!socket->waitForEncrypted()) {

        qDebug() << "waitForEncrypted Error" << socket->errorString();

        return; // An error occured

    }

    // This is the Storedata request

    socket->write("STOREDATA\r\n");

       for(int i = 1; i <= 1000; i++){

            socket->write("A 4096 BYTE string")           

            written++;

    }

Apart from this, there is no other code.

>> Did something actually check the write was successful?

The writes are happening properly. It completes in less than a second.
Its just they are being read too slow. As posted in the first post. The data is received but its takes nearly 22-25 seconds.

>> Did you investigate how to turn off delayed ACKs as mentioned by Dave ?

I dont know how to do this. If you could shed some light on this, I would do it right away.

[Alexey Borzenkov]

Hi,

Are you sure your 40MB buffer is actually written in the underlying socket? Last I looked into Qt sources was a pretty long time, but I remember that data is usually read/written when you're back in event loop, so all that data may very well be in the internal buffer, and not on the wire. You should probably connect to encryptedBytesWritten(qint64) (see http://doc.qt.digia.com/qt/qsslsocket.html#encryptedBytesWritten) to find out how much data is actually written and how fast.

On Sat, Dec 29, 2012 at 12:24 PM, <rahe...@gmail.com> wrote:

Hi,

I am using net.Listen("tcp", addr) for a small server program which is to accept data and STORE it on the server.
On the client side, I have a c++ program and I have simply written 4096000 BYTES to the socket (connected to my server program)
The write on the client side finishes in less than a second.
When using the Read() funtions of the connection net.Conn, the read happens very slow.

Following is the Read() for loop :
      // Handle the reads

   var tbuf [81920]byte

      for {

        n, err := c.rwc.Read(tbuf[0:])

        // Was there an error in reading ?

        if err != nil {

            log.Printf("Could not read packet : %s", err.Error())

            break

        }

        log.Println(n)

    }

    return

c.rwc is of type net.Conn

--
 
 

[Kyle Lemons]

Why are you editing net/http?  If you're interested in benchmarking a connection, just do it in main() with a net.Listen (or the SSL equivalent).

--
 
 

[Raheel Gupta]

>>Why are you editing net/http?  If you're interested in benchmarking a connection, just do it in main() with a net.Listen (or the SSL equivalent).

Well I wanted the same port number to be able to serve web files and save the data.

Hence I am using this.

Can it cause any issue ?

I went through the HTTP package and it uses the net.Listen("tcp", addr) as it is.

Does the http package modify the net.Conn to read data slowly.

[Raheel Gupta]

>> Are you sure your 40MB buffer is actually written in the underlying socket?

I confirmed this with another function after the write loop :

qDebug() << socket->encryptedBytesToWrite();

The output was "0" which means there is nothing else to write as everything has been written. 

[Rémy Oudompheng]

On 2012/12/30 Raheel Gupta <rahe...@gmail.com> wrote:
>>>Why are you editing net/http? If you're interested in benchmarking a
>>> connection, just do it in main() with a net.Listen (or the SSL equivalent).
>
> Well I wanted the same port number to be able to serve web files and save
> the data.
> Hence I am using this.
> Can it cause any issue ?

Yes it causes the issue that you don't have the same standard library
as other people, and it makes things harder to debug. I favour the
following approach (in simplified form):

type ChanListener chan net.Conn

func (c ChanListener) Accept() (net.Conn, error) {
return <-c, nil
}

func (c ChanListener) Close() error {
close(c)
}

Listen yourself for sockets, run the http server on the ChanListener
and if you don't see a SERVEDATA request, send it down the channel.

> I went through the HTTP package and it uses the net.Listen("tcp", addr) as
> it is.
> Does the http package modify the net.Conn to read data slowly.

No. Check your system settings (I have no idea how to do that, but a
web search could give results).

Rémy.

[Raheel Gupta]

>> Listen yourself for sockets, run the http server on the ChanListener
and if you don't see a SERVEDATA request, send it down the channel.

If I am listening seperately, the issue is that the HTTP server cannot run on the same port as my port. I am actually not sure how should I send it to the http server if the header is not STOREDATA.

Could you give an example sir ?

>> No. Check your system settings (I have no idea how to do that, but a
web search could give results).

Well if it doesnt modify the net.Conn (rwc) then why would the data be slow in reading ?

What system settings should I look for sir ?