From 8a901e3b4f381aa0ccb89ef577a931617e7c9318 Mon Sep 17 00:00:00 2001 From: Andrew Kozlov Date: Wed, 18 Dec 2019 00:11:27 +0300 Subject: [PATCH] logging events/runnables invocations via MessageBus GitOrigin-RevId: f2b40143ff183ab951e7f526fa15cb01bd0335b5 --- .../intellij/diagnostic/EventsWatcher.java | 262 ++++++++---------- .../diagnostic/RunnablesListener.java | 232 ++++++++++++++++ 2 files changed, 351 insertions(+), 143 deletions(-) create mode 100644 platform/core-impl/src/com/intellij/diagnostic/RunnablesListener.java diff --git a/platform/core-impl/src/com/intellij/diagnostic/EventsWatcher.java b/platform/core-impl/src/com/intellij/diagnostic/EventsWatcher.java index 54526c6856ee..7bb75cb9930a 100644 --- a/platform/core-impl/src/com/intellij/diagnostic/EventsWatcher.java +++ b/platform/core-impl/src/com/intellij/diagnostic/EventsWatcher.java @@ -13,6 +13,8 @@ import com.intellij.openapi.util.NotNullLazyValue; import com.intellij.openapi.util.io.FileUtil; import com.intellij.openapi.util.registry.Registry; import com.intellij.util.concurrency.AppExecutorUtil; +import com.intellij.util.messages.MessageBus; +import com.intellij.util.messages.MessageBusConnection; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @@ -23,18 +25,24 @@ import java.io.File; import java.io.IOException; import java.lang.reflect.Field; import java.lang.reflect.Modifier; +import java.util.List; import java.util.Queue; import java.util.*; import java.util.concurrent.*; +import java.util.function.Supplier; import java.util.regex.MatchResult; import java.util.regex.Matcher; import java.util.regex.Pattern; import java.util.stream.Collector; import java.util.stream.Collectors; +import java.util.stream.Stream; @ApiStatus.Experimental public final class EventsWatcher implements Disposable { + private static final int PUBLISHER_INITIAL_DELAY = 100; + private static final int PUBLISHER_PERIOD = 1000; + @NotNull private static final Logger LOG = Logger.getInstance(EventsWatcher.class); @NotNull @@ -71,13 +79,14 @@ public final class EventsWatcher implements Disposable { } @NotNull - private final Set> myWrappers = new HashSet<>(); + private final ConcurrentMap myWrappers = new ConcurrentHashMap<>(); @NotNull - private final Map myDurationsByFqn = new HashMap<>(); + private final ConcurrentMap myDurationsByFqn = new ConcurrentHashMap<>(); @NotNull - private final ConcurrentLinkedQueue myRunnables = new ConcurrentLinkedQueue<>(); + private final ConcurrentLinkedQueue myRunnables = new ConcurrentLinkedQueue<>(); @NotNull - private final ConcurrentMap, ConcurrentLinkedQueue> myEventsByClass = new ConcurrentHashMap<>(); + private final ConcurrentMap, ConcurrentLinkedQueue> myEventsByClass = + new ConcurrentHashMap<>(); @NotNull private final File myLogPath = new File( @@ -92,33 +101,54 @@ public final class EventsWatcher implements Disposable { @NotNull private final ScheduledFuture myThread = myExecutor.scheduleWithFixedDelay( this::dumpDescriptions, - getDelay(), - getDelay(), + PUBLISHER_INITIAL_DELAY, + PUBLISHER_PERIOD, TimeUnit.MILLISECONDS ); + @NotNull + private final MessageBus myMessageBus; + @NotNull + private final MessageBusConnection myConnection; + @Nullable private Object myCurrentInstance = null; @Nullable private MatchResult myCurrentResult = null; - public void logTimeMillis(@NotNull String processId, long startedAt) { - Duration duration = new Duration(startedAt); - if (!duration.shouldLog()) return; + public EventsWatcher(@NotNull MessageBus messageBus) { + myMessageBus = messageBus; + myConnection = myMessageBus.connect(); - duration.log(processId); + myConnection.subscribe( + RunnablesListener.TOPIC, + new RunnablesListener() { + @Override + public void eventsProcessed(@NotNull Class eventClass, + @NotNull Collection descriptions) { + appendToLogFile(eventClass.getSimpleName(), descriptions.stream()); + } + + @Override + public void runnablesProcessed(@NotNull Collection invocations) { + appendToLogFile("Runnables", invocations.stream()); + } + } + ); + } + + public void logTimeMillis(@NotNull String processId, long startedAt) { + new InvocationLogger(processId, startedAt) + .log(() -> null); } public void logTimeMillis(@NotNull AWTEvent event, long startedAt) { if ("LaterInvocator.FlushQueue".equals(findGroupByName("runnable"))) return; - Duration duration = new Duration(startedAt); - if (!duration.shouldLog()) return; - - Runnable runnable = event instanceof InvocationEvent ? - (Runnable)getValue(event, ourRunnableField.getValue()) : - null; - duration.log(runnable != null ? runnable : event); + new InvocationLogger(event, startedAt) + .log(() -> event instanceof InvocationEvent ? + (Runnable)getValue(event, ourRunnableField.getValue()) : + null); } public void runnableStarted(@NotNull Runnable runnable) { @@ -129,7 +159,10 @@ public final class EventsWatcher implements Disposable { Field field = findTargetField(originalClass); if (field != null) { - myWrappers.add(originalClass); + myWrappers.compute( + originalClass.getName(), + RunnablesListener.WrapperDescription::computeNext + ); current = getValue(current, field); } else { @@ -142,19 +175,18 @@ public final class EventsWatcher implements Disposable { public void runnableFinished(@NotNull Runnable runnable, long startedAt) { - Duration duration = new Duration(startedAt); - String representation = Objects.requireNonNull(myCurrentInstance).getClass().getName(); + String fqn = Objects.requireNonNull(myCurrentInstance).getClass().getName(); myCurrentInstance = null; + RunnablesListener.InvocationDescription description = new RunnablesListener.InvocationDescription(fqn, startedAt); + myRunnables.offer(description); myDurationsByFqn.compute( - representation, - (ignored, count) -> InvocationInfo.computeNext(count, duration) + fqn, + (ignored, info) -> RunnablesListener.InvocationsInfo.computeNext(fqn, description.getDuration(), info) ); - myRunnables.offer(String.format("%tc,%s%n", startedAt, representation)); - - if (!duration.shouldLog()) return; - duration.log(runnable); + new InvocationLogger(description) + .log(() -> runnable); } public void edtEventStarted(@NotNull AWTEvent event) { @@ -169,24 +201,24 @@ public final class EventsWatcher implements Disposable { String representation = findGroupByName("description"); myCurrentResult = null; - String description = String.format( - "%dms %s%n", - System.currentTimeMillis() - startedAt, - representation != null ? representation : event.toString() - ); - Class eventClass = event.getClass(); myEventsByClass.putIfAbsent(eventClass, new ConcurrentLinkedQueue<>()); - myEventsByClass.get(eventClass).offer(description); + myEventsByClass.get(eventClass) + .offer(new RunnablesListener.InvocationDescription( + representation != null ? representation : event.toString(), + startedAt + )); } @Override public void dispose() { + appendToLogFile("Wrappers", myWrappers); + appendToLogFile("Timings", myDurationsByFqn); + myThread.cancel(true); myExecutor.shutdownNow(); - appendToLogFile("Timing", joinSorted(myDurationsByFqn)); - appendToLogFile("Wrapper", join(myWrappers)); + myConnection.disconnect(); } @Nullable @@ -197,29 +229,34 @@ public final class EventsWatcher implements Disposable { } private void dumpDescriptions() { - myEventsByClass.forEach((eventClass, events) -> appendToLogFile( - eventClass.getSimpleName(), - join(events) - )); + if (myMessageBus.isDisposed()) return; - appendToLogFile("Runnable", join(myRunnables)); + RunnablesListener publisher = myMessageBus.syncPublisher(RunnablesListener.TOPIC); + myEventsByClass.forEach((eventClass, events) -> + publisher.eventsProcessed(eventClass, joinPolling(events))); + publisher.runnablesProcessed(joinPolling(myRunnables)); } - private void appendToLogFile(@NotNull String kind, @NotNull String text) { + private void appendToLogFile(@NotNull String kind, + @NotNull Map entities) { + appendToLogFile(kind, entities.values().stream().sorted()); + } + + private void appendToLogFile(@NotNull String kind, + @NotNull Stream lines) { if (!(myLogPath.isDirectory() || myLogPath.mkdirs())) return; try { - File logFile = new File(myLogPath, kind + "s.log"); - FileUtil.writeToFile(logFile, text, true); + FileUtil.writeToFile( + new File(myLogPath, kind + ".log"), + lines.map(Objects::toString).collect(JOINING_COLLECTOR), + true + ); } catch (IOException ignored) { } } - private static long getDelay() { - return 10000; - } - @Nullable private static Field findTargetField(@NotNull Class originalClass) { for (Class currentClass = originalClass; @@ -258,60 +295,53 @@ public final class EventsWatcher implements Disposable { } @NotNull - private static > String joinSorted(@NotNull Map map) { - return map - .entrySet() - .stream() - .sorted(Map.Entry.comparingByValue()) - .map(Objects::toString) - .collect(JOINING_COLLECTOR); - } - - @NotNull - private static String join(@NotNull Set> classes) { - return classes - .stream() - .map(Class::getName) - .sorted() - .collect(JOINING_COLLECTOR); - } - - @NotNull - private static String join(@NotNull Queue queue) { - StringBuilder builder = new StringBuilder(); + private static List joinPolling(@NotNull Queue queue) { + ArrayList builder = new ArrayList<>(); while (!queue.isEmpty()) { - builder.append(queue.poll()); + builder.add(queue.poll()); } - return builder.toString(); + return Collections.unmodifiableList(builder); } - private static final class Duration { + private static final class InvocationLogger { - private final long myDuration; + @NotNull + private final RunnablesListener.InvocationDescription myDescription; - private Duration(long startedAt) { - myDuration = System.currentTimeMillis() - startedAt; + private InvocationLogger(@NotNull RunnablesListener.InvocationDescription description) { + myDescription = description; } - public long getDuration() { - return myDuration; + private InvocationLogger(@NotNull Object process, + long startedAt) { + this(new RunnablesListener.InvocationDescription(process.toString(), startedAt)); } - // do not measure a time if the threshold is too small - public boolean shouldLog() { + public void log(@NotNull Supplier lazyRunnable) { int threshold = Registry.intValue("ide.event.queue.dispatch.threshold", -1); - return myDuration >= threshold && threshold >= 0; + if (threshold < 0 || + threshold > myDescription.getDuration()) { + return; // do not measure a time if the threshold is too small + } + + Runnable runnable = lazyRunnable.get(); + RunnablesListener.InvocationDescription description = runnable != null ? + new RunnablesListener.InvocationDescription( + runnable.toString(), + myDescription.getStartedAt(), + myDescription.getFinishedAt() + ) : + myDescription; + LOG.warn(description.toString()); + + if (runnable != null) { + addPluginCost(runnable.getClass(), description.getDuration()); + } } - public void log(@NotNull Object process) { - LOG.warn(String.format("%dms to process %s", myDuration, process)); - - if (!(process instanceof Runnable)) return; - addPluginCost((Runnable)process); - } - - private void addPluginCost(@NotNull Runnable runnable) { - ClassLoader loader = runnable.getClass().getClassLoader(); + private static void addPluginCost(@NotNull Class runnableClass, + long duration) { + ClassLoader loader = runnableClass.getClassLoader(); String pluginId = loader instanceof PluginClassLoader ? ((PluginClassLoader)loader).getPluginIdString() : PluginManagerCore.CORE_PLUGIN_ID; @@ -319,61 +349,7 @@ public final class EventsWatcher implements Disposable { StartUpMeasurer.addPluginCost( pluginId, "invokeLater", - TimeUnit.MILLISECONDS.toNanos(myDuration) - ); - } - } - - private static final class InvocationInfo implements Comparable { - - private final int myCount; - private final long myDuration; - - private InvocationInfo(int count, long duration) { - myCount = count; - myDuration = duration; - } - - @Override - public int compareTo(@NotNull InvocationInfo info) { - int result = Integer.compare(info.myCount, myCount); - - return result != 0 ? - result : - Double.compare(info.myDuration, myDuration); - } - - @Override - public boolean equals(Object other) { - if (this == other) return true; - if (other == null || getClass() != other.getClass()) return false; - - InvocationInfo count = (InvocationInfo)other; - return myCount == count.myCount && - myDuration == count.myDuration; - } - - @Override - public int hashCode() { - return Objects.hash(myCount, myDuration); - } - - @NotNull - @Override - public String toString() { - return String.format( - "[average: %.2f; count: %d]", - (double)myDuration / myCount, - myCount - ); - } - - @NotNull - public static InvocationInfo computeNext(@Nullable InvocationInfo info, - @NotNull Duration duration) { - return new InvocationInfo( - 1 + (info != null ? info.myCount : 0), - duration.getDuration() + (info != null ? info.myDuration : 0) + TimeUnit.MILLISECONDS.toNanos(duration) ); } } diff --git a/platform/core-impl/src/com/intellij/diagnostic/RunnablesListener.java b/platform/core-impl/src/com/intellij/diagnostic/RunnablesListener.java new file mode 100644 index 000000000000..ab591ed2f0d7 --- /dev/null +++ b/platform/core-impl/src/com/intellij/diagnostic/RunnablesListener.java @@ -0,0 +1,232 @@ +// Copyright 2000-2019 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license that can be found in the LICENSE file. +package com.intellij.diagnostic; + +import com.intellij.util.messages.Topic; +import org.jetbrains.annotations.NotNull; +import org.jetbrains.annotations.Nullable; + +import java.awt.*; +import java.util.Collection; +import java.util.Objects; + +public interface RunnablesListener { + + Topic TOPIC = Topic.create( + "RunnableListener", + RunnablesListener.class + ); + + default void eventsProcessed(@NotNull Class eventClass, + @NotNull Collection descriptions) {} + + default void runnablesProcessed(@NotNull Collection invocations) {} + + final class InvocationDescription implements Comparable { + + @NotNull + private final String myProcessId; + private final long myStartedAt; + private final long myFinishedAt; + + InvocationDescription(@NotNull String processId, + long startedAt, + long finishedAt) { + myProcessId = processId; + myStartedAt = startedAt; + myFinishedAt = finishedAt; + } + + InvocationDescription(@NotNull String processId, + long startedAt) { + this(processId, startedAt, System.currentTimeMillis()); + } + + @NotNull + public String getProcessId() { + return myProcessId; + } + + public long getStartedAt() { + return myStartedAt; + } + + public long getFinishedAt() { + return myFinishedAt; + } + + public long getDuration() { + return myFinishedAt - myStartedAt; + } + + @Override + public int compareTo(@NotNull InvocationDescription description) { + int result = Long.compare(myStartedAt, description.myStartedAt); + + return result != 0 ? + result : + Long.compare(myFinishedAt, description.myFinishedAt); + } + + @Override + public boolean equals(Object o) { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + + InvocationDescription description = (InvocationDescription)o; + return myStartedAt == description.myStartedAt && + myFinishedAt == description.myFinishedAt && + myProcessId.equals(description.myProcessId); + } + + @Override + public int hashCode() { + return Objects.hash(myProcessId, myStartedAt, myFinishedAt); + } + + @Override + public String toString() { + return String.format( + "%dms to process %s; started at: %tc; finished at: %tc", + getDuration(), + myProcessId, + myStartedAt, + myFinishedAt + ); + } + } + + final class InvocationsInfo implements Comparable { + + @NotNull + static InvocationsInfo computeNext(@NotNull String fqn, + long duration, + @Nullable InvocationsInfo info) { + return new InvocationsInfo( + fqn, + info != null ? info.myCount : 0, + (info != null ? info.myDuration : 0) + duration + ); + } + + @NotNull + private final String myFQN; + private final int myCount; + private final long myDuration; + + private InvocationsInfo(@NotNull String fqn, + int count, + long duration) { + myFQN = fqn; + myCount = 1 + count; + myDuration = duration; + } + + @NotNull + public String getFQN() { + return myFQN; + } + + public int getCount() { + return myCount; + } + + public double getAverageDuration() { + return (double)myDuration / myCount; + } + + @Override + public int compareTo(@NotNull InvocationsInfo info) { + int result = Integer.compare(info.myCount, myCount); + + return result != 0 ? + result : + Double.compare(info.myDuration, myDuration); + } + + @Override + public boolean equals(Object o) { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + + InvocationsInfo info = (InvocationsInfo)o; + return myCount == info.myCount && + myDuration == info.myDuration && + myFQN.equals(info.myFQN); + } + + @Override + public int hashCode() { + return Objects.hash(myFQN, myCount, myDuration); + } + + @NotNull + @Override + public String toString() { + return String.format( + "%s=[average: %.2f; count: %d]", + myFQN, + getAverageDuration(), + myCount + ); + } + } + + final class WrapperDescription implements Comparable { + + @NotNull + static WrapperDescription computeNext(@NotNull String fqn, + @Nullable WrapperDescription description) { + return new WrapperDescription( + fqn, + description != null ? description.myUsagesCount : 0 + ); + } + + @NotNull + private final String myFQN; + private final int myUsagesCount; + + private WrapperDescription(@NotNull String fqn, int count) { + myFQN = fqn; + myUsagesCount = 1 + count; + } + + @NotNull + public String getFQN() { + return myFQN; + } + + public int getUsagesCount() { + return myUsagesCount; + } + + @Override + public int compareTo(@NotNull WrapperDescription description) { + return Integer.compare(description.myUsagesCount, myUsagesCount); + } + + @Override + public boolean equals(Object o) { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + + WrapperDescription description = (WrapperDescription)o; + return myUsagesCount == description.myUsagesCount && + myFQN.equals(description.myFQN); + } + + @Override + public int hashCode() { + return Objects.hash(myFQN, myUsagesCount); + } + + @Override + public String toString() { + return String.format( + "%s; usages: %d", + myFQN, + myUsagesCount + ); + } + } +}