From fd5ff4a5dd08827e19f3a9f060042a43fa9a41b2 Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 16:35:21 +1100 Subject: [PATCH 01/22] Update Stopwatch.cs --- Tests/Stopwatch.cs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 1af87e1e..78250a17 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -30,4 +30,9 @@ public long ElapsedMilliseconds return elapsedTicks / TicksPerMillisecond; } } + + public TimeSpan Elapsed + { + get => new TimeSpan(elapsedTicks); + } } \ No newline at end of file From f433722a2ca7f36aad5acf5256b4f8bac02ae5ba Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 16:40:20 +1100 Subject: [PATCH 02/22] . --- MethodTimer.Fody/ReferenceFinder.cs | 22 ++++++++-------------- MethodTimer.Fody/StopwatchCreator.cs | 19 ++++++++++++++++++- 2 files changed, 26 insertions(+), 15 deletions(-) diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index c5403a51..1a38b97f 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -14,10 +14,12 @@ public partial class ModuleWeaver public MethodReference ElapsedMilliseconds; public MethodReference GetMethodFromHandle; public MethodReference ObjectConstructorMethod; + public MethodReference TimeSpanConstructorMethod; public MethodReference MaxMethod; public MethodReference GetTicksMethod; public MethodReference UtcNowMethod; public TypeReference DateTimeType; + public TypeReference TimeSpanType; public TypeReference BooleanType; public TypeReference VoidType; @@ -37,6 +39,11 @@ public void FindReferences() var objectConstructor = FindTypeDefinition("System.Object").Method(".ctor"); ObjectConstructorMethod = ModuleDefinition.ImportReference(objectConstructor); + var timeSpanDefinition = FindTypeDefinition("System.TimeSpan"); + TimeSpanType = ModuleDefinition.ImportReference(timeSpanDefinition); + var timeSpanConstructor = timeSpanDefinition.Method(".ctor","Int64"); + TimeSpanConstructorMethod = ModuleDefinition.ImportReference(timeSpanConstructor); + var mathType = FindTypeDefinition("System.Math"); MaxMethod = ModuleDefinition.ImportReference(mathType.Method("Max", "Int64", "Int64")); @@ -60,19 +67,6 @@ public void FindReferences() var concatMethod = TypeSystem.StringDefinition.Method("Concat", "Object", "Object", "Object"); ConcatMethod = ModuleDefinition.ImportReference(concatMethod); - if (TryFindTypeDefinition("System.Diagnostics.Stopwatch", out var stopwatchType)) - { - StopwatchType = ModuleDefinition.ImportReference(stopwatchType); - StartNewMethod = ModuleDefinition.ImportReference(stopwatchType.Method("StartNew")); - StopMethod = ModuleDefinition.ImportReference(stopwatchType.Method("Stop")); - Elapsed = ModuleDefinition.ImportReference(stopwatchType.Method("get_Elapsed")); - ElapsedMilliseconds = ModuleDefinition.ImportReference(stopwatchType.Method("get_ElapsedMilliseconds")); - IsRunning = ModuleDefinition.ImportReference(stopwatchType.Method("get_IsRunning")); - } - else - { - // Note: injected stopwatch is not supported for TimeSpan elapsed, should we error or add? - InjectStopwatchType(); - } + InjectStopwatchType(); } } \ No newline at end of file diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index 5e53baa0..68a4c0c3 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -101,8 +101,25 @@ public void InjectStopwatchType() Instruction.Create(OpCodes.Conv_I8), Instruction.Create(OpCodes.Div), Instruction.Create(OpCodes.Ret)); - ElapsedMilliseconds = elapsedMilliseconds; + + var elapsed = new MethodDefinition( + "GetElapsed", + MethodAttributes.HideBySig | MethodAttributes.Public, + TimeSpanType); + type.Methods.Add(elapsed); + elapsed.Body.Add( + Instruction.Create(OpCodes.Ldarg_0), + Instruction.Create(OpCodes.Call, stop), + Instruction.Create(OpCodes.Ldarg_0), + Instruction.Create(OpCodes.Ldfld, elapsedTicks), + Instruction.Create(OpCodes.Newobj, TimeSpanConstructorMethod), + Instruction.Create(OpCodes.Ret)); + + + IsRunning = ModuleDefinition.ImportReference(stopwatchType.Method("get_IsRunning")); + + Elapsed = elapsed; StopMethod = stop; StopwatchType = type; StartNewMethod = startNew; From 55fe0be2b2f5c7df8facd1e7883bde1bd25e7f0c Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 16:40:51 +1100 Subject: [PATCH 03/22] Update Stopwatch.cs --- Tests/Stopwatch.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 873f5e30..0e62daee 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -32,6 +32,6 @@ public long ElapsedMilliseconds public TimeSpan Elapsed { - get => new TimeSpan(elapsedTicks); + get => new(elapsedTicks); } } \ No newline at end of file From 08ac43385f87c44ae14399d260dbc6b876906606 Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 16:49:59 +1100 Subject: [PATCH 04/22] . --- MethodTimer.Fody/StopwatchCreator.cs | 18 ++++++++++++++---- Tests/Stopwatch.cs | 8 +++++++- 2 files changed, 21 insertions(+), 5 deletions(-) diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index 68a4c0c3..1d1b4142 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -101,7 +101,6 @@ public void InjectStopwatchType() Instruction.Create(OpCodes.Conv_I8), Instruction.Create(OpCodes.Div), Instruction.Create(OpCodes.Ret)); - ElapsedMilliseconds = elapsedMilliseconds; var elapsed = new MethodDefinition( "GetElapsed", @@ -115,11 +114,22 @@ public void InjectStopwatchType() Instruction.Create(OpCodes.Ldfld, elapsedTicks), Instruction.Create(OpCodes.Newobj, TimeSpanConstructorMethod), Instruction.Create(OpCodes.Ret)); - - - IsRunning = ModuleDefinition.ImportReference(stopwatchType.Method("get_IsRunning")); + var isRunning = new MethodDefinition( + "IsRunning", + MethodAttributes.HideBySig | MethodAttributes.Public, + TypeSystem.BooleanReference); + type.Methods.Add(isRunning); + isRunning.Body.Add( + Instruction.Create(OpCodes.Ldarg_0), + Instruction.Create(OpCodes.Ldfld, stopped), + Instruction.Create(OpCodes.Ldc_I4_0), + Instruction.Create(OpCodes.Ceq), + Instruction.Create(OpCodes.Ret)); + + IsRunning = isRunning; Elapsed = elapsed; + ElapsedMilliseconds = elapsedMilliseconds; StopMethod = stop; StopwatchType = type; StartNewMethod = startNew; diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 0e62daee..77bd8ed3 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -18,6 +18,8 @@ public void Stop() } } + public bool IsRunning { get => !stopped; } + static long CurrentTicks() => DateTime.UtcNow.Ticks; @@ -32,6 +34,10 @@ public long ElapsedMilliseconds public TimeSpan Elapsed { - get => new(elapsedTicks); + get + { + Stop(); + return new(elapsedTicks); + } } } \ No newline at end of file From 27a6aef9448269f57dd4ec81c8ed228a50a9ecc8 Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 17:13:27 +1100 Subject: [PATCH 05/22] . --- MethodTimer.Fody/StopwatchCreator.cs | 2 +- Tests/Stopwatch.cs | 11 ++++------- 2 files changed, 5 insertions(+), 8 deletions(-) diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index 1d1b4142..d41b95c2 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -116,7 +116,7 @@ public void InjectStopwatchType() Instruction.Create(OpCodes.Ret)); var isRunning = new MethodDefinition( - "IsRunning", + "GetIsRunning", MethodAttributes.HideBySig | MethodAttributes.Public, TypeSystem.BooleanReference); type.Methods.Add(isRunning); diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 4d0acd83..caf07f82 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -17,7 +17,7 @@ public void Stop() } } - public bool IsRunning { get => !stopped; } + public bool GetIsRunning() => !stopped; static long CurrentTicks() => DateTime.UtcNow.Ticks; @@ -28,12 +28,9 @@ public long GetElapsedMilliseconds() return elapsedTicks / 10000; } - public TimeSpan Elapsed + public TimeSpan GetElapsed() { - get - { - Stop(); - return new(elapsedTicks); - } + Stop(); + return new(elapsedTicks); } } \ No newline at end of file From bdd1f7c86acdd5d33493c43d04b0b45328927edf Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 17:18:44 +1100 Subject: [PATCH 06/22] . --- Tests/StopWatchTemplateUsage.cs | 12 ++++++++++++ Tests/Stopwatch.cs | 2 +- 2 files changed, 13 insertions(+), 1 deletion(-) create mode 100644 Tests/StopWatchTemplateUsage.cs diff --git a/Tests/StopWatchTemplateUsage.cs b/Tests/StopWatchTemplateUsage.cs new file mode 100644 index 00000000..59a58ab2 --- /dev/null +++ b/Tests/StopWatchTemplateUsage.cs @@ -0,0 +1,12 @@ +using System.Threading; + +public class StopWatchTemplateUsage +{ + public static long Foo() + { + var stopwatch = Stopwatch.StartNew(); + Thread.Sleep(100); + + return stopwatch.GetElapsedMilliseconds(); + } +} \ No newline at end of file diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 1f1ea94f..ad2b9cc3 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -1,6 +1,6 @@ using System; -class Stopwatch +struct Stopwatch { long startTicks; long elapsedTicks; From f22486780c16ecb93e2ff8ad9e539df57ba075e5 Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 18:15:05 +1100 Subject: [PATCH 07/22] Update StopWatchTemplateUsage.cs --- Tests/StopWatchTemplateUsage.cs | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/Tests/StopWatchTemplateUsage.cs b/Tests/StopWatchTemplateUsage.cs index 59a58ab2..79106b84 100644 --- a/Tests/StopWatchTemplateUsage.cs +++ b/Tests/StopWatchTemplateUsage.cs @@ -1,12 +1,20 @@ -using System.Threading; +using System; +using System.Diagnostics; +using System.Threading; public class StopWatchTemplateUsage { - public static long Foo() + public static void Foo() { var stopwatch = Stopwatch.StartNew(); - Thread.Sleep(100); - - return stopwatch.GetElapsedMilliseconds(); + try + { + Thread.Sleep(100); + } + finally + { + stopwatch.Stop(); + Trace.WriteLine("ClassWithAttribute.Method " + stopwatch.GetElapsedMilliseconds() + "ms"); + } } } \ No newline at end of file From e122bbb3bc3cf7a260e299cc69245847f6545a88 Mon Sep 17 00:00:00 2001 From: Simon Cropp Date: Fri, 6 Jan 2023 18:42:13 +1100 Subject: [PATCH 08/22] . --- MethodTimer.Fody/AsyncMethodProcessor.cs | 4 ++-- MethodTimer.Fody/StopwatchCreator.cs | 14 ++++++++++---- MethodTimer.Fody/StopwatchHelper.cs | 8 ++++---- Tests/StopWatchTemplateUsage.cs | 16 +++++++++++++++- 4 files changed, 31 insertions(+), 11 deletions(-) diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 7ee2e5f4..76f15bdc 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -266,14 +266,14 @@ IEnumerable GetWriteTimeInstruction() // Check if stopwatch is actually running yield return stopwatchRunningCheck; yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); - yield return Instruction.Create(OpCodes.Callvirt, ModuleWeaver.IsRunning); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.IsRunning); yield return Instruction.Create(OpCodes.Ldc_I4_0); yield return Instruction.Create(OpCodes.Ceq); yield return Instruction.Create(OpCodes.Brfalse_S, startOfRealMethod); yield return Instruction.Create(OpCodes.Ret); yield return startOfRealMethod; // Ldarg_0 - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, stopwatchFieldReference); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.StopMethod); var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index d41b95c2..b6efac2d 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -5,11 +5,12 @@ public partial class ModuleWeaver { public void InjectStopwatchType() { + var valueType = FindTypeDefinition("System.ValueType"); var type = new TypeDefinition( "MethodTimer", "Stopwatch", - TypeAttributes.BeforeFieldInit | TypeAttributes.AnsiClass | TypeAttributes.AutoClass, - TypeSystem.ObjectReference); + TypeAttributes.Sealed |TypeAttributes.AnsiClass | TypeAttributes.BeforeFieldInit | TypeAttributes.SequentialLayout | TypeAttributes.NotPublic, + ModuleDefinition.ImportReference(valueType)); ModuleDefinition.Types.Add(type); var startTicks = new FieldDefinition("startTicks", FieldAttributes.Private, TypeSystem.Int64Reference); @@ -47,11 +48,16 @@ public void InjectStopwatchType() TypeSystem.VoidReference); type.Methods.Add(constructor); constructor.Body.Add( + Instruction.Create(OpCodes.Ldarg_0), + Instruction.Create(OpCodes.Ldc_I4_0), + Instruction.Create(OpCodes.Conv_I8), + Instruction.Create(OpCodes.Stfld, elapsedTicks), + Instruction.Create(OpCodes.Ldarg_0), + Instruction.Create(OpCodes.Ldc_I4_0), + Instruction.Create(OpCodes.Stfld, stopped), Instruction.Create(OpCodes.Ldarg_0), Instruction.Create(OpCodes.Call, currentTicks), Instruction.Create(OpCodes.Stfld, startTicks), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, ObjectConstructorMethod), Instruction.Create(OpCodes.Ret)); var startNew = new MethodDefinition( diff --git a/MethodTimer.Fody/StopwatchHelper.cs b/MethodTimer.Fody/StopwatchHelper.cs index d1283f3b..79afc0a4 100644 --- a/MethodTimer.Fody/StopwatchHelper.cs +++ b/MethodTimer.Fody/StopwatchHelper.cs @@ -7,7 +7,7 @@ public partial class ModuleWeaver { public IEnumerable GetWriteTimeInstruction(VariableDefinition stopwatchVariableDefinition, MethodDefinition methodDefinition) { - yield return Instruction.Create(OpCodes.Ldloc, stopwatchVariableDefinition); + yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); yield return Instruction.Create(OpCodes.Call, StopMethod); var logWithMessageMethodUsingLong = LogWithMessageMethodUsingLong; @@ -21,7 +21,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition stopw if (logMethodUsingLong is null && logMethodUsingTimeSpan is null) { yield return Instruction.Create(OpCodes.Ldstr, methodDefinition.MethodName()); - yield return Instruction.Create(OpCodes.Ldloc, stopwatchVariableDefinition); + yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); yield return Instruction.Create(OpCodes.Call, ElapsedMilliseconds); yield return Instruction.Create(OpCodes.Box, TypeSystem.Int64Reference); yield return Instruction.Create(OpCodes.Ldstr, "ms"); @@ -34,7 +34,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition stopw yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloc, stopwatchVariableDefinition); + yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); if (logMethodUsingTimeSpan != null) { @@ -60,7 +60,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition stopw yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloc, stopwatchVariableDefinition); + yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); if (logWithMessageMethodUsingTimeSpan is null) { diff --git a/Tests/StopWatchTemplateUsage.cs b/Tests/StopWatchTemplateUsage.cs index 79106b84..ae088026 100644 --- a/Tests/StopWatchTemplateUsage.cs +++ b/Tests/StopWatchTemplateUsage.cs @@ -1,6 +1,7 @@ using System; using System.Diagnostics; using System.Threading; +using System.Threading.Tasks; public class StopWatchTemplateUsage { @@ -9,7 +10,7 @@ public static void Foo() var stopwatch = Stopwatch.StartNew(); try { - Thread.Sleep(100); + Thread.Sleep(10); } finally { @@ -17,4 +18,17 @@ public static void Foo() Trace.WriteLine("ClassWithAttribute.Method " + stopwatch.GetElapsedMilliseconds() + "ms"); } } + public async Task MethodWithAwaitExpected() + { + var stopwatch = Stopwatch.StartNew(); + try + { + await Task.Delay(500); + } + finally + { + stopwatch.Stop(); + Trace.WriteLine("ClassWithAsyncMethod.MethodWithAwaitExpected " + stopwatch.GetElapsedMilliseconds() + "ms"); + } + } } \ No newline at end of file From 7f174dd270d6196fcf6384e9b74c11815c09353c Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Thu, 20 Feb 2025 07:09:50 +0100 Subject: [PATCH 09/22] Create example assembly for IL comparison --- ExampleAssembly/ExampleAssembly.csproj | 6 ++++ ExampleAssembly/Method.cs | 44 ++++++++++++++++++++++++++ ExampleAssembly/MethodTimerHelper.cs | 7 ++++ MethodTimer.sln | 14 ++++++-- 4 files changed, 69 insertions(+), 2 deletions(-) create mode 100644 ExampleAssembly/ExampleAssembly.csproj create mode 100644 ExampleAssembly/Method.cs create mode 100644 ExampleAssembly/MethodTimerHelper.cs diff --git a/ExampleAssembly/ExampleAssembly.csproj b/ExampleAssembly/ExampleAssembly.csproj new file mode 100644 index 00000000..7890704b --- /dev/null +++ b/ExampleAssembly/ExampleAssembly.csproj @@ -0,0 +1,6 @@ + + + + net48;net6 + + \ No newline at end of file diff --git a/ExampleAssembly/Method.cs b/ExampleAssembly/Method.cs new file mode 100644 index 00000000..052b5cd0 --- /dev/null +++ b/ExampleAssembly/Method.cs @@ -0,0 +1,44 @@ +using System; +using System.Diagnostics; +using System.Threading.Tasks; + +public class TestClass +{ + public void SyncMethod() + { + long startTimestamp; + long endTimestamp; + long elapsed; + long ticks; + TimeSpan elapsedTimeSpan; + + startTimestamp = Stopwatch.GetTimestamp(); + + // Do something + + endTimestamp = Stopwatch.GetTimestamp(); + + elapsed = endTimestamp - startTimestamp; + ticks = (long)(MethodTimerHelper.TimestampToTicks * elapsed); + elapsedTimeSpan = new TimeSpan(ticks); + } + + public async Task AsyncMethod() + { + long startTimestamp; + long endTimestamp; + long elapsed; + long ticks; + TimeSpan elapsedTimeSpan; + + startTimestamp = Stopwatch.GetTimestamp(); + + await Task.Delay(10); + + endTimestamp = Stopwatch.GetTimestamp(); + + elapsed = endTimestamp - startTimestamp; + ticks = (long)(MethodTimerHelper.TimestampToTicks * elapsed); + elapsedTimeSpan = new TimeSpan(ticks); + } +} \ No newline at end of file diff --git a/ExampleAssembly/MethodTimerHelper.cs b/ExampleAssembly/MethodTimerHelper.cs new file mode 100644 index 00000000..a3c4ef0b --- /dev/null +++ b/ExampleAssembly/MethodTimerHelper.cs @@ -0,0 +1,7 @@ +using System; +using System.Diagnostics; + +internal static class MethodTimerHelper +{ + internal static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; +} \ No newline at end of file diff --git a/MethodTimer.sln b/MethodTimer.sln index b05b1f72..d953ff90 100644 --- a/MethodTimer.sln +++ b/MethodTimer.sln @@ -1,7 +1,7 @@  Microsoft Visual Studio Solution File, Format Version 12.00 -# Visual Studio Version 16 -VisualStudioVersion = 16.0.29201.188 +# Visual Studio Version 17 +VisualStudioVersion = 17.14.35806.103 d17.14 MinimumVisualStudioVersion = 16.0.29201.188 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "MethodTimer.Fody", "MethodTimer.Fody\MethodTimer.Fody.csproj", "{C3578A7B-09A6-4444-9383-0DEAFA4958BD}" EndProject @@ -44,6 +44,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "AssemblyWithInterceptorAndF EndProject Project("{F184B08F-C81C-45F6-A57F-5ABD9991F28F}") = "VBNetAssemblyWithInterceptor", "VBNetAssemblyWithInterceptor\VBNetAssemblyWithInterceptor.vbproj", "{43900789-E1BA-4204-8766-FCEDB7129EEA}" EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ExampleAssembly", "ExampleAssembly\ExampleAssembly.csproj", "{557AA7AF-D013-DA32-3486-1441B786E7D7}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -162,6 +164,14 @@ Global {43900789-E1BA-4204-8766-FCEDB7129EEA}.Release|Any CPU.Build.0 = Release|Any CPU {43900789-E1BA-4204-8766-FCEDB7129EEA}.Release|x86.ActiveCfg = Release|Any CPU {43900789-E1BA-4204-8766-FCEDB7129EEA}.Release|x86.Build.0 = Release|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Debug|Any CPU.Build.0 = Debug|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Debug|x86.ActiveCfg = Debug|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Debug|x86.Build.0 = Debug|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Release|Any CPU.ActiveCfg = Release|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Release|Any CPU.Build.0 = Release|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Release|x86.ActiveCfg = Release|Any CPU + {557AA7AF-D013-DA32-3486-1441B786E7D7}.Release|x86.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE From 382681d1e2f6e22ce1aae29c94288b47e8275377 Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Thu, 20 Feb 2025 07:10:46 +0100 Subject: [PATCH 10/22] Add partial nullable annotations --- MethodTimer.Fody/InterceptorFinder.cs | 12 ++++++------ MethodTimer.Fody/MethodTimer.Fody.csproj | 1 + 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/MethodTimer.Fody/InterceptorFinder.cs b/MethodTimer.Fody/InterceptorFinder.cs index 9b4eff9e..fdfbb8a4 100644 --- a/MethodTimer.Fody/InterceptorFinder.cs +++ b/MethodTimer.Fody/InterceptorFinder.cs @@ -10,11 +10,11 @@ public partial class ModuleWeaver const string LongType = "System.Int64"; const string TimeSpanTypeName = "System.TimeSpan"; - public MethodReference LogMethodUsingLong; - public MethodReference LogWithMessageMethodUsingLong; + public MethodReference? LogMethodUsingLong; + public MethodReference? LogWithMessageMethodUsingLong; - public MethodReference LogMethodUsingTimeSpan; - public MethodReference LogWithMessageMethodUsingTimeSpan; + public MethodReference? LogMethodUsingTimeSpan; + public MethodReference? LogWithMessageMethodUsingTimeSpan; public bool LogMethodIsNop; @@ -106,7 +106,7 @@ public void FindInterceptor() } } - MethodDefinition FindLogMethod(TypeDefinition interceptorType, string elapsedParameterTypeName) + MethodDefinition? FindLogMethod(TypeDefinition interceptorType, string elapsedParameterTypeName) { var requiredParameterTypes = new[] { @@ -131,7 +131,7 @@ MethodDefinition FindLogMethod(TypeDefinition interceptorType, string elapsedPar return logMethod; } - MethodDefinition FindLogWithMessageMethod(TypeDefinition interceptorType, string elapsedParameterTypeName) + MethodDefinition? FindLogWithMessageMethod(TypeDefinition interceptorType, string elapsedParameterTypeName) { var requiredParameterTypes = new[] { diff --git a/MethodTimer.Fody/MethodTimer.Fody.csproj b/MethodTimer.Fody/MethodTimer.Fody.csproj index 8b1de123..9ee5e4ac 100644 --- a/MethodTimer.Fody/MethodTimer.Fody.csproj +++ b/MethodTimer.Fody/MethodTimer.Fody.csproj @@ -2,6 +2,7 @@ netstandard2.0 + annotations From fe592c8e631cc27c1341d0d98532382d75e6c3d3 Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Fri, 21 Feb 2025 21:00:41 +0100 Subject: [PATCH 11/22] Migrate sync methods to new allocation free measurement --- .../ClassWithMethod.cs | 11 +- .../MethodTimeLogger.cs | 6 + ExampleAssembly/Method.cs | 40 ++-- MethodTimer.Fody/MethodProcessor.cs | 170 ++++++++++++++++- MethodTimer.Fody/MethodProcessor.variables.cs | 51 ++++++ MethodTimer.Fody/ReferenceFinder.cs | 54 +++++- MethodTimer.Fody/StopwatchCreator.cs | 173 +++++------------- MethodTimer.Fody/StopwatchHelper.cs | 151 --------------- .../WithInterceptorAndFormattingTests.cs | 4 +- 9 files changed, 356 insertions(+), 304 deletions(-) create mode 100644 MethodTimer.Fody/MethodProcessor.variables.cs delete mode 100644 MethodTimer.Fody/StopwatchHelper.cs diff --git a/AssemblyWithInterceptorAndFormatting/ClassWithMethod.cs b/AssemblyWithInterceptorAndFormatting/ClassWithMethod.cs index c327374d..433ec15b 100644 --- a/AssemblyWithInterceptorAndFormatting/ClassWithMethod.cs +++ b/AssemblyWithInterceptorAndFormatting/ClassWithMethod.cs @@ -1,4 +1,5 @@ -using System.Diagnostics; +using System; +using System.Diagnostics; using System.Threading; using MethodTimer; @@ -18,16 +19,18 @@ public void Method(string fileName, int id) public void Method_Expected(string fileName, int id) { - var stopwatch = Stopwatch.StartNew(); + var start = Stopwatch.GetTimestamp(); try { Thread.Sleep(10); } finally { - stopwatch.Stop(); + var end = Stopwatch.GetTimestamp(); + var duration = end - start; + var elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * duration)); var methodTimerMessage = $"File name '{fileName}' with id '{id}'"; - MethodTimeLogger.Log(null, stopwatch.ElapsedMilliseconds, methodTimerMessage); + MethodTimeLogger.Log(null, (long)elapsedTimeSpan.TotalMilliseconds, methodTimerMessage); } } diff --git a/AssemblyWithInterceptorAndFormatting/MethodTimeLogger.cs b/AssemblyWithInterceptorAndFormatting/MethodTimeLogger.cs index fb60cd8a..e4465654 100644 --- a/AssemblyWithInterceptorAndFormatting/MethodTimeLogger.cs +++ b/AssemblyWithInterceptorAndFormatting/MethodTimeLogger.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Reflection; public static class MethodTimeLogger @@ -18,4 +19,9 @@ public static void Log(MethodBase methodBase, long milliseconds, string message) Messages.Add(message); } } +} + +internal static class MethodTimerHelper +{ + internal static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; } \ No newline at end of file diff --git a/ExampleAssembly/Method.cs b/ExampleAssembly/Method.cs index 052b5cd0..4b77f7d2 100644 --- a/ExampleAssembly/Method.cs +++ b/ExampleAssembly/Method.cs @@ -9,18 +9,22 @@ public void SyncMethod() long startTimestamp; long endTimestamp; long elapsed; - long ticks; TimeSpan elapsedTimeSpan; startTimestamp = Stopwatch.GetTimestamp(); - // Do something - - endTimestamp = Stopwatch.GetTimestamp(); - - elapsed = endTimestamp - startTimestamp; - ticks = (long)(MethodTimerHelper.TimestampToTicks * elapsed); - elapsedTimeSpan = new TimeSpan(ticks); + try + { + // Do something + Console.WriteLine("Hello, World!"); + } + finally + { + endTimestamp = Stopwatch.GetTimestamp(); + + elapsed = endTimestamp - startTimestamp; + elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * elapsed)); + } } public async Task AsyncMethod() @@ -28,17 +32,19 @@ public async Task AsyncMethod() long startTimestamp; long endTimestamp; long elapsed; - long ticks; TimeSpan elapsedTimeSpan; startTimestamp = Stopwatch.GetTimestamp(); - - await Task.Delay(10); - - endTimestamp = Stopwatch.GetTimestamp(); - - elapsed = endTimestamp - startTimestamp; - ticks = (long)(MethodTimerHelper.TimestampToTicks * elapsed); - elapsedTimeSpan = new TimeSpan(ticks); + try + { + await Task.Delay(10); + } + finally + { + endTimestamp = Stopwatch.GetTimestamp(); + + elapsed = endTimestamp - startTimestamp; + elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * elapsed)); + } } } \ No newline at end of file diff --git a/MethodTimer.Fody/MethodProcessor.cs b/MethodTimer.Fody/MethodProcessor.cs index f5cdd974..f167aff9 100644 --- a/MethodTimer.Fody/MethodProcessor.cs +++ b/MethodTimer.Fody/MethodProcessor.cs @@ -1,16 +1,22 @@ using System; +using System.Collections.Generic; using System.Linq; using Fody; using Mono.Cecil; using Mono.Cecil.Cil; using Mono.Cecil.Rocks; -public class MethodProcessor +public partial class MethodProcessor { public ModuleWeaver ModuleWeaver; public MethodDefinition Method; MethodBody body; - VariableDefinition stopwatchVar; + VariableDefinition startTimestampVar; + VariableDefinition endTimestampVar; + VariableDefinition durationTimestampVar; + VariableDefinition durationTimespanVar; + + ParameterFormattingProcessor parameterFormattingProcessor = new(); public void Process() { @@ -35,7 +41,10 @@ void InnerProcess() var returnInstruction = FixReturns(); - stopwatchVar = ModuleWeaver.InjectStopwatch(body, indexOf); + startTimestampVar = InjectStartTimestamp(body, indexOf); + endTimestampVar = InjectEndTimestamp(body, indexOf); + durationTimestampVar = InjectDurationTimestamp(body, indexOf); + durationTimespanVar = InjectDurationTimespan(body, indexOf); var beforeReturn = Instruction.Create(OpCodes.Nop); body.InsertBefore(returnInstruction, beforeReturn); @@ -130,11 +139,164 @@ Instruction FixReturns() void InjectIlForFinally(Instruction beforeThis) { - foreach (var instruction in ModuleWeaver.GetWriteTimeInstruction(stopwatchVar, Method)) + foreach (var instruction in GetWriteTimeInstruction(startTimestampVar, endTimestampVar, + durationTimestampVar, durationTimespanVar, Method)) { body.InsertBefore(beforeThis, instruction); } body.InsertBefore(beforeThis, Instruction.Create(OpCodes.Endfinally)); } + + public IEnumerable GetWriteTimeInstruction(VariableDefinition startTimestampVar, + VariableDefinition endTimestampVar, VariableDefinition durationTimestampVar, + VariableDefinition durationTimespanVar, MethodDefinition methodDefinition) + { + // endTimestamp = Stopwatch.GetTimestamp(); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod); + yield return Instruction.Create(OpCodes.Stloc, endTimestampVar); + + // durationTimestamp = endTimestampVar - endTimestampVar; + yield return Instruction.Create(OpCodes.Ldloc, endTimestampVar); + yield return Instruction.Create(OpCodes.Ldloc, startTimestampVar); + yield return Instruction.Create(OpCodes.Sub); + yield return Instruction.Create(OpCodes.Stloc, durationTimestampVar); + + // durationTimespanVar = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * (double)durationTimestamp)); + + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); + yield return Instruction.Create(OpCodes.Ldsfld, ModuleWeaver.MethodTimerHelper_TimestampToTicks); + yield return Instruction.Create(OpCodes.Ldloc, durationTimestampVar); + yield return Instruction.Create(OpCodes.Conv_R8); + yield return Instruction.Create(OpCodes.Mul); + yield return Instruction.Create(OpCodes.Conv_I8); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_ConstructorMethod); + + var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; + var logWithMessageMethodUsingTimeSpan = ModuleWeaver.LogWithMessageMethodUsingTimeSpan; + + var logMethodUsingLong = ModuleWeaver.LogMethodUsingLong; + var logMethodUsingTimeSpan = ModuleWeaver.LogMethodUsingTimeSpan; + + if (logWithMessageMethodUsingLong is null && logWithMessageMethodUsingTimeSpan is null) + { + if (logMethodUsingLong is null && logMethodUsingTimeSpan is null) + { + var elapsedMillisecondsVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + methodDefinition.Body.Variables.Add(elapsedMillisecondsVariable); + yield return Instruction.Create(OpCodes.Ldstr, methodDefinition.MethodName()); + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); + yield return Instruction.Create(OpCodes.Stloc, elapsedMillisecondsVariable); + yield return Instruction.Create(OpCodes.Ldloca, elapsedMillisecondsVariable); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Int64ToString); + yield return Instruction.Create(OpCodes.Ldstr, "ms"); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ConcatMethod); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TraceWriteLineMethod); + + yield break; + } + + yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); + yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); + + if (logMethodUsingTimeSpan != null) + { + //yield return Instruction.Create(OpCodes.Call, Elapsed); + yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); + yield break; + } + + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); + yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); + yield break; + } + + var formattedVariableDefinition = new VariableDefinition(ModuleWeaver.TypeSystem.StringReference); + methodDefinition.Body.Variables.Add(formattedVariableDefinition); + + foreach (var instruction in ProcessTimeAttribute(methodDefinition, formattedVariableDefinition)) + { + yield return instruction; + } + + // Handle call to log method + yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); + yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); + + if (logWithMessageMethodUsingTimeSpan is null) + { + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); + yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); + yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingLong); + yield break; + } + + //yield return Instruction.Create(OpCodes.Call, Elapsed); + yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); + yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); + } + + IEnumerable ProcessTimeAttribute(MethodDefinition methodDefinition, VariableDefinition formattedVariableDefinition) + { + // Load everything for a string format + var timeAttribute = methodDefinition.GetTimeAttribute(); + if (timeAttribute == null) + { + yield break; + } + + var value = timeAttribute.ConstructorArguments.FirstOrDefault().Value as string; + if (string.IsNullOrWhiteSpace(value)) + { + // Load null a string + yield return Instruction.Create(OpCodes.Ldnull); + } + else + { + var info = parameterFormattingProcessor.ParseParameterFormatting(value); + + yield return Instruction.Create(OpCodes.Ldstr, info.Format); + yield return Instruction.Create(OpCodes.Ldc_I4, info.ParameterNames.Count); + yield return Instruction.Create(OpCodes.Newarr, ModuleWeaver.TypeSystem.ObjectReference); + + for (var i = 0; i < info.ParameterNames.Count; i++) + { + // Note: no need to validate, already done in AssemblyProcessor::ProcessMethod + var parameterName = info.ParameterNames[i]; + + yield return Instruction.Create(OpCodes.Dup); + yield return Instruction.Create(OpCodes.Ldc_I4, i); + + if (string.Equals(parameterName, "this")) + { + // IL_0028: ldarg.0 + yield return Instruction.Create(OpCodes.Ldarg_0); + } + else + { + var parameter = methodDefinition.Parameters.First(_ => _.Name.Equals(parameterName)); + yield return Instruction.Create(OpCodes.Ldarg, parameter); + + if (parameter.ParameterType.IsBoxingRequired(ModuleWeaver.TypeSystem.ObjectReference)) + { + yield return Instruction.Create(OpCodes.Box, ModuleWeaver.ModuleDefinition.ImportReference(parameter.ParameterType)); + } + } + + yield return Instruction.Create(OpCodes.Stelem_Ref); + } + + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.StringFormatWithArray); + } + + yield return Instruction.Create(OpCodes.Stloc, formattedVariableDefinition); + } } \ No newline at end of file diff --git a/MethodTimer.Fody/MethodProcessor.variables.cs b/MethodTimer.Fody/MethodProcessor.variables.cs new file mode 100644 index 00000000..b4f7b1de --- /dev/null +++ b/MethodTimer.Fody/MethodProcessor.variables.cs @@ -0,0 +1,51 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using Fody; +using Mono.Cecil; +using Mono.Cecil.Cil; +using Mono.Cecil.Rocks; + +public partial class MethodProcessor +{ + public VariableDefinition InjectStartTimestamp(MethodBody body, int index) + { + // inject as variable + var startTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + body.Variables.Add(startTimestampVariable); + body.Insert(index, new List( + new[] + { + Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod), + Instruction.Create(OpCodes.Stloc, startTimestampVariable) + })); + return startTimestampVariable; + } + + public VariableDefinition InjectEndTimestamp(MethodBody body, int index) + { + // inject as variable + var endTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + body.Variables.Add(endTimestampVariable); + + return endTimestampVariable; + } + + public VariableDefinition InjectDurationTimestamp(MethodBody body, int index) + { + // inject as variable + var durationTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + body.Variables.Add(durationTimestampVariable); + + return durationTimestampVariable; + } + + public VariableDefinition InjectDurationTimespan(MethodBody body, int index) + { + // inject as variable + var durationTimespan = new VariableDefinition(ModuleWeaver.TimeSpanType); + body.Variables.Add(durationTimespan); + + return durationTimespan; + } +} \ No newline at end of file diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index 1d76f8aa..ed96929d 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -1,3 +1,4 @@ +using System.Linq; using Fody; using Mono.Cecil; @@ -14,14 +15,21 @@ public partial class ModuleWeaver public MethodReference ElapsedMilliseconds; public MethodReference GetMethodFromHandle; public MethodReference ObjectConstructorMethod; - public MethodReference TimeSpanConstructorMethod; public MethodReference MaxMethod; public MethodReference GetTicksMethod; + public MethodReference Stopwatch_GetTimestampMethod; + public FieldReference Stopwatch_GetFrequencyField; public MethodReference UtcNowMethod; + public MethodReference TimeSpan_ConstructorMethod; + public MethodReference TimeSpan_TotalMillisecondsMethod; + public FieldReference TimeSpan_TicksPerSecondField; + public FieldDefinition MethodTimerHelper_TimestampToTicks; public TypeReference DateTimeType; public TypeReference TimeSpanType; public TypeReference BooleanType; public TypeReference VoidType; + public TypeReference Float64Type; + public TypeReference MethodTimerHelperType; public MethodReference Int64ToString; public void FindReferences() @@ -40,10 +48,19 @@ public void FindReferences() var objectConstructor = TypeSystem.ObjectDefinition.Method(".ctor"); ObjectConstructorMethod = ModuleDefinition.ImportReference(objectConstructor); + var voidType = FindTypeDefinition("System.Void"); + VoidType = ModuleDefinition.ImportReference(voidType); + var timeSpanDefinition = FindTypeDefinition("System.TimeSpan"); TimeSpanType = ModuleDefinition.ImportReference(timeSpanDefinition); var timeSpanConstructor = timeSpanDefinition.Method(".ctor","Int64"); - TimeSpanConstructorMethod = ModuleDefinition.ImportReference(timeSpanConstructor); + TimeSpan_ConstructorMethod = ModuleDefinition.ImportReference(timeSpanConstructor); + + var timeSpanTotalMilliseconds = timeSpanDefinition.Method("get_TotalMilliseconds"); + TimeSpan_TotalMillisecondsMethod = ModuleDefinition.ImportReference(timeSpanTotalMilliseconds); + + var timeSpanTicksPerSecond = timeSpanDefinition.Fields.First(x => x.Name == "TicksPerSecond"); + TimeSpan_TicksPerSecondField = ModuleDefinition.ImportReference(timeSpanTicksPerSecond); var mathType = FindTypeDefinition("System.Math"); MaxMethod = ModuleDefinition.ImportReference(mathType.Method("Max", "Int64", "Int64")); @@ -65,6 +82,37 @@ public void FindReferences() var concatMethod = TypeSystem.StringDefinition.Method("Concat", "String", "String", "String"); ConcatMethod = ModuleDefinition.ImportReference(concatMethod); - InjectStopwatchType(); + var float64Type = FindTypeDefinition("System.Double"); + Float64Type = ModuleDefinition.ImportReference(float64Type); + + var stopwatchType = FindTypeDefinition("System.Diagnostics.Stopwatch"); + StopwatchType = ModuleDefinition.ImportReference(stopwatchType); + if (StopwatchType is null) + { + throw new WeavingException($"Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); + } + + var startNewMethod = stopwatchType.Method("StartNew"); + StartNewMethod = ModuleDefinition.ImportReference(startNewMethod); + + var stopMethod = stopwatchType.Method("Stop"); + StopMethod = ModuleDefinition.ImportReference(stopMethod); + + var getElapsedMillisecondsMethod = stopwatchType.Method("get_ElapsedMilliseconds"); + ElapsedMilliseconds = ModuleDefinition.ImportReference(getElapsedMillisecondsMethod); + + var getElapsedMethod = stopwatchType.Method("get_Elapsed"); + Elapsed = ModuleDefinition.ImportReference(getElapsedMethod); + + var getIsRunning = stopwatchType.Method("get_IsRunning"); + IsRunning = ModuleDefinition.ImportReference(getIsRunning); + + var stopwatch_GetTimestampMethod = stopwatchType.Method("GetTimestamp"); + Stopwatch_GetTimestampMethod = ModuleDefinition.ImportReference(stopwatch_GetTimestampMethod); + + var stopwatch_GetFrequencyField = stopwatchType.Fields.First(x => x.Name == "Frequency"); + Stopwatch_GetFrequencyField = ModuleDefinition.ImportReference(stopwatch_GetFrequencyField); + + InjectMethodTimerHelper(); } } \ No newline at end of file diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index b6efac2d..e8771362 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -3,141 +3,66 @@ public partial class ModuleWeaver { - public void InjectStopwatchType() + public void InjectMethodTimerHelper() { - var valueType = FindTypeDefinition("System.ValueType"); - var type = new TypeDefinition( - "MethodTimer", - "Stopwatch", - TypeAttributes.Sealed |TypeAttributes.AnsiClass | TypeAttributes.BeforeFieldInit | TypeAttributes.SequentialLayout | TypeAttributes.NotPublic, - ModuleDefinition.ImportReference(valueType)); - ModuleDefinition.Types.Add(type); + //.class private auto ansi abstract sealed beforefieldinit MethodTimerHelper - var startTicks = new FieldDefinition("startTicks", FieldAttributes.Private, TypeSystem.Int64Reference); - type.Fields.Add(startTicks); + // extends[System.Runtime] System.Object + // { + // // Fields + // .field assembly static initonly float64 TimestampToTicks - var stopped = new FieldDefinition("stopped", FieldAttributes.Private, TypeSystem.BooleanReference); - type.Fields.Add(stopped); + // // Methods + // .method private hidebysig specialname rtspecialname static + // void .cctor() cil managed + // { + // // Method begins at RVA 0x20e9 + // // Header size: 1 + // // Code size: 22 (0x16) + // .maxstack 8 - var elapsedTicks = new FieldDefinition("elapsedTicks", FieldAttributes.Private, TypeSystem.Int64Reference); - type.Fields.Add(elapsedTicks); + // // TimestampToTicks = (double)TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; + // IL_0000: ldc.r8 10000000 + // IL_0009: ldsfld int64 [System.Runtime] + // System.Diagnostics.Stopwatch::Frequency + // IL_000e: conv.r8 + // IL_000f: div + // IL_0010: stsfld float64 MethodTimerHelper::TimestampToTicks + // // } + // IL_0015: ret + // } // end of method MethodTimerHelper::.cctor - var currentTicks = new MethodDefinition( - "CurrentTicks", - MethodAttributes.HideBySig | MethodAttributes.Private | MethodAttributes.Static, - TypeSystem.Int64Reference) - { - Body = - { - InitLocals = true - } - }; - type.Methods.Add(currentTicks); - var timeVariable = new VariableDefinition(DateTimeType); - currentTicks.Body.Variables.Add(timeVariable); - currentTicks.Body.Add( - Instruction.Create(OpCodes.Call, UtcNowMethod), - Instruction.Create(OpCodes.Stloc, timeVariable), - Instruction.Create(OpCodes.Ldloca_S, timeVariable), - Instruction.Create(OpCodes.Call, GetTicksMethod), - Instruction.Create(OpCodes.Ret)); + //} // end of class MethodTimerHelper - var constructor = new MethodDefinition( - ".ctor", - MethodAttributes.RTSpecialName | MethodAttributes.SpecialName | MethodAttributes.HideBySig | MethodAttributes.Public, - TypeSystem.VoidReference); - type.Methods.Add(constructor); - constructor.Body.Add( - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldc_I4_0), - Instruction.Create(OpCodes.Conv_I8), - Instruction.Create(OpCodes.Stfld, elapsedTicks), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldc_I4_0), - Instruction.Create(OpCodes.Stfld, stopped), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, currentTicks), - Instruction.Create(OpCodes.Stfld, startTicks), - Instruction.Create(OpCodes.Ret)); - - var startNew = new MethodDefinition( - "StartNew", - MethodAttributes.HideBySig | MethodAttributes.Public | MethodAttributes.Static, - type); - type.Methods.Add(startNew); - startNew.Body.Add( - Instruction.Create(OpCodes.Newobj, constructor), - Instruction.Create(OpCodes.Ret)); + var type = new TypeDefinition( + "MethodTimer", + "MethodTimerHelper", + TypeAttributes.Sealed | TypeAttributes.AnsiClass | TypeAttributes.AutoClass | TypeAttributes.Abstract | TypeAttributes.NotPublic, + TypeSystem.ObjectReference); + ModuleDefinition.Types.Add(type); - var stop = new MethodDefinition( - "Stop", - MethodAttributes.HideBySig | MethodAttributes.Public, - TypeSystem.VoidReference); - type.Methods.Add(stop); - var stopReturn = Instruction.Create(OpCodes.Ret); - stop.Body.Add( - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, stopped), - Instruction.Create(OpCodes.Brtrue, stopReturn), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldc_I4_1), - Instruction.Create(OpCodes.Stfld, stopped), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldc_I4_0), - Instruction.Create(OpCodes.Conv_I8), - Instruction.Create(OpCodes.Call, currentTicks), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, startTicks), - Instruction.Create(OpCodes.Sub), - Instruction.Create(OpCodes.Call, MaxMethod), - Instruction.Create(OpCodes.Stfld, elapsedTicks), - stopReturn); + var timestampToTicksField = new FieldDefinition("TimestampToTicks", + FieldAttributes.Assembly | FieldAttributes.Static | FieldAttributes.InitOnly, + Float64Type); + type.Fields.Add(timestampToTicksField); - var elapsedMilliseconds = new MethodDefinition( - "GetElapsedMilliseconds", - MethodAttributes.HideBySig | MethodAttributes.Public, - TypeSystem.Int64Reference); - type.Methods.Add(elapsedMilliseconds); - elapsedMilliseconds.Body.Add( - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, stop), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, elapsedTicks), - Instruction.Create(OpCodes.Ldc_I4, 10000), - Instruction.Create(OpCodes.Conv_I8), + var staticConstructor = new MethodDefinition(".cctor", + MethodAttributes.Private | MethodAttributes.HideBySig | MethodAttributes.SpecialName | MethodAttributes.RTSpecialName | MethodAttributes.Static, + VoidType); + staticConstructor.Body.Add( + // Note: it's a const (10000000) + Instruction.Create(OpCodes.Ldc_R8, 10000000d), + //Instruction.Create(OpCodes.Ldsfld, TimeSpan_TicksPerSecondField), + //Instruction.Create(OpCodes.Conv_R8), + Instruction.Create(OpCodes.Ldsfld, Stopwatch_GetFrequencyField), + Instruction.Create(OpCodes.Conv_R8), Instruction.Create(OpCodes.Div), + Instruction.Create(OpCodes.Stsfld, timestampToTicksField), Instruction.Create(OpCodes.Ret)); - var elapsed = new MethodDefinition( - "GetElapsed", - MethodAttributes.HideBySig | MethodAttributes.Public, - TimeSpanType); - type.Methods.Add(elapsed); - elapsed.Body.Add( - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, stop), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, elapsedTicks), - Instruction.Create(OpCodes.Newobj, TimeSpanConstructorMethod), - Instruction.Create(OpCodes.Ret)); - - var isRunning = new MethodDefinition( - "GetIsRunning", - MethodAttributes.HideBySig | MethodAttributes.Public, - TypeSystem.BooleanReference); - type.Methods.Add(isRunning); - isRunning.Body.Add( - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, stopped), - Instruction.Create(OpCodes.Ldc_I4_0), - Instruction.Create(OpCodes.Ceq), - Instruction.Create(OpCodes.Ret)); + type.Methods.Add(staticConstructor); - IsRunning = isRunning; - Elapsed = elapsed; - ElapsedMilliseconds = elapsedMilliseconds; - StopMethod = stop; - StopwatchType = type; - StartNewMethod = startNew; + MethodTimerHelperType = type; + MethodTimerHelper_TimestampToTicks = timestampToTicksField; } } \ No newline at end of file diff --git a/MethodTimer.Fody/StopwatchHelper.cs b/MethodTimer.Fody/StopwatchHelper.cs deleted file mode 100644 index 076536c8..00000000 --- a/MethodTimer.Fody/StopwatchHelper.cs +++ /dev/null @@ -1,151 +0,0 @@ -using System.Collections.Generic; -using System.Linq; -using Mono.Cecil; -using Mono.Cecil.Cil; - -public partial class ModuleWeaver -{ - public IEnumerable GetWriteTimeInstruction(VariableDefinition stopwatchVariableDefinition, MethodDefinition methodDefinition) - { - yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); - yield return Instruction.Create(OpCodes.Call, StopMethod); - - var logWithMessageMethodUsingLong = LogWithMessageMethodUsingLong; - var logWithMessageMethodUsingTimeSpan = LogWithMessageMethodUsingTimeSpan; - - var logMethodUsingLong = LogMethodUsingLong; - var logMethodUsingTimeSpan = LogMethodUsingTimeSpan; - - if (logWithMessageMethodUsingLong is null && logWithMessageMethodUsingTimeSpan is null) - { - if (logMethodUsingLong is null && logMethodUsingTimeSpan is null) - { - var elapsedMillisecondsVariable = new VariableDefinition(TypeSystem.Int64Reference); - methodDefinition.Body.Variables.Add(elapsedMillisecondsVariable); - yield return Instruction.Create(OpCodes.Ldstr, methodDefinition.MethodName()); - yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); - yield return Instruction.Create(OpCodes.Call, ElapsedMilliseconds); - yield return Instruction.Create(OpCodes.Stloc, elapsedMillisecondsVariable); - yield return Instruction.Create(OpCodes.Ldloca, elapsedMillisecondsVariable); - yield return Instruction.Create(OpCodes.Call, Int64ToString); - yield return Instruction.Create(OpCodes.Ldstr, "ms"); - yield return Instruction.Create(OpCodes.Call, ConcatMethod); - yield return Instruction.Create(OpCodes.Call, TraceWriteLineMethod); - - yield break; - } - - yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); - yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); - yield return Instruction.Create(OpCodes.Call, GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); - - if (logMethodUsingTimeSpan != null) - { - yield return Instruction.Create(OpCodes.Call, Elapsed); - yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); - yield break; - } - - yield return Instruction.Create(OpCodes.Call, ElapsedMilliseconds); - yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); - yield break; - } - - var formattedVariableDefinition = new VariableDefinition(TypeSystem.StringReference); - methodDefinition.Body.Variables.Add(formattedVariableDefinition); - - foreach (var instruction in ProcessTimeAttribute(methodDefinition, formattedVariableDefinition)) - { - yield return instruction; - } - - // Handle call to log method - yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); - yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); - yield return Instruction.Create(OpCodes.Call, GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloca, stopwatchVariableDefinition); - - if (logWithMessageMethodUsingTimeSpan is null) - { - yield return Instruction.Create(OpCodes.Call, ElapsedMilliseconds); - yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); - yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingLong); - yield break; - } - - yield return Instruction.Create(OpCodes.Call, Elapsed); - yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); - yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); - } - - IEnumerable ProcessTimeAttribute(MethodDefinition methodDefinition, VariableDefinition formattedVariableDefinition) - { - // Load everything for a string format - var timeAttribute = methodDefinition.GetTimeAttribute(); - if (timeAttribute == null) - { - yield break; - } - - var value = timeAttribute.ConstructorArguments.FirstOrDefault().Value as string; - if (string.IsNullOrWhiteSpace(value)) - { - // Load null a string - yield return Instruction.Create(OpCodes.Ldnull); - } - else - { - var info = parameterFormattingProcessor.ParseParameterFormatting(value); - - yield return Instruction.Create(OpCodes.Ldstr, info.Format); - yield return Instruction.Create(OpCodes.Ldc_I4, info.ParameterNames.Count); - yield return Instruction.Create(OpCodes.Newarr, TypeSystem.ObjectReference); - - for (var i = 0; i < info.ParameterNames.Count; i++) - { - // Note: no need to validate, already done in AssemblyProcessor::ProcessMethod - var parameterName = info.ParameterNames[i]; - - yield return Instruction.Create(OpCodes.Dup); - yield return Instruction.Create(OpCodes.Ldc_I4, i); - - if (string.Equals(parameterName, "this")) - { - // IL_0028: ldarg.0 - yield return Instruction.Create(OpCodes.Ldarg_0); - } - else - { - var parameter = methodDefinition.Parameters.First(_ => _.Name.Equals(parameterName)); - yield return Instruction.Create(OpCodes.Ldarg, parameter); - - if (parameter.ParameterType.IsBoxingRequired(TypeSystem.ObjectReference)) - { - yield return Instruction.Create(OpCodes.Box, ModuleDefinition.ImportReference(parameter.ParameterType)); - } - } - - yield return Instruction.Create(OpCodes.Stelem_Ref); - } - - yield return Instruction.Create(OpCodes.Call, StringFormatWithArray); - } - - yield return Instruction.Create(OpCodes.Stloc, formattedVariableDefinition); - } - - public VariableDefinition InjectStopwatch(MethodBody body, int index) - { - // inject as variable - var stopwatchVar = new VariableDefinition(StopwatchType); - body.Variables.Add(stopwatchVar); - body.Insert(index, new List( - new[] - { - Instruction.Create(OpCodes.Call, StartNewMethod), - Instruction.Create(OpCodes.Stloc, stopwatchVar) - })); - return stopwatchVar; - } -} \ No newline at end of file diff --git a/Tests/AssemblyTesterSets/WithInterceptorAndFormattingTests.cs b/Tests/AssemblyTesterSets/WithInterceptorAndFormattingTests.cs index 0cdf3b4e..4b7827e2 100644 --- a/Tests/AssemblyTesterSets/WithInterceptorAndFormattingTests.cs +++ b/Tests/AssemblyTesterSets/WithInterceptorAndFormattingTests.cs @@ -21,7 +21,9 @@ static WithInterceptorAndFormattingTests() #if NETCOREAPP2_1 , runPeVerify: false #endif - ); var methodTimeLogger = testResult.Assembly.GetType("MethodTimeLogger"); + ); + + var methodTimeLogger = testResult.Assembly.GetType("MethodTimeLogger"); methodBaseField = methodTimeLogger.GetField("MethodBase"); messagesField = methodTimeLogger.GetField("Messages"); } From ed6ba261af8f857c0650ce31a23b70c6c4e47e54 Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 14:20:22 +0100 Subject: [PATCH 12/22] Add benchmark to ensure the new strategy is an improvement --- ExampleAssembly/Benchmarks.cs | 27 +++++++++++++ ExampleAssembly/ExampleAssembly.csproj | 6 ++- ExampleAssembly/MethodsWithStopwatch.cs | 39 +++++++++++++++++++ .../{Method.cs => MethodsWithTimestamp.cs} | 6 +-- ExampleAssembly/Program.cs | 12 ++++++ 5 files changed, 86 insertions(+), 4 deletions(-) create mode 100644 ExampleAssembly/Benchmarks.cs create mode 100644 ExampleAssembly/MethodsWithStopwatch.cs rename ExampleAssembly/{Method.cs => MethodsWithTimestamp.cs} (89%) create mode 100644 ExampleAssembly/Program.cs diff --git a/ExampleAssembly/Benchmarks.cs b/ExampleAssembly/Benchmarks.cs new file mode 100644 index 00000000..b6cd5588 --- /dev/null +++ b/ExampleAssembly/Benchmarks.cs @@ -0,0 +1,27 @@ +namespace ExampleAssembly +{ + using BenchmarkDotNet.Attributes; + + [MemoryDiagnoser] + public class StopwatchVsTimestamp + { + private TestClassWithStopwatch _testClassWithStopwatch = new TestClassWithStopwatch(); + private TestClassWithTimestamp _testClassWithTimestamp = new TestClassWithTimestamp(); + + public StopwatchVsTimestamp() + { + } + + [Benchmark] + public void Timestamp_Sync() => _testClassWithTimestamp.SyncMethod(); + + [Benchmark] + public void Timestamp_Async() => _testClassWithTimestamp.SyncMethod(); + + [Benchmark] + public void Stopwatch_Sync() => _testClassWithStopwatch.SyncMethod(); + + [Benchmark] + public void Stopwatch_Async() => _testClassWithStopwatch.SyncMethod(); + } +} diff --git a/ExampleAssembly/ExampleAssembly.csproj b/ExampleAssembly/ExampleAssembly.csproj index 7890704b..e7eaffd7 100644 --- a/ExampleAssembly/ExampleAssembly.csproj +++ b/ExampleAssembly/ExampleAssembly.csproj @@ -1,6 +1,10 @@  - net48;net6 + net6 + Exe + + + \ No newline at end of file diff --git a/ExampleAssembly/MethodsWithStopwatch.cs b/ExampleAssembly/MethodsWithStopwatch.cs new file mode 100644 index 00000000..80abb020 --- /dev/null +++ b/ExampleAssembly/MethodsWithStopwatch.cs @@ -0,0 +1,39 @@ +using System; +using System.Diagnostics; +using System.Threading.Tasks; + +public class TestClassWithStopwatch +{ + public void SyncMethod() + { + var stopwatch = Stopwatch.StartNew(); + + try + { + // Do something + //Console.WriteLine("Hello, World!"); + } + finally + { + stopwatch.Stop(); + + var elapsedTimeSpan = stopwatch.Elapsed; + } + } + + public async Task AsyncMethod() + { + var stopwatch = Stopwatch.StartNew(); + + try + { + await Task.Delay(5); + } + finally + { + stopwatch.Stop(); + + var elapsedTimeSpan = stopwatch.Elapsed; + } + } +} \ No newline at end of file diff --git a/ExampleAssembly/Method.cs b/ExampleAssembly/MethodsWithTimestamp.cs similarity index 89% rename from ExampleAssembly/Method.cs rename to ExampleAssembly/MethodsWithTimestamp.cs index 4b77f7d2..cac96c21 100644 --- a/ExampleAssembly/Method.cs +++ b/ExampleAssembly/MethodsWithTimestamp.cs @@ -2,7 +2,7 @@ using System.Diagnostics; using System.Threading.Tasks; -public class TestClass +public class TestClassWithTimestamp { public void SyncMethod() { @@ -16,7 +16,7 @@ public void SyncMethod() try { // Do something - Console.WriteLine("Hello, World!"); + //Console.WriteLine("Hello, World!"); } finally { @@ -37,7 +37,7 @@ public async Task AsyncMethod() startTimestamp = Stopwatch.GetTimestamp(); try { - await Task.Delay(10); + await Task.Delay(5); } finally { diff --git a/ExampleAssembly/Program.cs b/ExampleAssembly/Program.cs new file mode 100644 index 00000000..d92c4a05 --- /dev/null +++ b/ExampleAssembly/Program.cs @@ -0,0 +1,12 @@ +namespace ExampleAssembly +{ + using BenchmarkDotNet.Running; + + public class Program + { + public static void Main(string[] args) + { + var summary = BenchmarkRunner.Run(); + } + } +} From 77833004725baac025d3cb701a30800edff8d1ec Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 14:43:55 +0100 Subject: [PATCH 13/22] First work on the async implementation --- ExampleAssembly/MethodsWithTimestamp.cs | 17 ++- MethodTimer.Fody/AsyncMethodProcessor.cs | 105 ++++++++++++------ .../AsyncMethodProcessor.fields.cs | 52 +++++++++ .../AsyncMethodProcessor.variables.cs | 4 + MethodTimer.Fody/MethodProcessor.variables.cs | 5 - MethodTimer.Fody/ReferenceFinder.cs | 30 ++--- 6 files changed, 157 insertions(+), 56 deletions(-) create mode 100644 MethodTimer.Fody/AsyncMethodProcessor.fields.cs create mode 100644 MethodTimer.Fody/AsyncMethodProcessor.variables.cs diff --git a/ExampleAssembly/MethodsWithTimestamp.cs b/ExampleAssembly/MethodsWithTimestamp.cs index cac96c21..7838836b 100644 --- a/ExampleAssembly/MethodsWithTimestamp.cs +++ b/ExampleAssembly/MethodsWithTimestamp.cs @@ -29,22 +29,29 @@ public void SyncMethod() public async Task AsyncMethod() { - long startTimestamp; + long startTimestamp = default; long endTimestamp; long elapsed; TimeSpan elapsedTimeSpan; - startTimestamp = Stopwatch.GetTimestamp(); + if (startTimestamp == 0) + { + startTimestamp = Stopwatch.GetTimestamp(); + } + try { await Task.Delay(5); } finally { - endTimestamp = Stopwatch.GetTimestamp(); + if (startTimestamp != 0) + { + endTimestamp = Stopwatch.GetTimestamp(); - elapsed = endTimestamp - startTimestamp; - elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * elapsed)); + elapsed = endTimestamp - startTimestamp; + elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * elapsed)); + } } } } \ No newline at end of file diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 098b375d..1c68504b 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -5,13 +5,11 @@ using Mono.Cecil.Cil; using Mono.Cecil.Rocks; -public class AsyncMethodProcessor +public partial class AsyncMethodProcessor { public ModuleWeaver ModuleWeaver; public MethodDefinition Method; MethodBody body; - FieldDefinition stopwatchFieldDefinition; - FieldReference stopwatchFieldReference; FieldDefinition stateFieldDefinition; FieldReference stateFieldReference; TypeDefinition stateMachineTypeDefinition; @@ -19,6 +17,15 @@ public class AsyncMethodProcessor MethodDefinition stopStopwatchMethod; ParameterFormattingProcessor parameterFormattingProcessor = new(); + FieldDefinition startTimestampField; + FieldReference startTimestampFieldReference; + FieldDefinition endTimestampField; + FieldReference endTimestampFieldReference; + FieldDefinition durationTimestampField; + FieldReference durationTimestampFieldReference; + FieldDefinition durationTimespanField; + FieldReference durationTimespanFieldReference; + public void Process() { try @@ -89,9 +96,9 @@ void InnerProcess() } stateFieldDefinition = (from x in stateMachineTypeDefinition.Fields - where x.Name.EndsWith("__state") || - x.Name.EndsWith("$State") - select x).First(); + where x.Name.EndsWith("__state") || + x.Name.EndsWith("$State") + select x).First(); stateFieldReference = new(stateFieldDefinition.Name, stateFieldDefinition.FieldType, stateMachineTypeReference); @@ -132,29 +139,38 @@ void InjectStopwatchStart(int index, Instruction nextInstruction) var boolVariable = new VariableDefinition(ModuleWeaver.TypeSystem.BooleanReference); body.Variables.Add(boolVariable); - stopwatchFieldDefinition = new("methodTimerStopwatch", new(), ModuleWeaver.StopwatchType); - stateMachineTypeDefinition.Fields.Add(stopwatchFieldDefinition); + // Field definitions + startTimestampField = InjectStartTimestamp(stateMachineTypeDefinition); + startTimestampFieldReference = new(startTimestampField.Name, startTimestampField.FieldType, stateMachineTypeReference); + + endTimestampField = InjectEndTimestamp(stateMachineTypeDefinition); + endTimestampFieldReference = new(endTimestampField.Name, endTimestampField.FieldType, stateMachineTypeReference); + + durationTimestampField = InjectDurationTimestamp(stateMachineTypeDefinition); + durationTimestampFieldReference = new(durationTimestampField.Name, durationTimestampField.FieldType, stateMachineTypeReference); - stopwatchFieldReference = new(stopwatchFieldDefinition.Name, stopwatchFieldDefinition.FieldType, stateMachineTypeReference); + durationTimespanField = InjectDurationTimespan(stateMachineTypeDefinition); + durationTimespanFieldReference = new(durationTimespanField.Name, durationTimespanField.FieldType, stateMachineTypeReference); body.Insert(index, new[] { // This code looks like this: - // if (_stopwatch is null) + // if (_startTimestamp == 0L) // { - // _stopwatch = Stopwatch.StartNew(); + // _startTimestamp = Stopwatch.GetTimestamp(); // } Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference), - Instruction.Create(OpCodes.Ldnull), + Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference), + Instruction.Create(OpCodes.Ldc_I4_0), + Instruction.Create(OpCodes.Conv_I8), Instruction.Create(OpCodes.Ceq), Instruction.Create(OpCodes.Stloc, boolVariable), Instruction.Create(OpCodes.Ldloc, boolVariable), Instruction.Create(OpCodes.Brfalse_S, nextInstruction), Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, ModuleWeaver.StartNewMethod), - Instruction.Create(OpCodes.Stfld, stopwatchFieldReference) + Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod), + Instruction.Create(OpCodes.Stfld, startTimestampFieldReference) }); } @@ -165,7 +181,9 @@ void InjectStopwatchStopMethod() return; } - var method = new MethodDefinition("StopMethodTimerStopwatch", MethodAttributes.Private, ModuleWeaver.TypeSystem.VoidReference); + var method = new MethodDefinition("StopMethodTimerStopwatch", + MethodAttributes.Private, + ModuleWeaver.TypeSystem.VoidReference); var methodBody = method.Body; methodBody.SimplifyMacros(); @@ -216,7 +234,7 @@ orderby handler.HandlerEnd.Offset descending for (var i = catchEndIndex; i >= catchStartIndex; i--) { - if (body.Instructions[i].Operand is MethodReference {Name: "SetException"}) + if (body.Instructions[i].Operand is MethodReference { Name: "SetException" }) { // Insert before for (var j = 0; j < stopwatchInstructions.Count; j++) @@ -231,7 +249,7 @@ orderby handler.HandlerEnd.Offset descending // 2: end of the method (either SetResult or end of the method) for (var i = body.Instructions.Count - 1; i >= 0; i--) { - if (body.Instructions[i].Operand is MethodReference {Name: "SetResult"}) + if (body.Instructions[i].Operand is MethodReference { Name: "SetResult" }) { // Next index, we want this to appear *after* the SetResult call endInstruction = body.Instructions[i + 1]; @@ -249,6 +267,9 @@ orderby handler.HandlerEnd.Offset descending IEnumerable GetWriteTimeInstruction(MethodBody methodBody) { + var boolVariable = new VariableDefinition(ModuleWeaver.TypeSystem.BooleanReference); + methodBody.Variables.Add(boolVariable); + var stopwatchRunningCheck = Instruction.Create(OpCodes.Ldarg_0); var startOfRealMethod = Instruction.Create(OpCodes.Ldarg_0); @@ -259,18 +280,39 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Beq_S, stopwatchRunningCheck); yield return Instruction.Create(OpCodes.Ret); - // Check if stopwatch is actually running + // Check if there is a start timestamp yield return stopwatchRunningCheck; - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.IsRunning); + + yield return Instruction.Create(OpCodes.Ldarg_0); + yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); yield return Instruction.Create(OpCodes.Ldc_I4_0); + yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ceq); + yield return Instruction.Create(OpCodes.Stloc, boolVariable); + yield return Instruction.Create(OpCodes.Ldloc, boolVariable); yield return Instruction.Create(OpCodes.Brfalse_S, startOfRealMethod); yield return Instruction.Create(OpCodes.Ret); yield return startOfRealMethod; // Ldarg_0 - yield return Instruction.Create(OpCodes.Ldflda, stopwatchFieldReference); - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.StopMethod); + + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod); + yield return Instruction.Create(OpCodes.Stfld, endTimestampFieldReference); + + // durationTimestamp = endTimestampVar - endTimestampVar; + yield return Instruction.Create(OpCodes.Ldfld, endTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); + yield return Instruction.Create(OpCodes.Sub); + yield return Instruction.Create(OpCodes.Stfld, durationTimestampFieldReference); + + // durationTimespanVar = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * (double)durationTimestamp)); + + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldsfld, ModuleWeaver.MethodTimerHelper_TimestampToTicks); + yield return Instruction.Create(OpCodes.Ldfld, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Conv_R8); + yield return Instruction.Create(OpCodes.Mul); + yield return Instruction.Create(OpCodes.Conv_I8); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_ConstructorMethod); var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; var logWithMessageMethodUsingTimeSpan = ModuleWeaver.LogWithMessageMethodUsingTimeSpan; @@ -286,8 +328,9 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) methodBody.Variables.Add(elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldstr, Method.MethodName()); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ElapsedMilliseconds); + yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Stloc, elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldloca, elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Int64ToString); @@ -301,16 +344,16 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); if (logMethodUsingTimeSpan is null) { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ElapsedMilliseconds); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); } else { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Elapsed); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); } } @@ -340,18 +383,18 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); if (logWithMessageMethodUsingTimeSpan is null) { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ElapsedMilliseconds); + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); + yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingLong); } else { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Elapsed); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); diff --git a/MethodTimer.Fody/AsyncMethodProcessor.fields.cs b/MethodTimer.Fody/AsyncMethodProcessor.fields.cs new file mode 100644 index 00000000..20966dca --- /dev/null +++ b/MethodTimer.Fody/AsyncMethodProcessor.fields.cs @@ -0,0 +1,52 @@ +using Mono.Cecil; +using Mono.Cecil.Cil; + +public partial class AsyncMethodProcessor +{ + public FieldDefinition InjectStartTimestamp(TypeDefinition typeDefinition) + { + var startTimestampField = new FieldDefinition("_MethodTimer_StartTimestamp", + FieldAttributes.Private, + ModuleWeaver.TypeSystem.Int64Reference); + + typeDefinition.Fields.Add(startTimestampField); + + return startTimestampField; + } + + public FieldDefinition InjectEndTimestamp(TypeDefinition typeDefinition) + { + // inject as variable + var endTimestampField = new FieldDefinition("_MethodTimer_EndTimestamp", + FieldAttributes.Private, + ModuleWeaver.TypeSystem.Int64Reference); + + typeDefinition.Fields.Add(endTimestampField); + + return endTimestampField; + } + + public FieldDefinition InjectDurationTimestamp(TypeDefinition typeDefinition) + { + // inject as variable + var durationTimestampField = new FieldDefinition("_MethodTimer_DurationTimestamp", + FieldAttributes.Private, + ModuleWeaver.TypeSystem.Int64Reference); + + typeDefinition.Fields.Add(durationTimestampField); + + return durationTimestampField; + } + + public FieldDefinition InjectDurationTimespan(TypeDefinition typeDefinition) + { + // inject as variable + var durationTimespanField = new FieldDefinition("_MethodTimer_DurationTimespan", + FieldAttributes.Private, + ModuleWeaver.TimeSpanType); + + typeDefinition.Fields.Add(durationTimespanField); + + return durationTimespanField; + } +} \ No newline at end of file diff --git a/MethodTimer.Fody/AsyncMethodProcessor.variables.cs b/MethodTimer.Fody/AsyncMethodProcessor.variables.cs new file mode 100644 index 00000000..86f4b9a7 --- /dev/null +++ b/MethodTimer.Fody/AsyncMethodProcessor.variables.cs @@ -0,0 +1,4 @@ +public partial class AsyncMethodProcessor +{ + // No variables (yet) +} \ No newline at end of file diff --git a/MethodTimer.Fody/MethodProcessor.variables.cs b/MethodTimer.Fody/MethodProcessor.variables.cs index b4f7b1de..f92eaa41 100644 --- a/MethodTimer.Fody/MethodProcessor.variables.cs +++ b/MethodTimer.Fody/MethodProcessor.variables.cs @@ -1,10 +1,5 @@ -using System; using System.Collections.Generic; -using System.Linq; -using Fody; -using Mono.Cecil; using Mono.Cecil.Cil; -using Mono.Cecil.Rocks; public partial class MethodProcessor { diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index ed96929d..fee8f986 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -5,14 +5,14 @@ public partial class ModuleWeaver { public MethodReference TraceWriteLineMethod; - public MethodReference StartNewMethod; - public MethodReference StopMethod; + //public MethodReference StartNewMethod; + //public MethodReference StopMethod; public TypeReference StopwatchType; public MethodReference StringFormatWithArray; public MethodReference ConcatMethod; - public MethodReference IsRunning; - public MethodReference Elapsed; - public MethodReference ElapsedMilliseconds; + //public MethodReference IsRunning; + //public MethodReference Elapsed; + //public MethodReference ElapsedMilliseconds; public MethodReference GetMethodFromHandle; public MethodReference ObjectConstructorMethod; public MethodReference MaxMethod; @@ -92,20 +92,20 @@ public void FindReferences() throw new WeavingException($"Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); } - var startNewMethod = stopwatchType.Method("StartNew"); - StartNewMethod = ModuleDefinition.ImportReference(startNewMethod); + //var startNewMethod = stopwatchType.Method("StartNew"); + //StartNewMethod = ModuleDefinition.ImportReference(startNewMethod); - var stopMethod = stopwatchType.Method("Stop"); - StopMethod = ModuleDefinition.ImportReference(stopMethod); + //var stopMethod = stopwatchType.Method("Stop"); + //StopMethod = ModuleDefinition.ImportReference(stopMethod); - var getElapsedMillisecondsMethod = stopwatchType.Method("get_ElapsedMilliseconds"); - ElapsedMilliseconds = ModuleDefinition.ImportReference(getElapsedMillisecondsMethod); + //var getElapsedMillisecondsMethod = stopwatchType.Method("get_ElapsedMilliseconds"); + //ElapsedMilliseconds = ModuleDefinition.ImportReference(getElapsedMillisecondsMethod); - var getElapsedMethod = stopwatchType.Method("get_Elapsed"); - Elapsed = ModuleDefinition.ImportReference(getElapsedMethod); + //var getElapsedMethod = stopwatchType.Method("get_Elapsed"); + //Elapsed = ModuleDefinition.ImportReference(getElapsedMethod); - var getIsRunning = stopwatchType.Method("get_IsRunning"); - IsRunning = ModuleDefinition.ImportReference(getIsRunning); + //var getIsRunning = stopwatchType.Method("get_IsRunning"); + //IsRunning = ModuleDefinition.ImportReference(getIsRunning); var stopwatch_GetTimestampMethod = stopwatchType.Method("GetTimestamp"); Stopwatch_GetTimestampMethod = ModuleDefinition.ImportReference(stopwatch_GetTimestampMethod); From 723aef50d962ad69117c62594433031e7adcbdeb Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 21:59:47 +0100 Subject: [PATCH 14/22] First working async implementation --- ExampleAssembly/MethodTimeLogger.cs | 21 +++++++++ ExampleAssembly/MethodsWithTimestamp.cs | 1 + .../MethodsWithTimestampPreweaved.cs | 46 +++++++++++++++++++ MethodTimer.Fody/AsyncMethodProcessor.cs | 20 ++++++-- 4 files changed, 83 insertions(+), 5 deletions(-) create mode 100644 ExampleAssembly/MethodTimeLogger.cs create mode 100644 ExampleAssembly/MethodsWithTimestampPreweaved.cs diff --git a/ExampleAssembly/MethodTimeLogger.cs b/ExampleAssembly/MethodTimeLogger.cs new file mode 100644 index 00000000..fb60cd8a --- /dev/null +++ b/ExampleAssembly/MethodTimeLogger.cs @@ -0,0 +1,21 @@ +using System; +using System.Collections.Generic; +using System.Reflection; + +public static class MethodTimeLogger +{ + public static List MethodBase = new(); + public static List Messages = new(); + + public static void Log(MethodBase methodBase, long milliseconds, string message) + { + Console.WriteLine($"{methodBase.Name} {milliseconds}: {message}"); + + MethodBase.Add(methodBase); + + if (message != null) + { + Messages.Add(message); + } + } +} \ No newline at end of file diff --git a/ExampleAssembly/MethodsWithTimestamp.cs b/ExampleAssembly/MethodsWithTimestamp.cs index 7838836b..518225ee 100644 --- a/ExampleAssembly/MethodsWithTimestamp.cs +++ b/ExampleAssembly/MethodsWithTimestamp.cs @@ -1,5 +1,6 @@ using System; using System.Diagnostics; +using System.Reflection; using System.Threading.Tasks; public class TestClassWithTimestamp diff --git a/ExampleAssembly/MethodsWithTimestampPreweaved.cs b/ExampleAssembly/MethodsWithTimestampPreweaved.cs new file mode 100644 index 00000000..004ed5d3 --- /dev/null +++ b/ExampleAssembly/MethodsWithTimestampPreweaved.cs @@ -0,0 +1,46 @@ +namespace ExampleAssembly +{ + using System; + using System.Diagnostics; + using System.Reflection; + using System.Threading.Tasks; + + public class MethodsWithTimestampPreweaved + { + private long _startTimestamp = default; + private long _endTimestamp; + private long _elapsed; + private TimeSpan _elapsedTimeSpan; + private int _state = 0; + private string methodTimerMessage; + + public async Task AsyncMethod() + { + if (_startTimestamp == 0) + { + _startTimestamp = Stopwatch.GetTimestamp(); + } + + try + { + await Task.Delay(5); + } + finally + { + StopMethodTimerStopwatch(); + } + } + + private void StopMethodTimerStopwatch() + { + if (_state == -2 && _startTimestamp != 0) + { + _endTimestamp = Stopwatch.GetTimestamp(); + _elapsed = _endTimestamp - _startTimestamp; + _elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * (double)_elapsed)); + methodTimerMessage = null; + MethodTimeLogger.Log(MethodBase.GetCurrentMethod(), (long)_elapsedTimeSpan.TotalMilliseconds, methodTimerMessage); + } + } + } +} diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 1c68504b..1d5a338b 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -281,9 +281,8 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ret); // Check if there is a start timestamp - yield return stopwatchRunningCheck; + yield return stopwatchRunningCheck; // Ldarg_0 - yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); yield return Instruction.Create(OpCodes.Ldc_I4_0); yield return Instruction.Create(OpCodes.Conv_I8); @@ -299,20 +298,26 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Stfld, endTimestampFieldReference); // durationTimestamp = endTimestampVar - endTimestampVar; + + yield return Instruction.Create(OpCodes.Ldarg_0); // Yes, ldarg_0 twice + yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, endTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); yield return Instruction.Create(OpCodes.Sub); yield return Instruction.Create(OpCodes.Stfld, durationTimestampFieldReference); // durationTimespanVar = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * (double)durationTimestamp)); - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldsfld, ModuleWeaver.MethodTimerHelper_TimestampToTicks); + yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, durationTimestampFieldReference); yield return Instruction.Create(OpCodes.Conv_R8); yield return Instruction.Create(OpCodes.Mul); yield return Instruction.Create(OpCodes.Conv_I8); - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_ConstructorMethod); + yield return Instruction.Create(OpCodes.Newobj, ModuleWeaver.TimeSpan_ConstructorMethod); + yield return Instruction.Create(OpCodes.Stfld, durationTimespanFieldReference); var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; var logWithMessageMethodUsingTimeSpan = ModuleWeaver.LogWithMessageMethodUsingTimeSpan; @@ -348,12 +353,14 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) if (logMethodUsingTimeSpan is null) { + // Use .TotalMilliseconds converted to long yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); } else { + // Use timespan directly yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); } } @@ -383,10 +390,11 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); if (logWithMessageMethodUsingTimeSpan is null) { + // Use .TotalMilliseconds converted to long yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ldarg_0); @@ -395,6 +403,8 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) } else { + // Use timespan directly + yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); From 1c0852bf97d43828b906b5fa7560515243fa594a Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 22:16:07 +0100 Subject: [PATCH 15/22] Fix more tests --- MethodTimer.Fody/AsyncMethodProcessor.cs | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 1d5a338b..e0a77a9c 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -333,7 +333,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) methodBody.Variables.Add(elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldstr, Method.MethodName()); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Stloc, elapsedMillisecondsVariable); @@ -349,7 +349,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); if (logMethodUsingTimeSpan is null) { @@ -404,7 +404,6 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) else { // Use timespan directly - yield return Instruction.Create(OpCodes.Ldflda, durationTimestampFieldReference); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); From adbe614f3b5118bea3f73c712caeddb35c881dcf Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 22:16:57 +0100 Subject: [PATCH 16/22] Remove unused file --- MethodTimer.Fody/AsyncMethodProcessor.variables.cs | 4 ---- 1 file changed, 4 deletions(-) delete mode 100644 MethodTimer.Fody/AsyncMethodProcessor.variables.cs diff --git a/MethodTimer.Fody/AsyncMethodProcessor.variables.cs b/MethodTimer.Fody/AsyncMethodProcessor.variables.cs deleted file mode 100644 index 86f4b9a7..00000000 --- a/MethodTimer.Fody/AsyncMethodProcessor.variables.cs +++ /dev/null @@ -1,4 +0,0 @@ -public partial class AsyncMethodProcessor -{ - // No variables (yet) -} \ No newline at end of file From c56146b686660a1a287377f8f4c657d67169bafe Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 23:14:52 +0100 Subject: [PATCH 17/22] Tweak to fix more unit tests --- MethodTimer.Fody/AsyncMethodProcessor.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index e0a77a9c..7412face 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -390,7 +390,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); if (logWithMessageMethodUsingTimeSpan is null) { From cd6271d04bc356ba3d701d18a81ebdfc1fe64dc6 Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 23:30:51 +0100 Subject: [PATCH 18/22] Fix final unit tests --- MethodTimer.Fody/AsyncMethodProcessor.cs | 6 ++++-- MethodTimer.Fody/MethodProcessor.cs | 10 +++++----- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 7412face..3b6b6924 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -349,11 +349,11 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); if (logMethodUsingTimeSpan is null) { // Use .TotalMilliseconds converted to long + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); @@ -361,6 +361,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) else { // Use timespan directly + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); } } @@ -390,11 +391,11 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldtoken, Method.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); if (logWithMessageMethodUsingTimeSpan is null) { // Use .TotalMilliseconds converted to long + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ldarg_0); @@ -404,6 +405,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) else { // Use timespan directly + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); diff --git a/MethodTimer.Fody/MethodProcessor.cs b/MethodTimer.Fody/MethodProcessor.cs index f167aff9..ab63cd6a 100644 --- a/MethodTimer.Fody/MethodProcessor.cs +++ b/MethodTimer.Fody/MethodProcessor.cs @@ -201,15 +201,15 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); - if (logMethodUsingTimeSpan != null) + if (logMethodUsingTimeSpan is not null) { - //yield return Instruction.Create(OpCodes.Call, Elapsed); + yield return Instruction.Create(OpCodes.Ldloc, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); yield break; } + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); @@ -228,10 +228,10 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); - yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); if (logWithMessageMethodUsingTimeSpan is null) { + yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); @@ -239,7 +239,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield break; } - //yield return Instruction.Create(OpCodes.Call, Elapsed); + yield return Instruction.Create(OpCodes.Ldloc, durationTimespanVar); yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); } From fb5360ebf46ca4ebc3a401b799aeca48e8c48b24 Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sat, 22 Feb 2025 23:38:28 +0100 Subject: [PATCH 19/22] Cleanup unused code --- MethodTimer.Fody/ReferenceFinder.cs | 20 -------------------- 1 file changed, 20 deletions(-) diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index fee8f986..79061e2f 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -5,14 +5,9 @@ public partial class ModuleWeaver { public MethodReference TraceWriteLineMethod; - //public MethodReference StartNewMethod; - //public MethodReference StopMethod; public TypeReference StopwatchType; public MethodReference StringFormatWithArray; public MethodReference ConcatMethod; - //public MethodReference IsRunning; - //public MethodReference Elapsed; - //public MethodReference ElapsedMilliseconds; public MethodReference GetMethodFromHandle; public MethodReference ObjectConstructorMethod; public MethodReference MaxMethod; @@ -92,21 +87,6 @@ public void FindReferences() throw new WeavingException($"Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); } - //var startNewMethod = stopwatchType.Method("StartNew"); - //StartNewMethod = ModuleDefinition.ImportReference(startNewMethod); - - //var stopMethod = stopwatchType.Method("Stop"); - //StopMethod = ModuleDefinition.ImportReference(stopMethod); - - //var getElapsedMillisecondsMethod = stopwatchType.Method("get_ElapsedMilliseconds"); - //ElapsedMilliseconds = ModuleDefinition.ImportReference(getElapsedMillisecondsMethod); - - //var getElapsedMethod = stopwatchType.Method("get_Elapsed"); - //Elapsed = ModuleDefinition.ImportReference(getElapsedMethod); - - //var getIsRunning = stopwatchType.Method("get_IsRunning"); - //IsRunning = ModuleDefinition.ImportReference(getIsRunning); - var stopwatch_GetTimestampMethod = stopwatchType.Method("GetTimestamp"); Stopwatch_GetTimestampMethod = ModuleDefinition.ImportReference(stopwatch_GetTimestampMethod); From 8057e963e6bdc2e6b25c7f7b09b14fa1fda7e1f2 Mon Sep 17 00:00:00 2001 From: Lucas Trzesniewski Date: Sun, 23 Feb 2025 15:58:30 +0100 Subject: [PATCH 20/22] Cleanup --- ExampleAssembly/ExampleAssembly.csproj | 2 +- MethodTimer.Fody/AsyncMethodProcessor.cs | 15 +++------ MethodTimer.Fody/AttributeChecker.cs | 2 +- MethodTimer.Fody/MethodProcessor.cs | 26 ++++++++++----- MethodTimer.Fody/MethodProcessor.variables.cs | 6 ++-- MethodTimer.Fody/ReferenceFinder.cs | 33 ++----------------- MethodTimer.Fody/StopwatchCreator.cs | 7 ++-- Tests/StopWatchTemplateUsage.cs | 3 +- global.json | 2 +- 9 files changed, 32 insertions(+), 64 deletions(-) diff --git a/ExampleAssembly/ExampleAssembly.csproj b/ExampleAssembly/ExampleAssembly.csproj index e7eaffd7..1d9ba1db 100644 --- a/ExampleAssembly/ExampleAssembly.csproj +++ b/ExampleAssembly/ExampleAssembly.csproj @@ -1,7 +1,7 @@  - net6 + net6.0 Exe diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 3b6b6924..0ace7a47 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -14,7 +14,7 @@ public partial class AsyncMethodProcessor FieldReference stateFieldReference; TypeDefinition stateMachineTypeDefinition; TypeReference stateMachineTypeReference; - MethodDefinition stopStopwatchMethod; + MethodDefinition? stopStopwatchMethod; ParameterFormattingProcessor parameterFormattingProcessor = new(); FieldDefinition startTimestampField; @@ -136,9 +136,6 @@ Instruction FixReturns() void InjectStopwatchStart(int index, Instruction nextInstruction) { - var boolVariable = new VariableDefinition(ModuleWeaver.TypeSystem.BooleanReference); - body.Variables.Add(boolVariable); - // Field definitions startTimestampField = InjectStartTimestamp(stateMachineTypeDefinition); startTimestampFieldReference = new(startTimestampField.Name, startTimestampField.FieldType, stateMachineTypeReference); @@ -165,8 +162,6 @@ void InjectStopwatchStart(int index, Instruction nextInstruction) Instruction.Create(OpCodes.Ldc_I4_0), Instruction.Create(OpCodes.Conv_I8), Instruction.Create(OpCodes.Ceq), - Instruction.Create(OpCodes.Stloc, boolVariable), - Instruction.Create(OpCodes.Ldloc, boolVariable), Instruction.Create(OpCodes.Brfalse_S, nextInstruction), Instruction.Create(OpCodes.Ldarg_0), Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod), @@ -267,9 +262,6 @@ orderby handler.HandlerEnd.Offset descending IEnumerable GetWriteTimeInstruction(MethodBody methodBody) { - var boolVariable = new VariableDefinition(ModuleWeaver.TypeSystem.BooleanReference); - methodBody.Variables.Add(boolVariable); - var stopwatchRunningCheck = Instruction.Create(OpCodes.Ldarg_0); var startOfRealMethod = Instruction.Create(OpCodes.Ldarg_0); @@ -287,8 +279,6 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return Instruction.Create(OpCodes.Ldc_I4_0); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ceq); - yield return Instruction.Create(OpCodes.Stloc, boolVariable); - yield return Instruction.Create(OpCodes.Ldloc, boolVariable); yield return Instruction.Create(OpCodes.Brfalse_S, startOfRealMethod); yield return Instruction.Create(OpCodes.Ret); @@ -329,6 +319,9 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) { if (logMethodUsingLong is null && logMethodUsingTimeSpan is null) { + // var elapsedMillisecondsVariable = (long)durationTimespanVar.TotalMilliseconds; + // Trace.WriteLine(string.Concat(methodName, elapsedMillisecondsVariable.ToString(), "ms")) + var elapsedMillisecondsVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); methodBody.Variables.Add(elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldstr, Method.MethodName()); diff --git a/MethodTimer.Fody/AttributeChecker.cs b/MethodTimer.Fody/AttributeChecker.cs index fbea59a1..c19dee10 100644 --- a/MethodTimer.Fody/AttributeChecker.cs +++ b/MethodTimer.Fody/AttributeChecker.cs @@ -3,7 +3,7 @@ public static class AttributeChecker { - public static CustomAttribute GetTimeAttribute(this ICustomAttributeProvider definition) + public static CustomAttribute? GetTimeAttribute(this ICustomAttributeProvider definition) { var customAttributes = definition.CustomAttributes; diff --git a/MethodTimer.Fody/MethodProcessor.cs b/MethodTimer.Fody/MethodProcessor.cs index ab63cd6a..390a72b7 100644 --- a/MethodTimer.Fody/MethodProcessor.cs +++ b/MethodTimer.Fody/MethodProcessor.cs @@ -42,9 +42,9 @@ void InnerProcess() var returnInstruction = FixReturns(); startTimestampVar = InjectStartTimestamp(body, indexOf); - endTimestampVar = InjectEndTimestamp(body, indexOf); - durationTimestampVar = InjectDurationTimestamp(body, indexOf); - durationTimespanVar = InjectDurationTimespan(body, indexOf); + endTimestampVar = InjectEndTimestamp(body); + durationTimestampVar = InjectDurationTimestamp(body); + durationTimespanVar = InjectDurationTimespan(body); var beforeReturn = Instruction.Create(OpCodes.Nop); body.InsertBefore(returnInstruction, beforeReturn); @@ -156,7 +156,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod); yield return Instruction.Create(OpCodes.Stloc, endTimestampVar); - // durationTimestamp = endTimestampVar - endTimestampVar; + // durationTimestamp = endTimestampVar - startTimestampVar; yield return Instruction.Create(OpCodes.Ldloc, endTimestampVar); yield return Instruction.Create(OpCodes.Ldloc, startTimestampVar); yield return Instruction.Create(OpCodes.Sub); @@ -182,6 +182,9 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start { if (logMethodUsingLong is null && logMethodUsingTimeSpan is null) { + // var elapsedMillisecondsVariable = (long)durationTimespanVar.TotalMilliseconds; + // Trace.WriteLine(string.Concat(methodName, elapsedMillisecondsVariable.ToString(), "ms")) + var elapsedMillisecondsVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); methodDefinition.Body.Variables.Add(elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldstr, methodDefinition.MethodName()); @@ -198,17 +201,20 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield break; } + // push the MethodBase yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); if (logMethodUsingTimeSpan is not null) { + // logMethod(MethodBase, TimeSpan) yield return Instruction.Create(OpCodes.Ldloc, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); yield break; } + // logMethod(MethodBase, long) yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); @@ -219,18 +225,20 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start var formattedVariableDefinition = new VariableDefinition(ModuleWeaver.TypeSystem.StringReference); methodDefinition.Body.Variables.Add(formattedVariableDefinition); + // formattedVariableDefinition = foreach (var instruction in ProcessTimeAttribute(methodDefinition, formattedVariableDefinition)) { yield return instruction; } - // Handle call to log method + // push the MethodBase yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition); yield return Instruction.Create(OpCodes.Ldtoken, methodDefinition.DeclaringType); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.GetMethodFromHandle); if (logWithMessageMethodUsingTimeSpan is null) { + // logMethod(MethodBase, long, string) yield return Instruction.Create(OpCodes.Ldloca, durationTimespanVar); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); @@ -239,6 +247,7 @@ public IEnumerable GetWriteTimeInstruction(VariableDefinition start yield break; } + // logMethod(MethodBase, TimeSpan, string) yield return Instruction.Create(OpCodes.Ldloc, durationTimespanVar); yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); @@ -256,7 +265,7 @@ IEnumerable ProcessTimeAttribute(MethodDefinition methodDefinition, var value = timeAttribute.ConstructorArguments.FirstOrDefault().Value as string; if (string.IsNullOrWhiteSpace(value)) { - // Load null a string + // Load a null string yield return Instruction.Create(OpCodes.Ldnull); } else @@ -277,12 +286,11 @@ IEnumerable ProcessTimeAttribute(MethodDefinition methodDefinition, if (string.Equals(parameterName, "this")) { - // IL_0028: ldarg.0 yield return Instruction.Create(OpCodes.Ldarg_0); } else { - var parameter = methodDefinition.Parameters.First(_ => _.Name.Equals(parameterName)); + var parameter = methodDefinition.Parameters.First(p => p.Name.Equals(parameterName)); yield return Instruction.Create(OpCodes.Ldarg, parameter); if (parameter.ParameterType.IsBoxingRequired(ModuleWeaver.TypeSystem.ObjectReference)) @@ -299,4 +307,4 @@ IEnumerable ProcessTimeAttribute(MethodDefinition methodDefinition, yield return Instruction.Create(OpCodes.Stloc, formattedVariableDefinition); } -} \ No newline at end of file +} diff --git a/MethodTimer.Fody/MethodProcessor.variables.cs b/MethodTimer.Fody/MethodProcessor.variables.cs index f92eaa41..8bc2f8dc 100644 --- a/MethodTimer.Fody/MethodProcessor.variables.cs +++ b/MethodTimer.Fody/MethodProcessor.variables.cs @@ -17,7 +17,7 @@ public VariableDefinition InjectStartTimestamp(MethodBody body, int index) return startTimestampVariable; } - public VariableDefinition InjectEndTimestamp(MethodBody body, int index) + public VariableDefinition InjectEndTimestamp(MethodBody body) { // inject as variable var endTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); @@ -26,7 +26,7 @@ public VariableDefinition InjectEndTimestamp(MethodBody body, int index) return endTimestampVariable; } - public VariableDefinition InjectDurationTimestamp(MethodBody body, int index) + public VariableDefinition InjectDurationTimestamp(MethodBody body) { // inject as variable var durationTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); @@ -35,7 +35,7 @@ public VariableDefinition InjectDurationTimestamp(MethodBody body, int index) return durationTimestampVariable; } - public VariableDefinition InjectDurationTimespan(MethodBody body, int index) + public VariableDefinition InjectDurationTimespan(MethodBody body) { // inject as variable var durationTimespan = new VariableDefinition(ModuleWeaver.TimeSpanType); diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index 79061e2f..307b670a 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -9,22 +9,13 @@ public partial class ModuleWeaver public MethodReference StringFormatWithArray; public MethodReference ConcatMethod; public MethodReference GetMethodFromHandle; - public MethodReference ObjectConstructorMethod; - public MethodReference MaxMethod; - public MethodReference GetTicksMethod; public MethodReference Stopwatch_GetTimestampMethod; public FieldReference Stopwatch_GetFrequencyField; - public MethodReference UtcNowMethod; public MethodReference TimeSpan_ConstructorMethod; public MethodReference TimeSpan_TotalMillisecondsMethod; - public FieldReference TimeSpan_TicksPerSecondField; public FieldDefinition MethodTimerHelper_TimestampToTicks; - public TypeReference DateTimeType; public TypeReference TimeSpanType; public TypeReference BooleanType; - public TypeReference VoidType; - public TypeReference Float64Type; - public TypeReference MethodTimerHelperType; public MethodReference Int64ToString; public void FindReferences() @@ -40,12 +31,6 @@ public void FindReferences() var writeLine = traceType.Method("WriteLine", "String"); TraceWriteLineMethod = ModuleDefinition.ImportReference(writeLine); - var objectConstructor = TypeSystem.ObjectDefinition.Method(".ctor"); - ObjectConstructorMethod = ModuleDefinition.ImportReference(objectConstructor); - - var voidType = FindTypeDefinition("System.Void"); - VoidType = ModuleDefinition.ImportReference(voidType); - var timeSpanDefinition = FindTypeDefinition("System.TimeSpan"); TimeSpanType = ModuleDefinition.ImportReference(timeSpanDefinition); var timeSpanConstructor = timeSpanDefinition.Method(".ctor","Int64"); @@ -54,17 +39,6 @@ public void FindReferences() var timeSpanTotalMilliseconds = timeSpanDefinition.Method("get_TotalMilliseconds"); TimeSpan_TotalMillisecondsMethod = ModuleDefinition.ImportReference(timeSpanTotalMilliseconds); - var timeSpanTicksPerSecond = timeSpanDefinition.Fields.First(x => x.Name == "TicksPerSecond"); - TimeSpan_TicksPerSecondField = ModuleDefinition.ImportReference(timeSpanTicksPerSecond); - - var mathType = FindTypeDefinition("System.Math"); - MaxMethod = ModuleDefinition.ImportReference(mathType.Method("Max", "Int64", "Int64")); - - var dateTimeType = FindTypeDefinition("System.DateTime"); - DateTimeType = ModuleDefinition.ImportReference(dateTimeType); - UtcNowMethod = ModuleDefinition.ImportReference(dateTimeType.Method("get_UtcNow")); - GetTicksMethod = ModuleDefinition.ImportReference(dateTimeType.Method("get_Ticks")); - var methodBaseType = FindTypeDefinition("System.Reflection.MethodBase"); var methodBase = methodBaseType.Method("GetMethodFromHandle", "RuntimeMethodHandle", "RuntimeTypeHandle"); GetMethodFromHandle = ModuleDefinition.ImportReference(methodBase); @@ -77,14 +51,11 @@ public void FindReferences() var concatMethod = TypeSystem.StringDefinition.Method("Concat", "String", "String", "String"); ConcatMethod = ModuleDefinition.ImportReference(concatMethod); - var float64Type = FindTypeDefinition("System.Double"); - Float64Type = ModuleDefinition.ImportReference(float64Type); - var stopwatchType = FindTypeDefinition("System.Diagnostics.Stopwatch"); StopwatchType = ModuleDefinition.ImportReference(stopwatchType); if (StopwatchType is null) { - throw new WeavingException($"Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); + throw new WeavingException("Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); } var stopwatch_GetTimestampMethod = stopwatchType.Method("GetTimestamp"); @@ -95,4 +66,4 @@ public void FindReferences() InjectMethodTimerHelper(); } -} \ No newline at end of file +} diff --git a/MethodTimer.Fody/StopwatchCreator.cs b/MethodTimer.Fody/StopwatchCreator.cs index e8771362..7cf29e86 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -43,17 +43,15 @@ public void InjectMethodTimerHelper() var timestampToTicksField = new FieldDefinition("TimestampToTicks", FieldAttributes.Assembly | FieldAttributes.Static | FieldAttributes.InitOnly, - Float64Type); + TypeSystem.DoubleReference); type.Fields.Add(timestampToTicksField); var staticConstructor = new MethodDefinition(".cctor", MethodAttributes.Private | MethodAttributes.HideBySig | MethodAttributes.SpecialName | MethodAttributes.RTSpecialName | MethodAttributes.Static, - VoidType); + TypeSystem.VoidReference); staticConstructor.Body.Add( // Note: it's a const (10000000) Instruction.Create(OpCodes.Ldc_R8, 10000000d), - //Instruction.Create(OpCodes.Ldsfld, TimeSpan_TicksPerSecondField), - //Instruction.Create(OpCodes.Conv_R8), Instruction.Create(OpCodes.Ldsfld, Stopwatch_GetFrequencyField), Instruction.Create(OpCodes.Conv_R8), Instruction.Create(OpCodes.Div), @@ -62,7 +60,6 @@ public void InjectMethodTimerHelper() type.Methods.Add(staticConstructor); - MethodTimerHelperType = type; MethodTimerHelper_TimestampToTicks = timestampToTicksField; } } \ No newline at end of file diff --git a/Tests/StopWatchTemplateUsage.cs b/Tests/StopWatchTemplateUsage.cs index ae088026..62bb90f1 100644 --- a/Tests/StopWatchTemplateUsage.cs +++ b/Tests/StopWatchTemplateUsage.cs @@ -1,5 +1,4 @@ -using System; -using System.Diagnostics; +using System.Diagnostics; using System.Threading; using System.Threading.Tasks; diff --git a/global.json b/global.json index b3853c22..aa697d6d 100644 --- a/global.json +++ b/global.json @@ -2,6 +2,6 @@ "sdk": { "version": "8.0.202", "allowPrerelease": true, - "rollForward": "latestFeature" + "rollForward": "latestMajor" } } \ No newline at end of file From c8eb36cb7947a56acd021477a8b71f430e32e03a Mon Sep 17 00:00:00 2001 From: Lucas Trzesniewski Date: Sun, 23 Feb 2025 16:03:34 +0100 Subject: [PATCH 21/22] I don't think creating field references is necessary --- MethodTimer.Fody/AsyncMethodProcessor.cs | 46 +++++++++--------------- 1 file changed, 16 insertions(+), 30 deletions(-) diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index 0ace7a47..986df452 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -11,20 +11,15 @@ public partial class AsyncMethodProcessor public MethodDefinition Method; MethodBody body; FieldDefinition stateFieldDefinition; - FieldReference stateFieldReference; TypeDefinition stateMachineTypeDefinition; TypeReference stateMachineTypeReference; MethodDefinition? stopStopwatchMethod; ParameterFormattingProcessor parameterFormattingProcessor = new(); FieldDefinition startTimestampField; - FieldReference startTimestampFieldReference; FieldDefinition endTimestampField; - FieldReference endTimestampFieldReference; FieldDefinition durationTimestampField; - FieldReference durationTimestampFieldReference; FieldDefinition durationTimespanField; - FieldReference durationTimespanFieldReference; public void Process() { @@ -99,9 +94,7 @@ void InnerProcess() where x.Name.EndsWith("__state") || x.Name.EndsWith("$State") select x).First(); - - stateFieldReference = new(stateFieldDefinition.Name, stateFieldDefinition.FieldType, stateMachineTypeReference); - + InjectStopwatchStart(index, body.Instructions[index]); InjectStopwatchStopMethod(); InjectStopwatchStopCalls(); @@ -138,16 +131,9 @@ void InjectStopwatchStart(int index, Instruction nextInstruction) { // Field definitions startTimestampField = InjectStartTimestamp(stateMachineTypeDefinition); - startTimestampFieldReference = new(startTimestampField.Name, startTimestampField.FieldType, stateMachineTypeReference); - endTimestampField = InjectEndTimestamp(stateMachineTypeDefinition); - endTimestampFieldReference = new(endTimestampField.Name, endTimestampField.FieldType, stateMachineTypeReference); - durationTimestampField = InjectDurationTimestamp(stateMachineTypeDefinition); - durationTimestampFieldReference = new(durationTimestampField.Name, durationTimestampField.FieldType, stateMachineTypeReference); - durationTimespanField = InjectDurationTimespan(stateMachineTypeDefinition); - durationTimespanFieldReference = new(durationTimespanField.Name, durationTimespanField.FieldType, stateMachineTypeReference); body.Insert(index, new[] { @@ -158,14 +144,14 @@ void InjectStopwatchStart(int index, Instruction nextInstruction) // } Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference), + Instruction.Create(OpCodes.Ldfld, startTimestampField), Instruction.Create(OpCodes.Ldc_I4_0), Instruction.Create(OpCodes.Conv_I8), Instruction.Create(OpCodes.Ceq), Instruction.Create(OpCodes.Brfalse_S, nextInstruction), Instruction.Create(OpCodes.Ldarg_0), Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod), - Instruction.Create(OpCodes.Stfld, startTimestampFieldReference) + Instruction.Create(OpCodes.Stfld, startTimestampField) }); } @@ -267,7 +253,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) // Check if state machine is completed (state == -2) yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, stateFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, stateFieldDefinition); yield return Instruction.Create(OpCodes.Ldc_I4, -2); yield return Instruction.Create(OpCodes.Beq_S, stopwatchRunningCheck); yield return Instruction.Create(OpCodes.Ret); @@ -275,7 +261,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) // Check if there is a start timestamp yield return stopwatchRunningCheck; // Ldarg_0 - yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, startTimestampField); yield return Instruction.Create(OpCodes.Ldc_I4_0); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ceq); @@ -285,29 +271,29 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) yield return startOfRealMethod; // Ldarg_0 yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod); - yield return Instruction.Create(OpCodes.Stfld, endTimestampFieldReference); + yield return Instruction.Create(OpCodes.Stfld, endTimestampField); // durationTimestamp = endTimestampVar - endTimestampVar; yield return Instruction.Create(OpCodes.Ldarg_0); // Yes, ldarg_0 twice yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, endTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, endTimestampField); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, startTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, startTimestampField); yield return Instruction.Create(OpCodes.Sub); - yield return Instruction.Create(OpCodes.Stfld, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Stfld, durationTimestampField); // durationTimespanVar = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * (double)durationTimestamp)); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldsfld, ModuleWeaver.MethodTimerHelper_TimestampToTicks); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldfld, durationTimestampFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, durationTimestampField); yield return Instruction.Create(OpCodes.Conv_R8); yield return Instruction.Create(OpCodes.Mul); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Newobj, ModuleWeaver.TimeSpan_ConstructorMethod); - yield return Instruction.Create(OpCodes.Stfld, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Stfld, durationTimespanField); var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; var logWithMessageMethodUsingTimeSpan = ModuleWeaver.LogWithMessageMethodUsingTimeSpan; @@ -326,7 +312,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) methodBody.Variables.Add(elapsedMillisecondsVariable); yield return Instruction.Create(OpCodes.Ldstr, Method.MethodName()); yield return Instruction.Create(OpCodes.Ldarg_0); - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanField); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Stloc, elapsedMillisecondsVariable); @@ -346,7 +332,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) if (logMethodUsingTimeSpan is null) { // Use .TotalMilliseconds converted to long - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanField); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); @@ -354,7 +340,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) else { // Use timespan directly - yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanField); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); } } @@ -388,7 +374,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) if (logWithMessageMethodUsingTimeSpan is null) { // Use .TotalMilliseconds converted to long - yield return Instruction.Create(OpCodes.Ldflda, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldflda, durationTimespanField); yield return Instruction.Create(OpCodes.Call, ModuleWeaver.TimeSpan_TotalMillisecondsMethod); yield return Instruction.Create(OpCodes.Conv_I8); yield return Instruction.Create(OpCodes.Ldarg_0); @@ -398,7 +384,7 @@ IEnumerable GetWriteTimeInstruction(MethodBody methodBody) else { // Use timespan directly - yield return Instruction.Create(OpCodes.Ldfld, durationTimespanFieldReference); + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanField); yield return Instruction.Create(OpCodes.Ldarg_0); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingTimeSpan); From 6cde18dc0b876d8bdddbaf38f1ddf8191973ebbd Mon Sep 17 00:00:00 2001 From: Geert van Horrik Date: Sun, 23 Feb 2025 19:57:43 +0100 Subject: [PATCH 22/22] Update readme --- readme.md | 34 ++++++++++++++++++++++------------ 1 file changed, 22 insertions(+), 12 deletions(-) diff --git a/readme.md b/readme.md index 6fe33a4e..e9eb9e79 100644 --- a/readme.md +++ b/readme.md @@ -4,6 +4,8 @@ Injects some very basic method timing code. +The implementation uses an allocation-free method to determine the duration of a method. + **See [Milestones](../../milestones?state=closed) for release notes.** @@ -62,7 +64,7 @@ public class MyClass { public void MyMethod() { - var stopwatch = Stopwatch.StartNew(); + var start = Stopwatch.GetTimestamp(); try { //Some code u are curious how long it takes @@ -70,8 +72,10 @@ public class MyClass } finally { - stopwatch.Stop(); - Trace.WriteLine("MyClass.MyMethod " + stopwatch.ElapsedMilliseconds + "ms"); + var end = Stopwatch.GetTimestamp(); + var elapsed = end - start; + var elapsedTimeSpan = new TimeSpan(...); + Trace.WriteLine("MyClass.MyMethod " + elapsedTimeSpan.TotalMilliseconds + "ms"); } } } @@ -106,7 +110,7 @@ public class MyClass { public void MyMethod() { - var stopwatch = Stopwatch.StartNew(); + var start = Stopwatch.GetTimestamp(); try { //Some code u are curious how long it takes @@ -114,8 +118,10 @@ public class MyClass } finally { - stopwatch.Stop(); - MethodTimeLogger.Log(methodof(MyClass.MyMethod), stopwatch.ElapsedMilliseconds); + var end = Stopwatch.GetTimestamp(); + var elapsed = end - start; + var elapsedTimeSpan = new TimeSpan(...); + MethodTimeLogger.Log(methodof(MyClass.MyMethod), (long)elapsedTimeSpan.TotalMilliseconds); } } } @@ -141,7 +147,7 @@ public class MyClass { public void MyMethod() { - var stopwatch = Stopwatch.StartNew(); + var start = Stopwatch.GetTimestamp(); try { //Some code u are curious how long it takes @@ -149,8 +155,10 @@ public class MyClass } finally { - stopwatch.Stop(); - MethodTimeLogger.Log(methodof(MyClass.MyMethod), stopwatch.Elapsed); + var end = Stopwatch.GetTimestamp(); + var elapsed = end - start; + var elapsedTimeSpan = new TimeSpan(...); + MethodTimeLogger.Log(methodof(MyClass.MyMethod), elapsedTimeSpan); } } } @@ -180,7 +188,7 @@ public class MyClass { public void MyMethod(string fileName) { - var stopwatch = Stopwatch.StartNew(); + var start = Stopwatch.GetTimestamp(); try { //Some code u are curious how long it takes @@ -188,9 +196,11 @@ public class MyClass } finally { - stopwatch.Stop(); + var end = Stopwatch.GetTimestamp(); + var elapsed = end - start; + var elapsedTimeSpan = new TimeSpan(...); var message = string.Format("File name: '{0}'", fileName); - MethodTimeLogger.Log(methodof(MyClass.MyMethod), stopwatch.ElapsedMilliseconds, message); + MethodTimeLogger.Log(methodof(MyClass.MyMethod), (long)elapsedTimeSpan.TotalMilliseconds, message); } } }