Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use high-resolution timestamps #1219

Merged
merged 9 commits into from
Oct 20, 2017
Merged

Use high-resolution timestamps #1219

merged 9 commits into from
Oct 20, 2017

Conversation

QuLogic
Copy link
Contributor

@QuLogic QuLogic commented Dec 31, 2016

I tried to follow #337, but it was too tangled to understand and just wrote it from scratch. Only the other-OS struct fields from there were used. #337 also tried to increase the resolution of the clocks for timing; I didn't bother with this change here.

Fixes #371.

Copy link
Collaborator

@evmar evmar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for taking this on! I only have minor remarks.

src/deps_log.h Outdated
: mtime(mtime), node_count(node_count), nodes(new Node*[node_count]) {}
~Deps() { delete [] nodes; }
int mtime;
int64_t mtime;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess this ought to use the TimeStamp type?

@@ -60,11 +60,11 @@ int MakeDir(const string& path) {
TimeStamp TimeStampFromFileTime(const FILETIME& filetime) {
// FILETIME is in 100-nanosecond increments since the Windows epoch.
// We don't much care about epoch correctness but we do want the
// resulting value to fit in an integer.
// resulting value to fit in a 64-bit integer.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

https://msdn.microsoft.com/en-us/library/windows/desktop/ms724284(v=vs.85).aspx
indicates that perhaps the raw time is just a 64-bit integer, so perhaps we could just use the time directly. Another way of saying this is that we could drop lines 66 and 67 I think (and then adjust the relevant comments).

Oh this doc is better:
https://msdn.microsoft.com/en-us/library/windows/desktop/ms724290(v=vs.85).aspx

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According to the first link, you shouldn't treat FILETIME as a 64-bit integer directly because of possible alignment issues.

// Windows we use a different value. Both fit in an int.
typedef int TimeStamp;
// real time. On POSIX we use timespec (seconds&nanoseconds since epoch)
// and on Windows we use a different value. Both fit in an int64.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(...with the Windows change, this would just say something like "File Time":
https://msdn.microsoft.com/en-us/library/windows/desktop/ms724290(v=vs.85).aspx
)

src/util.h Outdated
@@ -18,6 +18,7 @@
#ifdef _WIN32
#include "win32port.h"
#else
#include <inttypes.h>
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is this for?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

win32port.h defines int64_t, etc., and related printf-specifiers. This header defines the print specifiers on non-Windows. However, based on the CI failing, I probably need to define something to enable those on older systems, or since this is C++ code, maybe try cinttypes.

src/deps_log.cc Outdated
int mtime = deps_data[1];
deps_data += 2;
int deps_count = (size / 4) - 2;
int64_t mtime = reinterpret_cast<int64_t*>(&deps_data[1])[0];
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are there potential alignment issues here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Probably, I was trying to avoid thinking about endianness, but I'll have to see if I can implement this in some way that's not annoying.

src/deps_log.cc Outdated
valid_header = false;
} else if (fread(&version, 4, 1, f) < 1) {
valid_header = false;
} else if (version != kCurrentVersion) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

BTW, I can attempt to read version 3 if wanted; it's not a major change.

@QuLogic
Copy link
Contributor Author

QuLogic commented Jan 28, 2017

Ping?

src/deps_log.cc Outdated
valid_header = false;
} else if (fread(&buf, 1, 4, f) < 4) {
valid_header = false;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMHO, the original code was slightly more readable, I wouldn't change it (&see below the question about endianess handling).

src/deps_log.cc Outdated
} else {
mtime = (TimeStamp)((uint64_t)deps_data[1] << 32 |
(uint64_t)deps_data[2]);
}
Copy link
Contributor

@maximuska maximuska Feb 15, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wouldn't casting to uint64_t* and dereference, instead of having to handle endianess be good enough? Does anyone really care about builds on platforms with misaligned access issues?

Also, an alternative could be writing mtime in two parts (low32, high32), so you could combine these in the same way w/o considering platform endianess.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The Windows link above says not to do that because of alignment problems; I think that's a large enough platform to worry about.

@maximuska
Copy link
Contributor

+1, I've just hit timestamp issue in my environment after adding some automatic tests to our metabuild system, could be nice to put it behind w/o adding sleeps.

@maximuska
Copy link
Contributor

@QuLogic, I believe MSDN guys had itanium (IA64) hardware in mind when writing the article.

x86/amd64 hardware handles misaligned access w/o involving OS, even performance impact vanished with the years, see e.g., here.

