From ac89c3e8e25f37c806e626d16c0a22c5dc8f31ad Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 06:22:19 -0500 Subject: [PATCH 1/6] formatting --- .../planetiler/stats/ProcessInfo.java | 36 ++++++++--- .../planetiler/stats/ProcessTime.java | 4 +- .../planetiler/stats/PrometheusStats.java | 2 +- .../onthegomap/planetiler/stats/Timers.java | 63 +++++++++++++++++-- .../onthegomap/planetiler/util/Format.java | 12 ++++ .../onthegomap/planetiler/worker/Worker.java | 1 + .../planetiler/stats/PrometheusStatsTest.java | 2 +- .../planetiler/stats/TimersTest.java | 4 +- .../planetiler/util/FormatTest.java | 20 ++++++ 9 files changed, 124 insertions(+), 20 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java index b54c849f75..947b4f95c9 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java @@ -109,9 +109,29 @@ public record ThreadState( String name, Duration cpuTime, Duration userTime, Duration waiting, Duration blocking, long id ) { + public ThreadState(ThreadMXBean threadMXBean, ThreadInfo thread) { + this( + thread.getThreadName(), + Duration.ofNanos(threadMXBean.getThreadCpuTime(thread.getThreadId())), + Duration.ofNanos(threadMXBean.getThreadUserTime(thread.getThreadId())), + Duration.ofMillis(thread.getWaitedTime()), + Duration.ofMillis(thread.getBlockedTime()), + thread.getThreadId()); + } + public static final ThreadState DEFAULT = new ThreadState("", Duration.ZERO, Duration.ZERO, Duration.ZERO, Duration.ZERO, -1); + /** Adds up the timers in two {@code ThreadState} instances */ + public static ThreadState sum(ThreadState a, ThreadState b) { + return new ThreadState("", + a.cpuTime.plus(b.cpuTime), + a.userTime.plus(b.userTime), + a.waiting.plus(b.waiting), + a.blocking.plus(b.blocking), + -1 + ); + } } /** Returns the amount of time this JVM has spent in any kind of garbage collection since startup. */ @@ -143,16 +163,14 @@ public static Map getThreadStats() { Map threadState = new TreeMap<>(); ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); for (ThreadInfo thread : threadMXBean.dumpAllThreads(false, false)) { - threadState.put(thread.getThreadId(), - new ThreadState( - thread.getThreadName(), - Duration.ofNanos(threadMXBean.getThreadCpuTime(thread.getThreadId())), - Duration.ofNanos(threadMXBean.getThreadUserTime(thread.getThreadId())), - Duration.ofMillis(thread.getWaitedTime()), - Duration.ofMillis(thread.getBlockedTime()), - thread.getThreadId() - )); + threadState.put(thread.getThreadId(), new ThreadState(threadMXBean, thread)); } return threadState; } + + public static ThreadState getCurrentThreadStats() { + ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); + ThreadInfo thread = threadMXBean.getThreadInfo(Thread.currentThread().getId()); + return new ThreadState(threadMXBean, thread); + } } diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java index 4b046b9239..3211454d57 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java @@ -30,10 +30,10 @@ ProcessTime minus(ProcessTime other) { public String toString(Locale locale) { Format format = Format.forLocale(locale); - Optional deltaCpu = cpu.map(format::seconds); + Optional deltaCpu = cpu.map(format::duration); String avgCpus = cpu.map(cpuTime -> " avg:" + format.decimal(cpuTime.toNanos() * 1d / wall.toNanos())) .orElse(""); - return format.seconds(wall) + " cpu:" + deltaCpu.orElse("-") + avgCpus; + return format.duration(wall) + " cpu:" + deltaCpu.orElse("-") + avgCpus; } @Override diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/PrometheusStats.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/PrometheusStats.java index 1c38d3a1ef..776b37126d 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/PrometheusStats.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/PrometheusStats.java @@ -220,7 +220,7 @@ public List collect() { List result = new ArrayList<>(); for (var entry : timers.all().entrySet()) { String name = entry.getKey(); - Timer timer = entry.getValue(); + Timer timer = entry.getValue().timer(); result.add(gaugeMetric(name + "_running", timer.running() ? 1 : 0)); ProcessTime time = timer.elapsed(); result.add(gaugeMetric(name + "_elapsed_time_seconds", time.wall().toNanos() / NANOSECONDS_PER_SECOND)); diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java index 8301e9785d..3cd5bc24c9 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java @@ -1,8 +1,13 @@ package com.onthegomap.planetiler.stats; +import com.onthegomap.planetiler.util.Format; +import java.time.Duration; import java.util.Collections; import java.util.LinkedHashMap; +import java.util.List; import java.util.Map; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.atomic.AtomicReference; import javax.annotation.concurrent.ThreadSafe; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -13,24 +18,72 @@ @ThreadSafe public class Timers { + record ThreadInfo(ProcessInfo.ThreadState state, String prefix) {} + + record Stage(Timer timer, List threadStats) { + + Stage(Timer timer) { + this(timer, new CopyOnWriteArrayList<>()); + } + } + private static final Logger LOGGER = LoggerFactory.getLogger(Stats.InMemory.class); - private final Map timers = Collections.synchronizedMap(new LinkedHashMap<>()); + private static final Format FORMAT = Format.defaultInstance(); + private final Map timers = Collections.synchronizedMap(new LinkedHashMap<>()); + private final AtomicReference currentStage = new AtomicReference<>(); public void printSummary() { for (var entry : all().entrySet()) { - LOGGER.info("\t" + entry.getKey() + "\t" + entry.getValue().elapsed()); + String name = entry.getKey(); + var elapsed = entry.getValue().timer.elapsed(); + LOGGER.info("\t" + name + "\t" + elapsed); + printStageDetails(name, "\t "); + } + } + + private void printStageDetails(String name, String prefix) { + Stage stage = timers.get(name); + var elapsed = stage.timer.elapsed(); + List threads = stage.threadStats.stream().map(d -> d.prefix).distinct().toList(); + for (String thread : threads) { + List threadStates = stage.threadStats.stream().filter(t -> t.prefix.equals(thread)) + .map(t -> t.state).toList(); + ProcessInfo.ThreadState sum = threadStates.stream().reduce(ProcessInfo.ThreadState.DEFAULT, + ProcessInfo.ThreadState::sum); + double totalNanos = elapsed.wall().multipliedBy(threadStates.size()).toNanos(); + + LOGGER.debug(prefix + thread.replace(name + "_", "") + " x" + threadStates.size() + "\t" + + FORMAT.duration(sum.cpuTime()) + + " (" + FORMAT.percent(sum.cpuTime().toNanos() / totalNanos) + ")" + + (sum.blocking().compareTo(Duration.ofSeconds(1)) > 0 ? " blocked:" + FORMAT.duration(sum.blocking()) : "") + + (sum.waiting().compareTo(Duration.ofSeconds(1)) > 0 ? " waiting:" + FORMAT.duration(sum.waiting()) : "") + ); } } public Finishable startTimer(String name) { Timer timer = Timer.start(); - timers.put(name, timer); + Stage stage = new Stage(timer); + timers.put(name, stage); + Stage last = currentStage.getAndSet(stage); + System.out.println(); LOGGER.info("Starting..."); - return () -> LOGGER.info("Finished in " + timers.get(name).stop() + System.lineSeparator()); + return () -> { + LOGGER.info("Finished in " + timers.get(name).timer.stop()); + printStageDetails(name, " "); + currentStage.set(last); + }; + } + + public void finishedWorker(String prefix) { + Stage stage = currentStage.get(); + if (stage != null) { + stage.threadStats.add(new ThreadInfo(ProcessInfo.getCurrentThreadStats(), prefix)); + } } /** Returns a snapshot of all timers currently running. Will not reflect timers that start after it's called. */ - public Map all() { + public Map all() { synchronized (timers) { return new LinkedHashMap<>(timers); } diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/util/Format.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/util/Format.java index 739f97793d..de10985a90 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/util/Format.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/util/Format.java @@ -126,6 +126,18 @@ public String seconds(Duration duration) { return decimal(seconds < 1 ? seconds : Math.round(seconds)) + "s"; } + /** Returns a duration formatted like "1h2m" or "2m3s". */ + public String duration(Duration duration) { + Duration simplified; + double seconds = duration.toNanos() * 1d / Duration.ofSeconds(1).toNanos(); + if (seconds < 1) { + return decimal(seconds) + "s"; + } else { + simplified = Duration.ofSeconds(Math.round(seconds)); + } + return simplified.toString().replace("PT", "").toLowerCase(Locale.ROOT); + } + /** Returns Java code that can re-create {@code string}: {@code null} if null, or {@code "contents"} if not empty. */ public static String quote(String string) { if (string == null) { diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java index be7cca8e1e..3c500a7668 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java @@ -47,6 +47,7 @@ public Worker(String prefix, Stats stats, int threads, RunnableThatThrows task) LOGGER.trace("Starting worker"); try { task.run(); + stats.timers().finishedWorker(prefix); } catch (Throwable e) { System.err.println("Worker " + id + " died"); throwRuntimeException(e); diff --git a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/PrometheusStatsTest.java b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/PrometheusStatsTest.java index eb4f6f20a0..5fcb5b8e7c 100644 --- a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/PrometheusStatsTest.java +++ b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/PrometheusStatsTest.java @@ -44,7 +44,7 @@ public void testTimer() { assertContainsStat("^planetiler_task1_elapsed_time_seconds [0-9\\.]+$", stats); assertContainsStat("^planetiler_task1_cpu_time_seconds [0-9\\.]+$", stats); - assertFalse(stats.timers().all().get("task1").running()); + assertFalse(stats.timers().all().get("task1").timer().running()); } @Test diff --git a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/TimersTest.java b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/TimersTest.java index ccf5056c97..a12c8ba385 100644 --- a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/TimersTest.java +++ b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/TimersTest.java @@ -14,9 +14,9 @@ public void testTimers() { timers.printSummary(); var finish = timers.startTimer("task2"); - assertTrue(timers.all().get("task2").running()); + assertTrue(timers.all().get("task2").timer().running()); finish.stop(); - assertFalse(timers.all().get("task2").running()); + assertFalse(timers.all().get("task2").timer().running()); timers.printSummary(); } diff --git a/planetiler-core/src/test/java/com/onthegomap/planetiler/util/FormatTest.java b/planetiler-core/src/test/java/com/onthegomap/planetiler/util/FormatTest.java index a7ab830e5f..e03eb6bc89 100644 --- a/planetiler-core/src/test/java/com/onthegomap/planetiler/util/FormatTest.java +++ b/planetiler-core/src/test/java/com/onthegomap/planetiler/util/FormatTest.java @@ -1,7 +1,9 @@ package com.onthegomap.planetiler.util; +import static io.prometheus.client.Collector.NANOSECONDS_PER_SECOND; import static org.junit.jupiter.api.Assertions.assertEquals; +import java.time.Duration; import java.util.Locale; import org.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.CsvSource; @@ -73,4 +75,22 @@ public void testPad(String in, Integer size, String out) { public void testFormatDecimal(Double in, String out, Locale locale) { assertEquals(out, Format.forLocale(locale).decimal(in)); } + + @ParameterizedTest + @CsvSource({ + "0,0s,en", + "0.1,0.1s,en", + "0.1,'0,1s',it", + "0.999,1s,en", + "1.1,1s,en", + "59,59s,en", + "60,1m,en", + "61.1,1m1s,en", + "3599,59m59s,en", + "3600,1h,en", + "3601,1h1s,en", + }) + public void testFormatDuration(double seconds, String out, Locale locale) { + assertEquals(out, Format.forLocale(locale).duration(Duration.ofNanos((long) (seconds * NANOSECONDS_PER_SECOND)))); + } } From e95480adf55b6d5f728a7f2414d7160c6512a7f0 Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 06:52:59 -0500 Subject: [PATCH 2/6] log thread details --- .../onthegomap/planetiler/stats/Timers.java | 42 ++++++++++++++----- 1 file changed, 32 insertions(+), 10 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java index 3cd5bc24c9..20a1eaeb34 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java @@ -2,6 +2,7 @@ import com.onthegomap.planetiler.util.Format; import java.time.Duration; +import java.util.ArrayList; import java.util.Collections; import java.util.LinkedHashMap; import java.util.List; @@ -37,28 +38,49 @@ public void printSummary() { String name = entry.getKey(); var elapsed = entry.getValue().timer.elapsed(); LOGGER.info("\t" + name + "\t" + elapsed); - printStageDetails(name, "\t "); + for (String detail : getStageDetails(name)) { + LOGGER.info("\t " + detail); + } } } - private void printStageDetails(String name, String prefix) { + private List getStageDetails(String name) { + List resultList = new ArrayList<>(); Stage stage = timers.get(name); var elapsed = stage.timer.elapsed(); List threads = stage.threadStats.stream().map(d -> d.prefix).distinct().toList(); for (String thread : threads) { + StringBuilder result = new StringBuilder(); List threadStates = stage.threadStats.stream().filter(t -> t.prefix.equals(thread)) .map(t -> t.state).toList(); + int num = threadStates.size(); ProcessInfo.ThreadState sum = threadStates.stream().reduce(ProcessInfo.ThreadState.DEFAULT, ProcessInfo.ThreadState::sum); - double totalNanos = elapsed.wall().multipliedBy(threadStates.size()).toNanos(); + double totalNanos = elapsed.wall().multipliedBy(num).toNanos(); + result.append(thread.replace(name + "_", "")) + .append("(") + .append(num) + .append("x") + .append(FORMAT.percent(sum.cpuTime().toNanos() / totalNanos)) + .append(" cpu:") + .append(FORMAT.duration(sum.cpuTime().dividedBy(num))); - LOGGER.debug(prefix + thread.replace(name + "_", "") + " x" + threadStates.size() + "\t" + - FORMAT.duration(sum.cpuTime()) + - " (" + FORMAT.percent(sum.cpuTime().toNanos() / totalNanos) + ")" + - (sum.blocking().compareTo(Duration.ofSeconds(1)) > 0 ? " blocked:" + FORMAT.duration(sum.blocking()) : "") + - (sum.waiting().compareTo(Duration.ofSeconds(1)) > 0 ? " waiting:" + FORMAT.duration(sum.waiting()) : "") - ); + Duration systemTime = sum.cpuTime().minus(sum.userTime()).dividedBy(num); + if (systemTime.compareTo(Duration.ofSeconds(1)) > 0) { + result.append(" sys:").append(FORMAT.duration(systemTime)); + } + Duration blockTime = sum.blocking().dividedBy(num); + if (blockTime.compareTo(Duration.ofSeconds(1)) > 0) { + result.append(" block:").append(FORMAT.duration(blockTime)); + } + Duration waitTime = sum.waiting().dividedBy(num); + if (waitTime.compareTo(Duration.ofSeconds(1)) > 0) { + result.append(" wait:").append(FORMAT.duration(waitTime)); + } + result.append(")"); + resultList.add(result.toString()); } + return resultList; } public Finishable startTimer(String name) { @@ -70,7 +92,7 @@ public Finishable startTimer(String name) { LOGGER.info("Starting..."); return () -> { LOGGER.info("Finished in " + timers.get(name).timer.stop()); - printStageDetails(name, " "); + LOGGER.info(" " + String.join(" -> ", getStageDetails(name))); currentStage.set(last); }; } From 84bcfc6f362f66afaac4c2354ee380e576c8a408 Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 06:56:47 -0500 Subject: [PATCH 3/6] handle unsupported --- .../planetiler/stats/ProcessInfo.java | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java index 947b4f95c9..447f24d8fd 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java @@ -15,6 +15,7 @@ import java.util.OptionalLong; import java.util.TreeMap; import java.util.concurrent.atomic.AtomicReference; +import java.util.function.LongSupplier; import java.util.stream.Collectors; import javax.management.NotificationEmitter; import javax.management.openmbean.CompositeData; @@ -109,13 +110,21 @@ public record ThreadState( String name, Duration cpuTime, Duration userTime, Duration waiting, Duration blocking, long id ) { + private static long zeroIfUnsupported(LongSupplier supplier) { + try { + return supplier.getAsLong(); + } catch (UnsupportedOperationException e) { + return 0; + } + } + public ThreadState(ThreadMXBean threadMXBean, ThreadInfo thread) { this( thread.getThreadName(), - Duration.ofNanos(threadMXBean.getThreadCpuTime(thread.getThreadId())), - Duration.ofNanos(threadMXBean.getThreadUserTime(thread.getThreadId())), - Duration.ofMillis(thread.getWaitedTime()), - Duration.ofMillis(thread.getBlockedTime()), + Duration.ofNanos(zeroIfUnsupported(() -> threadMXBean.getThreadCpuTime(thread.getThreadId()))), + Duration.ofNanos(zeroIfUnsupported(() -> threadMXBean.getThreadUserTime(thread.getThreadId()))), + Duration.ofMillis(zeroIfUnsupported(thread::getWaitedTime)), + Duration.ofMillis(zeroIfUnsupported(thread::getBlockedTime)), thread.getThreadId()); } From a17290703a2233376ecf53b6163fd31076ea1fd2 Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 07:32:34 -0500 Subject: [PATCH 4/6] add gc time and thread done time --- .../planetiler/stats/ProcessInfo.java | 12 ++--- .../planetiler/stats/ProcessTime.java | 13 ++++-- .../onthegomap/planetiler/stats/Timers.java | 45 ++++++++++++------- .../onthegomap/planetiler/worker/Worker.java | 3 +- .../planetiler/stats/ProcessInfoTest.java | 15 +++++++ 5 files changed, 60 insertions(+), 28 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java index 447f24d8fd..c971825d8a 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessInfo.java @@ -132,12 +132,12 @@ public ThreadState(ThreadMXBean threadMXBean, ThreadInfo thread) { Duration.ZERO, -1); /** Adds up the timers in two {@code ThreadState} instances */ - public static ThreadState sum(ThreadState a, ThreadState b) { + public ThreadState plus(ThreadState other) { return new ThreadState("", - a.cpuTime.plus(b.cpuTime), - a.userTime.plus(b.userTime), - a.waiting.plus(b.waiting), - a.blocking.plus(b.blocking), + cpuTime.plus(other.cpuTime), + userTime.plus(other.userTime), + waiting.plus(other.waiting), + blocking.plus(other.blocking), -1 ); } @@ -177,7 +177,7 @@ public static Map getThreadStats() { return threadState; } - public static ThreadState getCurrentThreadStats() { + public static ThreadState getCurrentThreadState() { ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); ThreadInfo thread = threadMXBean.getThreadInfo(Thread.currentThread().getId()); return new ThreadState(threadMXBean, thread); diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java index 3211454d57..da37da0f1a 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/ProcessTime.java @@ -16,16 +16,21 @@ * LOGGER.log("Expensive work took " + end.minus(start)); * } */ -public record ProcessTime(Duration wall, Optional cpu) { +public record ProcessTime(Duration wall, Optional cpu, Duration gc) { /** Takes a snapshot of current wall and CPU time of this JVM. */ public static ProcessTime now() { - return new ProcessTime(Duration.ofNanos(System.nanoTime()), ProcessInfo.getProcessCpuTime()); + return new ProcessTime(Duration.ofNanos(System.nanoTime()), ProcessInfo.getProcessCpuTime(), + ProcessInfo.getGcTime()); } /** Returns the amount of time elapsed between {@code other} and {@code this}. */ ProcessTime minus(ProcessTime other) { - return new ProcessTime(wall.minus(other.wall), cpu.flatMap(thisCpu -> other.cpu.map(thisCpu::minus))); + return new ProcessTime( + wall.minus(other.wall), + cpu.flatMap(thisCpu -> other.cpu.map(thisCpu::minus)), + gc.minus(other.gc) + ); } public String toString(Locale locale) { @@ -33,7 +38,7 @@ public String toString(Locale locale) { Optional deltaCpu = cpu.map(format::duration); String avgCpus = cpu.map(cpuTime -> " avg:" + format.decimal(cpuTime.toNanos() * 1d / wall.toNanos())) .orElse(""); - return format.duration(wall) + " cpu:" + deltaCpu.orElse("-") + avgCpus; + return format.duration(wall) + " cpu:" + deltaCpu.orElse("-") + " gc:" + format.duration(gc) + avgCpus; } @Override diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java index 20a1eaeb34..c88ef5441a 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java @@ -19,25 +19,17 @@ @ThreadSafe public class Timers { - record ThreadInfo(ProcessInfo.ThreadState state, String prefix) {} - - record Stage(Timer timer, List threadStats) { - - Stage(Timer timer) { - this(timer, new CopyOnWriteArrayList<>()); - } - } - private static final Logger LOGGER = LoggerFactory.getLogger(Stats.InMemory.class); private static final Format FORMAT = Format.defaultInstance(); private final Map timers = Collections.synchronizedMap(new LinkedHashMap<>()); private final AtomicReference currentStage = new AtomicReference<>(); public void printSummary() { + int maxLength = (int) all().keySet().stream().mapToLong(String::length).max().orElse(0); for (var entry : all().entrySet()) { String name = entry.getKey(); var elapsed = entry.getValue().timer.elapsed(); - LOGGER.info("\t" + name + "\t" + elapsed); + LOGGER.info("\t" + Format.padRight(name, maxLength) + " " + elapsed); for (String detail : getStageDetails(name)) { LOGGER.info("\t " + detail); } @@ -51,16 +43,18 @@ private List getStageDetails(String name) { List threads = stage.threadStats.stream().map(d -> d.prefix).distinct().toList(); for (String thread : threads) { StringBuilder result = new StringBuilder(); - List threadStates = stage.threadStats.stream().filter(t -> t.prefix.equals(thread)) - .map(t -> t.state).toList(); + List threadStates = stage.threadStats.stream() + .filter(t -> t.prefix.equals(thread)) + .toList(); int num = threadStates.size(); - ProcessInfo.ThreadState sum = threadStates.stream().reduce(ProcessInfo.ThreadState.DEFAULT, - ProcessInfo.ThreadState::sum); + ProcessInfo.ThreadState sum = threadStates.stream() + .map(d -> d.state) + .reduce(ProcessInfo.ThreadState.DEFAULT, ProcessInfo.ThreadState::plus); double totalNanos = elapsed.wall().multipliedBy(num).toNanos(); result.append(thread.replace(name + "_", "")) .append("(") .append(num) - .append("x") + .append("x ") .append(FORMAT.percent(sum.cpuTime().toNanos() / totalNanos)) .append(" cpu:") .append(FORMAT.duration(sum.cpuTime().dividedBy(num))); @@ -77,6 +71,14 @@ private List getStageDetails(String name) { if (waitTime.compareTo(Duration.ofSeconds(1)) > 0) { result.append(" wait:").append(FORMAT.duration(waitTime)); } + Duration totalThreadElapsedTime = threadStates.stream().map(d -> d.elapsed) + .reduce(Duration::plus) + .orElse(Duration.ZERO) + .dividedBy(num); + Duration doneTime = elapsed.wall().minus(totalThreadElapsedTime); + if (doneTime.compareTo(Duration.ofSeconds(1)) > 0) { + result.append(" done:").append(FORMAT.duration(doneTime)); + } result.append(")"); resultList.add(result.toString()); } @@ -97,10 +99,10 @@ public Finishable startTimer(String name) { }; } - public void finishedWorker(String prefix) { + public void finishedWorker(String prefix, Duration elapsed) { Stage stage = currentStage.get(); if (stage != null) { - stage.threadStats.add(new ThreadInfo(ProcessInfo.getCurrentThreadStats(), prefix)); + stage.threadStats.add(new ThreadInfo(ProcessInfo.getCurrentThreadState(), prefix, elapsed)); } } @@ -116,4 +118,13 @@ public interface Finishable { void stop(); } + + record ThreadInfo(ProcessInfo.ThreadState state, String prefix, Duration elapsed) {} + + record Stage(Timer timer, List threadStats) { + + Stage(Timer timer) { + this(timer, new CopyOnWriteArrayList<>()); + } + } } diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java index 3c500a7668..abfee42b40 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/worker/Worker.java @@ -46,8 +46,9 @@ public Worker(String prefix, Stats stats, int threads, RunnableThatThrows task) String id = Thread.currentThread().getName(); LOGGER.trace("Starting worker"); try { + long start = System.nanoTime(); task.run(); - stats.timers().finishedWorker(prefix); + stats.timers().finishedWorker(prefix, Duration.ofNanos(System.nanoTime() - start)); } catch (Throwable e) { System.err.println("Worker " + id + " died"); throwRuntimeException(e); diff --git a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/ProcessInfoTest.java b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/ProcessInfoTest.java index bad8815264..644d65e298 100644 --- a/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/ProcessInfoTest.java +++ b/planetiler-core/src/test/java/com/onthegomap/planetiler/stats/ProcessInfoTest.java @@ -1,8 +1,10 @@ package com.onthegomap.planetiler.stats; +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertTrue; +import java.time.Duration; import org.junit.jupiter.api.Test; public class ProcessInfoTest { @@ -21,4 +23,17 @@ public void testCPU() { public void testThreads() { assertFalse(ProcessInfo.getThreadStats().isEmpty()); } + + @Test + public void testAdd() { + var a = new ProcessInfo.ThreadState("", Duration.ofSeconds(1), Duration.ofSeconds(2), Duration.ofSeconds(3), + Duration.ofSeconds(4), -1); + var b = new ProcessInfo.ThreadState("", Duration.ofSeconds(5), Duration.ofSeconds(6), Duration.ofSeconds(7), + Duration.ofSeconds(8), -1); + var sum = a.plus(b); + assertEquals(Duration.ofSeconds(6), sum.cpuTime()); + assertEquals(Duration.ofSeconds(8), sum.userTime()); + assertEquals(Duration.ofSeconds(10), sum.waiting()); + assertEquals(Duration.ofSeconds(12), sum.blocking()); + } } From 67fd3421b55ce755da006947a5b25b9234c95902 Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 07:53:03 -0500 Subject: [PATCH 5/6] formatting --- .../onthegomap/planetiler/stats/Timers.java | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java index c88ef5441a..0137e04aa0 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java @@ -30,17 +30,21 @@ public void printSummary() { String name = entry.getKey(); var elapsed = entry.getValue().timer.elapsed(); LOGGER.info("\t" + Format.padRight(name, maxLength) + " " + elapsed); - for (String detail : getStageDetails(name)) { + for (String detail : getStageDetails(name, false)) { LOGGER.info("\t " + detail); } } } - private List getStageDetails(String name) { + private List getStageDetails(String name, boolean pad) { List resultList = new ArrayList<>(); Stage stage = timers.get(name); var elapsed = stage.timer.elapsed(); List threads = stage.threadStats.stream().map(d -> d.prefix).distinct().toList(); + int maxLength = !pad ? 0 : (int) (threads.stream() + .map(n -> n.replace(name + "_", "")) + .mapToLong(String::length) + .max().orElse(0)) + 1; for (String thread : threads) { StringBuilder result = new StringBuilder(); List threadStates = stage.threadStats.stream() @@ -51,10 +55,9 @@ private List getStageDetails(String name) { .map(d -> d.state) .reduce(ProcessInfo.ThreadState.DEFAULT, ProcessInfo.ThreadState::plus); double totalNanos = elapsed.wall().multipliedBy(num).toNanos(); - result.append(thread.replace(name + "_", "")) - .append("(") - .append(num) - .append("x ") + result.append(Format.padRight(thread.replace(name + "_", ""), maxLength)) + .append(Format.padLeft(Integer.toString(num), 2)) + .append("x(") .append(FORMAT.percent(sum.cpuTime().toNanos() / totalNanos)) .append(" cpu:") .append(FORMAT.duration(sum.cpuTime().dividedBy(num))); @@ -94,7 +97,9 @@ public Finishable startTimer(String name) { LOGGER.info("Starting..."); return () -> { LOGGER.info("Finished in " + timers.get(name).timer.stop()); - LOGGER.info(" " + String.join(" -> ", getStageDetails(name))); + for (var details : getStageDetails(name, false)) { + LOGGER.info(" " + details); + } currentStage.set(last); }; } From bb0cfd4b5ac2b843ce2a49739458061a2231b4d5 Mon Sep 17 00:00:00 2001 From: Mike Barry Date: Thu, 24 Feb 2022 08:10:49 -0500 Subject: [PATCH 6/6] tweak --- .../src/main/java/com/onthegomap/planetiler/stats/Stats.java | 1 + .../src/main/java/com/onthegomap/planetiler/stats/Timers.java | 4 ++-- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Stats.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Stats.java index 81122f0465..3046dbcb7d 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Stats.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Stats.java @@ -43,6 +43,7 @@ static Stats prometheusPushGateway(String destination, String job, Duration inte default void printSummary() { Format format = Format.defaultInstance(); Logger LOGGER = LoggerFactory.getLogger(getClass()); + System.out.println(); LOGGER.info("-".repeat(40)); timers().printSummary(); LOGGER.info("-".repeat(40)); diff --git a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java index 0137e04aa0..9f8ca989fc 100644 --- a/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java +++ b/planetiler-core/src/main/java/com/onthegomap/planetiler/stats/Timers.java @@ -30,7 +30,7 @@ public void printSummary() { String name = entry.getKey(); var elapsed = entry.getValue().timer.elapsed(); LOGGER.info("\t" + Format.padRight(name, maxLength) + " " + elapsed); - for (String detail : getStageDetails(name, false)) { + for (String detail : getStageDetails(name, true)) { LOGGER.info("\t " + detail); } } @@ -97,7 +97,7 @@ public Finishable startTimer(String name) { LOGGER.info("Starting..."); return () -> { LOGGER.info("Finished in " + timers.get(name).timer.stop()); - for (var details : getStageDetails(name, false)) { + for (var details : getStageDetails(name, true)) { LOGGER.info(" " + details); } currentStage.set(last);