zap icon indicating copy to clipboard operation
zap copied to clipboard

Timestamps

Open jamiebuilds opened this issue 5 years ago • 3 comments

Right now ZAP uses ISO 8601 date and time strings for every event:

{ ... "timestamp": "2018-07-25T23:47:58.102Z" ... }

However, as @lox pointed out, "time" isn't very stable, especially in CI environments.

For example: If we're streaming events from multiple different machines, those timestamps could be wildly different.

@lox suggested using absolute offsets in nanoseconds since the start time of the build.

Only I'm not sure what that ends up looking like when you have streams being merged together which would have different offsets. Because with timestamps this works:

(zap-producer-1 & zap-producer-2) | zap-consumer

We should probably consider doing something else though

jamiebuilds avatar Aug 08 '18 01:08 jamiebuilds

Beyond that, ISO 8601 timestamps will show builds that ran over a DST change as running for a negative duration. This can cause funny bugs where builds fail once a year.

lox avatar Aug 08 '18 01:08 lox

Okay so I think it's not actually a big deal using offsets with (prod1 & prod2) | cons, offsets just might not be in order, but ZAP is already designed for things to be out of order.

But instead of using nanoseconds I think we should use milliseconds with arbitrary precision. Especially since Spectre, not every language/hardware is able to provide high precision timings up to nanoseconds.

So I think it should look like this:

{ ... "time": 257.0332779996097 ... }
{ ... "time": 304.6154760001227 ... }
{ ... "time": 397.152665999718 ... }
{ ... "time": 425.59379499964416 ... }
{ ... "time": 496.1821520002559 ... }

jamiebuilds avatar Aug 08 '18 19:08 jamiebuilds

In order to deal with offsets having different start times when merging two streams, I think we should also build it into the spec that the "time" is relative to a top-level "time": 0.

It would look like this:

{ "id": "0",   "time": 0,                 "kind": "group", "event": "started" }
{ "id": "0.0", "time": 257.0332779996097  ... }
{ "id": "0.1", "time": 304.6154760001227  ... }
{ "id": "0.0", "time": 397.152665999718   ... }
{ "id": "0.1", "time": 425.59379499964416 ... }
{ "id": "0",   "time": 496.1821520002559, "kind": "group", "event": "passed"  }

However, if you see a stream that looks like this:

{ "id": "0", "time": 0, "kind": "group", "event": "started" }
...
{ "id": "0.4", "time": 0, "kind": "group", "event": "started" }
{ "id": "0.4.0", "time": 257.0332779996097  ... }
...
{ "id": "0", "time": 13412.152665999718, "kind": "group", "event": "passed" }

You have no way to calculate 0.4.0's time in relation to 0 (which may be fine)

jamiebuilds avatar Aug 08 '18 20:08 jamiebuilds