nix: trivial instantiation timing experiment #2761
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
Some trivial experiment with timing.
after `make install`:
./inst/bin/nix-instantiate '<nixpkgs/pkgs/top-level/release.nix>' \
-A unstable -vvvvvv 2>&1 > log
cat log | grep ':clock:' | sort \
| awk '
{ sums[$2] += $3; calls[$2] += 1; }
END {
for (category in sums) {
print category, sums[category], calls[category],
sums[category] / calls[category];
}
}'
showed me:
| function-position | ns | calls |
|---------------------------------------------------------------------------------------------------------------------------------|---------|-------|
| /nix/store/xnjvl3lnbl729hsi585v5075fqsgijl9-nixos-19.03.172138.5c52b25283a/nixos/pkgs/stdenv/generic/make-derivation.nix:108:33 | 437582 | 8981 |
| /nix/store/xnjvl3lnbl729hsi585v5075fqsgijl9-nixos-19.03.172138.5c52b25283a/nixos/pkgs/stdenv/generic/check-meta.nix:22:5 | 503557 | 14230 |
| /nix/store/xnjvl3lnbl729hsi585v5075fqsgijl9-nixos-19.03.172138.5c52b25283a/nixos/pkgs/stdenv/generic/check-meta.nix:214:9 | 2817229 | 5093 |
and:
| function-position | ns | calls | ns/call |
|---------------------------------------------------------------------------------------------------------------------------------|---------|-------|---------|
| /nix/store/xnjvl3lnbl729hsi585v5075fqsgijl9-nixos-19.03.172138.5c52b25283a/nixos/pkgs/development/compilers/ghc/8.6.4.nix:20:27 | 3309 | 3 | 1103 |
| /nix/var/nix/profiles/per-user/root/channels/nixos/pkgs/top-level/release-lib.nix:83:9 | 272303 | 195 | 1396.43 |
| /nix/var/nix/profiles/per-user/root/channels/nixos/lib/systems/parse.nix:174:12 | 10180 | 6 | 1696.67 |
grahamc
commented
Apr 11, 2019
| forceValue(v); | ||
| if (v.type != tLambda && v.type != tPrimOp && v.type != tPrimOpApp && !isFunctor(v)) | ||
| throwTypeError("value is %1% while a function was expected, at %2%", v, pos); | ||
|
|
There was a problem hiding this comment.
Originally I tried to do an entry time log entry and an exit time log entry to make a stack graph / flame graph, but found the evaluation log messages were linearized, each entry was immediately followed with its exit time -- so obviously this was the wrong place to put that message.
|
I forgot about |
10 tasks
grahamc
added a commit
to grahamc/nixpkgs
that referenced
this pull request
Apr 11, 2019
Generated from NixOS/nix#2761: ``` ns calls ns/call - /home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:22:5 591200 15026 39.3451 + /home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:22:5 8744 308 28.3896 ``` more, generated by: ``` $ NIX_SHOW_STATS=1 NIX_COUNT_CALLS=1 nix-instantiate ./pkgs/top-level/release.nix -A unstable > before 2>&1 $ jq -r '.functions | map((.name + ":" + .file + ":" + (.line|tostring) + ":" + (.column|tostring) + " " + (.count|tostring))) | .[]' before | sort > before.list ``` applying this patch, then: ``` $ NIX_SHOW_STATS=1 NIX_COUNT_CALLS=1 nix-instantiate ./pkgs/top-level/release.nix -A unstable > after 2>&1 $ jq -r '.functions | map((.name + ":" + .file + ":" + (.line|tostring) + ":" + (.column|tostring) + " " + (.count|tostring))) | .[]' after | sort > after.list ``` and then diffing before.list and after.list to get: ``` calls - :/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:4:1 7513 + :/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:4:1 154 - mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:23 7513 + mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:23 154 - mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:26 7513 + mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:26 154 - onlyLicenses:/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:21:18 15026 + onlyLicenses:/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:21:18 308 ``` The following information is from `NIX_SHOW_STATS=1 GC_INITIAL_HEAP_SIZE=4g nix-env -f ./outpaths.nix -qaP --no-name --out-path --arg checkMeta true`: | stat | before | after | Δ | Δ% | |:---------------------------|---------------:|---------------:|:----------------|--------:| | **cpuTime** | 179.915 | 145.543 | 🡖 34.372 | -19.10% | | **envs-bytes** | 3,900,878,824 | 3,599,483,208 | 🡖 301,395,616 | -7.73% | | **envs-elements** | 214,426,071 | 185,881,709 | 🡖 28,544,362 | -13.31% | | **envs-number** | 136,591,891 | 132,026,846 | 🡖 4,565,045 | -3.34% | | **gc-heapSize** | 11,400,048,640 | 12,314,890,240 | 🡕 914,841,600 | 8.02% | | **gc-totalBytes** | 25,976,902,560 | 24,510,740,176 | 🡖 1,466,162,384 | -5.64% | | **list-bytes** | 1,665,290,080 | 1,665,290,080 | 0 | | | **list-concats** | 7,264,417 | 7,264,417 | 0 | | | **list-elements** | 208,161,260 | 208,161,260 | 0 | | | **nrAvoided** | 191,359,386 | 179,693,661 | 🡖 11,665,725 | -6.10% | | **nrFunctionCalls** | 119,665,062 | 116,348,547 | 🡖 3,316,515 | -2.77% | | **nrLookups** | 80,996,257 | 76,069,825 | 🡖 4,926,432 | -6.08% | | **nrOpUpdateValuesCopied** | 213,930,649 | 213,930,649 | 0 | | | **nrOpUpdates** | 12,025,937 | 12,025,937 | 0 | | | **nrPrimOpCalls** | 88,105,604 | 86,451,598 | 🡖 1,654,006 | -1.88% | | **nrThunks** | 196,842,044 | 175,126,701 | 🡖 21,715,343 | -11.03% | | **sets-bytes** | 7,678,425,776 | 7,285,767,928 | 🡖 392,657,848 | -5.11% | | **sets-elements** | 310,241,340 | 294,373,227 | 🡖 15,868,113 | -5.11% | | **sets-number** | 29,079,202 | 27,601,310 | 🡖 1,477,892 | -5.08% | | **sizes-Attr** | 24 | 24 | 0 | | | **sizes-Bindings** | 8 | 8 | 0 | | | **sizes-Env** | 16 | 16 | 0 | | | **sizes-Value** | 24 | 24 | 0 | | | **symbols-bytes** | 16,474,666 | 16,474,676 | 🡕 10 | 0.00% | | **symbols-number** | 376,426 | 376,427 | 🡕 1 | 0.00% | | **values-bytes** | 6,856,506,288 | 6,316,585,560 | 🡖 539,920,728 | -7.87% | | **values-number** | 285,687,762 | 263,191,065 | 🡖 22,496,697 | -7.87% | The following information is from `NIX_SHOW_STATS=1 GC_INITIAL_HEAP_SIZE=4g nix-instantiate ./nixos/release-combined.nix -A tested`: | stat | before | after | Δ | Δ% | |:---------------------------|---------------:|---------------:|:----------------|-------:| | **cpuTime** | 256.071 | 237.531 | 🡖 18.54 | -7.24% | | **envs-bytes** | 7,111,004,192 | 7,041,478,520 | 🡖 69,525,672 | -0.98% | | **envs-elements** | 346,236,940 | 339,588,487 | 🡖 6,648,453 | -1.92% | | **envs-number** | 271,319,292 | 270,298,164 | 🡖 1,021,128 | -0.38% | | **gc-heapSize** | 8,995,291,136 | 10,110,009,344 | 🡕 1,114,718,208 | 12.39% | | **gc-totalBytes** | 37,172,737,408 | 36,878,391,888 | 🡖 294,345,520 | -0.79% | | **list-bytes** | 1,886,162,656 | 1,886,163,472 | 🡕 816 | 0.00% | | **list-concats** | 6,898,114 | 6,898,114 | 0 | | | **list-elements** | 235,770,332 | 235,770,434 | 🡕 102 | 0.00% | | **nrAvoided** | 328,829,821 | 326,618,157 | 🡖 2,211,664 | -0.67% | | **nrFunctionCalls** | 240,850,845 | 239,998,495 | 🡖 852,350 | -0.35% | | **nrLookups** | 144,849,632 | 142,126,339 | 🡖 2,723,293 | -1.88% | | **nrOpUpdateValuesCopied** | 251,032,504 | 251,032,504 | 0 | | | **nrOpUpdates** | 17,903,110 | 17,903,110 | 0 | | | **nrPrimOpCalls** | 140,674,913 | 139,485,975 | 🡖 1,188,938 | -0.85% | | **nrThunks** | 294,643,131 | 288,678,022 | 🡖 5,965,109 | -2.02% | | **sets-bytes** | 9,464,322,192 | 9,456,172,048 | 🡖 8,150,144 | -0.09% | | **sets-elements** | 377,474,889 | 377,134,877 | 🡖 340,012 | -0.09% | | **sets-number** | 50,615,607 | 50,616,875 | 🡕 1,268 | 0.00% | | **sizes-Attr** | 24 | 24 | 0 | | | **sizes-Bindings** | 8 | 8 | 0 | | | **sizes-Env** | 16 | 16 | 0 | | | **sizes-Value** | 24 | 24 | 0 | | | **symbols-bytes** | 3,147,102 | 3,147,064 | 🡖 38 | -0.00% | | **symbols-number** | 82,819 | 82,819 | 0 | | | **values-bytes** | 11,147,448,768 | 10,996,111,512 | 🡖 151,337,256 | -1.36% | | **values-number** | 464,477,032 | 458,171,313 | 🡖 6,305,719 | -1.36% |
grahamc
added a commit
to grahamc/nixpkgs
that referenced
this pull request
Apr 11, 2019
Generated from NixOS/nix#2761: ``` ns calls ns/call - /home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:22:5 591200 15026 39.3451 + /home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:22:5 8744 308 28.3896 ``` more, generated by: ``` $ NIX_SHOW_STATS=1 NIX_COUNT_CALLS=1 nix-instantiate ./pkgs/top-level/release.nix -A unstable > before 2>&1 $ jq -r '.functions | map((.name + ":" + .file + ":" + (.line|tostring) + ":" + (.column|tostring) + " " + (.count|tostring))) | .[]' before | sort > before.list ``` applying this patch, then: ``` $ NIX_SHOW_STATS=1 NIX_COUNT_CALLS=1 nix-instantiate ./pkgs/top-level/release.nix -A unstable > after 2>&1 $ jq -r '.functions | map((.name + ":" + .file + ":" + (.line|tostring) + ":" + (.column|tostring) + " " + (.count|tostring))) | .[]' after | sort > after.list ``` and then diffing before.list and after.list to get: ``` calls - :/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:4:1 7513 + :/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:4:1 154 - mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:23 7513 + mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:23 154 - mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:26 7513 + mutuallyExclusive:/home/grahamc/projects/github.com/NixOS/nixpkgs/lib/lists.nix:658:26 154 - onlyLicenses:/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:21:18 15026 + onlyLicenses:/home/grahamc/projects/github.com/NixOS/nixpkgs/pkgs/stdenv/generic/check-meta.nix:21:18 308 ``` The following information is from `NIX_SHOW_STATS=1 GC_INITIAL_HEAP_SIZE=4g nix-env -f ./outpaths.nix -qaP --no-name --out-path --arg checkMeta true`: | stat | before | after | Δ | Δ% | |:---------------------------|---------------:|---------------:|:----------------|--------:| | **cpuTime** | 179.915 | 145.543 | 🡖 34.372 | -19.10% | | **envs-bytes** | 3,900,878,824 | 3,599,483,208 | 🡖 301,395,616 | -7.73% | | **envs-elements** | 214,426,071 | 185,881,709 | 🡖 28,544,362 | -13.31% | | **envs-number** | 136,591,891 | 132,026,846 | 🡖 4,565,045 | -3.34% | | **gc-heapSize** | 11,400,048,640 | 12,314,890,240 | 🡕 914,841,600 | 8.02% | | **gc-totalBytes** | 25,976,902,560 | 24,510,740,176 | 🡖 1,466,162,384 | -5.64% | | **list-bytes** | 1,665,290,080 | 1,665,290,080 | 0 | | | **list-concats** | 7,264,417 | 7,264,417 | 0 | | | **list-elements** | 208,161,260 | 208,161,260 | 0 | | | **nrAvoided** | 191,359,386 | 179,693,661 | 🡖 11,665,725 | -6.10% | | **nrFunctionCalls** | 119,665,062 | 116,348,547 | 🡖 3,316,515 | -2.77% | | **nrLookups** | 80,996,257 | 76,069,825 | 🡖 4,926,432 | -6.08% | | **nrOpUpdateValuesCopied** | 213,930,649 | 213,930,649 | 0 | | | **nrOpUpdates** | 12,025,937 | 12,025,937 | 0 | | | **nrPrimOpCalls** | 88,105,604 | 86,451,598 | 🡖 1,654,006 | -1.88% | | **nrThunks** | 196,842,044 | 175,126,701 | 🡖 21,715,343 | -11.03% | | **sets-bytes** | 7,678,425,776 | 7,285,767,928 | 🡖 392,657,848 | -5.11% | | **sets-elements** | 310,241,340 | 294,373,227 | 🡖 15,868,113 | -5.11% | | **sets-number** | 29,079,202 | 27,601,310 | 🡖 1,477,892 | -5.08% | | **sizes-Attr** | 24 | 24 | 0 | | | **sizes-Bindings** | 8 | 8 | 0 | | | **sizes-Env** | 16 | 16 | 0 | | | **sizes-Value** | 24 | 24 | 0 | | | **symbols-bytes** | 16,474,666 | 16,474,676 | 🡕 10 | 0.00% | | **symbols-number** | 376,426 | 376,427 | 🡕 1 | 0.00% | | **values-bytes** | 6,856,506,288 | 6,316,585,560 | 🡖 539,920,728 | -7.87% | | **values-number** | 285,687,762 | 263,191,065 | 🡖 22,496,697 | -7.87% | The following information is from `NIX_SHOW_STATS=1 GC_INITIAL_HEAP_SIZE=4g nix-instantiate ./nixos/release-combined.nix -A tested`: | stat | before | after | Δ | Δ% | |:---------------------------|---------------:|---------------:|:----------------|-------:| | **cpuTime** | 256.071 | 237.531 | 🡖 18.54 | -7.24% | | **envs-bytes** | 7,111,004,192 | 7,041,478,520 | 🡖 69,525,672 | -0.98% | | **envs-elements** | 346,236,940 | 339,588,487 | 🡖 6,648,453 | -1.92% | | **envs-number** | 271,319,292 | 270,298,164 | 🡖 1,021,128 | -0.38% | | **gc-heapSize** | 8,995,291,136 | 10,110,009,344 | 🡕 1,114,718,208 | 12.39% | | **gc-totalBytes** | 37,172,737,408 | 36,878,391,888 | 🡖 294,345,520 | -0.79% | | **list-bytes** | 1,886,162,656 | 1,886,163,472 | 🡕 816 | 0.00% | | **list-concats** | 6,898,114 | 6,898,114 | 0 | | | **list-elements** | 235,770,332 | 235,770,434 | 🡕 102 | 0.00% | | **nrAvoided** | 328,829,821 | 326,618,157 | 🡖 2,211,664 | -0.67% | | **nrFunctionCalls** | 240,850,845 | 239,998,495 | 🡖 852,350 | -0.35% | | **nrLookups** | 144,849,632 | 142,126,339 | 🡖 2,723,293 | -1.88% | | **nrOpUpdateValuesCopied** | 251,032,504 | 251,032,504 | 0 | | | **nrOpUpdates** | 17,903,110 | 17,903,110 | 0 | | | **nrPrimOpCalls** | 140,674,913 | 139,485,975 | 🡖 1,188,938 | -0.85% | | **nrThunks** | 294,643,131 | 288,678,022 | 🡖 5,965,109 | -2.02% | | **sets-bytes** | 9,464,322,192 | 9,456,172,048 | 🡖 8,150,144 | -0.09% | | **sets-elements** | 377,474,889 | 377,134,877 | 🡖 340,012 | -0.09% | | **sets-number** | 50,615,607 | 50,616,875 | 🡕 1,268 | 0.00% | | **sizes-Attr** | 24 | 24 | 0 | | | **sizes-Bindings** | 8 | 8 | 0 | | | **sizes-Env** | 16 | 16 | 0 | | | **sizes-Value** | 24 | 24 | 0 | | | **symbols-bytes** | 3,147,102 | 3,147,064 | 🡖 38 | -0.00% | | **symbols-number** | 82,819 | 82,819 | 0 | | | **values-bytes** | 11,147,448,768 | 10,996,111,512 | 🡖 151,337,256 | -1.36% | | **values-number** | 464,477,032 | 458,171,313 | 🡖 6,305,719 | -1.36% | (cherry picked from commit 817c933)
10 tasks
|
#2782 is probably a nicer route. |
|
Actually, this PR does something a bit different -- so keeping it open for now. |
|
I marked this as stale due to inactivity. → More info |
|
I closed this issue due to inactivity. → More info |
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.
Some trivial experiment with timing. This is probably wrong in MANY ways.
cc @zimbatm
after
make install:showed me:
and: