Add logging to TimestampGranularityMonitor.

These new log statements help in understanding what files trigger the
TimestampGranularityMonitor's wait logic and when the wait is performed.

--
MOS_MIGRATED_REVID=137868235

2 files changed, 16 insertions, 7 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/FileStateValue.java b/src/main/java/com/google/devtools/build/lib/skyframe/FileStateValue.java
index b08cec71ac..bd6038f33a 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/FileStateValue.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/FileStateValue.java
@@ -89,7 +89,7 @@ public abstract class FileStateValue implements SkyValue {
     Path path = rootedPath.asPath();
     if (statNoFollow.isFile()) {
       return statNoFollow.isSpecialFile()
-          ? SpecialFileStateValue.fromStat(statNoFollow, tsgm)
+          ? SpecialFileStateValue.fromStat(path.asFragment(), statNoFollow, tsgm)
           : RegularFileStateValue.fromPath(path, statNoFollow, tsgm);
     } else if (statNoFollow.isDirectory()) {
       return DIRECTORY_FILE_STATE_NODE;
@@ -172,7 +172,7 @@ public abstract class FileStateValue implements SkyValue {
           // Note that TimestampGranularityMonitor#notifyDependenceOnFileTime is a thread-safe
           // method.
           if (tsgm != null) {
-            tsgm.notifyDependenceOnFileTime(mtime);
+            tsgm.notifyDependenceOnFileTime(path.asFragment(), mtime);
           }
           return new RegularFileStateValue(stat.getSize(), stat.getLastModifiedTime(), null,
               FileContentsProxy.create(mtime, stat.getNodeId()));
@@ -261,13 +261,13 @@ public abstract class FileStateValue implements SkyValue {
       this.contentsProxy = contentsProxy;
     }
 
-    static SpecialFileStateValue fromStat(FileStatusWithDigest stat,
+    static SpecialFileStateValue fromStat(PathFragment path, FileStatusWithDigest stat,
         @Nullable TimestampGranularityMonitor tsgm) throws IOException {
       long mtime = stat.getLastModifiedTime();
       // Note that TimestampGranularityMonitor#notifyDependenceOnFileTime is a thread-safe
       // method.
       if (tsgm != null) {
-        tsgm.notifyDependenceOnFileTime(mtime);
+        tsgm.notifyDependenceOnFileTime(path, mtime);
       }
       return new SpecialFileStateValue(FileContentsProxy.create(mtime, stat.getNodeId()));
     }
diff --git a/src/main/java/com/google/devtools/build/lib/util/io/TimestampGranularityMonitor.java b/src/main/java/com/google/devtools/build/lib/util/io/TimestampGranularityMonitor.java
index 09d00676e4..2924b3777f 100644
--- a/src/main/java/com/google/devtools/build/lib/util/io/TimestampGranularityMonitor.java
+++ b/src/main/java/com/google/devtools/build/lib/util/io/TimestampGranularityMonitor.java
@@ -20,6 +20,9 @@ import com.google.devtools.build.lib.profiler.Profiler;
 import com.google.devtools.build.lib.profiler.ProfilerTask;
 import com.google.devtools.build.lib.util.Clock;
 
+import com.google.devtools.build.lib.vfs.PathFragment;
+import java.util.logging.Logger;
+
 /**
  * A utility class for dealing with filesystem timestamp granularity issues.
  *
@@ -36,8 +39,8 @@ import com.google.devtools.build.lib.util.Clock;
  * on foo/bar is not changed by the second command, even though some time has
  * passed, because the times are the same when rounded to the file system
  * timestamp granularity (often 1 second).
- * For performance, we assume that files
- * timestamps haven't changed  can safely be cached without reexamining their contents.
+ * For performance, we assume that files whose
+ * timestamps haven't changed can safely be cached without reexamining their contents.
  * But this assumption would be violated in the above scenario.
  *
  * <p>
@@ -72,6 +75,7 @@ import com.google.devtools.build.lib.util.Clock;
  */
 @ThreadCompatible
 public class TimestampGranularityMonitor {
+  private static final Logger log = Logger.getLogger(TimestampGranularityMonitor.class.getName());
 
   /**
    * The time of the start of the current Blaze command,
@@ -121,11 +125,13 @@ public class TimestampGranularityMonitor {
    * of a build file or source file with the specified time stamp.
    */
   @ThreadSafe
-  public void notifyDependenceOnFileTime(long mtime) {
+  public void notifyDependenceOnFileTime(PathFragment path, long mtime) {
     if (mtime == this.commandStartTimeMillis) {
+      log.info("Will have to wait for a millisecond on completion because of " + path);
       this.waitAMillisecond = true;
     }
     if (mtime == this.commandStartTimeMillisRounded) {
+      log.info("Will have to wait for a second on completion because of " + path);
       this.waitASecond = true;
     }
   }
@@ -147,6 +153,7 @@ public class TimestampGranularityMonitor {
    */
   public void waitForTimestampGranularity(OutErr outErr) {
     if (this.waitASecond || this.waitAMillisecond) {
+      long before = clock.currentTimeMillis();
       long startedWaiting = Profiler.nanoTimeMaybe();
       boolean interrupted = false;
 
@@ -180,6 +187,8 @@ public class TimestampGranularityMonitor {
 
       Profiler.instance().logSimpleTask(startedWaiting, ProfilerTask.WAIT,
                                         "Timestamp granularity");
+      log.info("Waited for " + (clock.currentTimeMillis() - before) + "ms for file system"
+          + " to catch up");
     }
   }