Merge pull request #115 from Workiva/AF-1540_consumer-specified-timing

AF-1540 AF-2674  consumer-specified timing for "first useful state"

Author: rmconsole6-wk

docs.yml

@@ -1,3 +1,6 @@
 title: w_module
 base: github:Workiva/w_module/
-src: README.md
+src: README.md
+topics:
+  - title: Tracing with w_module
+    src: docs/tracing.md

documentation/tracing.md

@@ -0,0 +1,73 @@
+# Tracing with w_module
+
+This library supports [OpenTracing][opentracingio] using [opentracing_dart][opentracingdart]. Your application will need to provide a `Tracer` and initialize it with `initGlobalTracer` to opt in to this feature.
+
+
+To get the traces provided by this library, your module must provide a definition for the `name` getter. This can simply be the name of the class. For example:
+
+```dart
+class SomeModule extends Module {
+  @override
+  final String name = 'SomeModule';
+  
+  // ... the of the module's implementation
+}
+```
+
+Spans will be in the form of:
+
+```
+$name.$operationName
+```
+
+## Types Of Provided Traces
+
+### Tracing Lifecycle Methods
+
+We automically trace each of its lifecycle methods:
+
+- Load
+- Unload
+- Suspend
+- Resume
+
+In addition, any spans created by child modules (loaded with `loadChildModule`) will have a `followsFrom` reference to the parent's span of the respective method to complete the story of the trace.
+
+If you wish to create other `childOf` or `followsFrom` spans on your module's lifecycle spans, you can simply request the `activeSpan`:
+
+```dart
+  @override
+  Future<Null> onLoad() {
+    // ... some loading logic
+
+    final span = globalTracer().startSpan(
+      operationName,
+      childOf: activeSpan.context, // see this line
+    );
+
+    // ... more loading logic
+    span.finish()
+  }
+```
+
+Note that `activeSpan` will be null at times when the module is not in the middle of a lifecycle transition.
+
+### Additional Load Time Granularity
+
+Sometimes, lifecycle methods such as `load` will complete before the module is semantically "loaded". For example, you may begin asynchronously fetching data for your module and then return from `onLoad` to keep from blocking the main thread.
+
+In cases like these, use `specifyStartupTiming`:
+
+```dart
+  Future<Null> onLoad() {
+    // ... kick off async loadData logic
+
+    listenToStream(_events.didLoadData.take(1),
+        (_) => specifyStartupTiming(StartupTimingType.firstUseful));
+  }
+```
+
+This will create a span starting from the same time as `load()` and ending at the moment the method was called. This library will handle the `operationName` and the `followsFrom` reference to the module's `load` span, but tags and references can be passed into this method just like with any other span in optional parameters.
+
+[opentracingio]: https://opentracing.io/
+[opentracingdart]: https://github.com/Workiva/opentracing_dart/

example/panel/modules/data_load_async_module.dart

@@ -18,6 +18,7 @@ import 'dart:async';
 
 import 'package:meta/meta.dart' show protected;
 import 'package:react/react.dart' as react;
+import 'package:w_common/disposable.dart';
 import 'package:w_flux/w_flux.dart';
 import 'package:w_module/w_module.dart';
 