It would be nice to use a wrapper macro getUint64(ptr) for misaligned access, which can expand to a simple cast & dereference on x86 hardware.

@fooishbar
Copy link

@maximuska ARM (unsure about v8, but certainly v5-7) requires natural alignment, or an OS exception handle and fixup.

@maximuska
Copy link
Contributor

maximuska commented Feb 16, 2017 via email

@fooishbar
Copy link

@maximuska Yes, I do, partly because for smaller projects at least, Ninja-backed build systems can make it quicker to build on-device (or on an ARM build server; there are many vendors shipping blade-style servers) than to set up cross-compiling.

@Maratyszcza
Copy link

@fooishbar ARM doesn't require natural alignment since ARMv6. The ARMv6 architecture introduced the first hardware support for unaligned accesses. ARM11 and Cortex-A/R processors can deal with unaligned accesses in hardware, removing the need for software routines. source

@QuLogic
Copy link
Contributor Author

QuLogic commented Apr 21, 2017

I rebased this and changed it up a bit to use (low, high) instead of dealing with endian issues in the old manner.

@QuLogic
Copy link
Contributor Author

QuLogic commented May 10, 2017

Turns out this delay was somewhat useful because I managed to find a bug in re-reading the saved timestamp.

Apparently, casting from a signed narrow type to an unsigned wide type does sign extension, producing a completely incorrect result out of the lower 32 bits, but it's kind of random because it depends on the 32nd bit.

@nico
Copy link
Collaborator

nico commented Jun 20, 2017

Thanks for the patch! Sorry about the slow turnaround time.

Generally looks great.

Did you check how this affects empty build time? The larger log size might impact incremental build speeds, it'd be good to know by how much.

@nirbheek
Copy link

As an aside, Meson has a PR that runs this patch on our testsuite on macOS, Windows (mingw, cygwin, native), and Linux (Ubuntu): mesonbuild/meson#1931. Also contains a test for the high-res changes. It's running a full build on all platforms right now.

@QuLogic
Copy link
Contributor Author

QuLogic commented Jul 1, 2017

I rebased this to fix the conflicts, and modified some bits so that it works correctly on Windows, Cygwin, and MinGW.

@nirbheek
Copy link

nirbheek commented Jul 17, 2017

Small caveat about macOS: if you're using HFS+, these patches will do nothing because the filesystem timestamp resolution is 1s. However, I tested on AppleFS and the patches work perfectly.

@nico

Did you check how this affects empty build time? The larger log size might impact incremental build speeds, it'd be good to know by how much.

So I tested full, incremental, and empty builds on Linux (Fedora 26, 64-bit) with a rotating disk and ext4 relatime,data=ordered

I compared ninja before and after these patches on gst-build, which is a huge mostly-C project with ~3000 targets and a 7.3MB build.ninja file.

  1. The log file size increased from 312K to 360K with these patches.

  2. Hot cache:

    Full builds, incremental builds, and empty builds took the same time for both.

  3. Cold cache echo 2 > /proc/sys/vm/drop_caches empty builds:

    I was getting strange results (it was faster with the patches than without), and after doing a bunch of testing and statistical analysis, I figured out that it was all noise. Both take the same time.

So all in all, these patches have negligible or no effect on the build times.

This prepares it for higher-resolution timestamps.
This uses nanoseconds on POSIX (±~292 years) and 100-ns increments on
Windows (±~29247 years).

The fallbacks to different structure fields is the only thing grabbed
from ninja-build#337, with a slight modification in implementation.
Not sure why the old way works in newer compilers; maybe they just
pre-define these types by defaulting to a newer standard.
This is needed on older compilers/stdlibs such as on Ubuntu Precise
which is used on Travis.
Read and write the timestamp as two separate 32-bit integers in a fixed
order to prevent any issues with alignment or byte order.
This uses the macros as defined by the man page, which, as noted in the
comments, are defined correctly on as many libc's that I could check.
Add parentheses so that constant does not overflow; include inttypes.h
when using MinGW to get the proper macros.
This prevents overflow on Windows where 'long' is not 64-bit.
@QuLogic
Copy link
Contributor Author

QuLogic commented Sep 16, 2017

This is rebased and I think I fixed the issue on Windows with the second-last commit. @nirbheek will try it out on the Meson test suite when he has a chance.

@ClausKlein
Copy link
Contributor

what is about merging to next?

@QuLogic
Copy link
Contributor Author

QuLogic commented Sep 26, 2017

We are now using this patch for testing downstream: mesonbuild/meson#2328.

@@ -353,7 +353,7 @@ BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) {
}

