commit e1b61d0d8a0b2bb7d2984f4aa3bd2b20c426f634
author Nathan Harmata <nharmata@google.com> Tue Oct 06 00:09:42 2015 +0000
committer Laszlo Csomor <laszlocsomor@google.com> Tue Oct 06 07:04:04 2015 +0000
tree fd8895d52eed8fe04be2afdf087c8174d876c396
parent b78e537405f98bad1df837233752fab40e02d891

Log how much time we spend manually checking files and directory listings for changes (also log how many nodes we checked & scanned - note that we currently "scan" the entire Skyframe graph since it's not segregated by type).

--
MOS_MIGRATED_REVID=104713225

src/main/java/com/google/devtools/build/lib/skyframe/FilesystemValueChecker.java

diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/FilesystemValueChecker.java b/src/main/java/com/google/devtools/build/lib/skyframe/FilesystemValueChecker.java
index 2d33c2f..35df110 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/FilesystemValueChecker.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/FilesystemValueChecker.java
@@ -26,6 +26,8 @@
 import com.google.devtools.build.lib.concurrent.ExecutorUtil;
 import com.google.devtools.build.lib.concurrent.Sharder;
 import com.google.devtools.build.lib.concurrent.ThrowableRecordingRunnableWrapper;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
+import com.google.devtools.build.lib.profiler.AutoProfiler.ElapsedTimeReceiver;
 import com.google.devtools.build.lib.skyframe.SkyValueDirtinessChecker.DirtyResult;
 import com.google.devtools.build.lib.util.LoggingUtil;
 import com.google.devtools.build.lib.util.Pair;
@@ -48,6 +50,7 @@
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.logging.Level;
 import java.util.logging.Logger;
@@ -293,27 +296,46 @@
     final BatchDirtyResult batchResult = new BatchDirtyResult();
     ThrowableRecordingRunnableWrapper wrapper =
         new ThrowableRecordingRunnableWrapper("FilesystemValueChecker#getDirtyValues");
-    for (final SkyKey key : values) {
-      final SkyValue value = valuesSupplier.get().get(key);
-      executor.execute(
-          wrapper.wrap(
-              new Runnable() {
-                @Override
-                public void run() {
-                  if (value != null || checkMissingValues) {
-                    DirtyResult result = checker.maybeCheck(key, value, tsgm);
-                    if (result != null && result.isDirty()) {
-                      batchResult.add(key, value, result.getNewValue());
+    final AtomicInteger numKeysScanned = new AtomicInteger(0);
+    final AtomicInteger numKeysChecked = new AtomicInteger(0);
+    ElapsedTimeReceiver elapsedTimeReceiver = new ElapsedTimeReceiver() {
+        @Override
+        public void accept(long elapsedTimeNanos) {
+          if (elapsedTimeNanos > 0) {
+            LOG.info(String.format("Spent %d ms checking %d filesystem nodes (%d scanned)",
+                TimeUnit.MILLISECONDS.convert(elapsedTimeNanos, TimeUnit.NANOSECONDS),
+                numKeysChecked.get(),
+                numKeysScanned.get()));
+          }
+        }
+    };
+    try (AutoProfiler prof = AutoProfiler.create(elapsedTimeReceiver)) {
+      for (final SkyKey key : values) {
+        final SkyValue value = valuesSupplier.get().get(key);
+        executor.execute(
+            wrapper.wrap(
+                new Runnable() {
+                  @Override
+                  public void run() {
+                    if (value != null || checkMissingValues) {
+                      numKeysScanned.incrementAndGet();
+                      DirtyResult result = checker.maybeCheck(key, value, tsgm);
+                      if (result != null) {
+                        numKeysChecked.incrementAndGet();
+                        if (result.isDirty()) {
+                          batchResult.add(key, value, result.getNewValue());
+                        }
+                      }
                     }
                   }
-                }
-              }));
-    }
+                }));
+      }
 
-    boolean interrupted = ExecutorUtil.interruptibleShutdown(executor);
-    Throwables.propagateIfPossible(wrapper.getFirstThrownError());
-    if (interrupted) {
-      throw new InterruptedException();
+      boolean interrupted = ExecutorUtil.interruptibleShutdown(executor);
+      Throwables.propagateIfPossible(wrapper.getFirstThrownError());
+      if (interrupted) {
+        throw new InterruptedException();
+      }
     }
     return batchResult;
   }