Can't record past event using the dart:developer Timeline and TimelineTask APIs

[DanTup]

I thought it would be useful to be able to use the DevTools performance page for debugging performance issues with the analysis server. The server already has some classes that record performance internally that map fairly closely onto the TimelineTask class used for the Performance page.

However, when using it I can't get the parent/child relationship to show up in the graphs so it's a little tricky to follow what's happening.

It's possible I'm using it wrong (or have the wrong expectations).

Here's a small repro. The code just runs some nested async tasks, and uses TimelineTask to record them. Each nested task has its parent provided.

import 'dart:developer';

const levelNames = ['zero', 'one', 'two', 'three', 'four', 'five'];

Future<void> main() async {
  print('Open DevTols performance page, filter to just Dart events, '
      'then resume, wait for break, click Refresh');
  debugger();

  var rootTask = TimelineTask();
  rootTask.start('root');
  await doWork(1, rootTask);
  rootTask.finish();

  debugger();
}

Future<void> doWork(int level, TimelineTask parent) async {
  final task = TimelineTask(parent: parent);
  task.start('level ${levelNames[level]}');
  await Future<void>.delayed(const Duration(milliseconds: 200));

  if (level < 5) {
    await doWork(level + 1, task);
  }
  task.finish();
}

When I review this in the performance page, it looks like this (both the new and legacy views are essentially the same):

The top-to-bottom ordering of the categories is not as I'd expect (it looks alphabetical), and there's no indication of which bars are children of other bars (although it's fairly clear in this case, when each async tasks have awaits that could allow other code to run, this relationship would be important).

I was expecting/hoping for it to look more like this chart from the docs page:

[DanTup]

I tried with a v2.19 SDK and it appears the relationship is visible:

So I went back and tried 3.0. and 3.1 using the legacy view, and apparently I was mistaken, because it looks fine there:

I'm not sure what I did when I believed that the legacy view was broken in latest - perhaps the issue is entirely restricted to the new charts.

[DanTup]

Oh, here it is:

I think it happens if you first view the new UI. So perhaps the new UI is mutating (sorting?) the data in a way that then affects switching back to the old UI?

[kenzieschmoll]

The parent parameter was added to support the custom tracing view with guidelines that you showed here.

This was added because the chrome tracing format does not support a couple of tracing scenarios. Here's a snapshot of the original doc on this problem:

The proper way create events within a timeline task is by using the start and finish methods. Example:

Future<void> sendB() async {
  final b = TimelineTask();
  b.start('B');
  await Future.delayed(Duration(milliseconds: 20), () {
    b.start('B1');
  });
  await Future.delayed(Duration(milliseconds: 30), () {
    b.start('B2');
  });
  await Future.delayed(Duration(milliseconds: 50), () {
    b.finish();
  });
  await Future.delayed(Duration(milliseconds: 50), () {
    b.finish();
  });
  await Future.delayed(Duration(milliseconds: 100), () {
    b.finish();
  });
}

This produces the following in the trace viewer:

@bkonyi should we consider deprecating the parent parameter now that the DevTools trace viewer has been retired?

[DanTup]

Ah! I didn't realise I was allowed to call start/finish multiple times on the same instance (I think I had assumed it was mor elike the servers existing performance classes than it actually is). That solves my problem perfectly:

I'll close this as seems there's nothing to do, but feel free to re-purpose it if you decide to remove parent or something.

Thanks!

[DanTup]

@kenzieschmoll btw, two related questions:

1. ~~Sometimes it seems like the bars are double height~~ (totally user error :) )
2. Is there any way to record an event that happened in the past (eg. pass a timestamp of the event)? For server, it would be useful to see the latency of a request on the timeline. The client provides us a timestamp of then the request was sent, but if our isolate is busy we might not pick the request up immediately. It would be useful to see this on the chart (for example to tell whether GC or another request cause a request to not be picked up immediately).

[kenzieschmoll]

You can pass arguments to the start event: https://api.flutter.dev/flutter/dart-developer/TimelineTask/start.html. Then when you select the event on the timeline, the details section that pops up from the bottom of the trace viewer will allow you to see an event's arguments.

[DanTup]

@kenzieschmoll I'm using those, but I was hoping to see it in the timeline. Eg. if the latency is 100ms, I'd like to see a block labelled "latency" for 100ms, as if I'd done:

task.start('latency');
await delay(latency);
task.finish();

