artin/nzbhydra2
1
0
Fork 0
mirror of https://github.com/theotherp/nzbhydra2.git synced 2026-02-06 11:17:18 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Delay performance logging because metrics endpoint is empty immediately after startup

Browse Source
This commit is contained in:
TheOtherP 2023-01-22 12:14:09 +01:00
parent 98979a5bf5
commit 5c5e429141
4 changed files with 93 additions and 66 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
compileCore.cmd Normal file
View File

@ -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

1
core/src/main/java/org/nzbhydra/NativeHints.java
View File

@ -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);

128
core/src/main/java/org/nzbhydra/debuginfos/DebugInfosProvider.java
View File

@ -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<TimeAndThreadCpuUsages> timeAndThreadCpuUsagesList = new ArrayList<>();
private final Map<String, Long> 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);
}

18
core/src/main/resources/changelog.yaml
View File

@ -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: