adding StatsDetail.Function option for measuring function time

Author: kelnishi

Wacs.Core/Runtime/ExecContext.cs

@@ -399,6 +399,19 @@ public void ResetStats()
             { 
                 Stats[(ushort)(ByteCode)opcode] = new ExecStat();
             }
+
+            for (int i = 0, l = Store.FunctionCount(); i < l; i++)
+            {
+
+                if (Store[new FuncAddr(i)] is FunctionInstance inst)
+                {
+                    inst.CallCount = 0;
+                }
+                if (!Stats.TryGetValue((ushort)i, out var stat))
+                {
+                    Stats[(ushort)i] = new ExecStat();
+                }
+            }
         }
 
         public OpCode GetEndFor() => 

Wacs.Core/Runtime/Frame.cs

@@ -26,6 +26,7 @@ namespace Wacs.Core.Runtime
 {
     public sealed class Frame : IPoolable
     {
+        public ushort FuncAddr;
         public ModuleInstance Module = null!;
         public Memory<Value> Locals;
         public Label ReturnLabel = new();

Wacs.Core/Runtime/InvokerOptions.cs

@@ -35,6 +35,7 @@ public enum StatsDetail: int
         None = 0,
         Total = 1,
         Instruction = 2,
+        Function = 4,
     }
 
     public class InvokerOptions
@@ -59,7 +60,7 @@ public bool UseFastPath()
                 return false;
             if (ShowPath)
                 return false;
-            if (CollectStats == StatsDetail.Instruction)
+            if (CollectStats is StatsDetail.Instruction or StatsDetail.Function)
                 return false;
             return true;
         }

Wacs.Core/Runtime/Store.cs

@@ -14,6 +14,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using Wacs.Core.Runtime.Types;
 using Wacs.Core.Types;
 
@@ -122,6 +123,7 @@ public FuncAddr AllocateWasmFunction(Module.Function func, ModuleInstance module
         {
             var funcInst = new FunctionInstance(moduleInst, func);
             var funcAddr = AddFunction(funcInst);
+            funcInst.Address = funcAddr;
             return funcAddr;
         }
 
@@ -270,5 +272,7 @@ public void DropElement(ElemAddr addr)
                 Elems[addr.Value] = ElementInstance.Empty;
             }
         }
+
+        public int FunctionCount() => Funcs.Count;
     }
 }

Wacs.Core/Runtime/Types/FunctionInstance.cs

@@ -40,6 +40,9 @@ public class FunctionInstance : IFunctionInstance
 
         public readonly FuncIdx Index;
 
+        public FuncAddr Address;
+        public int CallCount;
+
         public readonly ModuleInstance Module;
 
         //Copied from the static Definition
@@ -120,6 +123,7 @@ public void Invoke(ExecContext context)
             //8.
             //Push the frame and operate on the frame on the stack.
             var frame = context.ReserveFrame(Module, funcType.ResultType.Arity);
+            frame.FuncAddr = (ushort)Address.Value;
             frame.Locals = context.OpStack.ReserveLocals(ParameterCount, TotalCount);
             context.OpStack.GuardExhaust(MaxStack);
 
@@ -143,6 +147,7 @@ public void Invoke(ExecContext context)
             frame.Head = LinkedOffset;
 
             context.InstructionPointer = LinkedOffset - 1;
+            CallCount++;
         }
 
         public void TailInvoke(ExecContext context)
@@ -178,6 +183,8 @@ public void TailInvoke(ExecContext context)
             frame.Head = LinkedOffset;
 
             context.InstructionPointer = LinkedOffset - 1;
+            
+            CallCount++;
         }
 
         public override string ToString() => $"FunctionInstance[{Id}] (Type: {Type}, IsExport: {IsExport})";

Wacs.Core/Runtime/WasmRuntimeExecution.cs

@@ -523,6 +523,27 @@ public async Task ProcessThreadWithOptions(InvokerOptions options)
                     st.duration += Context.InstructionTimer.ElapsedTicks;
                     Context.Stats[(ushort)inst.Op] = st;
                 }
+                else if (options.CollectStats == StatsDetail.Function)
+                {
+                    Context.InstructionTimer.Restart();
+                    if (inst.PointerAdvance > 0)
+                        Context.InstructionPointer += inst.PointerAdvance;
+                    if (inst.Nop)
+                        continue;
+                    
+                    if (inst.IsAsync)
+                        await inst.ExecuteAsync(Context);
+                    else
+                        inst.Execute(Context);
+
+                    Context.InstructionTimer.Stop();
+                    Context.steps += inst.Size;
+
+                    var st = Context.Stats[Context.Frame.FuncAddr];
+                    st.count += inst.Size;
+                    st.duration += Context.InstructionTimer.ElapsedTicks;
+                    Context.Stats[Context.Frame.FuncAddr] = st;
+                }
                 else
                 {
                     Context.InstructionTimer.Start();
@@ -652,10 +673,10 @@ private void LogPostInstruction(InvokerOptions options, InstructionBase inst)
         private void PrintStats(InvokerOptions options)
         {
             long procTicks = Context.ProcessTimer.ElapsedTicks;
-            long totalExecs = options.CollectStats == StatsDetail.Instruction
+            long totalExecs = options.CollectStats is StatsDetail.Instruction or StatsDetail.Function
                 ? Context.Stats.Values.Sum(dc => dc.count)
                 : Context.steps;
-            long execTicks = options.CollectStats == StatsDetail.Instruction
+            long execTicks = options.CollectStats is StatsDetail.Instruction or StatsDetail.Function
                 ? Context.Stats.Values.Sum(dc => dc.duration)
                 : Context.InstructionTimer.ElapsedTicks;
             long overheadTicks = procTicks - execTicks;
@@ -690,12 +711,32 @@ private void PrintStats(InvokerOptions options)
 
             foreach (var (opcode, st) in orderedStats)
             {
-                string label = $"{((ByteCode)opcode).GetMnemonic()}".PadLeft(totalLabel.Length, ' ');
                 TimeSpan instTime = new TimeSpan(st.duration/100); //100ns
                 double percent = 100.0 * st.duration / execTicks;
-                string execsLabel = $"{st.count}".PadLeft(totalInst.Length, ' ');
+                int count = (int)st.count;
+                
                 string percentLabel = $"{percent:#0.###}%e".PadLeft(8,' ');
-                string instAve = $"{instTime.TotalMilliseconds * 1000000.0/st.count:#0.#}ns/i";
+                string label;
+                string instAve;
+                if (options.CollectStats == StatsDetail.Function)
+                {
+                    if (Context.Store[new FuncAddr(opcode)] is FunctionInstance func)
+                    {
+                        count = func.CallCount;
+                        label = $"{func.ModuleName}[{func.Index.Value}]".PadLeft(totalLabel.Length, ' ');
+                        instAve = $"{instTime.TotalMilliseconds * 1000000.0/count:#0.#}ns/call";
+                    }
+                    else
+                    {
+                        continue;
+                    }
+                }
+                else
+                {
+                    label = $"{((ByteCode)opcode).GetMnemonic()}".PadLeft(totalLabel.Length, ' ');
+                    instAve = $"{instTime.TotalMilliseconds * 1000000.0/count:#0.#}ns/i";
+                }
+                string execsLabel = $"{count}".PadLeft(totalInst.Length, ' ');
                 Console.Error.WriteLine($"{label}: {execsLabel}| ({percentLabel}) {instTime.TotalMilliseconds:#0.000}ms {instAve}");
             }
         }