why resty very slow #205

codenoid · 2019-01-01T11:03:19Z

Resty vs Curl

Resty vs Curl
Access Same URL

Result

Resty + fmt :

time ./main
real	0m11.247s
user	0m0.045s
sys	0m0.027s

curl :

time curl "sameurl"
real	0m1.373s
user	0m0.069s
sys	0m0.020s

Code

package main

import (
	"fmt"
)

import (
	"gopkg.in/resty.v1"
)

func main() {
	resp, _ := resty.R().Get("https://someurl")
	fmt.Println(resp)
}

codenoid · 2019-01-01T11:23:33Z

using : https://github.com/andelf/go-curl

time ./main
real	0m1.413s
user	0m0.034s
sys	0m0.021s

jeevatkm · 2019-01-01T18:12:46Z

@codenoid Thanks for trying Resty! Happy new year 2019!

I thought I will not touch my laptop today, but I checked my email and jumped on it 🎉

I can assure you Resty performance is damn good (I'm proud of it 😄).

As always testing performance involves many factors. Its applies to testing http client too. Above stated scenario involves (few comes to my mind)-

Network latency
DNS resolution
Server responsiveness

I have updated your code snippet with few additional info. Resty always captures timing of -

Request fire time to server
Response received time from server (body is not yet read)

Code snippet

package main

import (
	"fmt"
	"time"

	"gopkg.in/resty.v1"
)

func main() {
	startTime := time.Now()
	resp, _ := resty.R().Get("http://httpbin.org/get")
	endTime := time.Since(startTime)
	fmt.Println("Total Time", endTime)
	fmt.Println("Request Fire Time", resp.Request.Time)
	fmt.Println("Response Received Time (body not read yet)", resp.ReceivedAt())
	fmt.Println("Diff request fire & receive", resp.Time())
	fmt.Println(resp)
}

Okay, let's proceed to execute.

First run : (clear local dns cache before each run)

Resty

jeeva@pmb-pro:~/go/src/test$ flushDNS
jeeva@pmb-pro:~/go/src/test$ time ./try
Total Time 193.59706ms
Request Fire Time 2019-01-01 09:26:21.843781 -0800 PST m=+0.001618649
Response Received Time (body not read yet) 2019-01-01 09:26:22.037195 -0800 PST m=+0.195026697
Diff request fire & receive 193.408048ms
{
  "args": {},
  "headers": {
    "Accept-Encoding": "gzip",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "go-resty/1.10.3 (https://github.com/go-resty/resty)"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.217s
user	0m0.011s
sys	0m0.011s

curl

jeeva@pmb-pro:~/go/src/test$ flushDNS
jeeva@pmb-pro:~/go/src/test$ time curl http://httpbin.org/get
{
  "args": {},
  "headers": {
    "Accept": "*/*",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "curl/7.54.0"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.201s
user	0m0.009s
sys	0m0.007s

Second run: (clear local dns cache once and order is Resty and then curl)

Resty

jeeva@pmb-pro:~/go/src/test$ flushDNS
jeeva@pmb-pro:~/go/src/test$ time ./try
Total Time 177.176549ms
Request Fire Time 2019-01-01 09:40:06.411273 -0800 PST m=+0.010590536
Response Received Time (body not read yet) 2019-01-01 09:40:06.586432 -0800 PST m=+0.185744155
Diff request fire & receive 175.153619ms
{
  "args": {},
  "headers": {
    "Accept-Encoding": "gzip",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "go-resty/1.10.3 (https://github.com/go-resty/resty)"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.265s
user	0m0.011s
sys	0m0.014s

curl


jeeva@pmb-pro:~/go/src/test$ time curl http://httpbin.org/get
{
  "args": {},
  "headers": {
    "Accept": "*/*",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "curl/7.54.0"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.175s
user	0m0.007s
sys	0m0.006s
jeeva@pmb-pro:~/go/src/test$

Third run: (clear local dns cache once and order is curl and then Resty)

curl

jeeva@pmb-pro:~/go/src/test$ flushDNS
jeeva@pmb-pro:~/go/src/test$ time curl http://httpbin.org/get
{
  "args": {},
  "headers": {
    "Accept": "*/*",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "curl/7.54.0"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.201s
user	0m0.007s
sys	0m0.006s

Resty

jeeva@pmb-pro:~/go/src/test$ time ./try
Total Time 153.40803ms
Request Fire Time 2019-01-01 09:41:37.278849 -0800 PST m=+0.001614385
Response Received Time (body not read yet) 2019-01-01 09:41:37.432076 -0800 PST m=+0.154837119
Diff request fire & receive 153.222734ms
{
  "args": {},
  "headers": {
    "Accept-Encoding": "gzip",
    "Connection": "close",
    "Host": "httpbin.org",
    "User-Agent": "go-resty/1.10.3 (https://github.com/go-resty/resty)"
  },
  "origin": "0.0.0.0",
  "url": "http://httpbin.org/get"
}

real	0m0.173s
user	0m0.010s
sys	0m0.008s
jeeva@pmb-pro:~/go/src/test$

I'm not sure, how much above results gonna help you. I would suggest test your use case (with some realistic approach like above follow some consistent steps).

If you come across bottleneck in Resty, please let me know I'm glad to work on it. Help me with some concrete inputs and data from you.

Again, thanks for trying Resty 😄.

codenoid · 2019-01-01T19:11:01Z

after following this script to flush DNS in my Ubuntu + with updated code :

Total Time 10.50609103s
Request Fire Time 2019-01-02 02:09:48.952850867 +0700 WIB m=+0.003682369
Response Received Time (body not read yet) 2019-01-02 02:09:59.45870066 +0700 WIB m=+10.509532235
Diff request fire & receive 10.505849866s
{
  "args": {}, 
  "headers": {
    "Accept-Encoding": "gzip", 
    "Connection": "close", 
    "Host": "httpbin.org", 
    "User-Agent": "go-resty/1.10.3 (https://github.com/go-resty/resty)"
  }, 
  "origin": "xxx.xxx.xxx.xxx", 
  "url": "http://httpbin.org/get"
}

real	0m10.515s
user	0m0.006s
sys	0m0.012s

jeevatkm · 2019-01-01T21:05:15Z

@codenoid It seems we need to further investigation. We cannot use https://github.com/andelf/go-curl since it's a binding for curl cmd.

Let's try Go default client at your end.

Default Go client snippet Resembles same behavior as Resty

package main

import (
	"fmt"
	"io/ioutil"
	"log"
	"net/http"
	"time"
)

func main() {
	startTime := time.Now()
	resp, err := http.Get("http://httpbin.org/get")
	if err != nil {
		log.Fatal(err)
	}
	b, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		log.Fatal(err)
	}
	endTime := time.Since(startTime)
	fmt.Println("Total Time", endTime)
	fmt.Println(string(b))
}

FYI, I have tried Resty and above go default client code snippets on -

My machine:

OS: macOS 10.14.2
go version go1.11.2 darwin/amd64

My DO VPS:

OS: Ubuntu 16.04.1
go version go1.11.1 linux/amd64

On both machine Resty and Default Go Client performs very good.

Could you try above default client code snippet at your end then provide the outcome also your env info?

moorereason · 2019-01-01T21:08:25Z

I was curious, so I made a httptrace version of this little test: https://gist.github.com/moorereason/f77d69a2c823fb222eba61c151e63a6b

$ go run main.go
DNS Lookup 85.082359ms
TCP Connection 49.376838ms
Server Processing 64.521936ms
TLS Handshake 0s
Content Transfer 136.181µs
Total Time 199.162309ms

@jeevatkm, what do you think about adding this kind of tracer to Resty?

jeevatkm · 2019-01-01T21:20:43Z

@moorereason Thank you. Nice suggestion👍 Just added to v2 action list #167 . Good to have on-demand tracer option in the Resty.

@codenoid Could you please also run @moorereason's code snippet (
https://gist.github.com/moorereason/f77d69a2c823fb222eba61c151e63a6b) at your end, which would provide more insights?

codenoid · 2019-01-02T05:34:04Z

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.5 LTS"
NAME="Ubuntu"
VERSION="16.04.5 LTS (Xenial Xerus)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 16.04.5 LTS"
VERSION_ID="16.04"

result :

$ go build main.go
$ ./main
DNS Lookup 10.292216062s
TCP Connection 242.602551ms
Server Processing 248.678901ms
TLS Handshake 0s
Content Transfer 264.778µs
Total Time 10.783885501s

jeevatkm · 2019-01-02T06:53:59Z

@codenoid Thanks for trying with @moorereason code snippet.

It seems on your machine, major time is occupied by DNS Lookup 10.292216062s. You might have to investigate your network settings, etc.

As always, feel free to ping me when needed.

codenoid · 2019-01-02T07:33:02Z

but what about with curl 😕

$ time curl "http://httpbin.org/get"
{
  "args": {}, 
  "headers": {
    "Accept": "*/*", 
    "Connection": "close", 
    "Host": "httpbin.org", 
    "User-Agent": "curl/7.47.0"
  }, 
  "origin": "xxx.xxx.xxx.xxx", 
  "url": "http://httpbin.org/get"
}

real	0m0.516s
user	0m0.007s
sys	0m0.010s

should i close this issue for a while ?

jeevatkm · 2019-01-02T07:55:44Z

@codenoid I understand what you're trying to convey. BTW what is your Go version?? Could you try with latest Go 1.11.4 version.

We can keep this issue open for a while 😄.

I have looked around found following issues on Go repo:
golang/go#28419
golang/go#21906

I have created a Go HTTP client with tracer based on @moorereason snippet.

package main

import (
	"context"
	"crypto/tls"
	"fmt"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httptrace"
	"time"
)

type HTTPTracer struct {
	GetConn              time.Time
	GotConn              time.Time
	GotFirstResponseByte time.Time
	DNSStart             time.Time
	DNSDone              time.Time
	ConnectStart         time.Time
	ConnectDone          time.Time
	TLSHandshakeStart    time.Time
	TLSHandshakeDone     time.Time
}

func (t *HTTPTracer) Context() context.Context {
	return httptrace.WithClientTrace(
		context.Background(),
		&httptrace.ClientTrace{
			GetConn:  func(_ string) { t.GetConn = time.Now() },
			DNSStart: func(_ httptrace.DNSStartInfo) { t.DNSStart = time.Now() },
			DNSDone:  func(_ httptrace.DNSDoneInfo) { t.DNSDone = time.Now() },
			ConnectStart: func(_, _ string) {
				if t.DNSDone.IsZero() {
					t.DNSDone = time.Now()
				}
			},
			GotConn:              func(_ httptrace.GotConnInfo) { t.GotConn = time.Now() },
			GotFirstResponseByte: func() { t.GotFirstResponseByte = time.Now() },
			TLSHandshakeStart:    func() { t.TLSHandshakeStart = time.Now() },
			TLSHandshakeDone:     func(_ tls.ConnectionState, _ error) { t.TLSHandshakeDone = time.Now() },
		},
	)
}

func main() {
	tr := &HTTPTracer{}
	req, _ := http.NewRequest("GET", "http://httpbin.org/get", nil)
	req = req.WithContext(tr.Context())
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		log.Fatal(err)
	}
	b, err := ioutil.ReadAll(resp.Body)
	if err != nil {
		log.Fatal(err)
	}
	endTime := time.Now()
	if tr.DNSStart.IsZero() {
		tr.DNSStart = tr.GetConn
		tr.DNSDone = tr.GetConn
	}
	fmt.Println(string(b))
	fmt.Println("DNS Lookup", tr.DNSDone.Sub(tr.DNSStart))
	fmt.Println("TCP Connection", tr.GotConn.Sub(tr.DNSDone))
	fmt.Println("Server Processing", tr.GotFirstResponseByte.Sub(tr.GotConn))
	fmt.Println("TLS Handshake", tr.TLSHandshakeDone.Sub(tr.TLSHandshakeStart))
	fmt.Println("Content Transfer", endTime.Sub(tr.GotFirstResponseByte))
	fmt.Println("Total Time", endTime.Sub(tr.GetConn))
}

Try this one and with this data reach out to Go community on Google Group or Slack channel. If anyone have clue around this.

codenoid · 2019-01-02T12:42:23Z

GO Version :

$ go version
go version go1.11 linux/amd64
$ go run main.go
{
  "args": {}, 
  "headers": {
    "Accept-Encoding": "gzip", 
    "Connection": "close", 
    "Host": "httpbin.org", 
    "User-Agent": "Go-http-client/1.1"
  }, 
  "origin": "xxx.xxx.xxx.xxx", 
  "url": "http://httpbin.org/get"
}

DNS Lookup 10.305910554s
TCP Connection 242.929337ms
Server Processing 248.50648ms
TLS Handshake 0s
Content Transfer 308.082µs
Total Time 10.797677572s

USING GO 1.11.4 🚀

{                                                           
  "args": {},                                               
  "headers": {                                              
    "Accept-Encoding": "gzip",                              
    "Connection": "close",                                  
    "Host": "httpbin.org",                                  
    "User-Agent": "Go-http-client/1.1"                      
  },                                                        
  "origin": "xxx.xxx.xxx.xxx",                              
  "url": "http://httpbin.org/get"                           
}                                                           
                                                            
DNS Lookup 95.017071ms                                      
TCP Connection 242.636152ms                                 
Server Processing 249.03363ms                               
TLS Handshake 0s                                            
Content Transfer 214.865µs                                  
Total Time 587.014321ms

codenoid · 2019-01-02T13:02:15Z

thank you ! 🚀 ✨

jeevatkm · 2019-01-02T20:34:54Z

@codenoid I'm glad to hear that you have to sorted the issue 😄

wlstony · 2024-12-03T08:00:38Z

I have the same problem,the output with http HTTPTracer。

DNS Lookup 1.546709ms
TCP Connection 5.201779416s
Server Processing 379.857667ms
TLS Handshake 4.85895675s
Content Transfer 285.708µs
Total Time 5.583717791s。

but using curl command is very fast

time_namelookup: 0.109017s
time_connect: 0.431880s
time_appconnect: 0.770520s
time_pretransfer: 0.770656s
time_redirect: 0.000000s
time_starttransfer: 1.098084s
----------
time_total: 1.098260s

jeevatkm · 2024-12-05T22:37:37Z

@wlstony I think it is related to your Go environment, machine, or connection. See these two lines: it took a lot of time -

TCP Connection 5.201779416s
...
TLS Handshake 4.85895675s
...

You could also try the Go HTTP client directly; if the issue is the same as mentioned above, you will get the same result.

codenoid closed this as completed Jan 1, 2019

codenoid reopened this Jan 1, 2019

jeevatkm added the support label Jan 1, 2019

jeevatkm self-assigned this Jan 1, 2019

jeevatkm mentioned this issue Jan 1, 2019

Resty v2.0.0 Action Item list #167

Closed

codenoid closed this as completed Jan 2, 2019

jeevatkm mentioned this issue Jan 10, 2019

Add on-demand tracer into resty #216

Closed

jeevatkm added the answered label May 11, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

why resty very slow #205

why resty very slow #205

codenoid commented Jan 1, 2019

codenoid commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019

Uh oh!

codenoid commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019 •

edited

Loading

Uh oh!

moorereason commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019

Uh oh!

codenoid commented Jan 2, 2019 •

edited by jeevatkm

Loading

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

codenoid commented Jan 2, 2019 •

edited

Loading

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

codenoid commented Jan 2, 2019 •

edited

Loading

Uh oh!

codenoid commented Jan 2, 2019

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

wlstony commented Dec 3, 2024 •

edited

Loading

Uh oh!

jeevatkm commented Dec 5, 2024

Uh oh!

Uh oh!

why resty very slow #205

why resty very slow #205

Comments

codenoid commented Jan 1, 2019

Resty vs Curl

Result

Code

codenoid commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019

First run : (clear local dns cache before each run)

Second run: (clear local dns cache once and order is Resty and then curl)

Third run: (clear local dns cache once and order is curl and then Resty)

Uh oh!

codenoid commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

moorereason commented Jan 1, 2019

Uh oh!

jeevatkm commented Jan 1, 2019

Uh oh!

codenoid commented Jan 2, 2019 • edited by jeevatkm Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

codenoid commented Jan 2, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

codenoid commented Jan 2, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codenoid commented Jan 2, 2019

Uh oh!

jeevatkm commented Jan 2, 2019

Uh oh!

wlstony commented Dec 3, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jeevatkm commented Dec 5, 2024

Uh oh!

jeevatkm commented Jan 1, 2019 •

edited

Loading

codenoid commented Jan 2, 2019 •

edited by jeevatkm

Loading

codenoid commented Jan 2, 2019 •

edited

Loading

codenoid commented Jan 2, 2019 •

edited

Loading

wlstony commented Dec 3, 2024 •

edited

Loading