Merge pull request #322 from csf-dev/craigfowler/issue215

Resolve #215 - Record timings in reports

Author: craigfowler

CSF.Screenplay/ReportModel/PerformableReport.cs

@@ -35,6 +35,24 @@ public class PerformableReport : ReportableModelBase
         /// </remarks>
         public string PerformancePhase { get; set; }
 
+        /// <summary>
+        /// Gets or sets the relative time at which this performable ended/finished.
+        /// </summary>
+        /// <remarks>
+        /// <para>
+        /// This property is expressed as an amount of time since the Screenplay began.  The beginning of the Screenplay is recorded in the
+        /// report metadata, at <see cref="ReportMetadata.Timestamp"/>.
+        /// </para>
+        /// <para>
+        /// Recall that it is quite normal for performances and thus reportable actions to occur in parallel.
+        /// Do not be alarmed if it appears that unrelated performances are interleaved with regard to their timings.
+        /// </para>
+        /// </remarks>
+        /// <seealso cref="ReportMetadata.Timestamp"/>
+        /// <seealso cref="PerformanceReport.Started"/>
+        /// <seealso cref="ReportableModelBase.Started"/>
+        public TimeSpan Ended { get; set; }
+
         /// <summary>
         /// Gets or sets a string representation of the result which was emitted by the corresponding performable.
         /// </summary>

CSF.Screenplay/ReportModel/PerformanceReport.cs

@@ -52,5 +52,23 @@ public List<ReportableModelBase> Reportables
             get => reportables;
             set => reportables = value ?? throw new ArgumentNullException(nameof(value));
         }
+
+        /// <summary>
+        /// Gets or sets the time at which this performance was begun.
+        /// </summary>
+        /// <remarks>
+        /// <para>
+        /// This property is expressed as an amount of time since the Screenplay began.  The beginning of the Screenplay is recorded in the
+        /// report metadata, at <see cref="ReportMetadata.Timestamp"/>.
+        /// </para>
+        /// <para>
+        /// Recall that it is quite normal for performances and thus reportable actions to occur in parallel.
+        /// Do not be alarmed if it appears that unrelated performances are interleaved with regard to their timings.
+        /// </para>
+        /// </remarks>
+        /// <seealso cref="ReportMetadata.Timestamp"/>
+        /// <seealso cref="ReportableModelBase.Started"/>
+        /// <seealso cref="PerformableReport.Ended"/>
+        public TimeSpan Started { get; set; }
     }
 }

CSF.Screenplay/ReportModel/ReportMetadata.cs

@@ -10,9 +10,14 @@ public class ReportMetadata
         const string reportFormatVersion = "2.0.0";
 
         /// <summary>
-        /// Gets or sets the UTC timestamp at which the report was generated.
+        /// Gets or sets the date &amp; time at which the Screenplay began.
         /// </summary>
-        public DateTime Timestamp { get; set; } = DateTime.UtcNow;
+        /// <remarks>
+        /// <para>
+        /// Other time-related values within the Screenplay report are expressed relative to this time.
+        /// </para>
+        /// </remarks>
+        public DateTimeOffset Timestamp { get; set; } = DateTimeOffset.UtcNow;
 
         /// <summary>
         /// Gets or sets a version number for the format of report that has been produced.

CSF.Screenplay/ReportModel/ReportableModelBase.cs

@@ -1,3 +1,4 @@
+using System;
 using System.Text.Json.Serialization;
 
 namespace CSF.Screenplay.ReportModel
@@ -32,5 +33,28 @@ public abstract class ReportableModelBase
         /// </para>
         /// </remarks>
         public string ActorName { get; set; }
+
+        /// <summary>
+        /// Gets or sets the relative time at which this reportable event occurred.
+        /// </summary>
+        /// <remarks>
+        /// <para>
+        /// For many types of reportable items (derived from this type), only the start time is recorded, because it is expected that the
+        /// activity upon which is being reported takes a trivial amount of time.
+        /// For <see cref="PerformableReport"/> instances, an end time is also recorded, as these are expected to take an appreciable amount of time.
+        /// </para>
+        /// <para>
+        /// This property is expressed as an amount of time since the Screenplay began.  The beginning of the Screenplay is recorded in the
+        /// report metadata, at <see cref="ReportMetadata.Timestamp"/>.
+        /// </para>
+        /// <para>
+        /// Recall that it is quite normal for performances and thus reportable actions to occur in parallel.
+        /// Do not be alarmed if it appears that unrelated performances are interleaved with regard to their timings.
+        /// </para>
+        /// </remarks>
+        /// <seealso cref="ReportMetadata.Timestamp"/>
+        /// <seealso cref="PerformanceReport.Started"/>
+        /// <seealso cref="PerformableReport.Ended"/>
+        public TimeSpan Started { get; set; }
     }
 }

