Nanoseconds support

[dvyukov]

Hi,

I want to use the trace viewer and it looks awesome.
But my traces have nanosecond precision. I've tried to divide the timestamps by 1000 and use fractional values, but it does not work. The viewer understands fractional values, but then the visual representation looks completely messed seemingly due to some rounding errors (it seem to assume that min duration of a slice is 1.0). Here is a reproducer:

{"traceEvents": [
{"name": "X1", "ph": "B", "pid": 1, "tid": 1, "ts": 0},
{"name": "X1", "ph": "E", "pid": 1, "tid": 1, "ts": 1.1},
{"name": "X2", "ph": "B", "pid": 1, "tid": 1, "ts": 1.1},
{"name": "X2", "ph": "E", "pid": 1, "tid": 1, "ts": 1.3},
{"name": "X3", "ph": "B", "pid": 1, "tid": 1, "ts": 1.3},
{"name": "X3", "ph": "E", "pid": 1, "tid": 1, "ts": 1.6},
{"name": "X4", "ph": "B", "pid": 1, "tid": 1, "ts": 1.7},
{"name": "X4", "ph": "E", "pid": 1, "tid": 1, "ts": 2.1},
{}]}

I've also noticed that if I have several flow events starting at the same microsecond:

{"name": "unblock", "ph": "s", "pid": 0, "tid": 0, "id": "86", "ts": 45747.68},
{"name": "unblock", "ph": "t", "pid": 0, "tid": 3, "id": "86", "ts": 45799.224},
{"name": "unblock", "ph": "s", "pid": 0, "tid": 0, "id": "87", "ts": 45747.989},
{"name": "unblock", "ph": "t", "pid": 0, "tid": 2, "id": "87", "ts": 45825.085},

Then, they are drawn on several rows. While I would expect them to be draw on the same row, as they start at different times.

I am on revision f306225.

[dvyukov]

I could just supply nanoseconds (w/o dividing them by 1000), and in fact the visualization is much better this way, all visual glitches go away. But UI says 1000 seconds trace, when I actually have 1 second trace.

So what would work as well -- is an ability to set timestamps units to nanoseconds.

[dj2]

@natduca

[natduca]

The math of the viewer requires that we use microseconds internally or else you end up with numeric precision issues. Nanoseconds simply won't work. So we must internally stay with milliseconds on the model.

Therefore, I can see two routes forward here: (1) make the importer convert from ns to ms internally, or (2) make the analysis system display using ns when appropriate (or always, based on a setting).

For 1, you'd add a field to the container object saying tsUnit: "ns", then modify traceEventImporter to use that and internally have it convert everything to ms.

For 2, you'd modify the core/analysis folder to display data using ns when it was small enough, or possibly based on a global setting. You'd probably make pretty good headway by searching for tsRound() in the code, which is the general code we use to go from ms to a rounded string.

I'm not up for writing these patches, but would review a pr to either effect.

[natduca]

Btw, I'd vote for 1 and 2 :)

[egonelbre]

I've created a quick patch for the second approach
https://gist.github.com/egonelbre/4cd61cb4d49229943512. (Sorry for using a patch file, I'm currently running on windows and the depot_tools setup is too involved for the moment).

Of course I'm really concerned about the patch - it seems like it could start causing issues to multiplying with 1e6, although I didn't notice a case where it happens.

Regarding the special case in unit.html - I'm not sure whether it's a good idea or not. It seems if the tracer is mostly in ms mode then outputting "0 ms" is better than "0 ns". Of course it's trivial to remove it.

PS. I have really no good understanding nor overview how the tool works internally and the patch was created by fixing the bugs I saw. Basically, I have no idea whether this may cause additional problems elsewehere.

[dvyukov]

Thanks, Egon!

Nat, does this approach look right to you?

[natduca]

Its good that you're finding some of the places that need to be touched. But, we want to break this apart into many little patches, each of which has tests and is individually tested.

I'd start with making the ruler show ns when very zoomed in.

I have to ask that this is contributed via codereview. It should be pretty straightforward to make depot_tools work on windows --- you just download it and put it in your path.

[dvyukov]

Currently I pass nanoseconds as if they are microseconds. Will I need to pass fractional microseconds with this patch? That is, currently I pass 1 assuming that it is 1ns but the viewer assumes it is 1us; with this patch I will need to pass 0.001 when I assume 1ns. Is it correct?

