Optimized Tracing and Restoring Replay Support

core-lib/Benchmarks/AsyncHarness.ns

@@ -120,6 +120,9 @@ class AsyncHarness usingPlatform: platform = Value (
     )
 
     printRun: runTime = (
+      | stats = system traceStatistics. |
+      (name + ': trace size:    ' + (stats at: 1) + 'byte') println.
+      (name + ': external data: ' + (stats at: 2) + 'byte') println.
       (name + ': iterations=1' + ' runtime: ' + runTime + 'us') println
     )
 

core-lib/System.ns

@@ -42,6 +42,9 @@ class System usingVmMirror: vmMirror = Value (
   public time  = ( ^ vmMirror systemTime: nil  )
   public ticks = ( ^ vmMirror systemTicks: nil ) (* returns the microseconds since start *)
 
+  (* Actor Tracing Statistics *)
+  public traceStatistics = ( ^ vmMirror traceStatistics: nil )
+
   (* Force Garbage Collection *)
   public fullGC = ( ^ vmMirror systemGC: nil )
 

som

@@ -86,6 +86,14 @@ tools.add_argument('-TF', '--disable-trace-file', help='trace file wont be writt
                     dest='disable_trace_file', action='store_true', default=False)
 tools.add_argument('-r', '--replay', help='execution of the program is guided by an existing trace file',
                     dest='replay', action='store_true', default=False)
+tools.add_argument('-BR', '--no-buffer-recycling', help='create singe-use buffers only',
+                    dest='buffer_recycling', action='store_true', default=False)
+tools.add_argument('-bpt', '--buffers-per-thread', help='used to calculate the number of buffers to use for tracing',
+                    dest='buffers_per_thread', default=4)
+tools.add_argument('-bs', '--buffer-size', help='set the size of buffer used for tracing',
+                    dest='buffer_size', default=1048576)
+tools.add_argument('-bd', '--buffer-delay', help='set the delay for checking if there are buffers to write',
+                    dest='buffer_delay', default=50)                    
 tools.add_argument('--coverage', help='determine SOMns code coverage and store in given file',
                    dest='coverage', default=None)
 tools.add_argument('--java-coverage', help='determine Java code coverage and store in given file',
@@ -315,6 +323,14 @@ if args.disable_trace_file:
     flags += ['-Dsom.disableTraceFile=true']
 if args.replay:
     flags += ['-Dsom.replay=true']
+if args.buffer_recycling:
+    flags += ['-Dsom.bufferRecycling=false']
+if args.buffer_size:
+    flags += ['-Dsom.buffSize=%s' % args.buffer_size ]
+if args.buffer_size:
+    flags += ['-Dsom.buffDelay=%s' % args.buffer_delay ]
+if args.buffers_per_thread:
+    flags += ['-Dsom.buffPerThread=%s' % args.buffers_per_thread ]
 
 if (args.truffle_profile or args.web_debugger or
     args.dynamic_metrics or args.coverage or args.si_candidates):

src/som/interpreter/actors/Actor.java

@@ -32,6 +32,7 @@
 import tools.debugger.entities.ActivityType;
 import tools.debugger.entities.DynamicScopeType;
 import tools.replay.actors.ActorExecutionTrace;
+import tools.replay.nodes.TraceActorContextNode;
 
 
 /**
@@ -230,6 +231,8 @@ protected ExecAllMessages(final Actor actor, final VM vm) {
       this.vm = vm;
     }
 
+    private static final TraceActorContextNode tracer = new TraceActorContextNode();
+
     @Override
     public void run() {
       assert executorRoot != null : "Actor system not initalized, call to initializeActorSystem(.) missing?";
@@ -249,7 +252,7 @@ void doRun() {
       t.currentlyExecutingActor = actor;
 
       if (VmSettings.ACTOR_TRACING) {
-        ActorExecutionTrace.recordActorContext((TracingActor) actor);
+        ActorExecutionTrace.recordActorContext((TracingActor) actor, tracer);
       } else if (VmSettings.KOMPOS_TRACING) {
         KomposTrace.currentActivity(actor);
       }
@@ -262,6 +265,10 @@ void doRun() {
         ObjectTransitionSafepoint.INSTANCE.unregister();
       }
 
+      if (VmSettings.ACTOR_TRACING && t.swapTracingBuffer) {
+        t.getBuffer().swapStorage();
+        t.swapTracingBuffer = false;
+      }
       t.currentlyExecutingActor = null;
     }
 
@@ -295,9 +302,6 @@ private void execute(final EventualMessage msg,
         if (VmSettings.KOMPOS_TRACING) {
           KomposTrace.scopeEnd(DynamicScopeType.TURN);
         }
-        if (VmSettings.ACTOR_TRACING) {
-          ActorExecutionTrace.recordMessage(msg);
-        }
       }
     }
 

src/som/interpreter/actors/ReceivedMessage.java

@@ -7,11 +7,9 @@
 import com.oracle.truffle.api.frame.VirtualFrame;
 import com.oracle.truffle.api.nodes.DirectCallNode;
 
-import som.interpreter.SArguments;
 import som.interpreter.SomException;
 import som.interpreter.SomLanguage;
 import som.interpreter.nodes.MessageSendNode.AbstractMessageSendNode;
-import som.vm.VmSettings;
 import som.vmobjects.SSymbol;
 
 
@@ -30,15 +28,8 @@ public ReceivedMessage(final AbstractMessageSendNode onReceive,
   }
 
   @Override
-  public Object execute(final VirtualFrame frame) {
-    EventualMessage msg = (EventualMessage) SArguments.rcvr(frame);
-    boolean haltOnResolver = msg.getHaltOnResolver();
-    boolean haltOnResolution = msg.getHaltOnResolution();
-
-    if (VmSettings.TRUFFLE_DEBUGGER_ENABLED && haltOnResolver) {
-      dbg.prepareSteppingAfterNextRootNode();
-    }
-
+  protected Object executeBody(final VirtualFrame frame, final EventualMessage msg,
+      final boolean haltOnResolver, final boolean haltOnResolution) {
     try {
       Object result = onReceive.doPreEvaluated(frame, msg.args);
       resolvePromise(frame, msg.resolver, result, haltOnResolver, haltOnResolution);
@@ -65,13 +56,8 @@ public ReceivedMessageForVMMain(final AbstractMessageSendNode onReceive,
     }
 
     @Override
-    public Object execute(final VirtualFrame frame) {
-      EventualMessage msg = (EventualMessage) SArguments.rcvr(frame);
-
-      if (VmSettings.TRUFFLE_DEBUGGER_ENABLED && msg.getHaltOnResolver()) {
-        dbg.prepareSteppingAfterNextRootNode();
-      }
-
+    protected Object executeBody(final VirtualFrame frame, final EventualMessage msg,
+        final boolean haltOnResolver, final boolean haltOnResolution) {
       Object result = onReceive.doPreEvaluated(frame, msg.args);
       future.complete(result);
       return result;
@@ -88,15 +74,8 @@ public ReceivedCallback(final RootCallTarget onReceive) {
     }
 
     @Override
-    public Object execute(final VirtualFrame frame) {
-      EventualMessage msg = (EventualMessage) SArguments.rcvr(frame);
-      boolean haltOnResolver = msg.getHaltOnResolver();
-      boolean haltOnResolution = msg.getHaltOnResolution();
-
-      if (VmSettings.TRUFFLE_DEBUGGER_ENABLED && haltOnResolver) {
-        dbg.prepareSteppingAfterNextRootNode();
-      }
-
+    protected Object executeBody(final VirtualFrame frame, final EventualMessage msg,
+        final boolean haltOnResolver, final boolean haltOnResolution) {
       try {
         Object result = onReceive.call(msg.args);
         resolvePromise(frame, msg.resolver, result, haltOnResolver,

src/som/interpreter/actors/ReceivedRootNode.java

@@ -7,17 +7,24 @@
 import com.oracle.truffle.api.source.SourceSection;
 
 import som.VM;
+import som.interpreter.SArguments;
 import som.interpreter.SomLanguage;
 import som.interpreter.actors.SPromise.SResolver;
 import som.vm.VmSettings;
+import tools.concurrency.KomposTrace;
 import tools.debugger.WebDebugger;
+import tools.debugger.entities.DynamicScopeType;
+import tools.replay.nodes.TraceMessageNode;
+import tools.replay.nodes.TraceMessageNodeGen;
 
 
 public abstract class ReceivedRootNode extends RootNode {
 
   @Child protected AbstractPromiseResolutionNode resolve;
   @Child protected AbstractPromiseResolutionNode error;
 
+  @Child protected TraceMessageNode msgTracer = TraceMessageNodeGen.create();
+
   private final VM            vm;
   protected final WebDebugger dbg;
   private final SourceSection sourceSection;
@@ -35,6 +42,46 @@ protected ReceivedRootNode(final SomLanguage language,
     this.sourceSection = sourceSection;
   }
 
+  protected abstract Object executeBody(VirtualFrame frame, EventualMessage msg,
+      boolean haltOnResolver, boolean haltOnResolution);
+
+  @Override
+  public final Object execute(final VirtualFrame frame) {
+    EventualMessage msg = (EventualMessage) SArguments.rcvr(frame);
+
+    boolean haltOnResolver;
+    boolean haltOnResolution;
+
+    if (VmSettings.TRUFFLE_DEBUGGER_ENABLED) {
+      haltOnResolver = msg.getHaltOnResolver();
+      haltOnResolution = msg.getHaltOnResolution();
+
+      if (haltOnResolver) {
+        dbg.prepareSteppingAfterNextRootNode();
+      }
+    } else {
+      haltOnResolver = false;
+      haltOnResolution = false;
+    }
+
+    if (VmSettings.KOMPOS_TRACING) {
+      KomposTrace.scopeStart(DynamicScopeType.TURN, msg.getMessageId(),
+          msg.getTargetSourceSection());
+    }
+
+    try {
+      return executeBody(frame, msg, haltOnResolver, haltOnResolution);
+    } finally {
+      if (VmSettings.ACTOR_TRACING) {
+        msgTracer.execute(msg);
+      }
+
+      if (VmSettings.KOMPOS_TRACING) {
+        KomposTrace.scopeEnd(DynamicScopeType.TURN);
+      }
+    }
+  }
+
   @Override
   public SourceSection getSourceSection() {
     return sourceSection;

src/som/primitives/SystemPrims.java

@@ -54,7 +54,9 @@
 import som.vmobjects.SSymbol;
 import tools.SourceCoordinate;
 import tools.concurrency.TraceParser;
+import tools.concurrency.TracingBackend;
 import tools.replay.actors.ActorExecutionTrace;
+import tools.replay.nodes.TraceActorContextNode;
 
 
 public final class SystemPrims {
@@ -74,6 +76,17 @@ public final Object set(final SObjectWithClass system) {
     }
   }
 
+  @GenerateNodeFactory
+  @Primitive(primitive = "traceStatistics:")
+  public abstract static class TraceStatisticsPrim extends UnarySystemOperation {
+    @Specialization
+    @TruffleBoundary
+    public final Object doSObject(final Object module) {
+      long[] stats = TracingBackend.getStatistics();
+      return new SImmutableArray(stats, Classes.valueArrayClass);
+    }
+  }
+
   public static Object loadModule(final VM vm, final String path,
       final ExceptionSignalingNode ioException) {
     // TODO: a single node for the different exceptions?
@@ -285,6 +298,8 @@ public final Object doSObject(final Object receiver) {
   @GenerateNodeFactory
   @Primitive(primitive = "systemTime:")
   public abstract static class TimePrim extends UnaryBasicOperation {
+    @Child TraceActorContextNode tracer = new TraceActorContextNode();
+
     @Specialization
     public final long doSObject(final Object receiver) {
       if (VmSettings.REPLAY) {
@@ -293,7 +308,7 @@ public final long doSObject(final Object receiver) {
 
       long res = System.currentTimeMillis() - startTime;
       if (VmSettings.ACTOR_TRACING) {
-        ActorExecutionTrace.longSystemCall(res);
+        ActorExecutionTrace.longSystemCall(res, tracer);
       }
       return res;
     }
@@ -319,6 +334,8 @@ public boolean matches(final Object[] args, final ExpressionNode[] argNodes) {
   @Primitive(primitive = "systemTicks:", selector = "ticks",
       specializer = IsSystemModule.class, noWrapper = true)
   public abstract static class TicksPrim extends UnaryBasicOperation implements Operation {
+    @Child TraceActorContextNode tracer = new TraceActorContextNode();
+
     @Specialization
     public final long doSObject(final Object receiver) {
       if (VmSettings.REPLAY) {
@@ -328,7 +345,7 @@ public final long doSObject(final Object receiver) {
       long res = System.nanoTime() / 1000L - startMicroTime;
 
       if (VmSettings.ACTOR_TRACING) {
-        ActorExecutionTrace.longSystemCall(res);
+        ActorExecutionTrace.longSystemCall(res, tracer);
       }
       return res;
     }

src/som/primitives/actors/CreateActorPrim.java

@@ -20,6 +20,7 @@
 import tools.concurrency.TracingActors.TracingActor;
 import tools.debugger.entities.ActivityType;
 import tools.replay.actors.ActorExecutionTrace;
+import tools.replay.nodes.TraceActorCreationNode;
 
 
 @GenerateNodeFactory
@@ -28,6 +29,7 @@
 public abstract class CreateActorPrim extends BinarySystemOperation {
   @Child protected IsValue                isValue = IsValueNodeGen.createSubNode();
   @Child protected ExceptionSignalingNode notAValue;
+  @Child protected TraceActorCreationNode trace   = new TraceActorCreationNode();
 
   @Override
   public final CreateActorPrim initialize(final VM vm) {
@@ -42,7 +44,7 @@ public final SFarReference createActor(final Object receiver, final Object argum
     SFarReference ref = new SFarReference(actor, argument);
 
     if (VmSettings.ACTOR_TRACING) {
-      ActorExecutionTrace.recordActorCreation(((TracingActor) actor).getActorId());
+      trace.trace((TracingActor) actor);
     } else if (VmSettings.KOMPOS_TRACING) {
       assert argument instanceof SClass;
       final SClass actorClass = (SClass) argument;

src/som/vm/VmSettings.java

@@ -31,6 +31,11 @@ public class VmSettings implements Settings {
 
   public static final String INSTRUMENTATION_PROP = "som.instrumentation";
 
+  public static final int     BUFFERS_PER_THREAD;
+  public static final int     BUFFER_SIZE;
+  public static final boolean RECYCLE_BUFFERS;
+  public static final int     BUFFER_TIMEOUT;
+
   static {
     String prop = System.getProperty("som.threads");
     if (prop == null) {
@@ -67,12 +72,21 @@ public class VmSettings implements Settings {
     IGV_DUMP_AFTER_PARSING = getBool("som.igvDumpAfterParsing", false);
 
     ANSI_COLOR_IN_OUTPUT = getBool("som.useAnsiColoring", false);
+
+    BUFFER_SIZE = getInteger("som.buffSize", 1024 * 1024);
+    BUFFERS_PER_THREAD = getInteger("som.buffPerThread", 4);
+    BUFFER_TIMEOUT = getInteger("som.buffDelay", 50);
+    RECYCLE_BUFFERS = getBool("som.bufferRecycling", true);
   }
 
   private static boolean getBool(final String prop, final boolean defaultVal) {
     return Boolean.parseBoolean(System.getProperty(prop, defaultVal ? "true" : "false"));
   }
 
+  private static int getInteger(final String prop, final int defaultVal) {
+    return Integer.parseInt(System.getProperty(prop, "" + defaultVal));
+  }
+
   @Override
   public boolean dynamicMetricsEnabled() {
     return DYNAMIC_METRICS;