Measure phase metrics in stdenv #45744
Closed
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
disassembler
requested review from
basvandijk,
Ericson2314,
peti and
ryantm
as code owners
|
Timed out, unknown build status on x86_64-darwin (full log) Attempted: stdenv Partial log (click to expand)
|
|
Timed out, unknown build status on x86_64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Success on aarch64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
grahamc
reviewed
Aug 29, 2018
pkgs/stdenv/generic/setup.sh
Outdated
| @@ -144,6 +144,11 @@ exitHandler() { | |||
| # - system time for all child processes | |||
| echo "build time elapsed: " "${times[@]}" | |||
| fi | |||
| if [ -n "${enablePhaseMetrics:-}" ] && [ -d "$out" ]; then | |||
There was a problem hiding this comment.
Maybe error out if enablePhaseMetrics is set but out is not a directory.
There was a problem hiding this comment.
my concern there was if I error out, then the actual error won't get displayed for why $out wasn't created.
grahamc
reviewed
Aug 29, 2018
pkgs/stdenv/generic/setup.sh
Outdated
| @@ -237,6 +242,19 @@ printWords() { | |||
| printf '%s ' "$@" | |||
| } | |||
|
|
|||
| performance-metrics() { | |||
| thingname=$1 | |||
There was a problem hiding this comment.
please indent the contents of this function.
grahamc
reviewed
Aug 29, 2018
pkgs/stdenv/generic/setup.sh
Outdated
| phase_end_time=$(date '+%s') | ||
| duration=$((phase_end_time - phase_start_time)) | ||
| if [ -n "${enablePhaseMetrics:-}" ]; then | ||
| echo "time.$curPhase $duration" >> "$NIX_BUILD_TOP/metrics" |
There was a problem hiding this comment.
Maybe set it to time.$curPhase.user or whichever of user/system/real is wall clock time, to be consistent with the other metrics emitted.
There was a problem hiding this comment.
I wanted it to be unique since both would show up in the metrics file, it might get confusing which one is the duration between two timestamps and which one is the performance metric real coming from the more detailed function.
|
|
I think it would be better to implement this as a setup hook, in order not to bloat stdenv and to make it easier to iterate (since a change to the phase metrics hook won't require a rebuild of everything). So users would enable metrics by adding to their Nix expression, where in This will still require some hooks to be added to stdenv though, e.g. a @grahamc We definitely can't enable this for most packages since it breaks binary reproducibility. |
edolstra
reviewed
Aug 29, 2018
pkgs/stdenv/generic/setup.sh
Outdated
| @@ -1012,7 +1030,7 @@ buildPhase() { | |||
| ) | |||
|
|
|||
| echoCmd 'build flags' "${flagsArray[@]}" | |||
| make ${makefile:+-f $makefile} "${flagsArray[@]}" | |||
| performance-metrics "build" make ${makefile:+-f $makefile} "${flagsArray[@]}" | |||
There was a problem hiding this comment.
Is this and the other calls to performance-metrics actually needed given that the duration of the phase is already tracked? The overhead of the phase is probably neglible.
There was a problem hiding this comment.
This was about collecting the real/user/system times. It's possible the times command might work. I need to play around with it some.
|
a setup-hook does sound nice, but that makes it difficult to gather the system and userspace time, which requires wrapping the phase in the |
|
I think it can be done using the |
|
Yes hooks would be better, if possible. The stdenv setup script is already far too big. |
|
Timed out, unknown build status on x86_64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Success on aarch64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Timed out, unknown build status on x86_64-darwin (full log) Attempted: stdenv Partial log (click to expand)
|
|
Then I was thinking about doing a similar thing, my idea was to simply unconditionally print a table like
```
phase | cpu time | wall time
```
at the very end of the build so that you could then fetch and parse it by asking nix for the build log. (Which, btw, begs for a nix feature that would allow to `nix copy` logs together with their derivations.)
|
Hmm, I wonder if one some level logs should just be another output. |
disassembler
force-pushed
the
stdenv-phase-metrics
branch
from
424f8e6
to
822dc2d
Compare
disassembler
force-pushed
the
stdenv-phase-metrics
branch
from
51a1427
to
d1144ce
Compare
|
Failure on x86_64-darwin (full log) Attempted: stdenv Partial log (click to expand)
|
|
Success on aarch64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Success on x86_64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Personally I like the idea of just printing the metrics to the log, since those are persisted, rather than storing them in the output. But that would require some better features in Nix for handling the logs, like copying and GC rooting them. |
disassembler
force-pushed
the
stdenv-phase-metrics
branch
from
d1144ce
to
0bebe3d
Compare
|
Failure on aarch64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
|
Failure on x86_64-darwin (full log) Attempted: stdenv Partial log (click to expand)
|
disassembler
changed the title
|
Updated this to output to |
|
Failure on x86_64-linux (full log) Attempted: stdenv Partial log (click to expand)
|
9 tasks
|
@edolstra What do you think about enabling this for all |
|
The log is not always reproducible anyway because of `enableParallelBuilding`.
|
|
Are there any updates on this pull request, please? |
|
Thank you for your contributions.
|
stale
bot
added
the
2.status: stale
stale
bot
removed
the
2.status: stale
|
I marked this as stale due to inactivity. → More info |
stale
bot
added
the
2.status: stale
|
similar thing done in #166827 but it prints them to the log instead of to a file |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Motivation for this change
This adds ability to record time it takes for each phase to run in a derivation. Note that this breaks reproducibility but is useful on CI systems for determining what's taking the longest in a derivation to complete. This is an optional parameter that most people won't want on most of the time.
Things done
sandboxinnix.confon non-NixOS)nix-shell -p nox --run "nox-review wip"./result/bin/)nix path-info -Sbefore and after)