[egonelbre]

@natduca I will split it tomorrow and get depot_tools running + learn the tooling tomorrow.

@dvyukov I didn't change the meaning of timestamps, so it uses microseconds. Somehow I managed to mix up microseconds and nanoseconds so yes, it should be "us". Probably needs some other fixes as well. I will fix it tomorrow.

[egonelbre]

I've created the CLs:

• ruler https://codereview.appspot.com/218870043/
• number formatting https://codereview.appspot.com/215970043/
• drawing glitches https://codereview.appspot.com/213310043/

[dvyukov]

@egonelbre I've tried to test your changes. My repo is on 2014e39 (current tip). Without your changes vulcanize_trace_viewer passes. With your changes it fails as:

trace-viewer dvyukov$ ./vulcanize_trace_viewer --config=lean
yui-compressor missing. CSS minification will be skipped.
Traceback (most recent call last):
  File "./vulcanize_trace_viewer", line 12, in <module>
    sys.exit(vulcanize_trace_viewer.Main(sys.argv[1:]))
  File "/Users/dvyukov/src/trace-viewer/trace_viewer/build/vulcanize_trace_viewer.py", line 56, in Main
    report_deps=options.report_deps)
  File "/Users/dvyukov/src/trace-viewer/trace_viewer/build/vulcanize_trace_viewer.py", line 88, in WriteTraceViewer
    output_html_head_and_body=output_html_head_and_body)
  File "/Users/dvyukov/src/trace-viewer/third_party/tvcm/tvcm/generate.py", line 315, in GenerateStandaloneHTMLToFile
    GenerateJS(load_sequence, minify=minify, report_sizes=report_sizes))
  File "/Users/dvyukov/src/trace-viewer/third_party/tvcm/tvcm/generate.py", line 145, in GenerateJS
    report_sizes=report_sizes)
  File "/Users/dvyukov/src/trace-viewer/third_party/tvcm/tvcm/generate.py", line 178, in GenerateJSToFile
    js = flatten_to_file.getvalue()
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/StringIO.py", line 271, in getvalue
    self.buf += ''.join(self.buflist)
UnicodeDecodeError: 'ascii' codec can't decode byte 0xce in position 416: ordinal not in range(128)

[dvyukov]

The failure happens when I apply both of separately:
https://codereview.appspot.com/218870043/
https://codereview.appspot.com/215970043/
When I apply https://codereview.appspot.com/213310043/ it does not happen.

[egonelbre]

I'm guessing it doesn't like that I'm using μs, I'll make it use us instead then.

[dvyukov]

Hello, Mr. Python, it is second decade of XXI century. Have you heard about unicode? :)

[egonelbre]

@dvyukov PTAL

[dvyukov]

@egonelbre works now!
I've created a Go change that incorporates your changes:
https://go-review.googlesource.com/7680

One issue that I noticed is that when I use Select tool (arrow), trace-viewer show duration of the current selection rounded down to 0.01ms (10us). This precision is not enough for Go, as some goroutines run for less (e.g. 5us), and the duration is shown as just 0ms.

[dvyukov]

ping
what are we waiting for here?

[egonelbre]

@dvyukov the review process takes some time due to, me not being familiar with the code, coding style & patches, review feedback comes with a day delay (time-zone difference) and, I guess, both are not working on this full time. But, it should be cleaned up soon enough.

[dvyukov]

Ah, sorry, @egonelbre. I wasn't subscribed on the code reviews, so I missed all activity there and thought that nothing happens at all. If the reviews are progressing, then it is great.

[egonelbre]

You can see all the reviews here, https://codereview.appspot.com/user/egon I think you missed some.

[egonelbre]

Now, regarding integrating this into model/UI. From Go users perspective an UI option wouldn't be useful as all the files will be in nanoseconds. It seems that most likely you want the precision that the model was recorded, but with option to go back to a larger time-scale, e.g. if you recorded a long time-span then viewing it in ms. might make sense.

Thoughts?

[dvyukov]

It seems that most likely you want the precision that the model was recorded

Either a meta element in input json file or a config file setting will do for Go.

if you recorded a long time-span then viewing it in ms. might make sense.

