Allow tracing of request durations

[bkircher]

Something that would be nice to have in gsclient-go is a way to easily trace how long an API call needs from request → to fulfillment.

With fulfillment I mean: I'm not interested in timings for each individual API call (e.g. HTTP request → HTTP response) but rather in "create storage" → "storage created"; how long did this take?

I thought about specifying a log-level in the client configuration, e.g., TRACE (or whatever logrus is using). This log-level should only be used for tracing the individual requests and their timings. One line per API request, printed when the request has finished. Output format should be JSON so that it can be processed further easily.

Example: If log level is set to TRACE, you would see something like this on stderr:

{
  "message": "Finished request CreateStorage",
  "requestId": "d8260ce6-7439-4543-85c4-794592a34346",
  "request": "CreateStorage",
  "success": true,
  "timeMs": 3042
}

timeMs is the time in milliseconds that has elapsed. success would be false when this errors, but I would still see timeMs.

What do you guys think? @fkr @nvthongswansea

[nvthongswansea]

Good idea 👍

[bkircher]

Let's put this on our plate then

[nvthongswansea]

@fkr @bkircher I've just figured out an interesting thing.

we can see that the GetServer() method takes around 1,5 second to finish, while the time it takes to get a response is 0,5 second => we spend around 1 second to do other stuff. Guess what? it because we wait before running the targetFunc (in this case the targetFunc is the function that sends the HTTP request); this affects the successful targetFunc badly.

So the line 47 in the image should be moved to the post-execution of the targetFunc.
Result:

[bkircher]

Looks good, @nvthongswansea . Can you add a small example on how to enable tracing request timings to the README? With example output and how to interpret the value?