CSF.Screenplay/Reporting/IProvidesReportTiming.cs

@@ -0,0 +1,25 @@
+using System;
+
+namespace CSF.Screenplay.Reporting
+{
+
+/// <summary>
+/// An object which acts as a stopwatch, intended for used in providing timing data for reports.
+/// </summary>
+public interface IMeasuresTime : IDisposable
+{
+    /// <summary>
+    /// Begins the timer, recording/tracking time.
+    /// </summary>
+    /// <returns>The current date &amp; time, at the point when timing began.</returns>
+    /// <exception cref="InvalidOperationException">If this method is used more than once upon the same object instance.</exception>
+    DateTimeOffset BeginTiming();
+
+    /// <summary>
+    /// Gets the amount of time (wall clock time) which has elapsed since <see cref="BeginTiming"/> was executed.
+    /// </summary>
+    /// <returns>A timespan which is the time elapsed since timing began.</returns>
+    /// <exception cref="InvalidOperationException">If this method is used before <see cref="BeginTiming"/> has been executed.</exception>
+    TimeSpan GetCurrentTime();
+}
+}

CSF.Screenplay/Reporting/JsonScreenplayReporter.cs

@@ -41,6 +41,7 @@ namespace CSF.Screenplay.Reporting
     public sealed class JsonScreenplayReporter : IReporter
     {
         readonly ScreenplayReportBuilder builder;
+        readonly IMeasuresTime reportTimer;
         readonly Utf8JsonWriter jsonWriter;
         readonly object syncRoot = new object();
         IHasPerformanceEvents subscribed;
@@ -134,7 +135,7 @@ void OnPerformanceBegun(object sender, PerformanceEventArgs e)
         void OnScreenplayStarted(object sender, EventArgs e)
         {
             jsonWriter.WriteStartObject();
-            var metadata = new ReportMetadata();
+            var metadata = new ReportMetadata() { Timestamp = reportTimer.BeginTiming() };
             jsonWriter.WritePropertyName(nameof(ScreenplayReport.Metadata));
             JsonSerializer.Serialize(jsonWriter, metadata);
             jsonWriter.WriteStartArray(nameof(ScreenplayReport.Performances));
@@ -171,15 +172,19 @@ static string GetPhaseString(PerformancePhase phase)
         /// Initializes a new instance of <see cref="JsonScreenplayReporter"/> for a specified file path.
         /// </summary>
         /// <param name="writeStream">The stream to which the JSON report shall be written.</param>
-        /// <param name="builder">The Screenplay report builder</param>
+        /// <param name="builderFactory">A factory for a Screenplay report builder</param>
+        /// <param name="reportTimer">A timing service for reports</param>
         /// <exception cref="ArgumentNullException">If <paramref name="writeStream"/> is <see langword="null" />.</exception>
-        public JsonScreenplayReporter(Stream writeStream, ScreenplayReportBuilder builder)
+        public JsonScreenplayReporter(Stream writeStream, Func<IMeasuresTime,ScreenplayReportBuilder> builderFactory, IMeasuresTime reportTimer)
         {
             if (writeStream is null)
                 throw new ArgumentNullException(nameof(writeStream));
+            if(builderFactory is null)
+                throw new ArgumentNullException(nameof(builderFactory));
 
             jsonWriter = new Utf8JsonWriter(writeStream, new JsonWriterOptions { Indented = false });
-            this.builder = builder ?? throw new ArgumentNullException(nameof(builder));
+            this.reportTimer = reportTimer ?? throw new ArgumentNullException(nameof(reportTimer));
+            builder = builderFactory(reportTimer);
         }
     }
 }

CSF.Screenplay/Reporting/PerformanceReportBuilder.cs

@@ -24,6 +24,7 @@ public class PerformanceReportBuilder
         readonly IGetsValueFormatter valueFormatterProvider;
         readonly IFormatsReportFragment formatter;
         readonly IGetsContentType contentTypeProvider;
+        readonly IMeasuresTime reportTimer;
 
         /// <summary>
         /// Gets a value indicating whether or not this builder has a 'current' performable that it is building.
@@ -84,6 +85,7 @@ public void ActorCreated(Actor actor)
             {
                 ActorName = actor.Name,
                 Report = string.Format(ReportStrings.ActorCreatedFormat, actor.Name),
+                Started = reportTimer.GetCurrentTime(),
             });
         }
 