Before the changes UI autotuned units. That is, even if input data is in microseconds, when you look at a long span, UI shows it in seconds. Does it still work? If yes, then we don't need to do anything on top of that I think.

[natduca]

How about for starters we modify trace event forat document [linked off
home page] to supoprt defaultTimeUnit: "ms" | "ns" on the outer container.
E.g. the {traceEvents: [...], defaultTimeUnit: 'ns'}. trace_event_importer
when it sees this converts it to one of the known units in base and throws
error if it doesn't match. Otherwise, it says says model.intrinsicTimeUnit =
unit. The setter on model throws if it is set twice [in case two importers
try to set this twice, i'd prefer to be robust!]. [Note, intrinsic unit, if not set, should default to ms]

Once we have that patch done, we can figure out how we want to connect the
default time unit to base/time.html... id love to have the timeline_view do
that, but if there are two timeline views in existence, then they both
fight over base/time...

Lets do the patch work for the stuff we're certain about and then we can
come back to ui binding next?

On Thu, Jun 4, 2015 at 4:29 AM Dmitry Vyukov notifications@github.com
wrote:

It seems that most likely you want the precision that the model was
recorded

Either a meta element in input json file or a config file setting will do
for Go.

if you recorded a long time-span then viewing it in ms. might make sense.

Before the changes UI autotuned units. That is, even if input data is in
microseconds, when you look at a long span, UI shows it in seconds. Does it
still work? If yes, then we don't need to do anything on top of that I
think.

—
Reply to this email directly or view it on GitHub
#624 (comment)
.

[egonelbre]

Regarding the UI binding, I started thinking whether it's necessary at all, if everything is showing correctly already. If there's a separate request, I guess then we could start thinking about it.

Anyways, I started implementing the importing and I hit one issue; the defaultTimeUnit for events is microseconds not milliseconds, but it is showing it in milliseconds. I'm not sure what is the correct handling is? It seems weird to have defaultTimeUnit:"ns", but the value imported is microseconds, or have defaultTimeUnit:"ns" import from nanoseconds, but defaultTimeUnit:"ms" import from microseconds. I can see two ways out of this... either make the defaultTimeUnit:"us" and when deriving the displayUnit, use defaultTimeUnit:"ms" for "us"... alternatively rename "defaultTimeUnit" -> "displayTimeUnit" to make clear that it's only being used for displaying not the values in the model itself.

Currently I'm going with the first approach, as it looks more right to me.

[natduca]

displayTimeUnit makes sense. I think we want the model to always be in ms.

On Sun, Jun 14, 2015 at 4:50 AM Egon Elbre notifications@github.com wrote:

Regarding the UI binding, I started thinking whether it's necessary at
all. If everything is showing correctly already.

Anyways, I started implementing the importing and I hit one issue; the
defaultTimeUnit for events is microseconds not milliseconds, but it is
showing it in milliseconds. I'm not sure what is the correct handling is?
It seems weird to have defaultTimeUnit:"ns", but the value imported is
microseconds, or have defaultTimeUnit:"ns" import from nanoseconds, but
defaultTimeUnit:"ms" import from microseconds. I can see two ways out of
this... either make the defaultTimeUnit:"us" and when deriving the
displayUnit, use defaultTimeUnit:"ms" for "us"... alternatively rename
"defaultTimeUnit" -> "displayTimeUnit" to make clear that it's only being
used for displaying not the values in the model itself.

—
Reply to this email directly or view it on GitHub
#624 (comment)
.

[egonelbre]

@natduca Sorry for confusion, I think I have used the wrong terminology. And as a response to:

i'm a bit confused though. we were not planning on changing the actual storage
unit on the model in your patch, were we?

Correction, the model is still in ms... Currently "trace event format" by default is in microseconds, and "model" timestamps are always in milliseconds. However, since the trace-event-format is in microseconds the model.intrinsicTimeUnit had to default to microseconds, i.e. in my patches "intrinsicTimeUnit" == "the precision unit that the data was recorded at". I might have misinterpreted the meaning of converting in your previous suggestion. I thought it was about converting the trace event format values based on the "defaultTimeUnit" vallue.

I went with that approach at that moment because modifying CLs from "defaultTimeUnit" -> "displayTimeUnit" is easier than "displayTimeUnit" -> "defaultTimeUnit". Also, as a confirmation to the adjustments I'm going to make: we want the JSON object format to always be in microseconds and the format only specifies 'displayTimeUnit'?

[egonelbre]

Now regarding attaching displayTimeUnit to the UI. I'm guessing the UI interface for changing the time-unit won't be necessary, since it is most likely to be the one set in the model; of course if it is necessary some will likely ask for it. Regarding binding the model.displayTimeUnit -> Time.currentDisplayTimeUnit - I have no clue where the most appropriate place would be.

[natduca]

Yeah, this seems racey if we do it wrong.

Thinking out loud, a timeline view owns the model, so a timeline view can have a "preferred" time precision, right?

So, what if every timeline-view owned an element like this:

  <preferred-display-unit>

TimelineView would set the preferredDisplayUnit on that widget anytime the model changes.

And that element has this prototype:

{
  get preferredDisplayUnit() {
  },
  set preferredDisplayUnit(unit) {
    tv.b.Time.didPreferredUnitChange()
  },
  attached: same as detached,
  detached: function() {
    tv.b.Time.didPreferredUnitChange()
  }
}

Then base's didPreferred goes through and finds all the display-unit-preference instances using deep_utils. It then asks each one for their preference, using the most precise one if there are multiple. It then sets its mode to that...

[egonelbre]

The main question is that when we should show

Start       124.798 ms
Wall Duration   25.154 ms
Self Time   8.445 ms

or

Start       124,798,217 ns
Wall Duration   25,153,925 ns
Self Time   8,444,776 ns

It's somewhat a problematic case, on one hand you can be recording 1-10s of data and then zoom into nanosecond level details. I.e. it probably needs something more advanced than just switching to ns to make it nice to use. Clearly losing precision when showing small values is bad, showing 0,000ms as the time isn't useful. Then again, showing big values will show irrelevant details. Also, showing ns when the recording precision was microseconds, makes no sense.

Maybe it should switch instead based on the zoom-level to the lowest intrinsicTimeUnit available. e.g. when the whole view span is less than 0.1ms it will switch to ns, if there is a model that has displayTimeUnit:ns.

[natduca]

I think the same architecture I suggested would support that. The timeline
view would request ms and then the track view could have another Element
that requests ns. The control code in base would pick the most precise.
On Thu, Jul 2, 2015 at 2:22 AM Egon Elbre notifications@github.com wrote:

The main question is that when we should show

Start 124.798 ms
Wall Duration 25.154 ms
Self Time 8.445 ms

or

Start 124,798,217 ns
Wall Duration 25,153,925 ns
Self Time 8,444,776 ns

It's somewhat a problematic case, on one hand you can be recording 1-10s
of data and then zoom into nanosecond level details. I.e. it probably needs
something more advanced than just switching to ns to make it nice to use.
Clearly losing precision when showing small values is bad, showing 0,000ms
as the time isn't useful. Then again, showing big values will show
irrelevant details. Also, showing ns when the recording precision was
microseconds, makes no sense.

Maybe it should switch instead based on the zoom-level to the lowest
intrinsicTimeUnit available. e.g. when the whole view span is less than
0.1ms it will switch to ns, if there is a model that has displayTimeUnit:ns.

—
Reply to this email directly or view it on GitHub
#624 (comment)
.

[egonelbre]

I somewhat am confused where to put everything, but here is this https://codereview.appspot.com/252340043. (PS. when creating "idea" CL-s should I mail them for CR or not?). I'll add tests to it once, I know I'm actually on the right track regards structuring things.

In didPreferredUnit has to do something better than just min/max over everything. I experimented with it a bit. The best unit seems to be "use the max(ruler-unit, min(model.intrinsicUnit))". Basically, we shouldn't show more precision than we actually have in the model and we shouldn't show details that we cannot see on the view.

[natduca]

Agreed on the min/max thing. And cl's are fine, if you're uncertain about how good the patch is, then you can always prefix the title with something like [NOT for landing] or similar to warn reviewers that you're not super sure about the approach.

[natduca]

Wow @egonelbre that patch was excellent. Ship it. :)

[dj2]

As a general reitveld note, it's better to put [NOT FOR LANDING] in the description then the title. Rietveld never seems to update the email title after sending the first one so it's really confusing to get not for landing in a email subject on a cl that's for landing, heh.

[catapult-bot]

Migrated to catapult-project/catapult#624