[NO ISSUE][TRACE] Cleanups for performance tracer
- user model changes: no
- storage format changes: no
- interface changes: yes
Details:
- Move all Trace categories into a single place.
- Cleanup the interface and add some javadocs.
- Performance optimizations when logger is used.
- Add a new storage log for last record in.
Change-Id: Ib65edd6e7093dfd6f94ef750c484501b92c7a8a0
Reviewed-on: https://asterix-gerrit.ics.uci.edu/2558
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: abdullah alamoudi <bamousaa@gmail.com>
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 b9cfac4..94ae75c 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
@@ -42,6 +42,7 @@
import org.apache.hyracks.dataflow.common.utils.TaskUtil;
import org.apache.hyracks.dataflow.std.base.AbstractUnaryInputUnaryOutputOperatorNodePushable;
import org.apache.hyracks.util.trace.ITracer;
+import org.apache.hyracks.util.trace.TraceUtils;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
@@ -108,7 +109,7 @@
this.recordDescProvider = recordDescProvider;
this.opDesc = feedMetaOperatorDescriptor;
tracer = ctx.getJobletContext().getServiceContext().getTracer();
- traceCategory = tracer.getRegistry().get("Process-Frame");
+ traceCategory = tracer.getRegistry().get(TraceUtils.STORAGE);
}
@Override
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 68053d3..c767157 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
@@ -21,6 +21,8 @@
import java.io.DataOutput;
import java.io.IOException;
import java.nio.ByteBuffer;
+import java.text.SimpleDateFormat;
+import java.util.Date;
import org.apache.asterix.common.api.INcApplicationContext;
import org.apache.asterix.common.dataflow.LSMIndexUtil;
@@ -68,6 +70,9 @@
import org.apache.hyracks.storage.common.IIndexAccessParameters;
import org.apache.hyracks.storage.common.IIndexCursor;
import org.apache.hyracks.storage.common.MultiComparator;
+import org.apache.hyracks.util.trace.ITracer;
+import org.apache.hyracks.util.trace.ITracer.Scope;
+import org.apache.hyracks.util.trace.TraceUtils;
public class LSMPrimaryUpsertOperatorNodePushable extends LSMIndexInsertUpdateDeleteOperatorNodePushable {
@@ -98,7 +103,9 @@
private final ISearchOperationCallbackFactory searchCallbackFactory;
private final IFrameTupleProcessor processor;
private LSMTreeIndexAccessor lsmAccessor;
- private IIndexAccessParameters iap;
+ private final ITracer tracer;
+ private final long traceCategory;
+ private long lastRecordInTimeStamp = 0L;
public LSMPrimaryUpsertOperatorNodePushable(IHyracksTaskContext ctx, int partition,
IIndexDataflowHelperFactory indexHelperFactory, int[] fieldPermutation, RecordDescriptor inputRecDesc,
@@ -190,6 +197,8 @@
lsmAccessor.getCtx().setOperation(IndexOperation.UPSERT);
}
};
+ tracer = ctx.getJobletContext().getServiceContext().getTracer();
+ traceCategory = tracer.getRegistry().get(TraceUtils.LATENCY);
}
// we have the permutation which has [pk locations, record location, optional:filter-location]
@@ -226,7 +235,7 @@
abstractModCallback = (AbstractIndexModificationOperationCallback) modCallback;
searchCallback = (LockThenSearchOperationCallback) searchCallbackFactory
.createSearchOperationCallback(indexHelper.getResource().getId(), ctx, this);
- iap = new IndexAccessParameters(abstractModCallback, searchCallback);
+ IIndexAccessParameters iap = new IndexAccessParameters(abstractModCallback, searchCallback);
indexAccessor = index.createAccessor(iap);
lsmAccessor = (LSMTreeIndexAccessor) indexAccessor;
cursor = indexAccessor.createSearchCursor(false);
@@ -289,7 +298,11 @@
@Override
public void nextFrame(ByteBuffer buffer) throws HyracksDataException {
accessor.reset(buffer);
+ int itemCount = accessor.getTupleCount();
lsmAccessor.batchOperate(accessor, tuple, processor, frameOpCallback);
+ if (itemCount > 0) {
+ lastRecordInTimeStamp = System.currentTimeMillis();
+ }
}
private void appendFilterToOutput() throws IOException {
@@ -366,12 +379,22 @@
@Override
public void close() throws HyracksDataException {
- Throwable failure = CleanupUtils.close(frameOpCallback, null);
- failure = CleanupUtils.destroy(failure, cursor);
- failure = CleanupUtils.close(writer, failure);
- failure = CleanupUtils.close(indexHelper, failure);
- if (failure != null) {
- throw HyracksDataException.create(failure);
+ try {
+ Throwable failure = CleanupUtils.close(frameOpCallback, null);
+ failure = CleanupUtils.destroy(failure, cursor);
+ failure = CleanupUtils.close(writer, failure);
+ failure = CleanupUtils.close(indexHelper, failure);
+ if (failure != null) {
+ throw HyracksDataException.create(failure);
+ }
+ } finally {
+ if (tracer.isEnabled(traceCategory) && lastRecordInTimeStamp > 0) {
+ tracer.instant("UpsertClose", traceCategory, Scope.t,
+ "{\"last-record-in\":\""
+ + new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSS")
+ .format(new Date(lastRecordInTimeStamp))
+ + "\", \"index\":" + indexHelper.getIndexInstance().toString() + "}");
+ }
}
}
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 a74a1ab..76b5c8c 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
@@ -96,6 +96,7 @@
import org.apache.hyracks.util.MaintainedThreadNameExecutorService;
import org.apache.hyracks.util.PidHelper;
import org.apache.hyracks.util.trace.ITracer;
+import org.apache.hyracks.util.trace.TraceUtils;
import org.apache.hyracks.util.trace.Tracer;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
@@ -713,7 +714,7 @@
public TraceCurrentTimeTask(ITracer tracer) {
this.tracer = tracer;
- this.traceCategory = tracer.getRegistry().get("Timestamp");
+ this.traceCategory = tracer.getRegistry().get(TraceUtils.TIMESTAMP);
}
@Override
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 17aa394..c993874 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
@@ -31,12 +31,12 @@
import org.apache.hyracks.storage.am.lsm.common.api.ILSMIOOperation.LSMIOOperationType;
import org.apache.hyracks.storage.am.lsm.common.api.ILSMIndex;
import org.apache.hyracks.storage.am.lsm.common.api.ILSMIndexOperationContext;
-import org.apache.hyracks.storage.common.IModificationOperationCallback;
import org.apache.hyracks.storage.common.ISearchOperationCallback;
import org.apache.hyracks.storage.common.ISearchPredicate;
import org.apache.hyracks.storage.common.MultiComparator;
import org.apache.hyracks.util.trace.ITracer;
import org.apache.hyracks.util.trace.ITracer.Scope;
+import org.apache.hyracks.util.trace.TraceUtils;
public abstract class AbstractLSMIndexOperationContext implements ILSMIndexOperationContext {
@@ -79,7 +79,7 @@
filterTuple = null;
}
this.tracer = tracer;
- this.traceCategory = tracer.getRegistry().get("op-ctx");
+ this.traceCategory = tracer.getRegistry().get(TraceUtils.INDEX_OPERATIONS);
}
@Override
@@ -209,6 +209,7 @@
this.recovery = recovery;
}
+ @Override
public LSMIOOperationType getIoOperationType() {
return ioOpType;
}
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 572e05c..7238f8e 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
@@ -27,6 +27,7 @@
import org.apache.hyracks.storage.am.lsm.common.api.ILSMIndexAccessor;
import org.apache.hyracks.util.trace.ITracer;
import org.apache.hyracks.util.trace.ITracer.Scope;
+import org.apache.hyracks.util.trace.TraceUtils;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
@@ -48,14 +49,14 @@
public static ILSMIOOperation wrap(final ILSMIOOperation ioOp, final ITracer tracer) {
final String ioOpName = ioOp.getIOOpertionType().name().toLowerCase();
- final long traceCategorySchedule = tracer.getRegistry().get("schedule-" + ioOpName);
- if (tracer.isEnabled(traceCategorySchedule)) {
- tracer.instant(ioOp.getTarget().getRelativePath(), traceCategorySchedule, Scope.p, null);
+ 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() + "\"}");
}
- final long traceCategoryExec = tracer.getRegistry().get(ioOpName);
- if (tracer.isEnabled(traceCategoryExec)) {
- return ioOp instanceof Comparable ? new ComparableTracedIOOperation(ioOp, tracer, traceCategoryExec)
- : new TracedIOOperation(ioOp, tracer, traceCategoryExec);
+ if (tracer.isEnabled(traceCategory)) {
+ return ioOp instanceof Comparable ? new ComparableTracedIOOperation(ioOp, tracer, traceCategory)
+ : new TracedIOOperation(ioOp, tracer, traceCategory);
}
return ioOp;
}
@@ -91,7 +92,8 @@
try {
return ioOp.call();
} finally {
- tracer.durationE(name, traceCategory, tid, "{\"size\":" + getTarget().getFile().length() + "}");
+ 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/trace/ITraceCategoryRegistry.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITraceCategoryRegistry.java
index efec0dc..4f17c46 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITraceCategoryRegistry.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/ITraceCategoryRegistry.java
@@ -25,6 +25,7 @@
long CATEGORIES_ALL = -1L;
long CATEGORIES_NONE = 0L;
+ String CATEGORIES_ALL_NAME = "*";
ITraceCategoryRegistry NONE = new TraceCategoryRegistry() {
@Override
@@ -33,19 +34,25 @@
}
@Override
- public long get(String... names) {
- return CATEGORIES_NONE;
- }
-
- @Override
public String getName(long categoryCode) {
return "";
}
};
+ /**
+ * Register the tracing category if not registered and return its code
+ *
+ * @param name
+ * the category name
+ * @return the long code of the category
+ */
long get(String name);
- long get(String... names);
-
+ /**
+ * Get the name of the category with the code categoryCode
+ *
+ * @param categoryCode
+ * @return the String name of the category
+ */
String getName(long categoryCode);
}
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceCategoryRegistry.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceCategoryRegistry.java
index db11285..baf6082 100644
--- a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceCategoryRegistry.java
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceCategoryRegistry.java
@@ -22,15 +22,15 @@
import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
-import java.util.Optional;
public class TraceCategoryRegistry implements ITraceCategoryRegistry {
- private Map<String, Long> categories = Collections.synchronizedMap(new HashMap<>());
+ private final Map<String, Long> categories = Collections.synchronizedMap(new HashMap<>());
+ private final String[] names = new String[NO_CATEGORIES];
private int bitPos = 0;
public TraceCategoryRegistry() {
- categories.put("*", ITraceCategoryRegistry.CATEGORIES_ALL);
+ categories.put(CATEGORIES_ALL_NAME, ITraceCategoryRegistry.CATEGORIES_ALL);
}
@Override
@@ -38,33 +38,40 @@
return categories.computeIfAbsent(name, this::nextCode);
}
- private long nextCode(String name) {
+ private synchronized long nextCode(String name) {
if (bitPos > NO_CATEGORIES - 1) {
throw new IllegalStateException("Cannot add category " + name);
}
+ names[bitPos] = name;
return 1L << bitPos++;
}
@Override
- public long get(String... names) {
- long result = 0;
- for (String name : names) {
- result |= get(name);
- }
- return result;
- }
-
- private Optional<Map.Entry<String, Long>> findEntry(long categoryCode) {
- return categories.entrySet().stream().filter(e -> e.getValue() == categoryCode).findFirst();
- }
-
- @Override
public String getName(long categoryCode) {
- Optional<Map.Entry<String, Long>> entry = findEntry(categoryCode);
- if (!entry.isPresent()) {
+ if (CATEGORIES_ALL == categoryCode) {
+ return CATEGORIES_ALL_NAME;
+ }
+ if (categoryCode == 0) {
+ throw new IllegalArgumentException("Illegal category code " + categoryCode);
+ }
+ int postition = mostSignificantBit(categoryCode);
+ if (postition >= bitPos) {
throw new IllegalArgumentException("No category for code " + categoryCode);
}
- return entry.get().getKey();
+ return nameAt(postition);
+ }
+
+ public String nameAt(int n) {
+ return names[n];
+ }
+
+ public static int mostSignificantBit(long n) {
+ int pos = -1;
+ while (n != 0) {
+ pos++;
+ n = n >>> 1;
+ }
+ return pos;
}
@Override
@@ -72,11 +79,10 @@
StringBuilder sb = new StringBuilder();
for (int pos = 0; pos < NO_CATEGORIES; ++pos) {
long categoryCode = 1L << pos;
- Optional<Map.Entry<String, Long>> entry = findEntry(categoryCode);
- if (!entry.isPresent()) {
+ String name = nameAt(pos);
+ if (name == null) {
continue;
}
- String name = entry.get().getKey();
String codeString = Long.toBinaryString(categoryCode);
sb.append(name).append(" -> ").append(codeString).append(' ');
}
diff --git a/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceUtils.java b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceUtils.java
new file mode 100644
index 0000000..60ec419
--- /dev/null
+++ b/hyracks-fullstack/hyracks/hyracks-util/src/main/java/org/apache/hyracks/util/trace/TraceUtils.java
@@ -0,0 +1,35 @@
+/*
+ * 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;
+
+public class TraceUtils {
+
+ private TraceUtils() {
+ }
+
+ // CATEGORIES
+ public static final String TRACER = "Tracer";
+ public static final String TIMESTAMP = "Timestamp";
+ public static final String INDEX_OPERATIONS = "IndexOperations";
+ public static final String INDEX_IO_OPERATIONS = "IndexIoOperations";
+ public static final String INGESTION = "Ingestion";
+ public static final String STORAGE = "Storage";
+ public static final String LATENCY = "Latency";
+
+}
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 ea3793d..1e8af75 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
@@ -37,7 +37,6 @@
public static final Logger LOGGER = LogManager.getLogger();
protected static final Level TRACE_LOG_LEVEL = Level.INFO;
- protected static final String CAT = "Tracer";
protected static final ThreadLocal<DateFormat> DATE_FORMAT =
ThreadLocal.withInitial(() -> new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSSXXX"));
@@ -53,7 +52,7 @@
this.traceLog = LogManager.getLogger(traceLoggerName);
this.categories = categories;
this.registry = registry;
- final long traceCategory = getRegistry().get(CAT);
+ final long traceCategory = getRegistry().get(TraceUtils.TRACER);
instant("Trace-Start", traceCategory, Scope.p, dateTimeStamp());
}
@@ -62,9 +61,18 @@
setCategories(categories);
}
+ @Override
public void setCategories(String... categories) {
LOGGER.info("Set categories for Tracer " + this.traceLog.getName() + " to " + Arrays.toString(categories));
- this.categories = getRegistry().get(categories);
+ this.categories = set(categories);
+ }
+
+ private long set(String... names) {
+ long result = 0;
+ for (String name : names) {
+ result |= getRegistry().get(name);
+ }
+ return result;
}
public static String dateTimeStamp() {