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
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 b08cec71..bd6038f 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 @@
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 @@
// 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 @@
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 09d0067..2924b37 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.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 @@
* 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 @@
*/
@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 @@
* 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 void waitForTimestampGranularity(OutErr outErr) {
if (this.waitASecond || this.waitAMillisecond) {
+ long before = clock.currentTimeMillis();
long startedWaiting = Profiler.nanoTimeMaybe();
boolean interrupted = false;
@@ -180,6 +187,8 @@
Profiler.instance().logSimpleTask(startedWaiting, ProfilerTask.WAIT,
"Timestamp granularity");
+ log.info("Waited for " + (clock.currentTimeMillis() - before) + "ms for file system"
+ + " to catch up");
}
}
