This is an automated email from the ASF dual-hosted git repository.
abhay pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/ranger.git
The following commit(s) were added to refs/heads/master by this push:
new 279f41f5b RANGER-4515: Enhance perf-tracer to get CPU time when
possible
279f41f5b is described below
commit 279f41f5bf058dfe7d44175932741e4da1414d33
Author: Abhay Kulkarni <ab...@apache.org>
AuthorDate: Tue Nov 7 11:21:41 2023 -0800
RANGER-4515: Enhance perf-tracer to get CPU time when possible
---
.../ranger/plugin/util/PerfDataRecorder.java | 49 ++++++++++++++++++----
.../plugin/util/RangerPerfCollectorTracer.java | 26 +++++++++---
.../ranger/plugin/util/RangerPerfTracer.java | 41 ++++++++++--------
.../plugin/util/RangerPerfTracerFactory.java | 42 +++++++++++++++++--
4 files changed, 124 insertions(+), 34 deletions(-)
diff --git
a/agents-common/src/main/java/org/apache/ranger/plugin/util/PerfDataRecorder.java
b/agents-common/src/main/java/org/apache/ranger/plugin/util/PerfDataRecorder.java
index 7e2c46fde..dce60b0ba 100644
---
a/agents-common/src/main/java/org/apache/ranger/plugin/util/PerfDataRecorder.java
+++
b/agents-common/src/main/java/org/apache/ranger/plugin/util/PerfDataRecorder.java
@@ -65,9 +65,9 @@ public class PerfDataRecorder {
}
}
- public static void recordStatistic(String tag, long elapsedTime) {
+ public static void recordStatistic(String tag, long cpuTime, long
elapsedTime) {
if (instance != null) {
- instance.record(tag, elapsedTime);
+ instance.record(tag, cpuTime, elapsedTime);
}
}
@@ -79,14 +79,23 @@ public class PerfDataRecorder {
for (String tag : tags) {
PerfStatistic perfStatistic = perfStatistics.get(tag);
+ long averageTimeSpentCpu = 0L;
long averageTimeSpent = 0L;
+ if (perfStatistic.numberOfInvocations.get() != 0L) {
+ averageTimeSpentCpu =
perfStatistic.microSecondsSpentCpu.get()/perfStatistic.numberOfInvocations.get();
+ }
+
if (perfStatistic.numberOfInvocations.get() != 0L) {
averageTimeSpent =
perfStatistic.microSecondsSpent.get()/perfStatistic.numberOfInvocations.get();
}
String logMsg = "[" + tag + "]" +
" execCount: " +
perfStatistic.numberOfInvocations.get() +
+ ", totalTimeTakenCpu: " +
perfStatistic.microSecondsSpentCpu.get() + " μs" +
+ ", maxTimeTakenCpu: " +
perfStatistic.maxTimeSpentCpu.get() + " μs" +
+ ", minTimeTakenCpu: " +
perfStatistic.minTimeSpentCpu.get() + " μs" +
+ ", avgTimeTakenCpu: " +
averageTimeSpentCpu + " μs" +
", totalTimeTaken: " +
perfStatistic.microSecondsSpent.get() + " μs" +
", maxTimeTaken: " +
perfStatistic.maxTimeSpent.get() + " μs" +
", minTimeTaken: " +
perfStatistic.minTimeSpent.get() + " μs" +
@@ -101,7 +110,7 @@ public class PerfDataRecorder {
perfStatistics.clear();
}
- private void record(String tag, long elapsedTime) {
+ private void record(String tag, long cpuTime, long elapsedTime) {
PerfStatistic perfStatistic = perfStatistics.get(tag);
if (perfStatistic == null) {
@@ -115,7 +124,7 @@ public class PerfDataRecorder {
}
}
- perfStatistic.addPerfDataItem(elapsedTime);
+ perfStatistic.addPerfDataItem(cpuTime, elapsedTime);
}
private PerfDataRecorder(List<String> names) {
@@ -136,20 +145,34 @@ public class PerfDataRecorder {
public static class PerfStatistic {
private AtomicLong numberOfInvocations = new AtomicLong(0L);
+
+ private AtomicLong microSecondsSpentCpu = new AtomicLong(0L);
+ private AtomicLong minTimeSpentCpu = new
AtomicLong(Long.MAX_VALUE);
+ private AtomicLong maxTimeSpentCpu = new
AtomicLong(Long.MIN_VALUE);
+
private AtomicLong microSecondsSpent = new AtomicLong(0L);
private AtomicLong minTimeSpent = new
AtomicLong(Long.MAX_VALUE);
private AtomicLong maxTimeSpent = new
AtomicLong(Long.MIN_VALUE);
- void addPerfDataItem(final long timeTaken) {
+ void addPerfDataItem(final long cpuTime, final long timeTaken) {
numberOfInvocations.getAndIncrement();
+ microSecondsSpentCpu.getAndAdd(cpuTime);
microSecondsSpent.getAndAdd(timeTaken);
- long min = minTimeSpent.get();
+ long min = minTimeSpentCpu.get();
+ if(cpuTime < min) {
+ minTimeSpentCpu.compareAndSet(min, cpuTime);
+ }
+ min = minTimeSpent.get();
if(timeTaken < min) {
minTimeSpent.compareAndSet(min, timeTaken);
}
- long max = maxTimeSpent.get();
+ long max = maxTimeSpentCpu.get();
+ if(cpuTime > max) {
+ maxTimeSpentCpu.compareAndSet(max, cpuTime);
+ }
+ max = maxTimeSpent.get();
if(timeTaken > max) {
maxTimeSpent.compareAndSet(max, timeTaken);
}
@@ -159,6 +182,18 @@ public class PerfDataRecorder {
return numberOfInvocations.get();
}
+ public long getMicroSecondsSpentCpu() {
+ return microSecondsSpentCpu.get();
+ }
+
+ public long getMinTimeSpentCpu() {
+ return minTimeSpentCpu.get();
+ }
+
+ public long getMaxTimeSpentCpu() {
+ return maxTimeSpentCpu.get();
+ }
+
public long getMicroSecondsSpent() {
return microSecondsSpent.get();
}
diff --git
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfCollectorTracer.java
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfCollectorTracer.java
index 6e95a56ff..ebfebdae8 100644
---
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfCollectorTracer.java
+++
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfCollectorTracer.java
@@ -21,17 +21,31 @@ package org.apache.ranger.plugin.util;
import org.slf4j.Logger;
+import java.lang.management.ThreadInfo;
+
public class RangerPerfCollectorTracer extends RangerPerfTracer {
- private final long startTimeNanos;
- public RangerPerfCollectorTracer(Logger logger, String tag, String
data) {
- super(logger, tag, data);
- startTimeNanos = System.nanoTime();
+ public RangerPerfCollectorTracer(Logger logger, String tag, String
data, ThreadInfo threadInfo) {
+ super(logger, tag, data, threadInfo);
}
@Override
public void log() {
- // Collect elapsed time in microseconds
- PerfDataRecorder.recordStatistic(tag, ((System.nanoTime() -
startTimeNanos) + 500) / 1000);
+ // Uncomment following line if the perf log for each individual
call details to this needs to be logged in the perf log
+ //super.log();
+ long elapsedTime = Math.max(getElapsedUserTime(),
getElapsedCpuTime());
+ long reportingThreshold = threadInfo == null ? 0L :
(1000000/1000 - 1); // just about a microsecond
+
+ if (elapsedTime > reportingThreshold) {
+ logger.debug("[PERF]:" + (threadInfo != null ?
threadInfo.getThreadName() : "") + ":" + tag + data + ":" + getElapsedCpuTime()
+ ":" + getElapsedUserTime());
+ }
}
+
+ @Override
+ public void logAlways() {
+ // Uncomment following line if the perf log for each individual
call details to this needs to be logged in the perf log
+ //super.logAlways();
+
+ // Collect elapsed time in microseconds
+ PerfDataRecorder.recordStatistic(tag,
(getElapsedCpuTime()+500)/1000, (getElapsedUserTime() + 500)/1000); }
}
diff --git
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
index 3c985c62c..c8804739f 100644
---
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
+++
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java
@@ -23,13 +23,15 @@ import org.apache.commons.lang.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import java.lang.management.ThreadInfo;
+
public class RangerPerfTracer {
protected final Logger logger;
protected final String tag;
protected final String data;
- private final long startTimeMs;
-
- private static long reportingThresholdMs;
+ protected final ThreadInfo threadInfo;
+ protected final long startTime;
+ protected final long userStartTime;
private final static String tagEndMarker = "(";
@@ -76,33 +78,36 @@ public class RangerPerfTracer {
tracer.logAlways();
}
}
- public RangerPerfTracer(Logger logger, String tag, String data) {
+ public RangerPerfTracer(Logger logger, String tag, String data,
ThreadInfo threadInfo) {
this.logger = logger;
this.tag = tag;
this.data = data;
- startTimeMs = System.currentTimeMillis();
- }
+ this.threadInfo = threadInfo;
- public final String getTag() {
- return tag;
+ startTime = threadInfo == null ? System.nanoTime() :
RangerPerfTracerFactory.threadMgmtBean.getThreadCpuTime(threadInfo.getThreadId());
+ userStartTime = System.nanoTime();
}
- public final long getStartTime() {
- return startTimeMs;
+ public final long getElapsedUserTime() {
+ return System.nanoTime() - userStartTime;
}
-
- public final long getElapsedTime() {
- return System.currentTimeMillis() - startTimeMs;
+ public final long getElapsedCpuTime() {
+ if (threadInfo == null) {
+ return getElapsedUserTime();
+ } else {
+ return
RangerPerfTracerFactory.threadMgmtBean.getThreadCpuTime(threadInfo.getThreadId())
- startTime;
+ }
}
public void log() {
- long elapsedTime = getElapsedTime();
- if (elapsedTime > reportingThresholdMs) {
- logger.debug("[PERF] " + tag + data + ": " +
elapsedTime);
+ long elapsedTime = Math.max(getElapsedUserTime(),
getElapsedCpuTime());
+ long reportingThreshold = threadInfo == null ? 0L :
(1000000/1000 - 1); // just about a microsecond
+
+ if (elapsedTime > reportingThreshold) {
+ logger.debug("[PERF]:" + (threadInfo != null ?
threadInfo.getThreadName() : "") + ":" + tag + data + ":" + getElapsedCpuTime()
+ ":" + getElapsedUserTime());
}
}
public void logAlways() {
- long elapsedTime = getElapsedTime();
- logger.debug("[PERF] " + tag + data + ": " + elapsedTime);
+ logger.debug("[PERF]:" + (threadInfo != null ?
threadInfo.getThreadName() : "") + ":" + tag + data + ":" + getElapsedCpuTime()
+ ":" + getElapsedUserTime());
}
}
diff --git
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracerFactory.java
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracerFactory.java
index 1a4e86dce..c42d631c0 100644
---
a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracerFactory.java
+++
b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracerFactory.java
@@ -21,16 +21,52 @@ package org.apache.ranger.plugin.util;
import org.slf4j.Logger;
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadInfo;
+import java.lang.management.ThreadMXBean;
+
public class RangerPerfTracerFactory {
+ static volatile ThreadMXBean threadMgmtBean = null;
+ private static boolean isThreadCPUTimeSupported = false;
+ private static boolean isThreadCPUTimeEnabled = false;
+
static RangerPerfTracer getPerfTracer(Logger logger, String tag, String
data) {
RangerPerfTracer ret = null;
+ if (logger.isDebugEnabled()) {
+ if (threadMgmtBean == null) {
+ synchronized (RangerPerfTracerFactory.class) {
+ if (threadMgmtBean == null) {
+ threadMgmtBean =
ManagementFactory.getThreadMXBean();
+ isThreadCPUTimeSupported =
threadMgmtBean.isThreadCpuTimeSupported();
+
logger.info("ThreadCPUTimeSupported (by JVM) = " + isThreadCPUTimeSupported);
+
+ isThreadCPUTimeEnabled =
threadMgmtBean.isThreadCpuTimeEnabled();
+
logger.info("ThreadCPUTimeEnabled = " + isThreadCPUTimeEnabled);
+
+ if (isThreadCPUTimeSupported) {
+ if
(!isThreadCPUTimeEnabled) {
+
threadMgmtBean.setThreadCpuTimeEnabled(true);
+
isThreadCPUTimeEnabled = threadMgmtBean.isThreadCpuTimeEnabled();
+ }
+
logger.info("ThreadCPUTimeEnabled = " + isThreadCPUTimeEnabled);
+ }
+ }
+ }
+ }
+ }
+
+ ThreadInfo threadInfo = null;
+ if (isThreadCPUTimeSupported && isThreadCPUTimeEnabled) {
+ threadInfo =
threadMgmtBean.getThreadInfo(Thread.currentThread().getId());
+ }
+
if (PerfDataRecorder.collectStatistics()) {
- ret = new RangerPerfCollectorTracer(logger, tag, data);
- } else if (logger.isDebugEnabled()) {
- ret = new RangerPerfTracer(logger, tag, data);
+ ret = new RangerPerfCollectorTracer(logger, tag, data,
threadInfo);
+ } else {
+ ret = new RangerPerfTracer(logger, tag, data,
threadInfo);
}
return ret;
}
