diff --git a/.github/ISSUE_TEMPLATE/timing.md b/.github/ISSUE_TEMPLATE/timing.md new file mode 100644 index 000000000..38a001578 --- /dev/null +++ b/.github/ISSUE_TEMPLATE/timing.md @@ -0,0 +1,5 @@ +--- +name: "package:timing" +about: "Create a bug or file a feature request against package:timing." +labels: "package:timing" +--- \ No newline at end of file diff --git a/.github/labeler.yml b/.github/labeler.yml index 1cc4b2058..35bba8f7a 100644 --- a/.github/labeler.yml +++ b/.github/labeler.yml @@ -108,6 +108,10 @@ - changed-files: - any-glob-to-any-file: 'pkgs/sse/**' +'package:timing': + - changed-files: + - any-glob-to-any-file: 'pkgs/timing/**' + 'package:unified_analytics': - changed-files: - any-glob-to-any-file: 'pkgs/unified_analytics/**' diff --git a/.github/workflows/timing.yaml b/.github/workflows/timing.yaml new file mode 100644 index 000000000..df77b137e --- /dev/null +++ b/.github/workflows/timing.yaml @@ -0,0 +1,67 @@ +name: package:timing + +on: + # Run on PRs and pushes to the default branch. + push: + branches: [ main ] + paths: + - '.github/workflows/timing.yaml' + - 'pkgs/timing/**' + pull_request: + branches: [ main ] + paths: + - '.github/workflows/timing.yaml' + - 'pkgs/timing/**' + schedule: + - cron: "0 0 * * 0" + +env: + PUB_ENVIRONMENT: bot.github + + +defaults: + run: + working-directory: pkgs/timing/ + +jobs: + # Check code formatting and static analysis on a single OS (linux) + # against Dart dev. + analyze: + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + sdk: [3.4, dev] + steps: + - uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 + - uses: dart-lang/setup-dart@e630b99d28a3b71860378cafdc2a067c71107f94 + with: + sdk: ${{ matrix.sdk }} + - id: install + run: dart pub get + - run: dart format --output=none --set-exit-if-changed . + if: always() && steps.install.outcome == 'success' + - run: dart analyze --fatal-infos + if: always() && steps.install.outcome == 'success' + + # Run tests on a matrix consisting of two dimensions: + # 1. OS: ubuntu-latest, (macos-latest, windows-latest) + # 2. release channel: dev, 2.2.0 + test: + needs: analyze + runs-on: ${{ matrix.os }} + strategy: + fail-fast: false + matrix: + # Add macos-latest and/or windows-latest if relevant for this package. + os: [ubuntu-latest] + sdk: [3.4, dev] + steps: + - uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 + - uses: dart-lang/setup-dart@e630b99d28a3b71860378cafdc2a067c71107f94 + with: + sdk: ${{ matrix.sdk }} + - id: install + run: dart pub get + - run: dart test --platform vm + if: always() && steps.install.outcome == 'success' diff --git a/README.md b/README.md index 79d1dde21..013ac0929 100644 --- a/README.md +++ b/README.md @@ -40,6 +40,7 @@ don't naturally belong to other topic monorepos (like | [source_maps](pkgs/source_maps/) | A library to programmatically manipulate source map files. | [![package issues](https://img.shields.io/badge/package:source_maps-4774bc)](https://github.com/dart-lang/tools/issues?q=is%3Aissue+is%3Aopen+label%3Apackage%3Asource_maps) | [![pub package](https://img.shields.io/pub/v/source_maps.svg)](https://pub.dev/packages/source_maps) | | [source_span](pkgs/source_span/) | Provides a standard representation for source code locations and spans. | [![package issues](https://img.shields.io/badge/package:source_span-4774bc)](https://github.com/dart-lang/tools/issues?q=is%3Aissue+is%3Aopen+label%3Apackage%3Asource_span) | [![pub package](https://img.shields.io/pub/v/source_span.svg)](https://pub.dev/packages/source_span) | | [sse](pkgs/sse/) | Provides client and server functionality for setting up bi-directional communication through Server Sent Events (SSE) and corresponding POST requests. | [![package issues](https://img.shields.io/badge/package:sse-4774bc)](https://github.com/dart-lang/tools/issues?q=is%3Aissue+is%3Aopen+label%3Apackage%3Asse) | [![pub package](https://img.shields.io/pub/v/sse.svg)](https://pub.dev/packages/sse) | +| [timing](pkgs/timing/) | A simple package for tracking the performance of synchronous and asynchronous actions. | [![package issues](https://img.shields.io/badge/package:timing-4774bc)](https://github.com/dart-lang/tools/issues?q=is%3Aissue+is%3Aopen+label%3Apackage%3Atiming) | [![pub package](https://img.shields.io/pub/v/timing.svg)](https://pub.dev/packages/timing) | | [unified_analytics](pkgs/unified_analytics/) | A package for logging analytics for all Dart and Flutter related tooling to Google Analytics. | [![package issues](https://img.shields.io/badge/package:unified_analytics-4774bc)](https://github.com/dart-lang/tools/issues?q=is%3Aissue+is%3Aopen+label%3Apackage%3Aunified_analytics) | [![pub package](https://img.shields.io/pub/v/unified_analytics.svg)](https://pub.dev/packages/unified_analytics) | ## Publishing automation diff --git a/pkgs/timing/.gitignore b/pkgs/timing/.gitignore new file mode 100644 index 000000000..1ddf798b7 --- /dev/null +++ b/pkgs/timing/.gitignore @@ -0,0 +1,7 @@ +.packages +/build/ +pubspec.lock + +# Files generated by dart tools +.dart_tool +doc/ diff --git a/pkgs/timing/CHANGELOG.md b/pkgs/timing/CHANGELOG.md new file mode 100644 index 000000000..8cdb8eadc --- /dev/null +++ b/pkgs/timing/CHANGELOG.md @@ -0,0 +1,34 @@ +## 1.0.2 + +- Require Dart `3.4`. +- Move to `dart-lang/tools` monorepo. + +## 1.0.1 + +- Require Dart `2.14`. + +## 1.0.0 + +- Enable null safety. +- Require Dart `2.12`. + +## 0.1.1+3 + +- Allow `package:json_annotation` `'>=1.0.0 <5.0.0'`. + +## 0.1.1+2 + +- Support the latest version of `package:json_annotation`. +- Require Dart 2.2 or later. + +## 0.1.1+1 + +- Support the latest version of `package:json_annotation`. + +## 0.1.1 + +- Add JSON serialization + +## 0.1.0 + +- Initial release diff --git a/pkgs/timing/LICENSE b/pkgs/timing/LICENSE new file mode 100644 index 000000000..9972f6e70 --- /dev/null +++ b/pkgs/timing/LICENSE @@ -0,0 +1,27 @@ +Copyright 2018, the Dart project authors. + +Redistribution and use in source and binary forms, with or without +modification, are permitted provided that the following conditions are +met: + + * Redistributions of source code must retain the above copyright + notice, this list of conditions and the following disclaimer. + * Redistributions in binary form must reproduce the above + copyright notice, this list of conditions and the following + disclaimer in the documentation and/or other materials provided + with the distribution. + * Neither the name of Google LLC nor the names of its + contributors may be used to endorse or promote products derived + from this software without specific prior written permission. + +THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +(INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. diff --git a/pkgs/timing/README.md b/pkgs/timing/README.md new file mode 100644 index 000000000..9dab7cc51 --- /dev/null +++ b/pkgs/timing/README.md @@ -0,0 +1,30 @@ +[![Build Status](https://github.com/dart-lang/tools/actions/workflows/timing.yaml/badge.svg)](https://github.com/dart-lang/tools/actions/workflows/timing.yaml) +[![pub package](https://img.shields.io/pub/v/timing.svg)](https://pub.dev/packages/timing) +[![package publisher](https://img.shields.io/pub/publisher/timing.svg)](https://pub.dev/packages/timing/publisher) + +Timing is a simple package for tracking performance of both async and sync actions + +## Usage + +```dart +var tracker = AsyncTimeTracker(); +await tracker.track(() async { + // some async code here +}); + +// Use results +print('${tracker.duration} ${tracker.innerDuration} ${tracker.slices}'); +``` + +## Building + +Use the following command to re-generate `lib/src/timing.g.dart` file: + +```bash +dart pub run build_runner build +``` + +## Publishing automation + +For information about our publishing automation and release process, see +https://github.com/dart-lang/ecosystem/wiki/Publishing-automation. diff --git a/pkgs/timing/analysis_options.yaml b/pkgs/timing/analysis_options.yaml new file mode 100644 index 000000000..396236d68 --- /dev/null +++ b/pkgs/timing/analysis_options.yaml @@ -0,0 +1,2 @@ +# https://dart.dev/tools/analysis#the-analysis-options-file +include: package:dart_flutter_team_lints/analysis_options.yaml diff --git a/pkgs/timing/lib/src/clock.dart b/pkgs/timing/lib/src/clock.dart new file mode 100644 index 000000000..6a9d29509 --- /dev/null +++ b/pkgs/timing/lib/src/clock.dart @@ -0,0 +1,20 @@ +// Copyright (c) 2017, the Dart project authors. Please see the AUTHORS file +// for details. All rights reserved. Use of this source code is governed by a +// BSD-style license that can be found in the LICENSE file. + +import 'dart:async'; + +/// A function that returns the current [DateTime]. +typedef _Clock = DateTime Function(); +DateTime _defaultClock() => DateTime.now(); + +const _zoneKey = #timing_Clock; + +/// Returns the current [DateTime]. +/// +/// May be overridden for tests using [scopeClock]. +DateTime now() => (Zone.current[_zoneKey] as _Clock? ?? _defaultClock)(); + +/// Runs [f], with [clock] scoped whenever [now] is called. +T scopeClock(DateTime Function() clock, T Function() f) => + runZoned(f, zoneValues: {_zoneKey: clock}); diff --git a/pkgs/timing/lib/src/timing.dart b/pkgs/timing/lib/src/timing.dart new file mode 100644 index 000000000..049ba8189 --- /dev/null +++ b/pkgs/timing/lib/src/timing.dart @@ -0,0 +1,338 @@ +// Copyright (c) 2018, the Dart project authors. Please see the AUTHORS file +// for details. All rights reserved. Use of this source code is governed by a +// BSD-style license that can be found in the LICENSE file. + +import 'dart:async'; + +import 'package:json_annotation/json_annotation.dart'; + +import 'clock.dart'; + +part 'timing.g.dart'; + +/// The timings of an operation, including its [startTime], [stopTime], and +/// [duration]. +@JsonSerializable() +class TimeSlice { + /// The total duration of this operation, equivalent to taking the difference + /// between [stopTime] and [startTime]. + Duration get duration => stopTime.difference(startTime); + + final DateTime startTime; + + final DateTime stopTime; + + TimeSlice(this.startTime, this.stopTime); + + factory TimeSlice.fromJson(Map json) => + _$TimeSliceFromJson(json); + + Map toJson() => _$TimeSliceToJson(this); + + @override + String toString() => '($startTime + $duration)'; +} + +/// The timings of an async operation, consist of several sync [slices] and +/// includes total [startTime], [stopTime], and [duration]. +@JsonSerializable() +class TimeSliceGroup implements TimeSlice { + final List slices; + + @override + DateTime get startTime => slices.first.startTime; + + @override + DateTime get stopTime => slices.last.stopTime; + + /// The total duration of this operation, equivalent to taking the difference + /// between [stopTime] and [startTime]. + @override + Duration get duration => stopTime.difference(startTime); + + /// Sum of [duration]s of all [slices]. + /// + /// If some of slices implements [TimeSliceGroup] [innerDuration] will be used + /// to compute sum. + Duration get innerDuration => slices.fold( + Duration.zero, + (duration, slice) => + duration + + (slice is TimeSliceGroup ? slice.innerDuration : slice.duration)); + + TimeSliceGroup(this.slices); + + /// Constructs TimeSliceGroup from JSON representation + factory TimeSliceGroup.fromJson(Map json) => + _$TimeSliceGroupFromJson(json); + + @override + Map toJson() => _$TimeSliceGroupToJson(this); + + @override + String toString() => slices.toString(); +} + +abstract class TimeTracker implements TimeSlice { + /// Whether tracking is active. + /// + /// Tracking is only active after `isStarted` and before `isFinished`. + bool get isTracking; + + /// Whether tracking is finished. + /// + /// Tracker can't be used as [TimeSlice] before it is finished + bool get isFinished; + + /// Whether tracking was started. + /// + /// Equivalent of `isTracking || isFinished` + bool get isStarted; + + T track(T Function() action); +} + +/// Tracks only sync actions +class SyncTimeTracker implements TimeTracker { + /// When this operation started, call [_start] to set this. + @override + DateTime get startTime => _startTime!; + DateTime? _startTime; + + /// When this operation stopped, call [_stop] to set this. + @override + DateTime get stopTime => _stopTime!; + DateTime? _stopTime; + + /// Start tracking this operation, must only be called once, before [_stop]. + void _start() { + assert(_startTime == null && _stopTime == null); + _startTime = now(); + } + + /// Stop tracking this operation, must only be called once, after [_start]. + void _stop() { + assert(_startTime != null && _stopTime == null); + _stopTime = now(); + } + + /// Splits tracker into two slices. + /// + /// Returns new [TimeSlice] started on [startTime] and ended now. Modifies + /// [startTime] of tracker to current time point + /// + /// Don't change state of tracker. Can be called only while [isTracking], and + /// tracker will sill be tracking after call. + TimeSlice _split() { + if (!isTracking) { + throw StateError('Can be only called while tracking'); + } + final splitPoint = now(); + final prevSlice = TimeSlice(_startTime!, splitPoint); + _startTime = splitPoint; + return prevSlice; + } + + @override + T track(T Function() action) { + if (isStarted) { + throw StateError('Can not be tracked twice'); + } + _start(); + try { + return action(); + } finally { + _stop(); + } + } + + @override + bool get isStarted => _startTime != null; + + @override + bool get isTracking => _startTime != null && _stopTime == null; + + @override + bool get isFinished => _startTime != null && _stopTime != null; + + @override + Duration get duration => _stopTime!.difference(_startTime!); + + /// Converts to JSON representation + /// + /// Can't be used before [isFinished] + @override + Map toJson() => _$TimeSliceToJson(this); +} + +/// Async actions returning [Future] will be tracked as single sync time span +/// from the beginning of execution till completion of future +class SimpleAsyncTimeTracker extends SyncTimeTracker { + @override + T track(T Function() action) { + if (isStarted) { + throw StateError('Can not be tracked twice'); + } + T result; + _start(); + try { + result = action(); + } catch (_) { + _stop(); + rethrow; + } + if (result is Future) { + return result.whenComplete(_stop) as T; + } else { + _stop(); + return result; + } + } +} + +/// No-op implementation of [SyncTimeTracker] that does nothing. +class NoOpTimeTracker implements TimeTracker { + static final sharedInstance = NoOpTimeTracker(); + + @override + Duration get duration => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + DateTime get startTime => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + DateTime get stopTime => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + bool get isStarted => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + bool get isTracking => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + bool get isFinished => + throw UnsupportedError('Unsupported in no-op implementation'); + + @override + T track(T Function() action) => action(); + + @override + Map toJson() => + throw UnsupportedError('Unsupported in no-op implementation'); +} + +/// Track all async execution as disjoint time [slices] in ascending order. +/// +/// Can [track] both async and sync actions. +/// Can exclude time of tested trackers. +/// +/// If tracked action spawns some dangled async executions behavior is't +/// defined. Tracked might or might not track time of such executions +class AsyncTimeTracker extends TimeSliceGroup implements TimeTracker { + final bool trackNested; + + static const _zoneKey = #timing_AsyncTimeTracker; + + AsyncTimeTracker({this.trackNested = true}) : super([]); + + T _trackSyncSlice(ZoneDelegate parent, Zone zone, T Function() action) { + // Ignore dangling runs after tracker completes + if (isFinished) { + return action(); + } + + final isNestedRun = slices.isNotEmpty && + slices.last is SyncTimeTracker && + (slices.last as SyncTimeTracker).isTracking; + final isExcludedNestedTrack = !trackNested && zone[_zoneKey] != this; + + // Exclude nested sync tracks + if (isNestedRun && isExcludedNestedTrack) { + final timer = slices.last as SyncTimeTracker; + // Split already tracked time into new slice. + // Replace tracker in slices.last with splitted slice, to indicate for + // recursive calls that we not tracking. + slices.last = parent.run(zone, timer._split); + try { + return action(); + } finally { + // Split tracker again and discard slice from nested tracker + parent.run(zone, timer._split); + // Add tracker back to list of slices and continue tracking + slices.add(timer); + } + } + + // Exclude nested async tracks + if (isExcludedNestedTrack) { + return action(); + } + + // Split time slices in nested sync runs + if (isNestedRun) { + return action(); + } + + final timer = SyncTimeTracker(); + slices.add(timer); + + // Pass to parent zone, in case of overwritten clock + return parent.runUnary(zone, timer.track, action); + } + + static final asyncTimeTrackerZoneSpecification = ZoneSpecification( + run: (Zone self, ZoneDelegate parent, Zone zone, R Function() f) { + final tracker = self[_zoneKey] as AsyncTimeTracker; + return tracker._trackSyncSlice(parent, zone, () => parent.run(zone, f)); + }, + runUnary: (Zone self, ZoneDelegate parent, Zone zone, R Function(T) f, + T arg) { + final tracker = self[_zoneKey] as AsyncTimeTracker; + return tracker._trackSyncSlice( + parent, zone, () => parent.runUnary(zone, f, arg)); + }, + runBinary: (Zone self, ZoneDelegate parent, Zone zone, + R Function(T1, T2) f, T1 arg1, T2 arg2) { + final tracker = self[_zoneKey] as AsyncTimeTracker; + return tracker._trackSyncSlice( + parent, zone, () => parent.runBinary(zone, f, arg1, arg2)); + }, + ); + + @override + T track(T Function() action) { + if (isStarted) { + throw StateError('Can not be tracked twice'); + } + _tracking = true; + final result = runZoned(action, + zoneSpecification: asyncTimeTrackerZoneSpecification, + zoneValues: {_zoneKey: this}); + if (result is Future) { + return result + // Break possible sync processing of future completion, so slice + // trackers can be finished + .whenComplete(Future.value) + .whenComplete(() => _tracking = false) as T; + } else { + _tracking = false; + return result; + } + } + + bool? _tracking; + + @override + bool get isStarted => _tracking != null; + + @override + bool get isFinished => _tracking == false; + + @override + bool get isTracking => _tracking == true; +} diff --git a/pkgs/timing/lib/src/timing.g.dart b/pkgs/timing/lib/src/timing.g.dart new file mode 100644 index 000000000..679c082ff --- /dev/null +++ b/pkgs/timing/lib/src/timing.g.dart @@ -0,0 +1,29 @@ +// GENERATED CODE - DO NOT MODIFY BY HAND + +part of 'timing.dart'; + +// ************************************************************************** +// JsonSerializableGenerator +// ************************************************************************** + +TimeSlice _$TimeSliceFromJson(Map json) => TimeSlice( + DateTime.parse(json['startTime'] as String), + DateTime.parse(json['stopTime'] as String), + ); + +Map _$TimeSliceToJson(TimeSlice instance) => { + 'startTime': instance.startTime.toIso8601String(), + 'stopTime': instance.stopTime.toIso8601String(), + }; + +TimeSliceGroup _$TimeSliceGroupFromJson(Map json) => + TimeSliceGroup( + (json['slices'] as List) + .map((e) => TimeSlice.fromJson(e as Map)) + .toList(), + ); + +Map _$TimeSliceGroupToJson(TimeSliceGroup instance) => + { + 'slices': instance.slices, + }; diff --git a/pkgs/timing/lib/timing.dart b/pkgs/timing/lib/timing.dart new file mode 100644 index 000000000..5cb16d423 --- /dev/null +++ b/pkgs/timing/lib/timing.dart @@ -0,0 +1,13 @@ +// Copyright (c) 2018, the Dart project authors. Please see the AUTHORS file +// for details. All rights reserved. Use of this source code is governed by a +// BSD-style license that can be found in the LICENSE file. + +export 'src/timing.dart' + show + AsyncTimeTracker, + NoOpTimeTracker, + SimpleAsyncTimeTracker, + SyncTimeTracker, + TimeSlice, + TimeSliceGroup, + TimeTracker; diff --git a/pkgs/timing/pubspec.yaml b/pkgs/timing/pubspec.yaml new file mode 100644 index 000000000..891a8af3d --- /dev/null +++ b/pkgs/timing/pubspec.yaml @@ -0,0 +1,18 @@ +name: timing +version: 1.0.2 +description: >- + A simple package for tracking the performance of synchronous and asynchronous + actions. +repository: https://github.com/dart-lang/tools/tree/main/pkgs/timing + +environment: + sdk: ^3.4.0 + +dependencies: + json_annotation: ^4.9.0 + +dev_dependencies: + build_runner: ^2.0.6 + dart_flutter_team_lints: ^3.0.0 + json_serializable: ^6.0.0 + test: ^1.17.10 diff --git a/pkgs/timing/test/timing_test.dart b/pkgs/timing/test/timing_test.dart new file mode 100644 index 000000000..b5836d9d2 --- /dev/null +++ b/pkgs/timing/test/timing_test.dart @@ -0,0 +1,416 @@ +// Copyright (c) 2018, the Dart project authors. Please see the AUTHORS file +// for details. All rights reserved. Use of this source code is governed by a +// BSD-style license that can be found in the LICENSE file. + +// ignore_for_file: only_throw_errors, inference_failure_on_instance_creation + +import 'dart:async'; + +import 'package:test/test.dart'; +import 'package:timing/src/clock.dart'; +import 'package:timing/src/timing.dart'; + +void _noop() {} + +void main() { + late DateTime time; + final startTime = DateTime(2017); + DateTime fakeClock() => time; + + late TimeTracker tracker; + late TimeTracker nestedTracker; + + T scopedTrack(T Function() f) => + scopeClock(fakeClock, () => tracker.track(f)); + + setUp(() { + time = startTime; + }); + + void canHandleSync([void Function() additionalExpects = _noop]) { + test('Can track sync code', () { + expect(tracker.isStarted, false); + expect(tracker.isTracking, false); + expect(tracker.isFinished, false); + scopedTrack(() { + expect(tracker.isStarted, true); + expect(tracker.isTracking, true); + expect(tracker.isFinished, false); + time = time.add(const Duration(seconds: 5)); + }); + expect(tracker.isStarted, true); + expect(tracker.isTracking, false); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 5)); + additionalExpects(); + }); + + test('Can track handled sync exceptions', () async { + scopedTrack(() { + try { + time = time.add(const Duration(seconds: 4)); + throw 'error'; + } on String { + time = time.add(const Duration(seconds: 1)); + } + }); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 5)); + additionalExpects(); + }); + + test('Can track in case of unhandled sync exceptions', () async { + expect( + () => scopedTrack(() { + time = time.add(const Duration(seconds: 5)); + throw 'error'; + }), + throwsA(const TypeMatcher())); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 5)); + additionalExpects(); + }); + + test('Can be nested sync', () { + scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + nestedTracker.track(() { + time = time.add(const Duration(seconds: 2)); + }); + time = time.add(const Duration(seconds: 4)); + }); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 7)); + expect(nestedTracker.startTime.isAfter(startTime), true); + expect(nestedTracker.stopTime.isBefore(time), true); + expect(nestedTracker.duration, const Duration(seconds: 2)); + additionalExpects(); + }); + } + + void canHandleAsync([void Function() additionalExpects = _noop]) { + test('Can track async code', () async { + expect(tracker.isStarted, false); + expect(tracker.isTracking, false); + expect(tracker.isFinished, false); + await scopedTrack(() => Future(() { + expect(tracker.isStarted, true); + expect(tracker.isTracking, true); + expect(tracker.isFinished, false); + time = time.add(const Duration(seconds: 5)); + })); + expect(tracker.isStarted, true); + expect(tracker.isTracking, false); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 5)); + additionalExpects(); + }); + + test('Can track handled async exceptions', () async { + await scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + return Future(() { + time = time.add(const Duration(seconds: 2)); + throw 'error'; + }).then((_) { + time = time.add(const Duration(seconds: 4)); + }).catchError((error, stack) { + time = time.add(const Duration(seconds: 8)); + }); + }); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 11)); + additionalExpects(); + }); + + test('Can track in case of unhandled async exceptions', () async { + final future = scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + return Future(() { + time = time.add(const Duration(seconds: 2)); + throw 'error'; + }).then((_) { + time = time.add(const Duration(seconds: 4)); + }); + }); + await expectLater(future, throwsA(const TypeMatcher())); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 3)); + additionalExpects(); + }); + + test('Can be nested async', () async { + await scopedTrack(() async { + time = time.add(const Duration(milliseconds: 1)); + await Future.value(); + time = time.add(const Duration(milliseconds: 2)); + await nestedTracker.track(() async { + time = time.add(const Duration(milliseconds: 4)); + await Future.value(); + time = time.add(const Duration(milliseconds: 8)); + await Future.value(); + time = time.add(const Duration(milliseconds: 16)); + }); + time = time.add(const Duration(milliseconds: 32)); + await Future.value(); + time = time.add(const Duration(milliseconds: 64)); + }); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(milliseconds: 127)); + expect(nestedTracker.startTime.isAfter(startTime), true); + expect(nestedTracker.stopTime.isBefore(time), true); + expect(nestedTracker.duration, const Duration(milliseconds: 28)); + additionalExpects(); + }); + } + + group('SyncTimeTracker', () { + setUp(() { + tracker = SyncTimeTracker(); + nestedTracker = SyncTimeTracker(); + }); + + canHandleSync(); + + test('Can not track async code', () async { + await scopedTrack(() => Future(() { + time = time.add(const Duration(seconds: 5)); + })); + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, startTime); + expect(tracker.duration, const Duration(seconds: 0)); + }); + }); + + group('AsyncTimeTracker.simple', () { + setUp(() { + tracker = SimpleAsyncTimeTracker(); + nestedTracker = SimpleAsyncTimeTracker(); + }); + + canHandleSync(); + + canHandleAsync(); + + test('Can not distinguish own async code', () async { + final future = scopedTrack(() => Future(() { + time = time.add(const Duration(seconds: 5)); + })); + time = time.add(const Duration(seconds: 10)); + await future; + expect(tracker.isFinished, true); + expect(tracker.startTime, startTime); + expect(tracker.stopTime, time); + expect(tracker.duration, const Duration(seconds: 15)); + }); + }); + + group('AsyncTimeTracker', () { + late AsyncTimeTracker asyncTracker; + late AsyncTimeTracker nestedAsyncTracker; + setUp(() { + tracker = asyncTracker = AsyncTimeTracker(); + nestedTracker = nestedAsyncTracker = AsyncTimeTracker(); + }); + + canHandleSync(() { + expect(asyncTracker.innerDuration, asyncTracker.duration); + expect(asyncTracker.slices.length, 1); + }); + + canHandleAsync(() { + expect(asyncTracker.innerDuration, asyncTracker.duration); + expect(asyncTracker.slices.length, greaterThan(1)); + }); + + test('Can track complex async innerDuration', () async { + final completer = Completer(); + final future = scopedTrack(() async { + time = time.add(const Duration(seconds: 1)); // Tracked sync + await Future.value(); + time = time.add(const Duration(seconds: 2)); // Tracked async + await completer.future; + time = time.add(const Duration(seconds: 4)); // Tracked async, delayed + }).then((_) { + time = time.add(const Duration(seconds: 8)); // Async, after tracking + }); + time = time.add(const Duration(seconds: 16)); // Sync, between slices + + await Future(() { + // Async, between slices + time = time.add(const Duration(seconds: 32)); + completer.complete(); + }); + await future; + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime.isBefore(time), true); + expect(asyncTracker.duration, const Duration(seconds: 55)); + expect(asyncTracker.innerDuration, const Duration(seconds: 7)); + expect(asyncTracker.slices.length, greaterThan(1)); + }); + + test('Can exclude nested sync', () { + tracker = asyncTracker = AsyncTimeTracker(trackNested: false); + scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + nestedAsyncTracker.track(() { + time = time.add(const Duration(seconds: 2)); + }); + time = time.add(const Duration(seconds: 4)); + }); + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime, time); + expect(asyncTracker.duration, const Duration(seconds: 7)); + expect(asyncTracker.innerDuration, const Duration(seconds: 5)); + expect(asyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker.stopTime.isBefore(time), true); + expect(nestedAsyncTracker.duration, const Duration(seconds: 2)); + expect(nestedAsyncTracker.innerDuration, const Duration(seconds: 2)); + expect(nestedAsyncTracker.slices.length, 1); + }); + + test('Can exclude complex nested sync', () { + tracker = asyncTracker = AsyncTimeTracker(trackNested: false); + nestedAsyncTracker = AsyncTimeTracker(trackNested: false); + final nestedAsyncTracker2 = AsyncTimeTracker(trackNested: false); + scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + nestedAsyncTracker.track(() { + time = time.add(const Duration(seconds: 2)); + nestedAsyncTracker2.track(() { + time = time.add(const Duration(seconds: 4)); + }); + time = time.add(const Duration(seconds: 8)); + }); + time = time.add(const Duration(seconds: 16)); + }); + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime, time); + expect(asyncTracker.duration, const Duration(seconds: 31)); + expect(asyncTracker.innerDuration, const Duration(seconds: 17)); + expect(asyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker.stopTime.isBefore(time), true); + expect(nestedAsyncTracker.duration, const Duration(seconds: 14)); + expect(nestedAsyncTracker.innerDuration, const Duration(seconds: 10)); + expect(nestedAsyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker2.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker2.stopTime.isBefore(time), true); + expect(nestedAsyncTracker2.duration, const Duration(seconds: 4)); + expect(nestedAsyncTracker2.innerDuration, const Duration(seconds: 4)); + expect(nestedAsyncTracker2.slices.length, 1); + }); + + test( + 'Can track all on grand-parent level and ' + 'exclude grand-childrens from parent', () { + tracker = asyncTracker = AsyncTimeTracker(trackNested: true); + nestedAsyncTracker = AsyncTimeTracker(trackNested: false); + final nestedAsyncTracker2 = AsyncTimeTracker(); + scopedTrack(() { + time = time.add(const Duration(seconds: 1)); + nestedAsyncTracker.track(() { + time = time.add(const Duration(seconds: 2)); + nestedAsyncTracker2.track(() { + time = time.add(const Duration(seconds: 4)); + }); + time = time.add(const Duration(seconds: 8)); + }); + time = time.add(const Duration(seconds: 16)); + }); + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime, time); + expect(asyncTracker.duration, const Duration(seconds: 31)); + expect(asyncTracker.innerDuration, const Duration(seconds: 31)); + expect(asyncTracker.slices.length, 1); + expect(nestedAsyncTracker.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker.stopTime.isBefore(time), true); + expect(nestedAsyncTracker.duration, const Duration(seconds: 14)); + expect(nestedAsyncTracker.innerDuration, const Duration(seconds: 10)); + expect(nestedAsyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker2.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker2.stopTime.isBefore(time), true); + expect(nestedAsyncTracker2.duration, const Duration(seconds: 4)); + expect(nestedAsyncTracker2.innerDuration, const Duration(seconds: 4)); + expect(nestedAsyncTracker2.slices.length, 1); + }); + + test('Can exclude nested async', () async { + tracker = asyncTracker = AsyncTimeTracker(trackNested: false); + await scopedTrack(() async { + time = time.add(const Duration(seconds: 1)); + await nestedAsyncTracker.track(() async { + time = time.add(const Duration(seconds: 2)); + await Future.value(); + time = time.add(const Duration(seconds: 4)); + await Future.value(); + time = time.add(const Duration(seconds: 8)); + }); + time = time.add(const Duration(seconds: 16)); + }); + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime, time); + expect(asyncTracker.duration, const Duration(seconds: 31)); + expect(asyncTracker.innerDuration, const Duration(seconds: 17)); + expect(asyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker.stopTime.isBefore(time), true); + expect(nestedAsyncTracker.duration, const Duration(seconds: 14)); + expect(nestedAsyncTracker.innerDuration, const Duration(seconds: 14)); + expect(nestedAsyncTracker.slices.length, greaterThan(1)); + }); + + test('Can handle callbacks in excluded nested async', () async { + tracker = asyncTracker = AsyncTimeTracker(trackNested: false); + await scopedTrack(() async { + time = time.add(const Duration(seconds: 1)); + final completer = Completer(); + final future = completer.future.then((_) { + time = time.add(const Duration(seconds: 2)); + }); + await nestedAsyncTracker.track(() async { + time = time.add(const Duration(seconds: 4)); + await Future.value(); + time = time.add(const Duration(seconds: 8)); + completer.complete(); + await future; + time = time.add(const Duration(seconds: 16)); + }); + time = time.add(const Duration(seconds: 32)); + }); + expect(asyncTracker.isFinished, true); + expect(asyncTracker.startTime, startTime); + expect(asyncTracker.stopTime, time); + expect(asyncTracker.duration, const Duration(seconds: 63)); + expect(asyncTracker.innerDuration, const Duration(seconds: 35)); + expect(asyncTracker.slices.length, greaterThan(1)); + expect(nestedAsyncTracker.startTime.isAfter(startTime), true); + expect(nestedAsyncTracker.stopTime.isBefore(time), true); + expect(nestedAsyncTracker.duration, const Duration(seconds: 30)); + expect(nestedAsyncTracker.innerDuration, const Duration(seconds: 28)); + expect(nestedAsyncTracker.slices.length, greaterThan(1)); + }); + }); +}