@@ -27,12 +28,16 @@ class DataLoadAsyncModule extends Module {
 
   DataLoadAsyncActions _actions;
   DataLoadAsyncComponents _components;
-  DataLoadAsyncStore _stores;
+  DataLoadAsyncEvents _events;
+  DataLoadAsyncStore _store;
 
   DataLoadAsyncModule() {
     _actions = new DataLoadAsyncActions();
-    _stores = new DataLoadAsyncStore(_actions);
-    _components = new DataLoadAsyncComponents(_actions, _stores);
+    _events = new DataLoadAsyncEvents();
+    _store = new DataLoadAsyncStore(_actions, _events);
+    _components = new DataLoadAsyncComponents(_actions, _store);
+
+    <Disposable>[_events, _store].forEach(manageDisposable);
   }
 
   @override
@@ -42,6 +47,8 @@ class DataLoadAsyncModule extends Module {
   @protected
   Future<Null> onLoad() {
     // trigger non-blocking async load of data
+    listenToStream(_events.didLoadData.take(1),
+        (_) => specifyStartupTiming(StartupTimingType.firstUseful));
     _actions.loadData();
     return new Future.value();
   }
@@ -62,15 +69,23 @@ class DataLoadAsyncActions {
   final Action loadData = new Action();
 }
 
+DispatchKey _dispatchKey = new DispatchKey('DataLoadAsync');
+
+class DataLoadAsyncEvents extends EventsCollection {
+  final Event didLoadData = new Event(_dispatchKey);
+  DataLoadAsyncEvents() : super(_dispatchKey) {
+    manageEvent(new Event(_dispatchKey));
+  }
+}
+
 class DataLoadAsyncStore extends Store {
   DataLoadAsyncActions _actions;
-  List<String> _data;
-  bool _isLoading;
+  DataLoadAsyncEvents _events;
+  List<String> _data = [];
+  bool _isLoading = false;
 
-  DataLoadAsyncStore(this._actions) {
-    _isLoading = false;
-    _data = [];
-    triggerOnAction(_actions.loadData, _loadData);
+  DataLoadAsyncStore(this._actions, this._events) {
+    manageActionSubscription(_actions.loadData.listen(_loadData));
   }
 
   /// Public data
@@ -89,6 +104,8 @@ class DataLoadAsyncStore extends Store {
     // trigger on return of final data
     _data = ['Aaron', 'Dustin', 'Evan', 'Jay', 'Max', 'Trent'];
     _isLoading = false;
+    _events.didLoadData(null, _dispatchKey);
+    trigger();
   }
 }
 

example/panel/modules/sample_tracer.dart

@@ -130,8 +130,7 @@ class SampleTracer implements AbstractTracer {
       references: references,
       startTime: startTime,
       tags: tags,
-    )
-      ..whenFinished.then((span) {
+    )..whenFinished.then((span) {
         print(span.toString());
       });
   }

lib/src/lifecycle_module.dart

@@ -22,6 +22,7 @@ import 'package:opentracing/opentracing.dart';
 import 'package:w_common/disposable.dart';
 
 import 'package:w_module/src/simple_module.dart';
+import 'package:w_module/src/timing_specifiers.dart';
 
 /// Possible states a [LifecycleModule] may occupy.
 enum LifecycleState {
@@ -54,7 +55,7 @@ enum LifecycleState {
 /// unified lifecycle API.
 abstract class LifecycleModule extends SimpleModule with Disposable {
   static int _nextId = 0;
-
+  // Used by tracing to tell apart multiple instances of the same module
   int _instanceId = _nextId++;
 
   List<LifecycleModule> _childModules = [];
@@ -64,7 +65,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
   LifecycleState _state = LifecycleState.instantiated;
   Completer<Null> _transition;
   Span _activeSpan;
-  SpanContext _loadSpanContext;
+
+  // Used by tracing to create a span if the consumer specifies when the module
+  // reaches its first useful state
+  DateTime _startLoadTime;
 
   // Lifecycle event StreamControllers
   StreamController<LifecycleModule> _willLoadChildModuleController =
@@ -116,9 +120,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
       _didUnloadController,
     ].forEach(manageStreamController);
 
-    <
-        String,
-        Stream>{
+    <String, Stream>{
       'willLoad': willLoad,
       'didLoad': didLoad,
       'willLoadChildModule': willLoadChildModule,
@@ -153,6 +155,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
   @protected
   Span get activeSpan => _activeSpan;
 
+  /// Set internally by this module for the load span so it can be used as a
+  /// `Reference` to other spans after the span is finished.
+  SpanContext _loadContext;
+
   /// Set internally by the parent module if this module is called by [loadChildModule]
   SpanContext _parentContext;
 
@@ -177,16 +183,74 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
       references.add(new Reference.followsFrom(_parentContext));
     }
 
-    return tracer.startSpan('$name.$operationName', references: references)
-      ..addTags({
-        'module.instanceId': _instanceId,
-      });
+    return tracer.startSpan(
+      '$name.$operationName',
+      references: references,
+      tags: _defaultTags,
+    );
+  }
+
+  /// Creates a span with `globalTracer` from the start of [load] until now.
+  ///
+  /// This span is intended to represent the time it takes for the module to
+  /// finish asynchronously loading any necessary data and entering a state which
+  /// is ready for user interaction.
+  ///
+  /// Any [tags] or [references] specified will be added to this span.
+  @protected
+  void specifyFirstUsefulState({
+    Map<String, dynamic> tags: const {},
+    List<Reference> references: const [],
+  }) =>
+      specifyStartupTiming(
+        StartupTimingType.firstUseful,
+        tags: tags,
+        references: references,
+      );
+
+  /// Creates a span with `globalTracer` from the start of [load] until now.
+  ///
+  /// The [specifier] indicates the purpose of this span.
+  ///
+  /// Any [tags] or [references] specified will be added to this span.
+  @protected
+  void specifyStartupTiming(
+    StartupTimingType specifier, {
+    Map<String, dynamic> tags: const {},
+    List<Reference> references: const [],
+  }) {
+    // Load didn't start
+    if (_loadContext == null || _startLoadTime == null) {
+      throw new StateError(
+          'Calling `specifyStartupTiming` before calling `load()`');
+    }
+
+    final tracer = globalTracer();
+    if (tracer == null) {
+      return null;
+    }
+
+    tracer
+        .startSpan(
+          '$name.${specifier.operationName}',
+          references: [tracer.followsFrom(_loadContext)]..addAll(references),
+          startTime: _startLoadTime,
+          tags: _defaultTags..addAll(tags),
+        )
+        .finish();
+
+    _startLoadTime = null;
   }
 
   /// Name of the module for identification in exceptions and debug messages.
   // ignore: unnecessary_getters_setters
   String get name => _defaultName;
 
+  Map<String, dynamic> get _defaultTags => {
+        'span.kind': 'client',
+        'module.instance_id': _instanceId,
+      };
+
   /// Deprecated: the module name should be defined by overriding the getter in
   /// a subclass and it should not be mutable.
   @deprecated
@@ -377,7 +441,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
     }
 
     _activeSpan = _startTransitionSpan('load');
-    _loadSpanContext = _activeSpan?.context;
+    _loadContext = _activeSpan?.context;
+    _startLoadTime = _activeSpan?.startTime;
 
     _state = LifecycleState.loading;
 
@@ -455,7 +520,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable {
 
       try {
         _childModules.add(childModule);
-        childModule._parentContext = _loadSpanContext;
+        childModule._parentContext = _loadContext;
 
         await childModule.load();
         await onDidLoadChildModule(childModule);

lib/src/timing_specifiers.dart

@@ -0,0 +1,11 @@
+/// The type of 'startup timing metric' to be used by `specifyStartupTiming`
+class StartupTimingType {
+  /// The `operationName` to be used for spans created using this [StartupTimingType].
+  final String operationName;
+
+  const StartupTimingType._(this.operationName);
+
+  /// Specifies that the module finished loading necessary data and is ready for user interaction.
+  static const StartupTimingType firstUseful =
+      const StartupTimingType._('entered_first_useful_state');
+}

lib/w_module.dart

@@ -26,3 +26,4 @@ export 'package:w_module/src/events_collection.dart';
 export 'package:w_module/src/lifecycle_module.dart' hide LifecycleState;
 export 'package:w_module/src/module.dart';
 export 'package:w_module/src/simple_module.dart';
+export 'package:w_module/src/timing_specifiers.dart';

pubspec.yaml

@@ -13,16 +13,16 @@ homepage: https://github.com/Workiva/w_module
 dependencies:
   logging: ^0.11.0
   meta: ^1.0.0
-  opentracing: ^0.2.1
+  opentracing: ^0.2.3
   platform_detect: ^1.1.0
   w_common: ^1.9.0
 
 dev_dependencies:
   browser: ^0.10.0+2
   coverage: ^0.7.3
   dart_dev: ^1.8.0
-  dart_style: ^0.2.16
-  dartdoc: ^0.9.0
+  dart_style: ^1.0.7
+  dartdoc: ">=0.13.0 <0.16.0"
   mockito: ^1.0.1
   react: ^3.0.0
   test: ^0.12.0