[NO ISSUE][OTH] Trace Scheduling of IO operations

- user model changes: no
- storage format changes: no
- interface changes: no

details:
- Add traces to capture the point of time an IO operation is scheduled.

Change-Id: Id5146d41de2ea4b46c53ce33ce467b8304bce177
Reviewed-on: https://asterix-gerrit.ics.uci.edu/2039
Tested-by: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Contrib: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Integration-Tests: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Reviewed-by: Till Westmann <tillw@apache.org>
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/api/ILSMIOOperation.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/api/ILSMIOOperation.java
index 79360d5..a13f82c 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/api/ILSMIOOperation.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/api/ILSMIOOperation.java
@@ -21,6 +21,7 @@
 import java.util.concurrent.Callable;
 
 import org.apache.hyracks.api.exceptions.HyracksDataException;
+import org.apache.hyracks.api.io.FileReference;
 import org.apache.hyracks.api.io.IODeviceHandle;
 
 public interface ILSMIOOperation extends Callable<Boolean> {
@@ -55,4 +56,11 @@
 
     @Override
     Boolean call() throws HyracksDataException;
+
+    /**
+     * The target of the io operation
+     *
+     * @return
+     */
+    FileReference getTarget();
 }
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractIoOperation.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractIoOperation.java
index 09e236e..6e51f83 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractIoOperation.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractIoOperation.java
@@ -49,6 +49,7 @@
         return callback;
     }
 
+    @Override
     public FileReference getTarget() {
         return target;
     }
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/FlushOperation.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/FlushOperation.java
index 3d65a6f..1173aeb 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/FlushOperation.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/FlushOperation.java
@@ -50,11 +50,6 @@
     }
 
     @Override
-    public FileReference getTarget() {
-        return target;
-    }
-
-    @Override
     public ILSMIndexAccessor getAccessor() {
         return accessor;
     }
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/TracedIOOperation.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/TracedIOOperation.java
index b4b846d..d801a44 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/TracedIOOperation.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/TracedIOOperation.java
@@ -22,10 +22,12 @@
 import java.util.logging.Logger;
 
 import org.apache.hyracks.api.exceptions.HyracksDataException;
+import org.apache.hyracks.api.io.FileReference;
 import org.apache.hyracks.api.io.IODeviceHandle;
 import org.apache.hyracks.storage.am.lsm.common.api.ILSMIOOperation;
 import org.apache.hyracks.storage.am.lsm.common.api.ILSMIOOperationCallback;
 import org.apache.hyracks.util.trace.Tracer;
+import org.apache.hyracks.util.trace.Tracer.Scope;
 
 class TracedIOOperation implements ILSMIOOperation {
 
@@ -45,6 +47,9 @@
 
     public static ILSMIOOperation wrap(final ILSMIOOperation ioOp, final Tracer tracer) {
         if (tracer != null && tracer.isEnabled()) {
+            tracer.instant(ioOp.getTarget().getRelativePath(),
+                    ioOp.getIOOpertionType() == LSMIOOpertionType.FLUSH ? "schedule-flush" : "schedule-merge", Scope.p,
+                    null);
             return ioOp instanceof Comparable ? new ComparableTracedIOOperation(ioOp, tracer)
                     : new TracedIOOperation(ioOp, tracer);
         }
@@ -55,31 +60,40 @@
         return ioOp;
     }
 
+    @Override
     public IODeviceHandle getDevice() {
         return ioOp.getDevice();
     }
 
+    @Override
     public ILSMIOOperationCallback getCallback() {
         return ioOp.getCallback();
     }
 
+    @Override
     public String getIndexIdentifier() {
         return ioOp.getIndexIdentifier();
     }
 
+    @Override
     public LSMIOOpertionType getIOOpertionType() {
         return ioOpType;
     }
 
     @Override
     public Boolean call() throws HyracksDataException {
-        final long tid = tracer.durationB(getDevice().toString(), cat, null);
+        final long tid = tracer.durationB(getTarget().getRelativePath(), cat, null);
         try {
             return ioOp.call();
         } finally {
             tracer.durationE(tid, "{\"optional\":\"value\"}");
         }
     }
+
+    @Override
+    public FileReference getTarget() {
+        return ioOp.getTarget();
+    }
 }
 
 class ComparableTracedIOOperation extends TracedIOOperation implements Comparable<ILSMIOOperation> {
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Event.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Event.java
new file mode 100644
index 0000000..4a46c19
--- /dev/null
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Event.java
@@ -0,0 +1,78 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.hyracks.util.trace;
+
+import org.apache.hyracks.util.trace.Tracer.Scope;
+
+final class Event {
+    public final String name;
+    public final String cat;
+    public final Tracer.Phase ph;
+    public final long ts;
+    public final int pid;
+    public final long tid;
+    public final Tracer.Scope scope;
+    public final String args;
+
+    private Event(String name, String cat, Tracer.Phase ph, long ts, int pid, long tid, Tracer.Scope scope,
+            String args) {
+        this.name = name;
+        this.cat = cat;
+        this.ph = ph;
+        this.ts = ts;
+        this.pid = pid;
+        this.tid = tid;
+        this.scope = scope;
+        this.args = args;
+    }
+
+    private static long timestamp() {
+        return System.nanoTime() / 1000;
+    }
+
+    public static Event create(String name, String cat, Tracer.Phase ph, int pid, long tid, Scope scope, String args) {
+        return new Event(name, cat, ph, timestamp(), pid, tid, scope, args);
+    }
+
+    public String toJson() {
+        return append(new StringBuilder()).toString();
+    }
+
+    public StringBuilder append(StringBuilder sb) {
+        sb.append("{");
+        if (name != null) {
+            sb.append("\"name\":\"").append(name).append("\",");
+        }
+        if (cat != null) {
+            sb.append("\"cat\":\"").append(cat).append("\",");
+        }
+        sb.append("\"ph\":\"").append(ph).append("\",");
+        sb.append("\"pid\":\"").append(pid).append("\",");
+        sb.append("\"tid\":").append(tid).append(",");
+        sb.append("\"ts\":").append(ts);
+        if (scope != null) {
+            sb.append(",\"s\":\"").append(scope).append("\"");
+        }
+        if (args != null) {
+            sb.append(",\"args\":").append(args);
+        }
+        sb.append("}");
+        return sb;
+    }
+}
\ No newline at end of file
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Tracer.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Tracer.java
index 1c02ac8..4dc2394 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Tracer.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/Tracer.java
@@ -44,7 +44,7 @@
         // Complete Events
         X,
         // Instant Events
-        I,
+        i,
         // Counter Events
         C,
         // Async Events
@@ -61,6 +61,12 @@
         D // destroyed
     }
 
