From 5c5e4291414231f535adc4010c3999f77fd55bbc Mon Sep 17 00:00:00 2001 From: TheOtherP Date: Sun, 22 Jan 2023 12:14:09 +0100 Subject: [PATCH] Delay performance logging because metrics endpoint is empty immediately after startup --- compileCore.cmd | 12 ++ .../main/java/org/nzbhydra/NativeHints.java | 1 + .../debuginfos/DebugInfosProvider.java | 128 ++++++++++-------- core/src/main/resources/changelog.yaml | 18 ++- 4 files changed, 93 insertions(+), 66 deletions(-) create mode 100644 compileCore.cmd diff --git a/compileCore.cmd b/compileCore.cmd new file mode 100644 index 000000000..c971ecae2 --- /dev/null +++ b/compileCore.cmd @@ -0,0 +1,12 @@ +@echo off + +setlocal + +call "C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build\vcvarsall.bat" x64 + +set path=c:\Programme\graalvm-ce-java17-22.2.0\bin\;%PATH%;c:\Programme\graalvm-ce-java17-22.2.0\bin\ +set java_home=c:\Programme\graalvm-ce-java17-22.2.0\ +set HYDRA_NATIVE_BUILD=true +call mvn -pl org.nzbhydra:core -Pnative clean compile package -DskipTests + +endlocal diff --git a/core/src/main/java/org/nzbhydra/NativeHints.java b/core/src/main/java/org/nzbhydra/NativeHints.java index eaf9c150d..1ca81d252 100644 --- a/core/src/main/java/org/nzbhydra/NativeHints.java +++ b/core/src/main/java/org/nzbhydra/NativeHints.java @@ -76,6 +76,7 @@ public class NativeHints implements RuntimeHintsRegistrar { } try { hints.reflection().registerMethod(MetricsEndpoint.class.getMethod("metric", String.class, List.class), ExecutableMode.INVOKE); + hints.reflection().registerMethod(MetricsEndpoint.MetricDescriptor.class.getMethod("getMeasurements"), ExecutableMode.INVOKE); hints.reflection().registerMethod(ThreadDumpEndpoint.class.getMethod("textThreadDump"), ExecutableMode.INVOKE); } catch (NoSuchMethodException e) { throw new RuntimeException(e); diff --git a/core/src/main/java/org/nzbhydra/debuginfos/DebugInfosProvider.java b/core/src/main/java/org/nzbhydra/debuginfos/DebugInfosProvider.java index 825eb9b21..bd950774b 100644 --- a/core/src/main/java/org/nzbhydra/debuginfos/DebugInfosProvider.java +++ b/core/src/main/java/org/nzbhydra/debuginfos/DebugInfosProvider.java @@ -48,6 +48,7 @@ import java.nio.file.Files; import java.text.DecimalFormat; import java.time.Instant; import java.util.ArrayList; +import java.util.Collections; import java.util.HashMap; import java.util.List; import java.util.Map; @@ -99,79 +100,86 @@ public class DebugInfosProvider { private final List timeAndThreadCpuUsagesList = new ArrayList<>(); private final Map lastThreadCpuTimes = new HashMap<>(); + @PostConstruct public void logMetrics() { try { if (!configProvider.getBaseConfig().getMain().getLogging().getMarkersToLog().contains(LoggingMarkers.PERFORMANCE.getName())) { return; } - logger.debug(LoggingMarkers.PERFORMANCE, "Will log performance metrics every {} seconds", LOG_METRICS_EVERY_SECONDS); - ScheduledExecutorService executor = Executors.newScheduledThreadPool(1); - executor.scheduleAtFixedRate(() -> { - try { - final String cpuMetric = "process.cpu.usage"; - String message = "Process CPU usage: " + formatSample(cpuMetric, metricsEndpoint.metric(cpuMetric, null).getMeasurements().get(0).getValue()); - logger.debug(LoggingMarkers.PERFORMANCE, message); - } catch (Exception e) { - logger.debug(LoggingMarkers.PERFORMANCE, "Error while logging CPU usage", e); - } - try { - final String memoryMetric = "jvm.memory.used"; - String message = "Process memory usage: " + formatSample(memoryMetric, metricsEndpoint.metric(memoryMetric, null).getMeasurements().get(0).getValue()); - logger.debug(LoggingMarkers.PERFORMANCE, message); - } catch (Exception e) { - logger.debug(LoggingMarkers.PERFORMANCE, "Error while logging memory usage", e); - } - ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean(); - final ThreadInfo[] threadInfos = threadMxBean.dumpAllThreads(true, true); - - }, 0, LOG_METRICS_EVERY_SECONDS, TimeUnit.SECONDS); - - int cpuCount = metricsEndpoint.metric("system.cpu.count", null).getMeasurements().get(0).getValue().intValue(); - ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean(); - final double[] previousUptime = {getUpTimeInMiliseconds()}; - ScheduledExecutorService executor2 = Executors.newScheduledThreadPool(1); - - executor2.scheduleAtFixedRate(new Runnable() { - @Override - public void run() { - final double upTime = getUpTimeInMiliseconds(); - double elapsedTime = upTime - previousUptime[0]; + final ScheduledExecutorService scheduledExecutorService = Executors.newSingleThreadScheduledExecutor(); + //The metrics endpoint is not available immediately after startup + scheduledExecutorService.schedule(() -> { + logger.debug(LoggingMarkers.PERFORMANCE, "Will log performance metrics every {} seconds", LOG_METRICS_EVERY_SECONDS); + ScheduledExecutorService executor = Executors.newScheduledThreadPool(1); + executor.scheduleAtFixedRate(() -> { + try { + final String cpuMetric = "process.cpu.usage"; + String message = "Process CPU usage: " + formatSample(cpuMetric, metricsEndpoint.metric(cpuMetric, Collections.emptyList()).getMeasurements().get(0).getValue()); + logger.debug(LoggingMarkers.PERFORMANCE, message); + } catch (Exception e) { + logger.debug(LoggingMarkers.PERFORMANCE, "Error while logging CPU usage", e); + } + try { + final String memoryMetric = "jvm.memory.used"; + String message = "Process memory usage: " + formatSample(memoryMetric, metricsEndpoint.metric(memoryMetric, null).getMeasurements().get(0).getValue()); + logger.debug(LoggingMarkers.PERFORMANCE, message); + } catch (Exception e) { + logger.debug(LoggingMarkers.PERFORMANCE, "Error while logging memory usage", e); + } + ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean(); final ThreadInfo[] threadInfos = threadMxBean.dumpAllThreads(true, true); - TimeAndThreadCpuUsages timeAndThreadCpuUsages = new TimeAndThreadCpuUsages(Instant.now()); - for (ThreadInfo threadInfo : threadInfos) { - final String threadName = threadInfo.getThreadName(); - final long threadCpuTime = threadMxBean.getThreadCpuTime(threadInfo.getThreadId()); - if (!lastThreadCpuTimes.containsKey(threadName)) { + + }, 0, LOG_METRICS_EVERY_SECONDS, TimeUnit.SECONDS); + + int cpuCount = metricsEndpoint.metric("system.cpu.count", null).getMeasurements().get(0).getValue().intValue(); + ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean(); + final double[] previousUptime = {getUpTimeInMiliseconds()}; + ScheduledExecutorService executor2 = Executors.newScheduledThreadPool(1); + + executor2.scheduleAtFixedRate(new Runnable() { + @Override + public void run() { + final double upTime = getUpTimeInMiliseconds(); + double elapsedTime = upTime - previousUptime[0]; + + final ThreadInfo[] threadInfos = threadMxBean.dumpAllThreads(true, true); + TimeAndThreadCpuUsages timeAndThreadCpuUsages = new TimeAndThreadCpuUsages(Instant.now()); + for (ThreadInfo threadInfo : threadInfos) { + final String threadName = threadInfo.getThreadName(); + final long threadCpuTime = threadMxBean.getThreadCpuTime(threadInfo.getThreadId()); + if (!lastThreadCpuTimes.containsKey(threadName)) { + lastThreadCpuTimes.put(threadName, threadCpuTime); + continue; + } + final Long lastThreadCpuTime = lastThreadCpuTimes.get(threadName); + long elapsedThreadCpuTime = threadCpuTime - lastThreadCpuTime; + if (elapsedThreadCpuTime < 0) { + //Not sure why but this happens with some threads + continue; + } + float cpuUsage = Math.min(99F, elapsedThreadCpuTime / (float) (elapsedTime * 1000 * cpuCount)); + if (cpuUsage < 0) { + cpuUsage = 0; + } + if (cpuUsage > 5F) { + logger.debug(LoggingMarkers.PERFORMANCE, "CPU usage of thread {}: {}", threadName, cpuUsage); + } + timeAndThreadCpuUsages.getThreadCpuUsages().add(new ThreadCpuUsage(threadName, (long) cpuUsage)); + lastThreadCpuTimes.put(threadName, threadCpuTime); - continue; } - final Long lastThreadCpuTime = lastThreadCpuTimes.get(threadName); - long elapsedThreadCpuTime = threadCpuTime - lastThreadCpuTime; - if (elapsedThreadCpuTime < 0) { - //Not sure why but this happens with some threads - continue; + timeAndThreadCpuUsagesList.add(timeAndThreadCpuUsages); + previousUptime[0] = upTime; + if (timeAndThreadCpuUsagesList.size() == 50) { + timeAndThreadCpuUsagesList.remove(0); } - float cpuUsage = Math.min(99F, elapsedThreadCpuTime / (float) (elapsedTime * 1000 * cpuCount)); - if (cpuUsage < 0) { - cpuUsage = 0; - } - if (cpuUsage > 5F) { - logger.debug(LoggingMarkers.PERFORMANCE, "CPU usage of thread {}: {}", threadName, cpuUsage); - } - timeAndThreadCpuUsages.getThreadCpuUsages().add(new ThreadCpuUsage(threadName, (long) cpuUsage)); - - lastThreadCpuTimes.put(threadName, threadCpuTime); } - timeAndThreadCpuUsagesList.add(timeAndThreadCpuUsages); - previousUptime[0] = upTime; - if (timeAndThreadCpuUsagesList.size() == 50) { - timeAndThreadCpuUsagesList.remove(0); - } - } - }, 0, LOG_METRICS_EVERY_SECONDS, TimeUnit.SECONDS); + }, 0, LOG_METRICS_EVERY_SECONDS, TimeUnit.SECONDS); + }, 5, TimeUnit.SECONDS); + } catch (Exception e) { logger.error("Error initializing performance metrics reading", e); } diff --git a/core/src/main/resources/changelog.yaml b/core/src/main/resources/changelog.yaml index 1e6aa5016..391663841 100644 --- a/core/src/main/resources/changelog.yaml +++ b/core/src/main/resources/changelog.yaml @@ -1,12 +1,18 @@ --- -- version: "v5.0.7" - date: "2023-01-22" - changes: - - type: "fix" - text: "Alright, so the binary fix from 5.0.6 didn't fix anything but made it worse.\ +- version: "v5.0.8" + date: "2023-01-22" + changes: + - type: "fix" + text: "Fixed performance logging. In 5.0.6 I disabled it, now it actually works." + final: true +- version: "v5.0.7" + date: "2023-01-22" + changes: + - type: "fix" + text: "Alright, so the binary fix from 5.0.6 didn't fix anything but made it worse.\ \ But now I've found a way to make the binary run for everybody (I hope, who\ \ knows by know)." - final: true + final: true - version: "v5.0.6" date: "2023-01-21" changes: