diff --git a/docs.yml b/docs.yml index c982e6ab..ea25afd3 100644 --- a/docs.yml +++ b/docs.yml @@ -1,3 +1,6 @@ title: w_module base: github:Workiva/w_module/ -src: README.md \ No newline at end of file +src: README.md +topics: + - title: Tracing with w_module + src: docs/tracing.md diff --git a/documentation/tracing.md b/documentation/tracing.md new file mode 100644 index 00000000..1ba41e5f --- /dev/null +++ b/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 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 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/ \ No newline at end of file diff --git a/example/panel/modules/data_load_async_module.dart b/example/panel/modules/data_load_async_module.dart index 6231176d..b11de0c1 100644 --- a/example/panel/modules/data_load_async_module.dart +++ b/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); + + [_events, _store].forEach(manageDisposable); } @override @@ -42,6 +47,8 @@ class DataLoadAsyncModule extends Module { @protected Future 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 _data; - bool _isLoading; + DataLoadAsyncEvents _events; + List _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(); } } diff --git a/example/panel/modules/sample_tracer.dart b/example/panel/modules/sample_tracer.dart index c636944e..3032a5f1 100644 --- a/example/panel/modules/sample_tracer.dart +++ b/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()); }); } diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 94613d7a..26cca641 100644 --- a/lib/src/lifecycle_module.dart +++ b/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 _childModules = []; @@ -64,7 +65,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { LifecycleState _state = LifecycleState.instantiated; Completer _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 _willLoadChildModuleController = @@ -116,9 +120,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _didUnloadController, ].forEach(manageStreamController); - < - 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 tags: const {}, + List 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 tags: const {}, + List 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 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); diff --git a/lib/src/timing_specifiers.dart b/lib/src/timing_specifiers.dart new file mode 100644 index 00000000..f1e63203 --- /dev/null +++ b/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'); +} diff --git a/lib/w_module.dart b/lib/w_module.dart index 374c2e38..2467cdd5 100644 --- a/lib/w_module.dart +++ b/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'; diff --git a/pubspec.yaml b/pubspec.yaml index 4eb55695..7b9b6415 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -13,7 +13,7 @@ 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 @@ -21,8 +21,8 @@ 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 diff --git a/smithy.yaml b/smithy.yaml deleted file mode 100644 index 9fac396e..00000000 --- a/smithy.yaml +++ /dev/null @@ -1,14 +0,0 @@ -project: dart -language: dart - -# dart 1.24.2 -runner_image: drydock-prod.workiva.net/workiva/smithy-runner-generator:203768 - -script: - - pub get --packages-dir - - xvfb-run -s '-screen 0 1024x768x24' pub run dart_dev test --pub-serve --web-compiler=dartdevc -p chrome -p vm - -artifacts: - build: - - ./pubspec.lock - diff --git a/test/lifecycle_module_test.dart b/test/lifecycle_module_test.dart index b613a133..946355dd 100644 --- a/test/lifecycle_module_test.dart +++ b/test/lifecycle_module_test.dart @@ -22,6 +22,7 @@ import 'package:opentracing/opentracing.dart'; import 'package:test/test.dart'; import 'package:w_module/src/lifecycle_module.dart'; +import 'package:w_module/src/timing_specifiers.dart'; import 'test_tracer.dart'; import 'utils.dart'; @@ -110,6 +111,23 @@ class TestLifecycleModule extends LifecycleModule { Future loadChildModule(LifecycleModule newModule) => super.loadChildModule(newModule); + @override + void specifyFirstUsefulState({ + Map tags: const {}, + List references: const [], + }) => + super.specifyFirstUsefulState(tags: tags, references: references); + + // Overriding without re-applying the @protected annotation allows us to call + // specifyStartupTiming in our tests below. + @override + void specifyStartupTiming( + StartupTimingType specifier, { + Map tags: const {}, + List references: const [], + }) => + super.specifyStartupTiming(specifier, tags: tags, references: references); + @override @protected Future onWillLoadChildModule(LifecycleModule module) async { @@ -346,6 +364,15 @@ TestTracer getTestTracer() { } void runTests(bool runSpanTests) { + test('Calling `specifyStartupTiming` without calling `load()` throws', () { + final module = new TestLifecycleModule(); + + expect( + () => module.specifyStartupTiming(StartupTimingType.firstUseful), + throwsStateError, + ); + }); + group('without children', () { TestLifecycleModule module; List subs = []; @@ -409,6 +436,76 @@ void runTests(bool runSpanTests) { await module.load(); }); + group('should record user specified timing', () { + DateTime startTime; + Span parentSpan; + + setUp(() async { + final Completer startTimeCompleter = new Completer(); + + subs.add(getTestTracer() + .onSpanFinish + .where( + (span) => span.operationName == 'TestLifecycleModule.load') + .listen(expectAsync1((span) { + startTimeCompleter.complete(span.startTime); + }))); + + await module.load(); + + startTime = await startTimeCompleter.future; + + parentSpan = getTestTracer().startSpan('custom span')..finish(); + }); + + tearDown(() { + startTime = null; + }); + + void specifyTimingTest( + StartupTimingType specifier, + void specifyDelegate( + {Map tags, List references}), + ) { + subs.add(getTestTracer() + .onSpanFinish + .where((span) => + span.operationName == + 'TestLifecycleModule.${specifier.operationName}') + .listen(expectAsync1((span) { + expect(span.startTime, startTime); + expect(span.tags, containsPair('custom.tag', 'custom value')); + expect(span.references.length, 2); + expect(span.references.map((ref) => ref.referencedContext), + contains(parentSpan.context)); + }))); + + specifyDelegate( + tags: {'custom.tag': 'custom value'}, + references: [getTestTracer().followsFrom(parentSpan.context)], + ); + } + + [ + StartupTimingType.firstUseful, + ].forEach((specifier) { + test('specifyStartupTiming for ${specifier.operationName}', () { + specifyTimingTest( + specifier, + ({tags, references}) => module.specifyStartupTiming( + specifier, + tags: tags, + references: references, + )); + }); + }); + + test('shorthand for firstUseful timing', () { + specifyTimingTest( + StartupTimingType.firstUseful, module.specifyFirstUsefulState); + }); + }); + test('activeSpan should be null when load is finished', () async { await module.load(); expect(module.activeSpan, isNull); @@ -1050,6 +1147,21 @@ void runTests(bool runSpanTests) { await module.resume(); }); + if (runSpanTests) { + test('should record a span', () async { + await gotoState(module, LifecycleState.suspended); + + subs.add(getTestTracer() + .onSpanFinish + .where( + (span) => span.operationName == 'TestLifecycleModule.resume') + .listen(expectAsync1((span) { + expect(span.tags['custom.resume.tag'], 'somevalue'); + }))); + + await module.resume(); + }); + } test('an error in suspend bubbles up during resume', () async { await gotoState(module, LifecycleState.loaded); @@ -1777,6 +1889,34 @@ void runTests(bool runSpanTests) { equals(['willSuspend', 'onSuspend', 'didSuspend'])); }); + if (runSpanTests) { + test('child module suspends should record spans', () async { + Completer childSpanCompleter = new Completer(); + + subs.add(getTestTracer() + .onSpanFinish + .where((span) => span.operationName == 'child.suspend') + .listen(expectAsync1((span) { + childSpanCompleter.complete(span); + }))); + + parentModule.eventList.clear(); + childModule.eventList.clear(); + await parentModule.suspend(); + expect(parentModule.eventList, + equals(['willSuspend', 'onSuspend', 'didSuspend'])); + expect(childModule.eventList, + equals(['willSuspend', 'onSuspend', 'didSuspend'])); + + final span = await childSpanCompleter.future; + await new Future(() {}); // wait for parent to finish suspending + + expect(parentSuspendContext?.spanId, isNotNull); + expect(span.parentContext.spanId, parentSuspendContext.spanId); + expect(span.tags['custom.suspend.tag'], 'somevalue'); + }); + } + test('an error in suspend bubbles up during resume', () async { assert(parentModule.isLoaded); @@ -2364,7 +2504,7 @@ void runTests(bool runSpanTests) { }); if (runSpanTests) { - test('should record a span for child with no parent', () async { + test('should record a span for child when parent has no name', () async { subs.add(getTestTracer() .onSpanFinish .where((span) => span.operationName == 'child.load') @@ -2376,7 +2516,8 @@ void runTests(bool runSpanTests) { await parentModule.loadChildModule(childModule); }); - test('should record a span with `error` tag and no parent', () async { + test('should record a span with `error` tag when parent has no name', + () async { childModule.onLoadError = testError; subs.add(getTestTracer() @@ -2391,7 +2532,8 @@ void runTests(bool runSpanTests) { throwsA(same(childModule.onLoadError))); }); - test('child module suspend should record spans with no parent', () async { + test('child module suspend should record spans when parent has no name', + () async { await parentModule.loadChildModule(childModule); subs.add(getTestTracer() .onSpanFinish @@ -2405,7 +2547,7 @@ void runTests(bool runSpanTests) { }); test( - 'child module suspend throws should record a span with `error` tag and no parent', + 'child module suspend throws should record a span with `error` tag and parent has no name', () async { await parentModule.loadChildModule(childModule); childModule.onSuspendError = testError; @@ -2422,7 +2564,8 @@ void runTests(bool runSpanTests) { parentModule.suspend(), throwsA(same(childModule.onSuspendError))); }); - test('child module resume should record a span with no parent', () async { + test('child module resume should record a span when parent has no name', + () async { await parentModule.loadChildModule(childModule); subs.add(getTestTracer() @@ -2438,7 +2581,7 @@ void runTests(bool runSpanTests) { }); test( - 'child module resume should record a span with `error` tag and no parent', + 'child module resume should record a span with `error` tag and parent has no name', () async { await parentModule.loadChildModule(childModule); childModule.onResumeError = testError; diff --git a/test/test_tracer.dart b/test/test_tracer.dart index ec1f5ef7..0df40080 100644 --- a/test/test_tracer.dart +++ b/test/test_tracer.dart @@ -35,7 +35,7 @@ class TestSpan implements Span { }) : this.startTime = startTime ?? new DateTime.now(), this.tags = tags ?? {}, - this.references = references ?? {} { + this.references = references ?? [] { if (childOf != null) { references.add(new Reference.childOf(childOf)); }