Event viewer arrow-key navigation could be improved

[randomascii]

The left-arrow key does not always select the correct flow event, and it does not make it visible.

If two flow events finish ("f") near the same time on the same thread then the second event is shown on a subsequent row (at least that is my interpretation of what is happening). This is okay, but unfortunately this display change appears to affect the behavior of how the left-arrow key decides which flow event to select.

The flow event associated with a RunTask event will, presumably, be the "f" event on the same thread which occurred immediately before. However the left arrow key actually selects the previous event that is on the same row, even if there is another flow event that is closer. This means that the left-arrow key does not reliably locate the relevant flow arrow.

It should be an easy fix to always find the immediately previous flow event.

Additionally (could be a separate issue if desired) the flow event that is selected is not reliably made visible. If it is off the left edge of the viewport then the viewport is moved so that it is exactly at the edge of the viewport -- still invisible. The viewport should be moved so that it is, perhaps 10% in, so that the red-highlighted flow arrow can be seen.

[randomascii]

In the screenshot below the top flow arrow is associated with a very brief RunTask event that cannot yet be seen. The bottom flow arrow is associated with the select RunTask event. If left-arrow is pressed then the top flow arrow is selected. This is incorrect, and avoidably so.

[randomascii]

After some discussions I now understand the problem better. The issue happens when the "f" event time is the same as the start time of the RunTask. The trace viewer then interprets this "f" event as being a child of the RunTask, because it calculates that the "f" event is fully contained within the RunTask. Then, because the "f" event is shown as a child the left-arrow navigation from the task does not go to it. This can be seen in the screen-shot above where the "f" event on the second row was erroneously calculated as being a child of the selected MessageLoop::RunTask event.

Possible fixes:

• Treat "f" events that overlap the start of another event as being before it.
• Treat any event that overlaps the start of another event as being before it.
• Tweak the recording of time such that time stamps are unique (separated by at least a microsecond, uggh)

[randomascii]

Update: in fact the ordering of the identical times can be determined when importing the trace. Although the time-stamps are identical the "f" event is located earlier in the .json data. For two events on the same thread this determines an ordering (I believe).

[randomascii]

I wrote a quick trace analyzer that looks for the time-delta between adjacent events on the same thread in a trace. It shows that on typical Windows traces from my machine 8-16% of events have the same time-stamp (o microseconds elapsed) as the previous event from the same thread. On a test trace from OSX this percentage is 0.046%, and 0.059% on Linux. This explains why the flow data import issues are far more common on Windows. Here are some typical results. They also show that the timer resolution is definitely one microsecond on Windows. The most likely explanation is that the timer function on OSX and Linux is much more expensive than on Windows.

162480 events loaded from OSXtrace.json.
0 delay hit 75 times (0.046%)
1 delay hit 134 times (0.082%)
2 delay hit 1703 times (1.048%)
3 delay hit 10148 times (6.246%)
4 delay hit 13963 times (8.594%)
174 negative intervals hit.

187173 events loaded from trace_linux.json.
0 delay hit 110 times (0.059%)
1 delay hit 1480 times (0.791%)
2 delay hit 8913 times (4.762%)
3 delay hit 12338 times (6.592%)
4 delay hit 11087 times (5.923%)
411 negative intervals hit.

218647 events loaded from trace_canary_Windows.json.
0 delay hit 19030 times (8.704%)
1 delay hit 31788 times (14.539%)
2 delay hit 19876 times (9.090%)
3 delay hit 12512 times (5.722%)
4 delay hit 10320 times (4.720%)
98 negative intervals hit.

Multiple Windows traces were collected and just single OSX and Linux traces. The differences are stark enough that the different trace collection details shouldn't matter.

[catapult-bot]

Migrated to catapult-project/catapult#787