Avoid overlapping events that start on the same time

[avilapa]

Calling two nested MTR_SCOPE/MTR_SCOPE_FUNC Complete Events in quick succession will cause them to overlap instead of nest when visualizing them in chrome://tracing. The cause seems to be that these will log the exact same ts, A() will finish first, therefore be logged first and B() will finish later and will be logged second with a longer dur. Chrome Tracing doesn't seem to be able to handle this out of order discrepancy (despite the docs seemingly stating that it should: the timestamps of complete events can be in any order) and will show a single box with two overlapping names instead of nesting them correctly (see .json example below to see this in action).

void A()
{
    MTR_SCOPE_FUNC()
    ...
}

void B()
{
    MTR_SCOPE_FUNC()
    A()
    ...
}

JSON example:

{"traceEvents":[
{"cat":"test","pid":0,"tid":0,"ts":0,"ph":"X","name":"FIRST","args":{},"dur":10},
{"cat":"test","pid":0,"tid":0,"ts":0,"ph":"X","name":"SECOND","args":{},"dur":20}
]}

This feels to me like it should be a very common setup so I expected to find more people running into this problem, but I didn't, so I wonder if I am using the tool wrong in any way. The snippets above are obviously manufactured examples for the sake of explanation.

Is this a known issue at all?

[hrydgard]

I haven't used the library myself in years, but I don't remember seeing this. it's possible that Chrome's behavior has changed for the worse, I don't really have another explanation.

It seems like the bug is in Chrome rather than in minitrace, so maybe report it to them?

I'd accept a PR with a workaround if you can come up with a nice and efficient one.

[avilapa]

Thanks for getting back to me!

The obvious workaround is using Duration Events instead of Complete Events on MTRScopedTrace, similarly to how MTRScopedTraceArg already does it.

class MTRScopedTrace {
public:
	MTRScopedTrace(const char *category, const char *name)
		: category_(category), name_(name) {
		internal_mtr_raw_event(category_, name_, 'B', 0);
	}
	~MTRScopedTrace() {
		internal_mtr_raw_event(category_, name_, 'E', 0);
	}

private:
	const char *category_;
	const char *name_;
};

For a more involved solution that still allows to use 'X' events, only thing I can think of (that doesn't involve a costly sorting pass at the end of the program, or runtime tracking X many raw events prior to the one you're writing to check if they have the exact same ts...) is to reserve the slot in the event_buffer when constructing a MTRScopedTrace, effectively writing an 'X' event at the beginning instead of at the end of its execution. There are some pitfalls to this solution though (e.g. what do you do if a flush is requested but the scope is still alive?).

Ideally Chrome can fix this, I have reported it as a bug, but I don't know if anyone is still providing support to it. For the time being I might stick with Duration Events locally.