Resp.Request.TraceInfo().TotalTime not include time spend to retry

[Zaazik]

We had a problem understanding why our endpoints were taking 30 seconds to complete.
After read logs, we couldn't figure out why we had two database selects and a request to an external endpoint (via RESTY).
It took 30 seconds to execute.
In the logs, we see that request to the external service:
trace_info.conn_time: 204ms,
trace_info.dns_lookup: 21ms
trace_info.total_time 363ms

We started building conspiracy theories about Postgres, CPU throttling, etc...

Then, with great difficulty, we managed to find the APM span for this rare request.
We discovered that out of the 30 seconds of this request, all 30 were taken by RESY. Im investigate my resty client settings config, find timeout is set to 30 seconds and retry.
Now the question is, why didn't this time show up in the total time?
My understanding is that total time is the time it took Resty to execute my request from the moment I called .Get(someURI) until RESTY return response. Or am I misunderstanding the meaning of total time?

[jeevatkm]

@Zaazik

My understanding is that total time is the time it took Resty to execute my request from the moment I called .Get(someURI) until RESTY return response. Or am I misunderstanding the meaning of total time?

The total time is “the moment Resty sends a request out and receives a response". It does not calculate time spent in all retry request(s) and its wait time. FYI, please refer to code at client.go#execute method.

The upcoming v3 release will have the ability to set CorrelationID to relate all the request retry attempts. Using that, a resty consumer could aggregate timing in their metrics system.

resty/request.go

Line 116 in 67ddf73

func (r *Request) SetCorrelationID(id string) *Request {

[jeevatkm]

@Zaazik Any feedback?