Commit 72ee042ab0c6dc823f839bca6d1511a144f62b49 | zig

author	Travis Martin <phasemage@live.com> 2021-10-10 21:57:26-07:00
committer	Andrew Kelley <andrew@ziglang.org> 2021-12-09 18:34:17-07:00
log	72ee042ab0c6dc823f839bca6d1511a144f62b49
tree	1ff98cf9f458f97a897758441e9f64338e5e2220
parent	01cb0bdb8317484cab0f8ee3896c981c851d3bb1

Cache: fix two issues with isProblematicTimestamp

1. It was looking for trailing zero bits when it should be looking for
   trailing decimal zeros.
2. Clock timestamps had more precision than the actual file timestamps

The fix is to grab a timestamp from a 'just now changed' temp file.
This timestamp is "problematic". Any file timestamp greater than or equal
to this timestamp is considered problematic. File timestamps **prior** to
this **can** be trusted.

Downside is that it causes a disk I/O to write to and then read the
timestamp from this file ~1ms on my system. This is partially mitigated by
keeping track of the most recent problematic timestamp, and only checking
for a new problematic timestamp when checking a timestamp that is equal to
or larger than the last problematic one.

This fixes #6082.

1 files changed, 51 insertions(+), 53 deletions(-)

src
- Cache.zig

src/Cache.zig+51-53