(but I can't do that, because I only know about the latency after it's happened)

[kenzieschmoll]

@dnfield do you have any techniques you use for finding latency like Danny is describing here?

[DanTup]

To clarify, this isn't latency necessarily happening inside the VM - part of this time is happening in another process (VS Code). The question is about whether we can record some time (to show up on the timeline) when we were only running Dart code when it finished, not when it started (but we know the timestamp of when the work started).

[dnfield]

TimelineTask is for async tasks. They don't get nested the same way. The nesting you were expecting to see can only happen if you have synchronous events, e.g. Timeline.startSync/finishSync or Timeline.timeSync.

If you have too many of these, you will run into overhead from recording the events themselves.

[DanTup]

@dnfield I'm a little confused - with the code Kenzie gave above I was able to time my async calls in the way I wanted (using a single TimelineTask and calling start/finish multiple times), see https://github.com/flutter/devtools/issues/5835#issuecomment-1557629640 above.

My outstanding question was about overriding the timestamp of an event though. Eg. if we have some additional data about an operation that started earlier than we're running Dart Code, could we pass a timestamp (or delta).

For example something like:

final task = TimelineTask();
task.start('latency', delta: Duration(seconds: -1));
task.finish();
task.start('processing...');
task.finish();

This could be useful when measuring things that go outside of the process - for example requests over a socket. If an incoming packet has a timestamp when it was created, you can compute the latency between the request being constructed on the other end, and your current process starting to process it. We already have this numerically, but it would be useful to see in the timeline because the latency could be caused by another item on the timeline, and the overlap would be really obvious.

(it's not a big deal, but if there's a way to do it it would certainly be useful to me)

[kenzieschmoll]

@bkonyi should we consider deprecating the parent parameter now that the DevTools trace viewer has been retired?

@bkonyi It looks like this is getting used more than we might have anticipated (see CS search query). I wonder how many of these use cases are being used not how this API was intended, or in other words being used in a way where using .start and .finish would have been sufficient (like in Danny's case).

[dnfield]

Ahh sorry, I misread it.

You should be able to provide the arguments parameter to start or finish depending on which makes sense. But I don't think those get surfaced in the Perfetto viewer right now, they'd have to be exported and viewed in Catapult (chrome://tracing).

[dnfield]

Also keep in mind that there's a non-trivial cost to serializing arguments

[kenzieschmoll]

Arguments do show up in the Perfetto viewer in DevTools because we are using the chrome trace format and recording from the VM, not systrace. If we were using the systrace recorder, they would not be included.

[dnfield]

Ahh nice, thanks for the clarification

[DanTup]

You should be able to provide the arguments parameter to start or finish depending on which makes sense

I am using these currently, but they're only shown as text. I was hoping to have something visible on the chart, like this:

We have latency show up in the timing graphics on the analysis server diagnostic pages (grey) and it can be quite useful when looking at performance issues (latency can be caused by the server being busy in ways that isn't always visible from request/response timings):

[dnfield]

@DanTup - maybe a GVC would be helpful at this point. We're trying to figure out what's missing from your screenshot that you want - it looks like the bar under the green one is already showing you the latency cost you're describing, but maybe there's something we're missing.

[DanTup]

@dnfield sure! I'm in the UK so it'll have to be morning if you're on the west coast (feel free to ping me on chat or discord - I sent you a friend request there).

But in case it helps clarify:

• The "latency" I'm referring to is a concept of the server, and not some latency Dart could know about
• The latency starts in another process so I only know about it after it has already happened

What I was trying to do was:

• accept a JSON messages from some stream
• look at the timestamp in that message that says when the message was created by the sender (another process)
• include an event on the timeline that "started" that long ago, and finished now

like:

void handleIncomingMessage(Message message) {
  // compute the latency between the client constructing this message and us starting to process it
  var latencyMilliseconds = DateTime.now().millisecondsSinceEpoch - message.clientRequestTime;
  var task = TimelineTask();
  task.recordPastEvent('latency', latencyMilliseconds); // something here to record this event that started in the past and finished now
  task.start('process request');
  _processRequest(message);
  task.finish();
}

This way, the "latency" block would be visible on the timeline (which might be useful if the latency is caused by the server being busy running other synchronous tasks that overlap it).

[kenzieschmoll]

@bkonyi would it be reasonable to extend the Timeline API in dart:developer to handle this case?

[elliette]

cc @schultek