@@ -102,6 +104,7 @@ public void ActorGainedAbility(Actor actor, object ability)
             {
                 ActorName = actor.Name,
                 Report = reportText,
+                Started = reportTimer.GetCurrentTime(),
             });
         }
 
@@ -120,6 +123,7 @@ public void ActorSpotlit(Actor actor)
             {
                 ActorName = actor.Name,
                 Report = string.Format(ReportStrings.ActorSpotlitFormat, actor.Name),
+                Started = reportTimer.GetCurrentTime(),
             });
         }
 
@@ -136,6 +140,7 @@ public void SpotlightTurnedOff()
             NewPerformableList.Add(new SpotlightTurnedOffReport
             {
                 Report = ReportStrings.SpotlightTurnedOff,
+                Started = reportTimer.GetCurrentTime(),
             });
         }
 
@@ -172,6 +177,7 @@ public void BeginPerformable(object performable, Actor actor, string performance
                 PerformableType = performable.GetType().FullName,
                 ActorName = actor.Name,
                 PerformancePhase = performancePhase,
+                Started = reportTimer.GetCurrentTime(),
             };
 
             NewPerformableList.Add(performableReport);
@@ -235,6 +241,7 @@ public void EndPerformable(object performable, Actor actor)
             CurrentPerformable.Report = performable is ICanReport reporter
                 ? reporter.GetReportFragment(actor, formatter).FormattedFragment
                 : string.Format(ReportStrings.FallbackReportFormat, actor.Name, performable.GetType().FullName);
+            CurrentPerformable.Ended = reportTimer.GetCurrentTime();
             performableStack.Pop();
         }
 
@@ -254,6 +261,7 @@ public void RecordFailureForCurrentPerformable(Exception exception)
         {
             CurrentPerformable.Exception = exception.ToString();
             CurrentPerformable.ExceptionIsFromConsumedPerformable = exception is PerformableException;
+            CurrentPerformable.Ended = reportTimer.GetCurrentTime();
             performableStack.Pop();
         }
 
@@ -266,21 +274,26 @@ public void RecordFailureForCurrentPerformable(Exception exception)
         /// <param name="valueFormatterProvider">A value formatter factory</param>
         /// <param name="formatter">A report-fragment formatter</param>
         /// <param name="contentTypeProvider">A content type provider service</param>
+        /// <param name="reportTimer">A report timer</param>
         /// <exception cref="ArgumentNullException">If any parameter is <see langword="null" />.</exception>
         public PerformanceReportBuilder(List<IdentifierAndNameModel> namingHierarchy,
                                         IGetsValueFormatter valueFormatterProvider,
                                         IFormatsReportFragment formatter,
-                                        IGetsContentType contentTypeProvider)
+                                        IGetsContentType contentTypeProvider,
+                                        IMeasuresTime reportTimer)
         {
             if (namingHierarchy is null)
                 throw new ArgumentNullException(nameof(namingHierarchy));
 
             this.valueFormatterProvider = valueFormatterProvider ?? throw new ArgumentNullException(nameof(valueFormatterProvider));
             this.formatter = formatter ?? throw new ArgumentNullException(nameof(formatter));
             this.contentTypeProvider = contentTypeProvider ?? throw new ArgumentNullException(nameof(contentTypeProvider));
+            this.reportTimer = reportTimer ?? throw new ArgumentNullException(nameof(reportTimer));
+
             report = new PerformanceReport
             {
                 NamingHierarchy = namingHierarchy.ToList(),
+                Started = reportTimer.GetCurrentTime(),
             };
         }
     }

CSF.Screenplay/Reporting/ReportTimer.cs

@@ -0,0 +1,36 @@
+using System;
+using System.Diagnostics;
+
+namespace CSF.Screenplay.Reporting
+{
+/// <summary>
+/// Default implementation of <see cref="IMeasuresTime"/> which uses a <see cref="Stopwatch"/>.
+/// </summary>
+public sealed class ReportTimer : IMeasuresTime
+{
+    readonly Stopwatch stopwatch = new Stopwatch();
+
+    /// <inheritdoc/>
+    public DateTimeOffset BeginTiming()
+    {
+        if(stopwatch.IsRunning) throw new InvalidOperationException($"The {nameof(BeginTiming)} method may not be used more than once.");
+
+        stopwatch.Start();
+        return DateTimeOffset.Now;
+    }
+
+    /// <inheritdoc/>
+    public void Dispose()
+    {
+        if(stopwatch.IsRunning)
+            stopwatch.Stop();
+    }
+
+    /// <inheritdoc/>
+    public TimeSpan GetCurrentTime()
+    {
+        if(!stopwatch.IsRunning) throw new InvalidOperationException($"The {nameof(GetCurrentTime)} method may not be used before {nameof(BeginTiming)}.");
+        return stopwatch.Elapsed;
+    }
+}
+}

