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/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 new file mode 100644 index 00000000..1d9ba1db --- /dev/null +++ b/ExampleAssembly/ExampleAssembly.csproj @@ -0,0 +1,10 @@ + + + + net6.0 + Exe + + + + + \ No newline at end of file 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/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/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/MethodsWithTimestamp.cs b/ExampleAssembly/MethodsWithTimestamp.cs new file mode 100644 index 00000000..518225ee --- /dev/null +++ b/ExampleAssembly/MethodsWithTimestamp.cs @@ -0,0 +1,58 @@ +using System; +using System.Diagnostics; +using System.Reflection; +using System.Threading.Tasks; + +public class TestClassWithTimestamp +{ + public void SyncMethod() + { + long startTimestamp; + long endTimestamp; + long elapsed; + TimeSpan elapsedTimeSpan; + + startTimestamp = Stopwatch.GetTimestamp(); + + 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() + { + long startTimestamp = default; + long endTimestamp; + long elapsed; + TimeSpan elapsedTimeSpan; + + if (startTimestamp == 0) + { + startTimestamp = Stopwatch.GetTimestamp(); + } + + try + { + await Task.Delay(5); + } + finally + { + if (startTimestamp != 0) + { + endTimestamp = Stopwatch.GetTimestamp(); + + elapsed = endTimestamp - startTimestamp; + elapsedTimeSpan = new TimeSpan((long)(MethodTimerHelper.TimestampToTicks * elapsed)); + } + } + } +} \ No newline at end of file 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/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(); + } + } +} diff --git a/MethodTimer.Fody/AsyncMethodProcessor.cs b/MethodTimer.Fody/AsyncMethodProcessor.cs index cb379d56..986df452 100644 --- a/MethodTimer.Fody/AsyncMethodProcessor.cs +++ b/MethodTimer.Fody/AsyncMethodProcessor.cs @@ -5,20 +5,22 @@ 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; TypeReference stateMachineTypeReference; - MethodDefinition stopStopwatchMethod; + MethodDefinition? stopStopwatchMethod; ParameterFormattingProcessor parameterFormattingProcessor = new(); + FieldDefinition startTimestampField; + FieldDefinition endTimestampField; + FieldDefinition durationTimestampField; + FieldDefinition durationTimespanField; + public void Process() { try @@ -89,12 +91,10 @@ void InnerProcess() } stateFieldDefinition = (from x in stateMachineTypeDefinition.Fields - where x.Name.EndsWith("__state") || - x.Name.EndsWith("$State") - select x).First(); - - stateFieldReference = new(stateFieldDefinition.Name, stateFieldDefinition.FieldType, stateMachineTypeReference); - + where x.Name.EndsWith("__state") || + x.Name.EndsWith("$State") + select x).First(); + InjectStopwatchStart(index, body.Instructions[index]); InjectStopwatchStopMethod(); InjectStopwatchStopCalls(); @@ -129,32 +129,29 @@ Instruction FixReturns() 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); - - stopwatchFieldReference = new(stopwatchFieldDefinition.Name, stopwatchFieldDefinition.FieldType, stateMachineTypeReference); + // Field definitions + startTimestampField = InjectStartTimestamp(stateMachineTypeDefinition); + endTimestampField = InjectEndTimestamp(stateMachineTypeDefinition); + durationTimestampField = InjectDurationTimestamp(stateMachineTypeDefinition); + durationTimespanField = InjectDurationTimespan(stateMachineTypeDefinition); 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, startTimestampField), + 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, startTimestampField) }); } @@ -165,7 +162,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 +215,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 +230,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]; @@ -254,23 +253,47 @@ 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); - // Check if stopwatch is actually running - yield return stopwatchRunningCheck; - yield return Instruction.Create(OpCodes.Ldfld, stopwatchFieldReference); - yield return Instruction.Create(OpCodes.Callvirt, ModuleWeaver.IsRunning); + // Check if there is a start timestamp + yield return stopwatchRunningCheck; // Ldarg_0 + + 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); 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.Call, ModuleWeaver.StopMethod); + + yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Stopwatch_GetTimestampMethod); + 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, endTimestampField); + yield return Instruction.Create(OpCodes.Ldarg_0); + yield return Instruction.Create(OpCodes.Ldfld, startTimestampField); + yield return Instruction.Create(OpCodes.Sub); + 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, 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, durationTimespanField); var logWithMessageMethodUsingLong = ModuleWeaver.LogWithMessageMethodUsingLong; var logWithMessageMethodUsingTimeSpan = ModuleWeaver.LogWithMessageMethodUsingTimeSpan; @@ -282,12 +305,16 @@ 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()); 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, durationTimespanField); + 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 +328,19 @@ 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); if (logMethodUsingTimeSpan is null) { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ElapsedMilliseconds); + // Use .TotalMilliseconds converted to long + 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); } else { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Elapsed); + // Use timespan directly + yield return Instruction.Create(OpCodes.Ldfld, durationTimespanField); yield return Instruction.Create(OpCodes.Call, logMethodUsingTimeSpan); } } @@ -340,18 +370,21 @@ 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); if (logWithMessageMethodUsingTimeSpan is null) { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.ElapsedMilliseconds); + // Use .TotalMilliseconds converted to long + 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); yield return Instruction.Create(OpCodes.Ldfld, formattedFieldReference); yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingLong); } else { - yield return Instruction.Create(OpCodes.Call, ModuleWeaver.Elapsed); + // Use timespan directly + 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); 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/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/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/MethodProcessor.cs b/MethodTimer.Fody/MethodProcessor.cs index f5cdd974..390a72b7 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); + durationTimestampVar = InjectDurationTimestamp(body); + durationTimespanVar = InjectDurationTimespan(body); var beforeReturn = Instruction.Create(OpCodes.Nop); body.InsertBefore(returnInstruction, beforeReturn); @@ -130,11 +139,172 @@ 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)); } -} \ No newline at end of file + + 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 - startTimestampVar; + 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 = (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()); + 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; + } + + // 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); + yield return Instruction.Create(OpCodes.Call, logMethodUsingLong); + yield break; + } + + var formattedVariableDefinition = new VariableDefinition(ModuleWeaver.TypeSystem.StringReference); + methodDefinition.Body.Variables.Add(formattedVariableDefinition); + + // formattedVariableDefinition = + foreach (var instruction in ProcessTimeAttribute(methodDefinition, formattedVariableDefinition)) + { + yield return instruction; + } + + // 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); + yield return Instruction.Create(OpCodes.Ldloc, formattedVariableDefinition); + yield return Instruction.Create(OpCodes.Call, logWithMessageMethodUsingLong); + 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); + } + + 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 a null 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")) + { + yield return Instruction.Create(OpCodes.Ldarg_0); + } + else + { + var parameter = methodDefinition.Parameters.First(p => p.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); + } +} diff --git a/MethodTimer.Fody/MethodProcessor.variables.cs b/MethodTimer.Fody/MethodProcessor.variables.cs new file mode 100644 index 00000000..8bc2f8dc --- /dev/null +++ b/MethodTimer.Fody/MethodProcessor.variables.cs @@ -0,0 +1,46 @@ +using System.Collections.Generic; +using Mono.Cecil.Cil; + +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) + { + // inject as variable + var endTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + body.Variables.Add(endTimestampVariable); + + return endTimestampVariable; + } + + public VariableDefinition InjectDurationTimestamp(MethodBody body) + { + // inject as variable + var durationTimestampVariable = new VariableDefinition(ModuleWeaver.TypeSystem.Int64Reference); + body.Variables.Add(durationTimestampVariable); + + return durationTimestampVariable; + } + + public VariableDefinition InjectDurationTimespan(MethodBody body) + { + // 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/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 diff --git a/MethodTimer.Fody/ReferenceFinder.cs b/MethodTimer.Fody/ReferenceFinder.cs index 2f7f544d..307b670a 100644 --- a/MethodTimer.Fody/ReferenceFinder.cs +++ b/MethodTimer.Fody/ReferenceFinder.cs @@ -1,23 +1,21 @@ +using System.Linq; using Fody; using Mono.Cecil; 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; - public MethodReference GetTicksMethod; - public MethodReference UtcNowMethod; - public TypeReference DateTimeType; + public MethodReference Stopwatch_GetTimestampMethod; + public FieldReference Stopwatch_GetFrequencyField; + public MethodReference TimeSpan_ConstructorMethod; + public MethodReference TimeSpan_TotalMillisecondsMethod; + public FieldDefinition MethodTimerHelper_TimestampToTicks; + public TypeReference TimeSpanType; + public TypeReference BooleanType; public MethodReference Int64ToString; public void FindReferences() @@ -33,16 +31,13 @@ public void FindReferences() var writeLine = traceType.Method("WriteLine", "String"); TraceWriteLineMethod = ModuleDefinition.ImportReference(writeLine); - var objectConstructor = TypeSystem.ObjectDefinition.Method(".ctor"); - ObjectConstructorMethod = ModuleDefinition.ImportReference(objectConstructor); + var timeSpanDefinition = FindTypeDefinition("System.TimeSpan"); + TimeSpanType = ModuleDefinition.ImportReference(timeSpanDefinition); + var timeSpanConstructor = timeSpanDefinition.Method(".ctor","Int64"); + TimeSpan_ConstructorMethod = ModuleDefinition.ImportReference(timeSpanConstructor); - 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 timeSpanTotalMilliseconds = timeSpanDefinition.Method("get_TotalMilliseconds"); + TimeSpan_TotalMillisecondsMethod = ModuleDefinition.ImportReference(timeSpanTotalMilliseconds); var methodBaseType = FindTypeDefinition("System.Reflection.MethodBase"); var methodBase = methodBaseType.Method("GetMethodFromHandle", "RuntimeMethodHandle", "RuntimeTypeHandle"); @@ -56,19 +51,19 @@ public void FindReferences() var concatMethod = TypeSystem.StringDefinition.Method("Concat", "String", "String", "String"); 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 + var stopwatchType = FindTypeDefinition("System.Diagnostics.Stopwatch"); + StopwatchType = ModuleDefinition.ImportReference(stopwatchType); + if (StopwatchType is null) { - // Note: injected stopwatch is not supported for TimeSpan elapsed, should we error or add? - InjectStopwatchType(); + throw new WeavingException("Could not find 'System.Diagnostics.Stopwatch', this seems to be an unsupported platform."); } + + 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 5e53baa0..7cf29e86 100644 --- a/MethodTimer.Fody/StopwatchCreator.cs +++ b/MethodTimer.Fody/StopwatchCreator.cs @@ -3,108 +3,63 @@ public partial class ModuleWeaver { - public void InjectStopwatchType() + public void InjectMethodTimerHelper() { - var type = new TypeDefinition( - "MethodTimer", - "Stopwatch", - TypeAttributes.BeforeFieldInit | TypeAttributes.AnsiClass | TypeAttributes.AutoClass, - TypeSystem.ObjectReference); - 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.Call, currentTicks), - Instruction.Create(OpCodes.Stfld, startTicks), - Instruction.Create(OpCodes.Ldarg_0), - Instruction.Create(OpCodes.Call, ObjectConstructorMethod), - 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 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 timestampToTicksField = new FieldDefinition("TimestampToTicks", + FieldAttributes.Assembly | FieldAttributes.Static | FieldAttributes.InitOnly, + TypeSystem.DoubleReference); + type.Fields.Add(timestampToTicksField); - var stop = new MethodDefinition( - "Stop", - MethodAttributes.HideBySig | MethodAttributes.Public, + var staticConstructor = new MethodDefinition(".cctor", + MethodAttributes.Private | MethodAttributes.HideBySig | MethodAttributes.SpecialName | MethodAttributes.RTSpecialName | MethodAttributes.Static, 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 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), + staticConstructor.Body.Add( + // Note: it's a const (10000000) + Instruction.Create(OpCodes.Ldc_R8, 10000000d), + Instruction.Create(OpCodes.Ldsfld, Stopwatch_GetFrequencyField), + Instruction.Create(OpCodes.Conv_R8), Instruction.Create(OpCodes.Div), + Instruction.Create(OpCodes.Stsfld, timestampToTicksField), Instruction.Create(OpCodes.Ret)); - ElapsedMilliseconds = elapsedMilliseconds; - StopMethod = stop; - StopwatchType = type; - StartNewMethod = startNew; + type.Methods.Add(staticConstructor); + + 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 dc32cfd2..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.Ldloc, 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.Ldloc, 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.Ldloc, 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.Ldloc, 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/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 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"); } diff --git a/Tests/StopWatchTemplateUsage.cs b/Tests/StopWatchTemplateUsage.cs new file mode 100644 index 00000000..62bb90f1 --- /dev/null +++ b/Tests/StopWatchTemplateUsage.cs @@ -0,0 +1,33 @@ +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; + +public class StopWatchTemplateUsage +{ + public static void Foo() + { + var stopwatch = Stopwatch.StartNew(); + try + { + Thread.Sleep(10); + } + finally + { + stopwatch.Stop(); + 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 diff --git a/Tests/Stopwatch.cs b/Tests/Stopwatch.cs index 283a11e5..ad2b9cc3 100644 --- a/Tests/Stopwatch.cs +++ b/Tests/Stopwatch.cs @@ -1,6 +1,6 @@ using System; -class Stopwatch +struct Stopwatch { long startTicks; long elapsedTicks; @@ -22,6 +22,8 @@ public void Stop() } } + public bool GetIsRunning() => !stopped; + static long CurrentTicks() => DateTime.UtcNow.Ticks; @@ -30,4 +32,10 @@ public long GetElapsedMilliseconds() Stop(); return elapsedTicks / 10000; } + + public TimeSpan GetElapsed() + { + Stop(); + return new(elapsedTicks); + } } \ No newline at end of file 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 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); } } }