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; }