Merge pull request #261 from stevehalliwell/tracing

Merge tracing into main
stevehalliwell · Jun 22, 2024 · 62ad87d · 62ad87d
2 parents a33b440 + 52811bf
commit 62ad87d
Show file tree

Hide file tree

Showing 15 changed files with 308 additions and 109 deletions.
diff --git a/ulox/ulox.core.tests/ByteCodeEngineTests.cs b/ulox/ulox.core.tests/ByteCodeEngineTests.cs
@@ -829,12 +829,12 @@ public void RuntimeException_WhenAddNullGlobal_ShouldThrow()
 var b = 1;
 var c = b + a;");
 
-            Assert.AreEqual(@"Cannot perform op across types 'Double' and 'Null' at ip:'7' in chunk:'unnamed_chunk(test:4)'.
+            Assert.AreEqual(@"Cannot perform op across types 'Double' and 'Null' at ip:'7' in chunk:'root(test:4)'.
 ===Stack===
-<closure unnamed_chunk upvals:0>
+<closure root upvals:0>
 
 ===CallStack===
-chunk:'unnamed_chunk(test)'
+chunk:'root(test)'
 
 ", testEngine.InterpreterResult);
         }

diff --git a/ulox/ulox.core.tests/ByteCodeInterpreterTestEngine.cs b/ulox/ulox.core.tests/ByteCodeInterpreterTestEngine.cs
@@ -14,7 +14,7 @@ public ByteCodeInterpreterTestEngine(Action<string> logger)
         {
             _logger = logger;
             MyEngine = Engine.CreateDefault();
-            MyEngine.Context.Vm.Statistics = new VmStatisticsReporter();
+            MyEngine.Context.Vm.Tracing = new VmTracingReporter();
             MyEngine.Context.OnLog += logger;
             MyEngine.Context.OnLog += AppendResult;
         }
@@ -55,7 +55,7 @@ public void Run(Script script)
                 _logger(JoinedCompilerMessages);
                 _logger(VmUtil.GenerateGlobalsDump(MyEngine.Context.Vm));
                 _logger(VmUtil.GenerateValueStackDump(MyEngine.Context.Vm));
-                _logger(MyEngine.Context.Vm.Statistics?.GetReport().GenerateStringReport() ?? string.Empty);
+                _logger(VmStatisticsReport.Create(MyEngine.Context.Vm.Tracing.PerChunkStats).GenerateStringReport());
                 _logger(MyEngine.Context.Program.Optimiser.OptimisationReporter?.GetReport().GenerateStringReport() ?? string.Empty);
             }
         }

diff --git a/ulox/ulox.core.tests/ClassTests.cs b/ulox/ulox.core.tests/ClassTests.cs
@@ -230,7 +230,7 @@ public void Engine_This_OutsideClass()
             testEngine.Run(@"
 var a = this.a;");
 
-            Assert.AreEqual("Cannot use the 'this' keyword outside of a class in chunk 'unnamed_chunk(test)' at 2:13 'this'.", testEngine.InterpreterResult);
+            Assert.AreEqual("Cannot use the 'this' keyword outside of a class in chunk 'root(test)' at 2:13 'this'.", testEngine.InterpreterResult);
         }
 
         [Test]
@@ -499,7 +499,7 @@ class T
 
 var t = T();");
 
-            Assert.AreEqual("Stage out of order. Type 'T' is at stage 'Method' has encountered a late 'Init' stage element in chunk 'T_typedeclare(test)' at 5:9 'init'.", testEngine.InterpreterResult);
+            Assert.AreEqual("Stage out of order. Type 'T' is at stage 'Method' has encountered a late 'Init' stage element in chunk 'T(test)' at 5:9 'init'.", testEngine.InterpreterResult);
         }
 
         [Test]
@@ -547,7 +547,7 @@ class T
 print(t.a);
 print(t.b);");
 
-            Assert.AreEqual("Stage out of order. Type 'T' is at stage 'Init' has encountered a late 'Var' stage element in chunk 'T_typedeclare(test)' at 5:8 'var'.", testEngine.InterpreterResult);
+            Assert.AreEqual("Stage out of order. Type 'T' is at stage 'Init' has encountered a late 'Var' stage element in chunk 'T(test)' at 5:8 'var'.", testEngine.InterpreterResult);
         }
 
         [Test]