...	...	@@ -187,11 +187,14 @@ pub const Manifest = struct {
187	187	/// of the files listed in the manifest.
188	188	failed_file_index: ?usize = null,
189	189
	190	/// most recent problematic timestamp
	191	recent_problematic_timestamp: i128 = 0,
	192
190	193	/// Add a file as a dependency of process being cached. When `hit` is
191	194	/// called, the file's contents will be checked to ensure that it matches
192	195	/// the contents from previous times.
193	196	///
194		/// Max file size will be used to determine the amount of space to the file contents
	197	/// Max file size will be used to determine the amount of space the file contents
195	198	/// are allowed to take up in memory. If max_file_size is null, then the contents
196	199	/// will not be loaded into memory.
197	200	///
...	...	@@ -414,7 +417,8 @@ pub const Manifest = struct {
414	417
415	418	cache_hash_file.stat = actual_stat;
416	419
417		if (isProblematicTimestamp(cache_hash_file.stat.mtime)) {
	420	if (try self.isProblematicTimestamp(cache_hash_file.stat.mtime)) {
	421	// The actual file has an unreliable timestamp, force it to be hashed
418	422	cache_hash_file.stat.mtime = 0;
419	423	cache_hash_file.stat.inode = 0;
420	424	}
...	...	@@ -485,7 +489,8 @@ pub const Manifest = struct {
485	489
486	490	ch_file.stat = try file.stat();
487	491
488		if (isProblematicTimestamp(ch_file.stat.mtime)) {
	492	if (try self.isProblematicTimestamp(ch_file.stat.mtime)) {
	493	// The actual file has an unreliable timestamp, force it to be hashed
489	494	ch_file.stat.mtime = 0;
490	495	ch_file.stat.inode = 0;
491	496	}
...	...	@@ -520,7 +525,7 @@ pub const Manifest = struct {
520	525	}
521	526
522	527	/// Add a file as a dependency of process being cached, after the initial hash has been
523		/// calculated. This is useful for processes that don't know the all the files that
	528	/// calculated. This is useful for processes that don't know all the files that
524	529	/// are depended on ahead of time. For example, a source file that can import other files
525	530	/// will need to be recompiled if the imported file is changed.
526	531	pub fn addFilePostFetch(self: *Manifest, file_path: []const u8, max_file_size: usize) ![]const u8 {
...	...	@@ -679,6 +684,26 @@ pub const Manifest = struct {
679	684	self.have_exclusive_lock = true;
680	685	}
681	686
	687	// Create/Write a file, close it, then grab its stat.mtime timestamp.
	688	fn isProblematicTimestamp(self: *Manifest, file_time: i128) !bool {
	689
	690	// PERF: Check if the file_time is prior to the most recent problematic timestamp
	691	// and break out early if so (avoids an I/O to update the recent_problematic_timestamp)
	692	if (file_time < self.recent_problematic_timestamp)
	693	return false;
	694
	695	var timestamp_file = try self.cache.manifest_dir.createFile("filetimestamp.tmp", .{
	696	.read = true,
	697	.truncate = false,
	698	});
	699	defer timestamp_file.close();
	700	try timestamp_file.setEndPos(0);
	701
	702	self.recent_problematic_timestamp = (try timestamp_file.stat()).mtime;
	703
	704	return (file_time >= self.recent_problematic_timestamp);
	705	}
	706
682	707	/// Obtain only the data needed to maintain a lock on the manifest file.
683	708	/// The `Manifest` remains safe to deinit.
684	709	/// Don't forget to call `writeManifest` before this!
...	...	@@ -741,35 +766,16 @@ fn hashFile(file: fs.File, bin_digest: *[Hasher.mac_length]u8) !void {
741	766	hasher.final(bin_digest);
742	767	}
743	768
744		/// If the wall clock time, rounded to the same precision as the
745		/// mtime, is equal to the mtime, then we cannot rely on this mtime
746		/// yet. We will instead save an mtime value that indicates the hash
747		/// must be unconditionally computed.
748		/// This function recognizes the precision of mtime by looking at trailing
749		/// zero bits of the seconds and nanoseconds.
750		fn isProblematicTimestamp(fs_clock: i128) bool {
751		const wall_clock = std.time.nanoTimestamp();
752
753		// We have to break the nanoseconds into seconds and remainder nanoseconds
754		// to detect precision of seconds, because looking at the zero bits in base
755		// 2 would not detect precision of the seconds value.
756		const fs_sec = @intCast(i64, @divFloor(fs_clock, std.time.ns_per_s));
757		const fs_nsec = @intCast(i64, @mod(fs_clock, std.time.ns_per_s));
758		var wall_sec = @intCast(i64, @divFloor(wall_clock, std.time.ns_per_s));
759		var wall_nsec = @intCast(i64, @mod(wall_clock, std.time.ns_per_s));
760
761		// First make all the least significant zero bits in the fs_clock, also zero bits in the wall clock.
762		if (fs_nsec == 0) {
763		wall_nsec = 0;
764		if (fs_sec == 0) {
765		wall_sec = 0;
766		} else {
767		wall_sec &= @as(i64, -1) << @intCast(u6, @ctz(i64, fs_sec));
768		}
769		} else {
770		wall_nsec &= @as(i64, -1) << @intCast(u6, @ctz(i64, fs_nsec));
771		}
772		return wall_nsec == fs_nsec and wall_sec == fs_sec;
	769	// Create/Write a file, close it, then grab its stat.mtime timestamp.
	770	fn testGetCurrentFileTimestamp() !i128 {
	771	var timestamp_file = try fs.cwd().createFile("zig-cache/filetimestamp.tmp", .{
	772	.read = true,
	773	.truncate = false,
	774	});
	775	defer timestamp_file.close();
	776	try timestamp_file.setEndPos(0);
	777
	778	return (try timestamp_file.stat()).mtime;
773	779	}
774	780
775	781	test "cache file and then recall it" {
...	...	@@ -783,10 +789,11 @@ test "cache file and then recall it" {
783	789	const temp_file = "test.txt";
784	790	const temp_manifest_dir = "temp_manifest_dir";
785	791
786		const ts = std.time.nanoTimestamp();
787	792	try cwd.writeFile(temp_file, "Hello, world!\n");
788	793
789		while (isProblematicTimestamp(ts)) {
	794	// Wait for file timestamps to tick
	795	const initial_time = try testGetCurrentFileTimestamp();
	796	while ((try testGetCurrentFileTimestamp()) == initial_time) {
790	797	std.time.sleep(1);
791	798	}
792	799
...	...	@@ -838,18 +845,6 @@ test "cache file and then recall it" {
838	845	try cwd.deleteFile(temp_file);
839	846	}
840	847
841		test "give problematic timestamp" {
842		var fs_clock = std.time.nanoTimestamp();
843		// to make it problematic, we make it only accurate to the second
844		fs_clock = @divTrunc(fs_clock, std.time.ns_per_s);
845		fs_clock *= std.time.ns_per_s;
846		try testing.expect(isProblematicTimestamp(fs_clock));
847		}
848
849		test "give nonproblematic timestamp" {
850		try testing.expect(!isProblematicTimestamp(std.time.nanoTimestamp() - std.time.ns_per_s));
851		}
852
853	848	test "check that changing a file makes cache fail" {
854	849	if (builtin.os.tag == .wasi) {
855	850	// https://github.com/ziglang/zig/issues/5437
...	...	@@ -865,10 +860,11 @@ test "check that changing a file makes cache fail" {
865	860	try cwd.deleteTree(temp_manifest_dir);
866	861	try cwd.deleteTree(temp_file);
867	862
868		const ts = std.time.nanoTimestamp();
869	863	try cwd.writeFile(temp_file, original_temp_file_contents);
870	864
871		while (isProblematicTimestamp(ts)) {
	865	// Wait for file timestamps to tick
	866	const initial_time = try testGetCurrentFileTimestamp();
	867	while ((try testGetCurrentFileTimestamp()) == initial_time) {
872	868	std.time.sleep(1);
873	869	}
874	870
...	...	@@ -982,11 +978,12 @@ test "Manifest with files added after initial hash work" {
982	978	const temp_file2 = "cache_hash_post_file_test2.txt";
983	979	const temp_manifest_dir = "cache_hash_post_file_manifest_dir";
984	980
985		const ts1 = std.time.nanoTimestamp();
986	981	try cwd.writeFile(temp_file1, "Hello, world!\n");
987	982	try cwd.writeFile(temp_file2, "Hello world the second!\n");
988	983
989		while (isProblematicTimestamp(ts1)) {
	984	// Wait for file timestamps to tick
	985	const initial_time = try testGetCurrentFileTimestamp();
	986	while ((try testGetCurrentFileTimestamp()) == initial_time) {
990	987	std.time.sleep(1);
991	988	}
992	989
...	...	@@ -1031,10 +1028,11 @@ test "Manifest with files added after initial hash work" {
1031	1028	try testing.expect(mem.eql(u8, &digest1, &digest2));
1032	1029
1033	1030	// Modify the file added after initial hash
1034		const ts2 = std.time.nanoTimestamp();
1035	1031	try cwd.writeFile(temp_file2, "Hello world the second, updated\n");
1036	1032
1037		while (isProblematicTimestamp(ts2)) {
	1033	// Wait for file timestamps to tick
	1034	const initial_time2 = try testGetCurrentFileTimestamp();
	1035	while ((try testGetCurrentFileTimestamp()) == initial_time2) {
1038	1036	std.time.sleep(1);
1039	1037	}
1040	1038