+    public enum Scope {
+        g, // Global scope
+        p, // Process scope
+        t // Thread scope
+    }
+
     public Tracer(String name, String[] categories) {
         this.traceLog = Logger.getLogger(Tracer.class.getName() + "@" + name);
         this.categories = categories;
@@ -88,64 +94,18 @@
     }
 
     public long durationB(String name, String cat, String args) {
-        Event e = Event.create(name, cat, Phase.B, pid, Thread.currentThread().getId(), args);
+        Event e = Event.create(name, cat, Phase.B, pid, Thread.currentThread().getId(), null, args);
         traceLog.log(TRACE_LOG_LEVEL, e.toJson());
         return e.tid;
     }
 
     public void durationE(long tid, String args) {
-        Event e = Event.create(null, null, Phase.E, pid, tid, args);
+        Event e = Event.create(null, null, Phase.E, pid, tid, null, args);
         traceLog.log(TRACE_LOG_LEVEL, e.toJson());
     }
-}
 
-class Event {
-    public final String name;
-    public final String cat;
-    public final Tracer.Phase ph;
-    public final long ts;
-    public final int pid;
-    public final long tid;
-    public final String args;
-
-    private Event(String name, String cat, Tracer.Phase ph, long ts, int pid, long tid, String args) {
-        this.name = name;
-        this.cat = cat;
-        this.ph = ph;
-        this.ts = ts;
-        this.pid = pid;
-        this.tid = tid;
-        this.args = args;
-    }
-
-    private static long timestamp() {
-        return System.nanoTime() / 1000;
-    }
-
-    public static Event create(String name, String cat, Tracer.Phase ph, int pid, long tid, String args) {
-        return new Event(name, cat, ph, timestamp(), pid, tid, args);
-    }
-
-    public String toJson() {
-        return append(new StringBuilder()).toString();
-    }
-
-    public StringBuilder append(StringBuilder sb) {
-        sb.append("{");
-        if (name != null) {
-            sb.append("\"name\":\"").append(name).append("\",");
-        }
-        if (cat != null) {
-            sb.append("\"cat\":\"").append(cat).append("\",");
-        }
-        sb.append("\"ph\":\"").append(ph).append("\",");
-        sb.append("\"pid\":\"").append(pid).append("\",");
-        sb.append("\"tid\":").append(tid).append(",");
-        sb.append("\"ts\":").append(ts);
-        if (args != null) {
-            sb.append(",\"args\":").append(args);
-        }
-        sb.append("}");
-        return sb;
+    public void instant(String name, String cat, Scope scope, String args) {
+        Event e = Event.create(name, cat, Phase.i, pid, Thread.currentThread().getId(), scope, args);
+        traceLog.log(TRACE_LOG_LEVEL, e.toJson());
     }
 }