System metric timestamps diverge from requests metric timestamps

[artych]

Let we have 1 request per iteration. We can expect that iteration metric collected at the end of the given one second interval equals to the previous value increased by the amount of requests done during that second.

This is the json output filtered with iterations and http_reqs metrics. Collected values and the order look coherent, but timestamps are in divergence.

{"type":"Point","data":{"time":"2017-03-08T17:45:42.169581798+01:00","value":0,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:43.169580571+01:00","value":0,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:41.936827867+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:44.169539323+01:00","value":1,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:43.827527342+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:45.169582892+01:00","value":2,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:43.608997943+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:46.169620394+01:00","value":3,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:45.237962291+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:45.605199699+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:47.169591471+01:00","value":5,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:46.333577564+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"2"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:46.777507765+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:48.169544811+01:00","value":7,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:47.087707911+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:49.16966946+01:00","value":8,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:48.233555942+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:47.970484183+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"2"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:48.534606285+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"1"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:50.169584212+01:00","value":11,"tags":null},"metric":"iterations"}

{"type":"Point","data":{"time":"2017-03-08T17:45:48.828083587+01:00","value":1,"tags":{"group":"","method":"GET","status":"200","url":"https://loadimpact.com","vu":"3"}},"metric":"http_reqs"}
{"type":"Point","data":{"time":"2017-03-08T17:45:51.169637474+01:00","value":12,"tags":null},"metric":"iterations"}

[liclac]

The problem is that metrics are buffered until the end of a VU iteration, so even though the request is made earlier, it's not actually pushed to a collector until the VU returns. What you're seeing here is a performance issue: the overhead of invoking a VU iteration is ridiculously high, so there's a noticeable delay. I'm keeping this in mind for #137, but there's no issue here per se.

[liclac]

Update: it was a problem, the iterations metric was emitted in the wrong place and in the wrong way. Fixed now.