diff --git a/ulox/ulox.core.tests/ListUsageTests.cs b/ulox/ulox.core.tests/ListUsageTests.cs
@@ -70,7 +70,7 @@ public void Count_WhenNull_ShouldFail()
 print(countof arr);
 ");
 
-            StringAssert.StartsWith("Cannot perform countof on 'null' at ip:'5' in chunk:'unnamed_chunk(test:3)'.", testEngine.InterpreterResult);
+            StringAssert.StartsWith("Cannot perform countof on 'null' at ip:'5' in chunk:'root(test:3)'.", testEngine.InterpreterResult);
         }
 
         [Test]

diff --git a/ulox/ulox.core.tests/LoopingTests.cs b/ulox/ulox.core.tests/LoopingTests.cs
@@ -50,7 +50,7 @@ public void Loop_WhenNoEscape_ShouldNotCompile()
     i = i + 1;
 }");
 
-            Assert.AreEqual("Loops must contain a termination in chunk 'unnamed_chunk(test)' at 7:2.", testEngine.InterpreterResult);
+            Assert.AreEqual("Loops must contain a termination in chunk 'root(test)' at 7:2.", testEngine.InterpreterResult);
         }
 
         [Test]
@@ -64,7 +64,7 @@ public void For_WhenNoEscape_ShouldNotCompile()
     i = i + 1;
 }");
 
-            Assert.AreEqual("Loops must contain a termination in chunk 'unnamed_chunk(test)' at 7:2.", testEngine.InterpreterResult);
+            Assert.AreEqual("Loops must contain a termination in chunk 'root(test)' at 7:2.", testEngine.InterpreterResult);
         }
 
         [Test]

diff --git a/ulox/ulox.core.tests/MapUsageTests.cs b/ulox/ulox.core.tests/MapUsageTests.cs
@@ -95,7 +95,7 @@ public void Invalid_WhenMixingListThenMap_ShouldFail()
 print(map[""a""]);
 ");
 
-            Assert.AreEqual("Expected to compile Expression, but encountered error in chunk 'unnamed_chunk(test)' at 2:20.", testEngine.InterpreterResult);
+            Assert.AreEqual("Expected to compile Expression, but encountered error in chunk 'root(test)' at 2:20.", testEngine.InterpreterResult);
         }
 
         [Test]

diff --git a/ulox/ulox.core.tests/TestSetTests.cs b/ulox/ulox.core.tests/TestSetTests.cs
@@ -306,7 +306,7 @@ test Add(lhs, rhs, expected)
 }"
             );
 
-            Assert.AreEqual("Test 'Add' has arguments but no data expression in chunk 'unnamed_chunk(test)' at 4:33.", testEngine.InterpreterResult);
+            Assert.AreEqual("Test 'Add' has arguments but no data expression in chunk 'root(test)' at 4:33.", testEngine.InterpreterResult);
         }
 
         [Test]
@@ -396,7 +396,7 @@ testset T
 }"
             );
 
-            Assert.AreEqual("Test 'IsOne' has data expression but no arguments in chunk 'unnamed_chunk(test)' at 7:26.", testEngine.InterpreterResult);
+            Assert.AreEqual("Test 'IsOne' has data expression but no arguments in chunk 'root(test)' at 7:26.", testEngine.InterpreterResult);
         }
 
         [Test]

