From 0b445bdf1a468bd0f69aaaa2776f60104b2bb6ec Mon Sep 17 00:00:00 2001 From: Ben Date: Tue, 7 Feb 2023 09:21:53 -0800 Subject: [PATCH] Add tracking for stream lifetime (#268) * Add tracking for stream lifetime * Fix test * Obsolete old StreamDisposedEventArgs constructor instead of changing it. * Mark creationTimestamp readonly * Update src/RecyclableMemoryStream.cs Co-authored-by: Gregory Bell <65985703+grbell-ms@users.noreply.github.com> * Make unit tests more reliable, remove unnecessary cast. * Give more time in unit tests * Add test error message * Fix timestamp casting * Update src/EventArgs.cs Co-authored-by: Ivan Maximov * Fix time calculation --------- Co-authored-by: Ben Watson Co-authored-by: Gregory Bell <65985703+grbell-ms@users.noreply.github.com> Co-authored-by: Ivan Maximov --- UnitTests/Tests.cs | 10 ++++++++++ src/EventArgs.cs | 21 +++++++++++++++++++++ src/Events.cs | 7 ++++--- src/RecyclableMemoryStream.cs | 6 +++++- src/RecyclableMemoryStreamManager.cs | 6 +++--- 5 files changed, 43 insertions(+), 7 deletions(-) diff --git a/UnitTests/Tests.cs b/UnitTests/Tests.cs index ad8e2cd0..840b11c8 100644 --- a/UnitTests/Tests.cs +++ b/UnitTests/Tests.cs @@ -25,6 +25,7 @@ namespace Microsoft.IO.UnitTests using System; using System.Buffers; using System.Collections.Generic; + using System.Diagnostics; using System.IO; using System.Runtime.InteropServices; using System.Threading; @@ -2658,7 +2659,13 @@ public void FinalizedStreamTriggersEvent() handlerTriggered = true; }; + mgr.StreamDisposed += (obj, args) => + { + Assert.That(args.Lifetime, Is.GreaterThanOrEqualTo(TimeSpan.Zero)); + }; + CreateDeadStream(mgr, expectedGuid, "Tag"); + Thread.Sleep(100); GC.Collect(2, GCCollectionMode.Forced, true); GC.WaitForPendingFinalizers(); @@ -3441,11 +3448,14 @@ public void EventStreamDisposed() { Assert.That(args.Id, Is.Not.EqualTo(Guid.Empty)); Assert.That(args.Tag, Is.EqualTo("UnitTest")); + Assert.That(args.Lifetime, Is.GreaterThan(TimeSpan.Zero), $"TicksPerSecond: {TimeSpan.TicksPerSecond}, Freq: {Stopwatch.Frequency} Div:{TimeSpan.TicksPerSecond / Stopwatch.Frequency}"); + Assert.That(args.Lifetime, Is.LessThan(TimeSpan.FromSeconds(2))); Assert.That(args.AllocationStack, Contains.Substring("Microsoft.IO.RecyclableMemoryStream..ctor")); Assert.That(args.DisposeStack, Contains.Substring("Microsoft.IO.RecyclableMemoryStream.Dispose")); raised = true; }; var stream = mgr.GetStream("UnitTest", 13); + Thread.Sleep(100); stream.Dispose(); Assert.That(raised, Is.True); } diff --git a/src/EventArgs.cs b/src/EventArgs.cs index 828a82e5..3a4dcb37 100644 --- a/src/EventArgs.cs +++ b/src/EventArgs.cs @@ -70,6 +70,11 @@ public sealed class StreamDisposedEventArgs : EventArgs /// public string DisposeStack { get; } + /// + /// Lifetime of the stream. + /// + public TimeSpan Lifetime { get; } + /// /// Initializes a new instance of the class. /// @@ -77,10 +82,26 @@ public sealed class StreamDisposedEventArgs : EventArgs /// Tag of the stream. /// Stack of original allocation. /// Dispose stack. + [Obsolete("Use another constructor override")] public StreamDisposedEventArgs(Guid guid, string tag, string allocationStack, string disposeStack) + :this(guid, tag, TimeSpan.Zero, allocationStack, disposeStack) + { + + } + + /// + /// Initializes a new instance of the class. + /// + /// Unique ID of the stream. + /// Tag of the stream. + /// Lifetime of the stream + /// Stack of original allocation. + /// Dispose stack. + public StreamDisposedEventArgs(Guid guid, string tag, TimeSpan lifetime, string allocationStack, string disposeStack) { this.Id = guid; this.Tag = tag; + this.Lifetime = lifetime; this.AllocationStack = allocationStack; this.DisposeStack = disposeStack; } diff --git a/src/Events.cs b/src/Events.cs index 2746fa40..a3a85bef 100644 --- a/src/Events.cs +++ b/src/Events.cs @@ -89,14 +89,15 @@ public void MemoryStreamCreated(Guid guid, string tag, long requestedSize, long /// /// A unique ID for this stream. /// A temporary ID for this stream, usually indicates current usage. + /// Lifetime of the stream /// Call stack of initial allocation. /// Call stack of the dispose. - [Event(2, Level = EventLevel.Verbose, Version = 2)] - public void MemoryStreamDisposed(Guid guid, string tag, string allocationStack, string disposeStack) + [Event(2, Level = EventLevel.Verbose, Version = 3)] + public void MemoryStreamDisposed(Guid guid, string tag, TimeSpan lifetime, string allocationStack, string disposeStack) { if (this.IsEnabled(EventLevel.Verbose, EventKeywords.None)) { - WriteEvent(2, guid, tag ?? string.Empty, allocationStack ?? string.Empty, disposeStack ?? string.Empty); + WriteEvent(2, guid, tag ?? string.Empty, lifetime, allocationStack ?? string.Empty, disposeStack ?? string.Empty); } } diff --git a/src/RecyclableMemoryStream.cs b/src/RecyclableMemoryStream.cs index 83fabf25..177762e0 100644 --- a/src/RecyclableMemoryStream.cs +++ b/src/RecyclableMemoryStream.cs @@ -102,6 +102,8 @@ public sealed class RecyclableMemoryStream : MemoryStream, IBufferWriter private readonly string tag; + private readonly long creationTimestamp; + /// /// This list is used to store buffers once they're replaced by something larger. /// This is for the cases where you have users of this class that may hold onto the buffers longer @@ -257,6 +259,7 @@ internal RecyclableMemoryStream(RecyclableMemoryStreamManager memoryManager, Gui this.id = id; this.tag = tag; this.blocks = new List(); + this.creationTimestamp = Stopwatch.GetTimestamp(); var actualRequestedSize = Math.Max(requestedSize, this.memoryManager.BlockSize); @@ -308,13 +311,14 @@ protected override void Dispose(bool disposing) } this.disposed = true; + var lifetime = TimeSpan.FromTicks((Stopwatch.GetTimestamp() - this.creationTimestamp) * TimeSpan.TicksPerSecond / Stopwatch.Frequency); if (this.memoryManager.GenerateCallStacks) { this.DisposeStack = Environment.StackTrace; } - this.memoryManager.ReportStreamDisposed(this.id, this.tag, this.AllocationStack, this.DisposeStack); + this.memoryManager.ReportStreamDisposed(this.id, this.tag, lifetime, this.AllocationStack, this.DisposeStack); if (disposing) { diff --git a/src/RecyclableMemoryStreamManager.cs b/src/RecyclableMemoryStreamManager.cs index c5694157..c638d7ca 100644 --- a/src/RecyclableMemoryStreamManager.cs +++ b/src/RecyclableMemoryStreamManager.cs @@ -665,10 +665,10 @@ internal void ReportStreamCreated(Guid id, string tag, long requestedSize, long this.StreamCreated?.Invoke(this, new StreamCreatedEventArgs(id, tag, requestedSize, actualSize)); } - internal void ReportStreamDisposed(Guid id, string tag, string allocationStack, string disposeStack) + internal void ReportStreamDisposed(Guid id, string tag, TimeSpan lifetime, string allocationStack, string disposeStack) { - Events.Writer.MemoryStreamDisposed(id, tag, allocationStack, disposeStack); - this.StreamDisposed?.Invoke(this, new StreamDisposedEventArgs(id, tag, allocationStack, disposeStack)); + Events.Writer.MemoryStreamDisposed(id, tag, lifetime, allocationStack, disposeStack); + this.StreamDisposed?.Invoke(this, new StreamDisposedEventArgs(id, tag, lifetime, allocationStack, disposeStack)); } internal void ReportStreamDoubleDisposed(Guid id, string tag, string allocationStack, string disposeStack1, string disposeStack2)