You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@asterixdb.apache.org by mb...@apache.org on 2021/12/23 12:49:57 UTC
[asterixdb] branch master updated: [NO ISSUE][HYR][MISC] Add option to provide tracer args via Suppliers
This is an automated email from the ASF dual-hosted git repository.
mblow pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/asterixdb.git
The following commit(s) were added to refs/heads/master by this push:
new f65e0ad [NO ISSUE][HYR][MISC] Add option to provide tracer args via Suppliers
f65e0ad is described below
commit f65e0adfcf538af769f2393b768fc8770cfebf51
Author: Michael Blow <mb...@apache.org>
AuthorDate: Wed Dec 22 09:36:02 2021 -0500
[NO ISSUE][HYR][MISC] Add option to provide tracer args via Suppliers
Change-Id: I040523a73e65a0fd86fff3fff38d2278d83ef65f
Reviewed-on: https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/14643
Reviewed-by: Michael Blow <mb...@apache.org>
Reviewed-by: Hussain Towaileb <hu...@gmail.com>
Integration-Tests: Jenkins <je...@fulliautomatix.ics.uci.edu>
Tested-by: Jenkins <je...@fulliautomatix.ics.uci.edu>
---
.../operators/FeedMetaStoreNodePushable.java | 4 +-
.../LSMPrimaryUpsertOperatorNodePushable.java | 2 +-
.../hyracks/control/nc/NodeControllerService.java | 2 +-
.../common/comm/io/AbstractFrameAppender.java | 2 +-
.../dataflow/common/comm/util/FrameUtils.java | 2 +-
.../impls/AbstractLSMIndexOperationContext.java | 2 +-
.../storage/am/lsm/common/impls/LSMHarness.java | 2 +-
.../am/lsm/common/impls/TracedIOOperation.java | 6 +-
.../util/MaintainedThreadNameExecutorService.java | 6 +-
.../org/apache/hyracks/util/trace/ITracer.java | 55 ++++++++++++++-
.../java/org/apache/hyracks/util/trace/Tracer.java | 82 ++++++++++++++++++----
.../org/apache/hyracks/util/trace/TraceTest.java | 12 ++--
12 files changed, 145 insertions(+), 32 deletions(-)
diff --git a/asterixdb/asterix-external-data/src/main/java/org/apache/asterix/external/operators/FeedMetaStoreNodePushable.java b/asterixdb/asterix-external-data/src/main/java/org/apache/asterix/external/operators/FeedMetaStoreNodePushable.java
index 37e589a..7bc3b4f 100644
--- a/asterixdb/asterix-external-data/src/main/java/org/apache/asterix/external/operators/FeedMetaStoreNodePushable.java
+++ b/asterixdb/asterix-external-data/src/main/java/org/apache/asterix/external/operators/FeedMetaStoreNodePushable.java
@@ -162,7 +162,7 @@ public class FeedMetaStoreNodePushable extends AbstractUnaryInputUnaryOutputOper
@Override
public void nextFrame(ByteBuffer buffer) throws HyracksDataException {
- long tid = tracer.durationB("Ingestion-Store", traceCategory, null);
+ long tid = tracer.durationB("Ingestion-Store", traceCategory);
try {
if (hasMessage) {
FeedUtils.processFeedMessage(buffer, message, fta);
@@ -172,7 +172,7 @@ public class FeedMetaStoreNodePushable extends AbstractUnaryInputUnaryOutputOper
LOGGER.log(Level.WARN, "Failure Processing a frame at store side", e);
throw HyracksDataException.create(e);
} finally {
- tracer.durationE(tid, traceCategory, null);
+ tracer.durationE(traceCategory, tid);
}
}
diff --git a/asterixdb/asterix-runtime/src/main/java/org/apache/asterix/runtime/operators/LSMPrimaryUpsertOperatorNodePushable.java b/asterixdb/asterix-runtime/src/main/java/org/apache/asterix/runtime/operators/LSMPrimaryUpsertOperatorNodePushable.java
index 591ff9a..1e7f4b7 100644
--- a/asterixdb/asterix-runtime/src/main/java/org/apache/asterix/runtime/operators/LSMPrimaryUpsertOperatorNodePushable.java
+++ b/asterixdb/asterix-runtime/src/main/java/org/apache/asterix/runtime/operators/LSMPrimaryUpsertOperatorNodePushable.java
@@ -459,7 +459,7 @@ public class LSMPrimaryUpsertOperatorNodePushable extends LSMIndexInsertUpdateDe
if (tracer.isEnabled(traceCategory) && lastRecordInTimeStamp > 0 && indexHelper != null
&& indexHelper.getIndexInstance() != null) {
tracer.instant("UpsertClose", traceCategory, Scope.t,
- "{\"last-record-in\":\"" + DATE_FORMAT.get().format(new Date(lastRecordInTimeStamp))
+ () -> "{\"last-record-in\":\"" + DATE_FORMAT.get().format(new Date(lastRecordInTimeStamp))
+ "\", \"index\":" + indexHelper.getIndexInstance().toString() + "}");
}
} catch (Throwable traceFailure) {
diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-nc/src/main/java/org/apache/hyracks/control/nc/NodeControllerService.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-nc/src/main/java/org/apache/hyracks/control/nc/NodeControllerService.java
index c774317..8c9cbfb 100644
--- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-nc/src/main/java/org/apache/hyracks/control/nc/NodeControllerService.java
+++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-nc/src/main/java/org/apache/hyracks/control/nc/NodeControllerService.java
@@ -710,7 +710,7 @@ public class NodeControllerService implements IControllerService {
@Override
public void run() {
try {
- tracer.instant("CurrentTime", traceCategory, Tracer.Scope.p, Tracer.dateTimeStamp());
+ tracer.instant("CurrentTime", traceCategory, ITracer.Scope.p, Tracer::dateTimeStamp);
} catch (Exception e) {
LOGGER.log(Level.WARN, "Exception tracing current time", e);
}
diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/io/AbstractFrameAppender.java b/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/io/AbstractFrameAppender.java
index 59ab2f4..e1acaee 100644
--- a/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/io/AbstractFrameAppender.java
+++ b/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/io/AbstractFrameAppender.java
@@ -116,7 +116,7 @@ public class AbstractFrameAppender implements IFrameAppender {
try {
flush(writer);
} finally {
- tracer.durationE(tid, traceCategory, args);
+ tracer.durationE(traceCategory, tid, args);
}
}
diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/util/FrameUtils.java b/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/util/FrameUtils.java
index ec45437..39e223b 100644
--- a/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/util/FrameUtils.java
+++ b/hyracks-fullstack/hyracks/hyracks-dataflow-common/src/main/java/org/apache/hyracks/dataflow/common/comm/util/FrameUtils.java
@@ -157,7 +157,7 @@ public class FrameUtils {
flushedBytes = frameTupleAppender.getBuffer().capacity();
long tid = tracer.durationB(name, cat, args);
frameTupleAppender.write(writer, true);
- tracer.durationE(tid, cat, args);
+ tracer.durationE(cat, tid, args);
if (!frameTupleAppender.append(tupleAccessor, tIndex)) {
throw HyracksDataException.create(ErrorCode.TUPLE_CANNOT_FIT_INTO_EMPTY_FRAME,
tupleAccessor.getTupleLength(tIndex));
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractLSMIndexOperationContext.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractLSMIndexOperationContext.java
index dfb1a17..0813a00 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractLSMIndexOperationContext.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/AbstractLSMIndexOperationContext.java
@@ -171,7 +171,7 @@ public abstract class AbstractLSMIndexOperationContext implements ILSMIndexOpera
public void logPerformanceCounters(int tupleCount) {
if (isTracingEnabled()) {
tracer.instant("store-counters", traceCategory, Scope.t,
- "{\"count\":" + tupleCount + ",\"enter-exit-duration-ns\":" + enterExitTime + "}");
+ () -> "{\"count\":" + tupleCount + ",\"enter-exit-duration-ns\":" + enterExitTime + "}");
resetCounters();
}
}
diff --git a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/LSMHarness.java b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/LSMHarness.java
index 92fa135..950a8e5 100644
--- a/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/LSMHarness.java
+++ b/hyracks-fullstack/hyracks/hyracks-storage-am-lsm-common/src/main/java/org/apache/hyracks/storage/am/lsm/common/impls/LSMHarness.java
@@ -262,7 +262,7 @@ public class LSMHarness implements ILSMHarness {
}
if (inactiveMemoryComponentsToBeCleanedUp != null) {
for (ILSMMemoryComponent c : inactiveMemoryComponentsToBeCleanedUp) {
- tracer.instant(c.toString(), traceCategory, Scope.p, lsmIndex.toString());
+ tracer.instant(c.toString(), traceCategory, Scope.p, lsmIndex::toString);
c.cleanup();
synchronized (opTracker) {
c.reset();
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 4ab57c5..eb48f82 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
@@ -58,7 +58,7 @@ class TracedIOOperation implements ILSMIOOperation {
final long traceCategory = tracer.getRegistry().get(TraceUtils.INDEX_IO_OPERATIONS);
if (tracer.isEnabled(traceCategory)) {
tracer.instant("schedule-" + ioOpName, traceCategory, Scope.p,
- "{\"path\": \"" + ioOp.getTarget().getRelativePath() + "\"}");
+ () -> "{\"path\": \"" + ioOp.getTarget().getRelativePath() + "\"}");
return new TracedIOOperation(ioOp, tracer, traceCategory);
}
return ioOp;
@@ -91,11 +91,11 @@ class TracedIOOperation implements ILSMIOOperation {
@Override
public LSMIOOperationStatus call() throws HyracksDataException {
final String name = getTarget().getRelativePath();
- final long tid = tracer.durationB(name, traceCategory, null);
+ final long tid = tracer.durationB(name, traceCategory);
try {
return ioOp.call();
} finally {
- tracer.durationE(ioOp.getIOOpertionType().name().toLowerCase(), traceCategory, tid, "{\"size\":"
+ tracer.durationE(ioOp.getIOOpertionType().name().toLowerCase(), traceCategory, tid, () -> "{\"size\":"
+ getTarget().getFile().length() + ", \"path\": \"" + ioOp.getTarget().getRelativePath() + "\"}");
}
}
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/MaintainedThreadNameExecutorService.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/MaintainedThreadNameExecutorService.java
index 9adac04..9b316ba 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/MaintainedThreadNameExecutorService.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/MaintainedThreadNameExecutorService.java
@@ -45,6 +45,10 @@ public class MaintainedThreadNameExecutorService extends ThreadPoolExecutor {
@Override
protected void afterExecute(Runnable r, Throwable t) {
super.afterExecute(r, t);
- Thread.currentThread().setName(savedName.get());
+ try {
+ Thread.currentThread().setName(savedName.get());
+ } finally {
+ savedName.remove();
+ }
}
}
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITracer.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITracer.java
index 908dc1c..3748cd8 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITracer.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITracer.java
@@ -19,6 +19,8 @@
package org.apache.hyracks.util.trace;
+import java.util.function.Supplier;
+
public interface ITracer {
enum Phase {
@@ -83,7 +85,12 @@ public interface ITracer {
}
@Override
- public void durationE(long tid, long cat, String args) {
+ public void durationE(long cat, long tid, String args) {
+ // nothing to do here
+ }
+
+ @Override
+ public void instant(String name, long cat, Scope scope) {
// nothing to do here
}
@@ -91,6 +98,36 @@ public interface ITracer {
public void instant(String name, long cat, Scope scope, String args) {
// nothing to do here
}
+
+ @Override
+ public long durationB(String name, long cat) {
+ return -1;
+ }
+
+ @Override
+ public long durationB(String name, long cat, Supplier<String> args) {
+ return -1;
+ }
+
+ @Override
+ public void durationE(long cat, long tid) {
+ // nothing to do here
+ }
+
+ @Override
+ public void durationE(long cat, long tid, Supplier<String> args) {
+ // nothing to do here
+ }
+
+ @Override
+ public void durationE(String name, long cat, long tid, Supplier<String> args) {
+ // nothing to do here
+ }
+
+ @Override
+ public void instant(String name, long cat, Scope scope, Supplier<String> args) {
+ // nothing to do here
+ }
};
String getName();
@@ -101,14 +138,28 @@ public interface ITracer {
boolean isEnabled(long cat);
+ long durationB(String name, long cat);
+
long durationB(String name, long cat, String args);
- void durationE(long tid, long cat, String args);
+ long durationB(String name, long cat, Supplier<String> args);
+
+ void durationE(long cat, long tid);
+
+ void durationE(long cat, long tid, String args);
+
+ void durationE(long cat, long tid, Supplier<String> args);
void durationE(String name, long cat, long tid, String args);
+ void durationE(String name, long cat, long tid, Supplier<String> args);
+
+ void instant(String name, long cat, Scope scope);
+
void instant(String name, long cat, Scope scope, String args);
+ void instant(String name, long cat, Scope scope, Supplier<String> args);
+
@Override
String toString();
}
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 c1c38cf..bc24949 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
@@ -23,6 +23,7 @@ import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Arrays;
import java.util.Date;
+import java.util.function.Supplier;
import org.apache.hyracks.util.PidHelper;
import org.apache.logging.log4j.Level;
@@ -44,7 +45,7 @@ public class Tracer implements ITracer {
private long categories;
private final TraceCategoryRegistry registry;
- private static final long pid = PidHelper.getPid();
+ private static final long PID = PidHelper.getPid();
public Tracer(String name, long categories, TraceCategoryRegistry registry) {
final String traceLoggerName = Tracer.class.getName() + ".Traces." + name;
@@ -53,7 +54,7 @@ public class Tracer implements ITracer {
this.categories = categories;
this.registry = registry;
final long traceCategory = getRegistry().get(TraceUtils.TRACER);
- instant("Trace-Start", traceCategory, Scope.p, dateTimeStamp());
+ instant("Trace-Start", traceCategory, Scope.p, Tracer::dateTimeStamp);
}
public Tracer(String name, String[] categories, TraceCategoryRegistry registry) {
@@ -100,11 +101,25 @@ public class Tracer implements ITracer {
}
@Override
+ public long durationB(String name, long cat) {
+ if (isEnabled(cat)) {
+ return emitDurationB(name, cat, null);
+ }
+ return -1;
+ }
+
+ @Override
public long durationB(String name, long cat, String args) {
if (isEnabled(cat)) {
- Event e = Event.create(name, cat, Phase.B, pid, Thread.currentThread().getId(), null, args, getRegistry());
- traceLog.log(TRACE_LOG_LEVEL, e.toJson());
- return e.tid;
+ return emitDurationB(name, cat, args);
+ }
+ return -1;
+ }
+
+ @Override
+ public long durationB(String name, long cat, Supplier<String> args) {
+ if (isEnabled(cat)) {
+ return emitDurationB(name, cat, args.get());
}
return -1;
}
@@ -112,24 +127,67 @@ public class Tracer implements ITracer {
@Override
public void durationE(String name, long cat, long tid, String args) {
if (isEnabled(cat)) {
- Event e = Event.create(name, cat, Phase.E, pid, tid, null, args, getRegistry());
- traceLog.log(TRACE_LOG_LEVEL, e.toJson());
+ emit(name, cat, null, Phase.E, tid, args);
+ }
+ }
+
+ @Override
+ public void durationE(String name, long cat, long tid, Supplier<String> args) {
+ if (isEnabled(cat)) {
+ emit(name, cat, null, Phase.E, tid, args.get());
}
}
@Override
- public void durationE(long tid, long cat, String args) {
+ public void durationE(long cat, long tid) {
if (isEnabled(cat)) {
- Event e = Event.create(null, 0L, Phase.E, pid, tid, null, args, getRegistry());
- traceLog.log(TRACE_LOG_LEVEL, e.toJson());
+ emit(null, 0L, null, Phase.E, tid, null);
+ }
+ }
+
+ @Override
+ public void durationE(long cat, long tid, String args) {
+ if (isEnabled(cat)) {
+ emit(null, 0L, null, Phase.E, tid, args);
+ }
+ }
+
+ @Override
+ public void durationE(long cat, long tid, Supplier<String> args) {
+ if (isEnabled(cat)) {
+ emit(null, 0L, null, Phase.E, tid, args.get());
+ }
+ }
+
+ @Override
+ public void instant(String name, long cat, Scope scope) {
+ if (isEnabled(cat)) {
+ emit(name, cat, scope, Phase.i, Thread.currentThread().getId(), null);
}
}
@Override
public void instant(String name, long cat, Scope scope, String args) {
if (isEnabled(cat)) {
- Event e = Event.create(name, cat, Phase.i, pid, Thread.currentThread().getId(), scope, args, getRegistry());
- traceLog.log(TRACE_LOG_LEVEL, e.toJson());
+ emit(name, cat, scope, Phase.i, Thread.currentThread().getId(), args);
+ }
+ }
+
+ @Override
+ public void instant(String name, long cat, Scope scope, Supplier<String> args) {
+ if (isEnabled(cat)) {
+ emit(name, cat, scope, Phase.i, Thread.currentThread().getId(), args.get());
}
}
+
+ private long emitDurationB(String name, long cat, String args) {
+ Event e = Event.create(name, cat, Phase.B, PID, Thread.currentThread().getId(), null, args, getRegistry());
+ traceLog.log(TRACE_LOG_LEVEL, e.toJson());
+ return e.tid;
+ }
+
+ private void emit(String name, long cat, Scope scope, Phase i, long tid, String args) {
+ Event e = Event.create(name, cat, i, PID, tid, scope, args, getRegistry());
+ traceLog.log(TRACE_LOG_LEVEL, e.toJson());
+ }
}
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/test/java/org/apache/hyracks/util/trace/TraceTest.java b/hyracks-fullstack/hyracks/hyracks-util/src/test/java/org/apache/hyracks/util/trace/TraceTest.java
index f842f3e..9df05b5 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/test/java/org/apache/hyracks/util/trace/TraceTest.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/test/java/org/apache/hyracks/util/trace/TraceTest.java
@@ -61,9 +61,9 @@ public class TraceTest {
ITracer tracer = new Tracer(name, new String[] { "CAT1", "CAT2" }, registry);
Log4j2Monitor.start();
- tracer.instant("test1", cat1, ITracer.Scope.p, null);
- tracer.instant("test2", cat2, ITracer.Scope.p, null);
- tracer.instant("test3", cat3, ITracer.Scope.p, null);
+ tracer.instant("test1", cat1, ITracer.Scope.p);
+ tracer.instant("test2", cat2, ITracer.Scope.p);
+ tracer.instant("test3", cat3, ITracer.Scope.p);
List<String> lines = Log4j2Monitor.getLogs();
for (String line : lines) {
@@ -76,9 +76,9 @@ public class TraceTest {
tracer.setCategories("CAT1", "CAT3");
Log4j2Monitor.reset();
- tracer.instant("test1", cat1, ITracer.Scope.p, null);
- tracer.instant("test2", cat2, ITracer.Scope.p, null);
- tracer.instant("test3", cat3, ITracer.Scope.p, null);
+ tracer.instant("test1", cat1, ITracer.Scope.p);
+ tracer.instant("test2", cat2, ITracer.Scope.p);
+ tracer.instant("test3", cat3, ITracer.Scope.p);
lines = Log4j2Monitor.getLogs();
for (String line : lines) {