diff --git a/ulox/ulox.core.tests/TracingTests.cs b/ulox/ulox.core.tests/TracingTests.cs
@@ -0,0 +1,87 @@
+using NUnit.Framework;
+
+namespace ULox.Core.Tests
+{
+    public class TracingTests : EngineTestBase
+    {
+        [Test]
+        public void VmStatisticsReport_WhenSimpleMathOps_ShouldMatchExpected()
+        {
+            testEngine.Run(@"
+var a = 1;
+var b = 2;
+var c = a + b;
+
+print(c);
+
+var d = Math.Sqrt(c);
+");
+            var statsReport = VmStatisticsReport.Create(testEngine.MyEngine.Context.Vm.Tracing.PerChunkStats).GenerateStringReport();
+
+            Assert.AreEqual("3", testEngine.InterpreterResult);
+            StringAssert.Contains("ADD   1", statsReport);
+            StringAssert.Contains("FETCH_GLOBAL   6", statsReport);
+        }
+
+        [Test]
+        public void Tracing_WhenEnabledAndSimpleMathOps_ShouldMatchExpected()
+        {
+            testEngine.MyEngine.Context.Vm.Tracing.EnableTracing = true;
+            testEngine.Run(@"
+var a = 1;
+var b = 2;
+var c = a + b;
+
+print(c);
+
+var d = Math.Sqrt(c);
+");
+            var statsReport = VmTracingReport.Create(testEngine.MyEngine.Context.Vm.Tracing.TimeLineEvents).GenerateJsonTracingEventArray();
+
+            Assert.AreEqual("3", testEngine.InterpreterResult);
+            StringAssert.Contains("\"name\":\"print\",\"ph\":\"B\"", statsReport);
+            StringAssert.Contains("\"name\":\"Sqrt\",\"ph\":\"E\"", statsReport);
+        }
+
+        [Test]
+        public void Tracing_WhenDisabledAndSimpleMathOps_ShouldMatchExpected()
+        {
+            testEngine.Run(@"
+var a = 1;
+var b = 2;
+var c = a + b;
+
+print(c);
+
+var d = Math.Sqrt(c);
+");
+            var statsReport = VmTracingReport.Create(testEngine.MyEngine.Context.Vm.Tracing.TimeLineEvents).GenerateJsonTracingEventArray();
+
+            Assert.AreEqual("3", testEngine.InterpreterResult);
+            StringAssert.DoesNotContain("\"name\":\"print\",\"ph\":\"B\"", statsReport);
+            StringAssert.DoesNotContain("\"name\":\"Sqrt\",\"ph\":\"E\"", statsReport);
+        }
+
+        [Test]
+        public void Tracing_WhenEnabledAndInstancesAndSimpleMathOps_ShouldMatchExpected()
+        {
+            testEngine.MyEngine.Context.Vm.Tracing.EnableTracing = true;
+            testEngine.MyEngine.Context.Vm.Tracing.EnableOpCodeInstantTraces = true;
+            testEngine.Run(@"
+var a = 1;
+var b = 2;
+var c = a + b;
+
+print(c);
+
+var d = Math.Sqrt(c);
+");
+            var statsReport = VmTracingReport.Create(testEngine.MyEngine.Context.Vm.Tracing.TimeLineEvents).GenerateJsonTracingEventArray();
+
+            Assert.AreEqual("3", testEngine.InterpreterResult);
+            StringAssert.Contains("\"name\":\"print\",\"ph\":\"B\"", statsReport);
+            StringAssert.Contains("\"name\":\"Sqrt\",\"ph\":\"E\"", statsReport);
+            StringAssert.Contains("\"name\":\"FETCH_GLOBAL\",\"ph\":\"I\",\"", statsReport);
+        }
+    }
+}
diff --git a/ulox/ulox.core/Package/Runtime/Compiler/Compiler.cs b/ulox/ulox.core/Package/Runtime/Compiler/Compiler.cs
@@ -254,7 +254,7 @@ public CompiledScript Compile(Scanner scanner, Script script)
             TokenIterator = new TokenIterator(script, tokens, this);
             TokenIterator.Advance();
 
-            PushCompilerState(string.Empty, FunctionType.Script);
+            PushCompilerState("root", FunctionType.Script);
 
             while (TokenIterator.CurrentToken.TokenType != TokenType.EOF)
             {
@@ -471,9 +471,9 @@ public void AutoDefineRetval()
             IncreaseReturn(retvalId);
         }
 
-        public Chunk Function(string name, FunctionType functionType)
+        public Chunk Function(string functionName, FunctionType functionType)
         {
-            PushCompilerState(name, functionType);
+            PushCompilerState(functionName, functionType);
 
             var returnCount = FuncArgsAndReturns();
 

diff --git a/ulox/ulox.core/Package/Runtime/Compiler/Compilettes/ClassTypeCompilette.cs b/ulox/ulox.core/Package/Runtime/Compiler/Compilettes/ClassTypeCompilette.cs
@@ -74,9 +74,9 @@ private void CompileMethod(Compiler compiler, FunctionType functionType)
                 compiler.TokenIterator.Consume(TokenType.IDENTIFIER, "Expect method name");
 
             var _ = compiler.AddStringConstant();
-            var name = compiler.TokenIterator.PreviousToken.Lexeme;
+            var methodName = compiler.TokenIterator.PreviousToken.Lexeme;
 
-            compiler.PushCompilerState(name, functionType);
+            compiler.PushCompilerState(methodName, functionType);
 
             if (functionType == FunctionType.Method
                || functionType == FunctionType.Init)

diff --git a/ulox/ulox.core/Package/Runtime/Compiler/Compilettes/TypeCompilette.cs b/ulox/ulox.core/Package/Runtime/Compiler/Compilettes/TypeCompilette.cs
@@ -60,7 +60,7 @@ private void DoDeclareType(Compiler compiler)
             _currentTypeInfo = new TypeInfoEntry((string)compiler.TokenIterator.PreviousToken.Literal, UserType); 
             compiler.TypeInfo.AddType(_currentTypeInfo);
 
-            compiler.PushCompilerState($"{CurrentTypeName}_typedeclare", FunctionType.TypeDeclare);
+            compiler.PushCompilerState($"{CurrentTypeName}", FunctionType.TypeDeclare);
             byte nameConstant = compiler.AddStringConstant();
 
             InitChainLabelId = compiler.UniqueChunkLabelStringConstant($"{Chunk.InternalLabelPrefix}InitChain");

diff --git a/ulox/ulox.core/Package/Runtime/Engine/VM.cs b/ulox/ulox.core/Package/Runtime/Engine/VM.cs
@@ -18,7 +18,7 @@ public sealed class Vm
         private readonly LinkedList<Value> openUpvalues = new LinkedList<Value>();
         public Table Globals { get; private set; } = new Table();
         public TestRunner TestRunner { get; private set; } = new TestRunner(() => new Vm());
-        public VmStatisticsReporter Statistics { get; set; }
+        public VmTracingReporter Tracing { get; set; }
 
         public Vm()
         {
@@ -105,7 +105,7 @@ private ByteCodePacket ReadPacket(Chunk chunk)
             => chunk.Instructions[_currentCallFrame.InstructionPointer++];
 
         [MethodImpl(MethodImplOptions.AggressiveInlining)]
-        private void PushNewCallframe(CallFrame callFrame)
+        private void PushNewCallFrame(CallFrame callFrame)
         {
             if (_callFrames.Count > 0)
             {
@@ -115,6 +115,9 @@ private void PushNewCallframe(CallFrame callFrame)
 
             _currentCallFrame = callFrame;
             _currentChunk = _currentCallFrame.Closure.chunk;
+#if VM_STATS
+            Tracing?.ProcessPushCallFrame(callFrame);
+#endif
             _callFrames.Push(callFrame);
             for (int i = 0; i < callFrame.ReturnCount; i++)
             {
@@ -155,7 +158,7 @@ public InterpreterResult Run()
                 var opCode = packet.OpCode;
 
 #if VM_STATS
-                Statistics?.ProcessingOpCode(chunk, opCode);
+                Tracing?.ProcessingOpCode(chunk, opCode);
 #endif
 
                 switch (opCode)
@@ -871,7 +874,10 @@ private void ProcessReturns()
             {
                 var poppedStackStart = _currentCallFrame.StackStart;
                 //remove top
-                _callFrames.Pop();
+                var popped = _callFrames.Pop();
+#if VM_STATS
+                Tracing?.ProcessPopCallFrame(popped);
+#endif
 
                 //update cache
                 if (_callFrames.Count > 0)
@@ -990,7 +996,7 @@ private void Call(ClosureInternal closureInternal, byte argCount)
 
 
             var stackStart = (byte)System.Math.Max(0, _valueStack.Count - argCount - 1);
-            PushNewCallframe(new CallFrame()
+            PushNewCallFrame(new CallFrame()
             {
                 StackStart = stackStart,
                 Closure = closureInternal,
@@ -1002,7 +1008,7 @@ private void Call(ClosureInternal closureInternal, byte argCount)
         [MethodImpl(MethodImplOptions.AggressiveInlining)]
         private void PushFrameCallNative(CallFrame.NativeCallDelegate nativeCallDel, byte argCount, byte returnCount)
         {
-            PushNewCallframe(new CallFrame()
+            PushNewCallFrame(new CallFrame()
             {
                 StackStart = (byte)(_valueStack.Count - argCount - 1),
                 Closure = NativeCallClosure,
@@ -1221,7 +1227,7 @@ private void CreateInstance(UserTypeInternal asClass, byte argCount)
                 if (!asClass.Initialiser.IsNull())
                     Push(inst);
 
-                PushNewCallframe(new CallFrame()
+                PushNewCallFrame(new CallFrame()
                 {
                     Closure = new ClosureInternal { chunk = chunk },
                     InstructionPointer = chunk.GetLabelPosition(labelID),