Add more logs for persistent workers. Added logs for WorkerLifecycleManager activity. Added logs for creation and destroying of workers. Also added logging of exception that could be threw during descendants collection. PiperOrigin-RevId: 477385940 Change-Id: I84602f3d830c084ee7d47f60c350d048d7e2878b
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java index 7de9ada..8a5b3dc 100644 --- a/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java +++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerFactory.java
@@ -13,6 +13,7 @@ // limitations under the License. package com.google.devtools.build.lib.worker; +import com.google.common.flogger.GoogleLogger; import com.google.common.io.BaseEncoding; import com.google.devtools.build.lib.events.Event; import com.google.devtools.build.lib.events.Reporter; @@ -40,6 +41,8 @@ // request_id (which is indistinguishable from 0 in proto3). private static final AtomicInteger pidCounter = new AtomicInteger(1); + private static final GoogleLogger logger = GoogleLogger.forEnclosingClass(); + private final Path workerBaseDir; private Reporter reporter; @@ -79,17 +82,16 @@ } else { worker = new SingleplexWorker(key, workerId, key.getExecRoot(), logFile); } - if (reporter != null) { - reporter.handle( - Event.info( - String.format( - "Created new %s %s %s (id %d), logging to %s", - key.isSandboxed() ? "sandboxed" : "non-sandboxed", - key.getMnemonic(), - workTypeName, - workerId, - worker.getLogFile()))); - } + + String msg = + String.format( + "Created new %s %s %s (id %d), logging to %s", + key.isSandboxed() ? "sandboxed" : "non-sandboxed", + key.getMnemonic(), + workTypeName, + workerId, + worker.getLogFile()); + WorkerLoggingHelper.logMessage(reporter, WorkerLoggingHelper.LogLevel.INFO, msg); return worker; } @@ -116,14 +118,11 @@ /** When a worker process is discarded, destroy its process, too. */ @Override public void destroyObject(WorkerKey key, PooledObject<Worker> p) { - if (reporter != null) { - int workerId = p.getObject().getWorkerId(); - reporter.handle( - Event.info( - String.format( - "Destroying %s %s (id %d)", - key.getMnemonic(), key.getWorkerTypeName(), workerId))); - } + int workerId = p.getObject().getWorkerId(); + String msg = + String.format( + "Destroying %s %s (id %d)", key.getMnemonic(), key.getWorkerTypeName(), workerId); + WorkerLoggingHelper.logMessage(reporter, WorkerLoggingHelper.LogLevel.INFO, msg); p.getObject().destroy(); } @@ -136,7 +135,7 @@ Worker worker = p.getObject(); Optional<Integer> exitValue = worker.getExitValue(); if (exitValue.isPresent()) { - if (reporter != null && worker.diedUnexpectedly()) { + if (worker.diedUnexpectedly()) { String msg = String.format( "%s %s (id %d) has unexpectedly died with exit code %d.", @@ -147,14 +146,15 @@ .logFile(worker.getLogFile()) .logSizeLimit(4096) .build(); - reporter.handle(Event.warn(errorMessage.toString())); + WorkerLoggingHelper.logMessage( + reporter, WorkerLoggingHelper.LogLevel.WARNING, errorMessage.toString()); } return false; } boolean filesChanged = !key.getWorkerFilesCombinedHash().equals(worker.getWorkerFilesCombinedHash()); - if (reporter != null && filesChanged) { + if (filesChanged) { StringBuilder msg = new StringBuilder(); msg.append( String.format( @@ -176,7 +176,8 @@ } } - reporter.handle(Event.warn(msg.toString())); + WorkerLoggingHelper.logMessage( + reporter, WorkerLoggingHelper.LogLevel.WARNING, msg.toString()); } return !filesChanged; @@ -202,4 +203,46 @@ public int hashCode() { return Objects.hashCode(workerBaseDir); } + + /** + * This class helps to log messages simulteneously on logger and send message to event reporter to + * show message in cmd. + */ + private static final class WorkerLoggingHelper { + private WorkerLoggingHelper() {} + + public static void logMessage(@Nullable Reporter reporter, LogLevel level, String message) { + switch (level) { + case INFO: + logger.atInfo().log("%s", message); + if (reporter != null) { + reporter.handle(Event.info(message)); + } + return; + case WARNING: + logger.atWarning().log("%s", message); + if (reporter != null) { + reporter.handle(Event.warn(message)); + } + return; + } + throw new IllegalStateException(String.format("illegel logging level %s", level)); + } + + public static enum LogLevel { + INFO("INFO"), + WARNING("WARNING"); + + private final String level; + + LogLevel(final String level) { + this.level = level; + } + + @Override + public String toString() { + return level; + } + } + } }
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerLifecycleManager.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerLifecycleManager.java index 8e5d64d..b5f8f60 100644 --- a/src/main/java/com/google/devtools/build/lib/worker/WorkerLifecycleManager.java +++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerLifecycleManager.java
@@ -40,16 +40,16 @@ private boolean isWorking = false; private final WorkerPool workerPool; - private final WorkerOptions workerOptions; + private final WorkerOptions options; - public WorkerLifecycleManager(WorkerPool workerPool, WorkerOptions workerOptions) { + public WorkerLifecycleManager(WorkerPool workerPool, WorkerOptions options) { this.workerPool = workerPool; - this.workerOptions = workerOptions; + this.options = options; } @Override public void run() { - if (workerOptions.totalWorkerMemoryLimitMb == 0) { + if (options.totalWorkerMemoryLimitMb == 0) { return; } @@ -67,7 +67,7 @@ WorkerMetricsCollector.instance().collectMetrics(METRICS_MINIMAL_INTERVAL); try { - evictWorkers(workerMetrics, workerPool, workerOptions); + evictWorkers(workerMetrics); } catch (InterruptedException e) { break; } @@ -81,9 +81,7 @@ } @VisibleForTesting // productionVisibility = Visibility.PRIVATE - static void evictWorkers( - ImmutableList<WorkerMetric> workerMetrics, WorkerPool workerPool, WorkerOptions options) - throws InterruptedException { + void evictWorkers(ImmutableList<WorkerMetric> workerMetrics) throws InterruptedException { if (options.totalWorkerMemoryLimitMb == 0) { return; @@ -101,27 +99,28 @@ ImmutableSet<Integer> candidates = collectEvictionCandidates( - workerPool, workerMetrics, options.totalWorkerMemoryLimitMb, workerMemeoryUsage); + workerMetrics, options.totalWorkerMemoryLimitMb, workerMemeoryUsage); + + if (candidates.isEmpty()) { + return; + } logger.atInfo().log("Going to evict %d workers with ids: %s", candidates.size(), candidates); evictCandidates(workerPool, candidates); } - private static void evictCandidates(WorkerPool pool, ImmutableSet<Integer> candidates) + private void evictCandidates(WorkerPool pool, ImmutableSet<Integer> candidates) throws InterruptedException { pool.evictWithPolicy(new CandidateEvictionPolicy(candidates)); } /** Collects worker candidates to evict. Choses workers with the largest memory consumption. */ @SuppressWarnings("JdkCollectors") - static ImmutableSet<Integer> collectEvictionCandidates( - WorkerPool workerPool, - ImmutableList<WorkerMetric> workerMetrics, - int memoryLimitMb, - int workerMemeoryUsageMb) + ImmutableSet<Integer> collectEvictionCandidates( + ImmutableList<WorkerMetric> workerMetrics, int memoryLimitMb, int workerMemeoryUsageMb) throws InterruptedException { - Set<Integer> idleWorkers = getIdleWorkers(workerPool); + Set<Integer> idleWorkers = getIdleWorkers(); List<WorkerMetric> idleWorkerMetrics = workerMetrics.stream() @@ -130,9 +129,13 @@ metric.getWorkerStat() != null && idleWorkers.contains(metric.getWorkerProperties().getWorkerId())) .collect(Collectors.toList()); - logger.atInfo().log( - "Difference between idle workers and idle worker metrics is %d", - idleWorkers.size() - idleWorkerMetrics.size()); + + if (idleWorkerMetrics.size() != idleWorkers.size()) { + logger.atInfo().log( + "Difference between idle workers and idle worker metrics is %d", + idleWorkers.size() - idleWorkerMetrics.size()); + } + idleWorkerMetrics.sort(new MemoryComparator()); ImmutableSet.Builder<Integer> candidates = ImmutableSet.builder(); @@ -153,7 +156,7 @@ * Calls workerPool.evict() to collect information, but doesn't kill any workers during this * process. */ - private static Set<Integer> getIdleWorkers(WorkerPool workerPool) throws InterruptedException { + private Set<Integer> getIdleWorkers() throws InterruptedException { InfoEvictionPolicy infoEvictionPolicy = new InfoEvictionPolicy(); workerPool.evictWithPolicy(infoEvictionPolicy); return infoEvictionPolicy.getWorkerIds(); @@ -188,7 +191,15 @@ @Override public boolean evict(EvictionConfig config, PooledObject<Worker> underTest, int idleCount) { - return workerIds.contains(underTest.getObject().getWorkerId()); + int workerId = underTest.getObject().getWorkerId(); + if (workerIds.contains(workerId)) { + logger.atInfo().log( + "Evicting worker %d with mnemonic %s", + workerId, underTest.getObject().getWorkerKey().getMnemonic()); + return true; + } + + return false; } }
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerMetricsCollector.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerMetricsCollector.java index 57f672f..27ac8c9 100644 --- a/src/main/java/com/google/devtools/build/lib/worker/WorkerMetricsCollector.java +++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerMetricsCollector.java
@@ -20,6 +20,7 @@ import com.google.auto.value.AutoValue; import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Splitter; +import com.google.common.base.VerifyException; import com.google.common.collect.HashMultimap; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; @@ -79,7 +80,13 @@ ImmutableMap.of(), Instant.ofEpochMilli(clock.currentTimeMillis())); } - ImmutableMap<Long, PsInfo> psInfos = collectDataFromPs(); + ImmutableMap<Long, PsInfo> psInfos; + try { + psInfos = collectDataFromPs(); + } catch (RuntimeException e) { + throw new VerifyException( + String.format("Could not collect data for pids: %s", processIds), e); + } ImmutableMap<Long, Integer> pidToMemoryInKb = summarizeDescendantsMemory(psInfos, processIds); return new MemoryCollectionResult(
diff --git a/src/test/java/com/google/devtools/build/lib/worker/WorkerLifecycleManagerTest.java b/src/test/java/com/google/devtools/build/lib/worker/WorkerLifecycleManagerTest.java index 66a3078..027b980 100644 --- a/src/test/java/com/google/devtools/build/lib/worker/WorkerLifecycleManagerTest.java +++ b/src/test/java/com/google/devtools/build/lib/worker/WorkerLifecycleManagerTest.java
@@ -89,10 +89,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 1024 * 100; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); @@ -117,10 +119,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 0; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); @@ -140,10 +144,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 1; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); @@ -168,10 +174,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 1; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(0); assertThat(workerPool.getNumActive(key)).isEqualTo(0); @@ -208,11 +216,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 2; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(3); assertThat(workerPool.getNumActive(key)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(1); assertThat(workerPool.getNumActive(key)).isEqualTo(0); @@ -250,10 +259,12 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 2; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(2); assertThat(workerPool.getNumActive(key)).isEqualTo(1); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key)).isEqualTo(0); assertThat(workerPool.getNumActive(key)).isEqualTo(1); @@ -301,12 +312,14 @@ WorkerOptions options = new WorkerOptions(); options.totalWorkerMemoryLimitMb = 2; + WorkerLifecycleManager manager = new WorkerLifecycleManager(workerPool, options); + assertThat(workerPool.getNumIdlePerKey(key1)).isEqualTo(2); assertThat(workerPool.getNumActive(key1)).isEqualTo(0); assertThat(workerPool.getNumIdlePerKey(key2)).isEqualTo(2); assertThat(workerPool.getNumActive(key2)).isEqualTo(0); - WorkerLifecycleManager.evictWorkers(workerMetrics, workerPool, options); + manager.evictWorkers(workerMetrics); assertThat(workerPool.getNumIdlePerKey(key1)).isEqualTo(1); assertThat(workerPool.getNumActive(key1)).isEqualTo(0);