bool BuildLog::WriteEntry(FILE* f, const LogEntry& entry) {
return fprintf(f, "%d\t%d\t%d\t%s\t%" PRIx64 "\n",
return fprintf(f, "%d\t%d\t%" PRId64 "\t%s\t%" PRIx64 "\n",
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unrelated to this change, but older ninjas will be pretty confused if they read build logs created by the new ninja. This isn't a new problem, but the if (log_version < kOldestSupportedVersion above should probably use != instead. Not in this change, mostly talking to myself.)

@nico nico merged commit e234a7b into ninja-build:master Oct 20, 2017
@nico
Copy link
Collaborator

nico commented Oct 20, 2017

Alright, it's early in the cycle, so let's merge this and see what (if anything) breaks :-) Do you want to send a short note to the list asking people to test this out? (If not, I can do it.)

@nico
Copy link
Collaborator

nico commented Oct 20, 2017

...and thanks everyone who contributed to this patch and helped with measuring performance. Much appreciated, and thanks for your patience.

@nirbheek
Copy link

nirbheek commented Aug 23, 2018

There hasn't been a release with this fix yet, and users still regularly report bugs to Meson that are already fixed by this. Most recently, this caused Valve to accidentally ship debug-only unoptimized DLLs for their Steam Play launch.

@nico do you have any plans you would like to share about a new release? :)

Thanks!

@mathstuf mathstuf mentioned this pull request Oct 3, 2018
@Twey Twey mentioned this pull request Oct 9, 2018
aarongable pushed a commit to chromium/chromium that referenced this pull request Jan 17, 2023
This reverts commit 52de615.

Reason for revert:
The Rust builder issue should be fixed by https://crrev.com/c/4154013

We found the timestamp format mismatch in .ninja_log.
ninja-build/ninja#1219

This causes an issue that ninja skips some actions unexpectedly. https://crbug.com/1406628
.ninja_log will be removed by build/landmines.py to avoid this issue.

Original change's description:
> Revert "Update ninja version to 1.11.1"
>
> This reverts commit 511967a.
>
> Reason for revert: It breaks rust builders that generates invalid depfiles because the the new ninja version checks depfile more strictly.
> https://ci.chromium.org/ui/p/chromium/builders/ci/linux-rust-x64-dbg/55612/blamelist
>
> Original change's description:
> > Update ninja version to 1.11.1
> >
> > There are no noticeable regressions.
> >
> > # Build performance tests on builders.
> > build-perf-android: https://ci.chromium.org/swarming/task/5f0dbe428f9fe510
> > build-perf-linux: https://ci.chromium.org/swarming/task/5f0dbe28bb7a4310
> > build-perf-windows: https://ci.chromium.org/swarming/task/5f0dbd8f5b7a3310
> >
> > # Full build performance tests on developer machines
> > There is no notable change. See the following results for more details.
> > Full builds: https://crbug.com/931218#c142
> > Noop builds: https://crbug.com/931218#c143
> >
> > Bug: 931218
> > Change-Id: I8f70055713efd90569bc49f5691a672b182b8ba8
> > Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4091014
> > Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> > Commit-Queue: Junji Watanabe <jwata@google.com>
> > Cr-Commit-Position: refs/heads/main@{#1091149}
>
> Bug: 931218
> Change-Id: If506d902c91c5b0342beb26f68eeed32bfbb3ef2
> No-Presubmit: true
> No-Tree-Checks: true
> No-Try: true
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4152932
> Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> Commit-Queue: Junji Watanabe <jwata@google.com>
> Cr-Commit-Position: refs/heads/main@{#1091202}

Bug: 931218, 1406628
Change-Id: I174d6c958d54378ee1bc393a14c04d496390bb3b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4164097
Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
Commit-Queue: Junji Watanabe <jwata@google.com>
Cr-Commit-Position: refs/heads/main@{#1093201}
jrguzman-ms pushed a commit to msft-mirror-aosp/platform.external.libchrome that referenced this pull request Jan 27, 2023
This reverts commit 52de615745c3aba2ab7339248c749d4be96b8693.

Reason for revert:
The Rust builder issue should be fixed by https://crrev.com/c/4154013

We found the timestamp format mismatch in .ninja_log.
ninja-build/ninja#1219

This causes an issue that ninja skips some actions unexpectedly. https://crbug.com/1406628
.ninja_log will be removed by build/landmines.py to avoid this issue.

Original change's description:
> Revert "Update ninja version to 1.11.1"
>
> This reverts commit 511967a00a7bdf882a3cd2315307c017a2d7fad0.
>
> Reason for revert: It breaks rust builders that generates invalid depfiles because the the new ninja version checks depfile more strictly.
> https://ci.chromium.org/ui/p/chromium/builders/ci/linux-rust-x64-dbg/55612/blamelist
>
> Original change's description:
> > Update ninja version to 1.11.1
> >
> > There are no noticeable regressions.
> >
> > # Build performance tests on builders.
> > build-perf-android: https://ci.chromium.org/swarming/task/5f0dbe428f9fe510
> > build-perf-linux: https://ci.chromium.org/swarming/task/5f0dbe28bb7a4310
> > build-perf-windows: https://ci.chromium.org/swarming/task/5f0dbd8f5b7a3310
> >
> > # Full build performance tests on developer machines
> > There is no notable change. See the following results for more details.
> > Full builds: https://crbug.com/931218#c142
> > Noop builds: https://crbug.com/931218#c143
> >
> > Bug: 931218
> > Change-Id: I8f70055713efd90569bc49f5691a672b182b8ba8
> > Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4091014
> > Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> > Commit-Queue: Junji Watanabe <jwata@google.com>
> > Cr-Commit-Position: refs/heads/main@{#1091149}
>
> Bug: 931218
> Change-Id: If506d902c91c5b0342beb26f68eeed32bfbb3ef2
> No-Presubmit: true
> No-Tree-Checks: true
> No-Try: true
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4152932
> Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> Commit-Queue: Junji Watanabe <jwata@google.com>
> Cr-Commit-Position: refs/heads/main@{#1091202}

Bug: 931218, 1406628
Change-Id: I174d6c958d54378ee1bc393a14c04d496390bb3b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4164097
Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
Commit-Queue: Junji Watanabe <jwata@google.com>
Cr-Commit-Position: refs/heads/main@{#1093201}


CrOS-Libchrome-Original-Commit: 448c9f1d052713d56d401b8cba90e9135a8b29f0
Kwizatz pushed a commit to AeonGames/build that referenced this pull request Feb 23, 2023
This reverts commit 52de615745c3aba2ab7339248c749d4be96b8693.

Reason for revert:
The Rust builder issue should be fixed by https://crrev.com/c/4154013

We found the timestamp format mismatch in .ninja_log.
ninja-build/ninja#1219

This causes an issue that ninja skips some actions unexpectedly. https://crbug.com/1406628
.ninja_log will be removed by build/landmines.py to avoid this issue.

Original change's description:
> Revert "Update ninja version to 1.11.1"
>
> This reverts commit 511967a00a7bdf882a3cd2315307c017a2d7fad0.
>
> Reason for revert: It breaks rust builders that generates invalid depfiles because the the new ninja version checks depfile more strictly.
> https://ci.chromium.org/ui/p/chromium/builders/ci/linux-rust-x64-dbg/55612/blamelist
>
> Original change's description:
> > Update ninja version to 1.11.1
> >
> > There are no noticeable regressions.
> >
> > # Build performance tests on builders.
> > build-perf-android: https://ci.chromium.org/swarming/task/5f0dbe428f9fe510
> > build-perf-linux: https://ci.chromium.org/swarming/task/5f0dbe28bb7a4310
> > build-perf-windows: https://ci.chromium.org/swarming/task/5f0dbd8f5b7a3310
> >
> > # Full build performance tests on developer machines
> > There is no notable change. See the following results for more details.
> > Full builds: https://crbug.com/931218#c142
> > Noop builds: https://crbug.com/931218#c143
> >
> > Bug: 931218
> > Change-Id: I8f70055713efd90569bc49f5691a672b182b8ba8
> > Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4091014
> > Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> > Commit-Queue: Junji Watanabe <jwata@google.com>
> > Cr-Commit-Position: refs/heads/main@{#1091149}
>
> Bug: 931218
> Change-Id: If506d902c91c5b0342beb26f68eeed32bfbb3ef2
> No-Presubmit: true
> No-Tree-Checks: true
> No-Try: true
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4152932
> Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
> Commit-Queue: Junji Watanabe <jwata@google.com>
> Cr-Commit-Position: refs/heads/main@{#1091202}

Bug: 931218, 1406628
Change-Id: I174d6c958d54378ee1bc393a14c04d496390bb3b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4164097
Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
Commit-Queue: Junji Watanabe <jwata@google.com>
Cr-Commit-Position: refs/heads/main@{#1093201}
NOKEYCHECK=True
GitOrigin-RevId: 448c9f1d052713d56d401b8cba90e9135a8b29f0
This pull request was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

9 participants