Increase the performance of parsing and evaluation speed

[jwiegley]

Here's the bar:

[nix-shell:~/src/hnix]$ time nix-instantiate -I nix=$PWD/data/nix/corepkgs --eval --expr "import $HOME/src/nix/nixpkgs {}" > /dev/null

real	0m0.089s
user	0m0.077s
sys	0m0.010s

[nix-shell:~/src/hnix]$ time ./dist/build/hnix/hnix -I nix=$PWD/data/nix/corepkgs --eval --expr "import $HOME/src/nix/nixpkgs {}" > /dev/null

real	0m1.125s
user	0m1.047s
sys	0m0.070s

[domenkozar]

Using branch vs-megaparsec-7:

$ \time ./result/bin/hnix -I nix=$PWD/data/nix/corepkgs --eval --expr "import $HOME/dev/nixpkgs {}" >/dev/null
1.26user 0.06system 0:01.33elapsed 99%CPU (0avgtext+0avgdata 210552maxresident)k
0inputs+0outputs (0major+49601minor)pagefaults 0swaps

$ \time nix-instantiate -I nix=$PWD/data/nix/corepkgs --eval --expr "import $HOME/dev/nixpkgs {}" >/dev/null
0.16user 0.01system 0:00.17elapsed 100%CPU (0avgtext+0avgdata 30660maxresident)k
0inputs+0outputs (0major+5412minor)pagefaults 0swaps

[domenkozar]

Here is the flamegraph of the invocation: https://static.domenkozar.com/hnix.svg

To reproduce:

diff --git a/default.nix b/default.nix
index f135e1d..be7aa0c 100644
--- a/default.nix
+++ b/default.nix
@@ -70,7 +70,8 @@ drv = haskellPackages.developPackage {
       pkgs.haskell.packages.${compiler}.cabal-install
     ];
 
-    enableLibraryProfiling = false;
+    enableExecutableProfiling = true;
+    doCheck = false;
 
     testHaskellDepends = attrs.testHaskellDepends ++
       [ pkgs.nix

Then invoke:

nix-build
./result/bin/hnix -I nix=$PWD/data/nix/corepkgs --eval --expr "import $HOME/dev/nixpkgs {}" +RTS -pj
nix-shell -p flamegraph haskellPackages.ghc-prof-aeson-flamegraph --run "cat hnix.prof | ghc-prof-aeson-flamegraph | flamegraph.pl > hnix.svg"

[domenkozar]

maybe @mrkkrp could chip in here :)

[mrkkrp]

@domenkozar Can you give me TLDR? So it got slower, if so, how much slower? There is only one thing that can make it slower, that's getSourcePos. It shouldn't be called too often (for example, it's a bad idea to call it on every token). But in general if you call it not-that-often, the performance should stay the same. At least it was so for MMark when I checked this before releasing Megaparsec 7.

[domenkozar]

@mrkkrp Megaparsec improved performance by about 10% on this particular case. We are wondering how to bridge the gap between original Nix implementation (0.16s) and HNix (1.26s) and majority of time is spend in Megaparsec as observed in the flamegraph linked above.

If you have any tips for what could be the underlying causes we'd be very grateful :)

[mrkkrp]

Megaparsec improved performance by about 10% on this particular case.

Ah good! I was fearing that I screwed up with version 7 :-P

how to bridge the gap between original Nix implementation (0.16s) and HNix (1.26s)

I think my suggestions are already applied in the code... Would be good to make it as fast as C, but I don't think I know how to do it.

[domenkozar]

Since productivity is around 50%, running profiling with -hd shows us what is allocated that makes GC slow.

[mpickering]

I did some profiling and it seems that the majority of allocated memory is never used. Digging deeper, it seemed that most of the wasted space is from things to do with parse errors where ParseError objects are allocated but then never used because the parse succeeds.

[domenkozar]

It seems currently the slowdown is about 10x even for bigger files (running on 2e4e5e0 with --arg doOptimize):

$ \time nix-instantiate --parse /home/ielectric/dev/nixpkgs/pkgs/development/haskell-modules/hackage-packages.nix >/dev/null
0.41user 0.04system 0:00.45elapsed 100%CPU (0avgtext+0avgdata 115912maxresident)k
0inputs+0outputs (0major+30692minor)pagefaults 0swaps

$ \time ./result/bin/hnix /home/ielectric/dev/nixpkgs/pkgs/development/haskell-modules/hackage-packages.nix +RTS -s >/dev/null
  19,764,470,152 bytes allocated in the heap
   2,079,365,984 bytes copied during GC
     273,960,304 bytes maximum residency (9 sample(s))
         916,584 bytes maximum slop
             755 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0     19093 colls,     0 par    1.314s   1.314s     0.0001s    0.0005s
  Gen  1         9 colls,     0 par    0.678s   0.678s     0.0753s    0.2529s

  INIT    time    0.000s  (  0.000s elapsed)
  MUT     time    3.190s  (  3.191s elapsed)
  GC      time    1.991s  (  1.992s elapsed)
  EXIT    time    0.000s  (  0.000s elapsed)
  Total   time    5.182s  (  5.182s elapsed)

  %GC     time      38.4%  (38.4% elapsed)

  Alloc rate    6,195,508,791 bytes per MUT second

  Productivity  61.6% of total user, 61.6% of total elapsed

4.96user 0.24system 0:05.21elapsed 99%CPU (0avgtext+0avgdata 787480maxresident)k
0inputs+0outputs (0major+193728minor)pagefaults 0swaps

[domenkozar]

+RTS -hd for the previous comment (using additional flag --doProfiling true)

[domenkozar]