CSF.Screenplay/Reporting/ScreenplayReportBuilder.cs

@@ -28,7 +28,8 @@ namespace CSF.Screenplay.Reporting
     public class ScreenplayReportBuilder
     {
         readonly ConcurrentDictionary<Guid, PerformanceReportBuilder> performanceReports = new ConcurrentDictionary<Guid, PerformanceReportBuilder>();
-        readonly Func<List<IdentifierAndNameModel>, PerformanceReportBuilder> performanceBuilderFactory;
+        readonly Func<List<IdentifierAndNameModel>,IMeasuresTime,PerformanceReportBuilder> performanceBuilderFactory;
+        readonly IMeasuresTime reportTimer;
 
         /// <summary>
         /// Begins building a report about a new performance.
@@ -52,7 +53,7 @@ public void BeginPerformance(Guid performanceIdentifier, IReadOnlyList<Identifie
             var mappedNamingHierarchy = namingHierarchy
                 .Select(x => new IdentifierAndNameModel { Identifier = x.Identifier, Name = x.Name, WasIdentifierAutoGenerated = x.WasIdentifierAutoGenerated })
                 .ToList();
-            performanceReports.TryAdd(performanceIdentifier, performanceBuilderFactory(mappedNamingHierarchy));
+            performanceReports.TryAdd(performanceIdentifier, performanceBuilderFactory(mappedNamingHierarchy, reportTimer));
         }
 
         /// <summary>
@@ -95,10 +96,12 @@ public PerformanceReport EndPerformanceAndGetReport(Guid performanceIdentifier,
         /// Initialises a new instance of <see cref="ScreenplayReportBuilder"/>.
         /// </summary>
         /// <param name="performanceBuilderFactory">A factory function for performance report builders</param>
+        /// <param name="reportTimer">A report timer</param>
         /// <exception cref="ArgumentNullException">If <paramref name="performanceBuilderFactory"/> is <see langword="null" />.</exception>
-        public ScreenplayReportBuilder(Func<List<IdentifierAndNameModel>,PerformanceReportBuilder> performanceBuilderFactory)
+        public ScreenplayReportBuilder(Func<List<IdentifierAndNameModel>,IMeasuresTime,PerformanceReportBuilder> performanceBuilderFactory, IMeasuresTime reportTimer)
         {
             this.performanceBuilderFactory = performanceBuilderFactory ?? throw new ArgumentNullException(nameof(performanceBuilderFactory));
+            this.reportTimer = reportTimer ?? throw new ArgumentNullException(nameof(reportTimer));
         }
     }
 }

CSF.Screenplay/ScreenplayServiceCollectionExtensions.cs

@@ -72,15 +72,20 @@ public static IServiceCollection AddScreenplay(this IServiceCollection services)
                 .AddTransient<JsonScreenplayReporter>()
                 .AddTransient<NoOpReporter>()
                 .AddTransient<ITestsPathForWritePermissions, WritePermissionTester>()
-                .AddTransient<Func<List<IdentifierAndNameModel>, PerformanceReportBuilder>>(s =>
+                .AddTransient<Func<List<IdentifierAndNameModel>, IMeasuresTime, PerformanceReportBuilder>>(s =>
                 {
-                    return idsAndNames => ActivatorUtilities.CreateInstance<PerformanceReportBuilder>(s, idsAndNames);
+                    return (idsAndNames, timer) => ActivatorUtilities.CreateInstance<PerformanceReportBuilder>(s, idsAndNames, timer);
                 })
                 .AddTransient<GetAssetFilePaths>()
                 .AddTransient<ToStringFormatter>()
                 .AddTransient<HumanizerFormatter>()
                 .AddTransient<NameFormatter>()
-                .AddTransient<FormattableFormatter>();
+                .AddTransient<FormattableFormatter>()
+                .AddTransient<IMeasuresTime, ReportTimer>()
+                .AddTransient<Func<IMeasuresTime, ScreenplayReportBuilder>>(s =>
+                {
+                    return timer => ActivatorUtilities.CreateInstance<ScreenplayReportBuilder>(s, timer);
+                });
 
             return services;
         }