vlc log entries: routine start time is always the same

[kptdobe]

The order of the Fastly logs is random in Epsagon:

• https://dashboard.epsagon.com/spans/06802eb3-360a-4102-938f-527d9a277b11?tab=timeline: RECV, LOG, HASH, DELIVER...
• https://dashboard.epsagon.com/spans/bd75958b-58c5-48cc-94e4-2dfb62d6fe77?tab=timeline: LOG, DELIVER, HASH...

i think

helix-publish/src/vcl/tracer.js

Line 80 in b893e8f

s: vcl`time.start.usec`,

is the issue: looking at time-start-usec doc, the value of time.start.usec is the request start time, i.e. it will be the same in each subroutine.

We should rather use (now-sec)[https://developer.fastly.com/reference/vcl/variables/date-and-time/now-sec/] but I do not think second is precise enough... Or maybe do time.start.usec + time.elapsed.usec is this is possible.

cc @trieloff

[trieloff]

@ranrib FYI. I think $t.s + $t.e should give us the right order, as $t.s is constant per request.

[kptdobe]

Correct.
I created https://fiddle.fastlydemo.net/fiddle/cfabc298 to double check.

[kptdobe]

@ranrib I do not know how this is architected internally but Epsagon API returns $t.s as the span start_time which here is then incorrect.

[kptdobe]

I also suspect that $t.e is used as the duration but that's not correct neither. I think the duration is missing in the data we send. I do not see in the tracer some logic that would compute the duration of a subroutine...

[trieloff]

We send the leased time twice: when we enter the subroutine and when we leave. This should enable accurate calculation of the duration.

[kptdobe]

ok, then only the maths on the Epsagon side need to be adjusted. As you mention, $t.s + $t.e always gives "the current time" to be used for entry time and exit time of the subroutine. And the diff between those gives the duration.

[ranrib]

Hi, I tested it and it seems that we're getting $t.s + $t.e which is a similar value for enter and leave (which means duration = 0). Do you have any way to check it on your end?