Skip to content

GitLab

  • Projects
  • Groups
  • Snippets
  • Help
    • Loading...
  • Help
    • Help
    • Support
    • Community forum
    • Submit feedback
  • Sign in / Register
GHC
GHC
  • Project overview
    • Project overview
    • Details
    • Activity
    • Releases
  • Repository
    • Repository
    • Files
    • Commits
    • Branches
    • Tags
    • Contributors
    • Graph
    • Compare
    • Locked Files
  • Issues 4,332
    • Issues 4,332
    • List
    • Boards
    • Labels
    • Service Desk
    • Milestones
    • Iterations
  • Merge Requests 370
    • Merge Requests 370
  • Requirements
    • Requirements
    • List
  • CI / CD
    • CI / CD
    • Pipelines
    • Jobs
    • Schedules
  • Security & Compliance
    • Security & Compliance
    • Dependency List
    • License Compliance
  • Operations
    • Operations
    • Incidents
    • Environments
  • Analytics
    • Analytics
    • CI / CD
    • Code Review
    • Insights
    • Issue
    • Repository
    • Value Stream
  • Wiki
    • Wiki
  • Snippets
    • Snippets
  • Members
    • Members
  • Collapse sidebar
  • Activity
  • Graph
  • Create a new issue
  • Jobs
  • Commits
  • Issue Boards
  • Glasgow Haskell Compiler
  • GHCGHC
  • Issues
  • #18947

Closed
Open
Opened Nov 13, 2020 by Ben Gamari@bgamari🐢Maintainer

`-prof` increases codegen cost significantly

For a long time I've noticed that profiled compilation is noticeably slower than vanilla compilation, even when no cost-centers are added.

To characterise this I built the Cabal library with and without -prof:

Vanilla

 196,673,290,048 bytes allocated in the heap                                          
  20,914,094,896 bytes copied during GC                                               
     900,734,016 bytes maximum residency (25 sample(s))                               
       7,783,360 bytes maximum slop                                                   
            2421 MiB total memory in use (0 MB lost due to fragmentation)             
                                                                                      
                                     Tot time (elapsed)  Avg pause  Max pause         
  Gen  0      3308 colls,     0 par   25.227s  25.233s     0.0076s    0.2840s         
  Gen  1        25 colls,     0 par    8.322s   8.322s     0.3329s    1.0535s         
                                                                                      
  TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)                             
                                                                                      
  SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)                     
                                                                                      
  INIT    time    0.001s  (  0.001s elapsed)                                          
  MUT     time  149.114s  (163.824s elapsed)                                          
  GC      time   33.549s  ( 33.555s elapsed)                                          
  EXIT    time    0.001s  (  0.001s elapsed)                                          
  Total   time  182.664s  (197.380s elapsed)                                          
                                                                                      
  Alloc rate    1,318,949,286 bytes per MUT second                                    
                                                                                      
  Productivity  81.6% of total user, 83.0% of total elapsed

Profiled

 219,458,638,840 bytes allocated in the heap                                              
  20,917,015,816 bytes copied during GC                                                   
     933,729,840 bytes maximum residency (26 sample(s))                                   
       7,875,024 bytes maximum slop                                                       
            2483 MiB total memory in use (0 MB lost due to fragmentation)                 
                                                                                          
                                     Tot time (elapsed)  Avg pause  Max pause             
  Gen  0      3426 colls,     0 par   25.475s  25.480s     0.0074s    0.2928s             
  Gen  1        26 colls,     0 par    8.532s   8.533s     0.3282s    1.0629s             
                                                                                          
  TASKS: 4 (1 bound, 3 peak workers (3 total), using -N1)                                 
                                                                                          
  SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)                         
                                                                                          
  INIT    time    0.001s  (  0.001s elapsed)                                              
  MUT     time  162.569s  (202.013s elapsed)                                              
  GC      time   34.006s  ( 34.013s elapsed)                                              
  EXIT    time    0.001s  (  0.004s elapsed)                                              
  Total   time  196.577s  (236.030s elapsed)                                              
                                                                                          
  Alloc rate    1,349,941,782 bytes per MUT second                                        
                                                                                          
  Productivity  82.7% of total user, 85.6% of total elapsed                               

This is a surprisingly large effect given that there are no cost-centers (beyond what we inherit from base).

On enabling -ddump-timings I noticed that the largest increase is cost seems to come in CodeGen, which frequently allocates between 10% and 100% more when profiling is enabled:

Module vanilla time vanilla alloc prof time prof alloc
[Distribution.Compat.Async]: 28.99 34.384 37.7 50.355
[Distribution.Compat.Binary]: 4.61 5.162 7.85 7.366
[Distribution.Compat.CreatePipe]: 0.58 0.545 0.62 0.792
[Distribution.Compat.Directory]: 0.48 0.544 0.63 0.79
[Distribution.Compat.Exception]: 5.74 6.108 6.98 9.017
[Distribution.Compat.FilePath]: 0.49 0.543 0.62 0.787
[Distribution.Compat.Internal.TempFile]: 19.59 25.547 26.19 36.768
[Distribution.Compat.MonadFail]: 0.48 0.544 0.87 0.79
[Distribution.Compat.Newtype]: 9.65 10.024 13.2 15.904
[Distribution.Compat.Process]: 9.18 10.248 10.4 13.938
[Distribution.Compat.Stack]: 11.02 14.512 15.54 20.672
[Distribution.Compat.Typeable]: 0.5 0.543 0.7 0.787
[Distribution.PackageDescription.Utils]: 4.2 4.958 5.78 6.988
[Distribution.Simple.Utils.Json]: 19.57 24.426 27.53 37.528
[Distribution.Utils.Base62]: 3.67 4.684 4.61 6.345
[Distribution.Utils.MD5]: 17.2 22.521 23.11 30.329
[Distribution.Utils.String]: 15.03 22.322 21.41 34.238
[Distribution.Utils.Structured]: 335.77 438.023 461.17 662.522
[Distribution.Compat.Semigroup]: 85.09 101.529 140.9 179.136
[Distribution.Compat.NonEmptySet]: 91.08 118.201 139.95 193.837
[Distribution.Compat.Prelude]: 8.45 9.089 9.68 12.065
[Distribution.Utils.ShortText]: 46.58 55.623 63.28 84.857
[Distribution.Utils.Progress]: 19.02 24.974 29.44 37.23
[Distribution.Utils.MapAccum]: 15.41 20.9 29.76 39.329
[Distribution.Utils.IOData]: 14.69 18.93 20.09 24.22
[Distribution.Utils.Generic]: 76.73 104.161 110.08 152.421
[Distribution.Types.Condition]: 164.13 217.113 244.43 354.658
[Distribution.TestSuite]: 140.28 185.253 204.25 290.584
[Distribution.Simple.Program.Internal]: 7.22 9.994 10.8 13.458
[Distribution.Simple.PreProcess.Unlit]: 50.95 72.934 67.49 101.876
[Distribution.Simple.InstallDirs.Internal]: 186.44 233.845 256.81 332.332
[Distribution.Simple.Flag]: 67.89 83.078 97.35 131.571
[Distribution.Simple.CCompiler]: 27.95 40.1 31.41 49.388
[Distribution.Parsec.Position]: 29.68 39.466 38.54 52.717
[Distribution.Parsec.Warning]: 179.65 234.019 252.46 331.293
[Distribution.Parsec.FieldLineStream]: 32.54 40.798 43.48 63.899
[Distribution.Parsec.Error]: 19.27 22.822 26.01 34.248
[Distribution.PackageDescription.Quirks]: 137.22 184.429 169.4 240.726
[Distribution.GetOpt]: 62.97 88.666 96.15 134.956
[Distribution.Fields.LexerMonad]: 53.03 73.963 65.65 94.034
[Distribution.Fields.Lexer]: 106.44 151.9 143.89 203.512
[Distribution.Fields.Field]: 161.2 213.464 231.13 320.513
[Distribution.Fields.Parser]: 148.4 206.094 221.75 321.188
[Distribution.Compat.ResponseFile]: 9.29 13.101 12.88 19.131
[Distribution.Compat.Parsing]: 129.51 162.705 211.33 299.86
[Distribution.Compat.GetShortPathName]: 1.01 0.909 1.23 1.23
[Distribution.Compat.Environment]: 3.88 4.608 5.66 6.533
[Distribution.Compat.DList]: 6.34 7.13 7.77 9.64
[Distribution.Lex]: 6.79 9.693 10.23 14.23
[Distribution.Compat.Lens]: 21.22 20.254 30.86 34.737
[Distribution.Types.CondTree]: 266.05 351.972 397.2 555.432
[Distribution.Compat.CopyFile]: 32.14 42.117 55.26 71.46
[Distribution.Compat.CharParsing]: 142.21 178.646 226.02 323.3
[Distribution.CabalSpecVersion]: 190.09 249.887 255.44 336.429
[Distribution.SPDX.LicenseListVersion]: 71.7 92.845 92.09 137.35
[Distribution.Pretty]: 28.41 36.752 36.49 51.693
[Distribution.Parsec]: 439.64 594.082 679.91 985.578
[Distribution.Types.Version]: 135.7 176.866 179.21 265.633
[Distribution.Types.VersionRange.Internal]: 435.26 585.241 652.73 952.65
[Distribution.Types.VersionInterval]: 136.38 210.052 167.16 267.607
[Distribution.Types.VersionRange]: 22.94 35.076 28.75 47.024
[Distribution.Types.SourceRepo]: 465.09 623.323 638.61 915.443
[Distribution.Types.SourceRepo.Lens]: 9.08 12.424 13.17 19.311
[Distribution.Types.PkgconfigVersion]: 80.5 116.712 121.49 172.978
[Distribution.Types.PkgconfigVersionRange]: 220.13 292.613 335 467.756
[Distribution.Types.PkgconfigName]: 47.02 56.558 67.73 88.157
[Distribution.Types.PkgconfigDependency]: 65.19 89.12 106.79 144.842
[Distribution.Types.PackageName]: 48.05 56.238 66.15 87.576
[Distribution.Types.UnqualComponentName]: 46.66 56.425 68.25 88.058
[Distribution.Types.LibraryVisibility]: 46.81 62.141 64.15 86.744
[Distribution.Types.LibraryName]: 80.38 105.107 110.04 155.855
[Distribution.Types.MungedPackageName]: 106.75 144.011 144.82 212.745
[Distribution.Types.ForeignLibType]: 57.35 76.681 72.36 104.413
[Distribution.Types.ForeignLibOption]: 33.46 43.044 44.22 61.296
[Distribution.Types.Flag]: 232.9 297.1 324.13 456.424
[Distribution.Types.ExecutableScope]: 45.05 59.768 62.37 83.087
[Distribution.Types.ComponentName]: 105.33 137.529 155.57 216.502
[Distribution.Types.ComponentId]: 43.8 57.774 66.53 89.568
[Distribution.Types.GivenComponent]: 45.11 61.546 71.79 99.577
[Distribution.Types.BuildType]: 66.03 84.915 86.14 118.105
[Distribution.Types.AbiHash]: 25.99 30.701 33.55 46.812
[Distribution.Text]: 1 0.895 1.18 1.178
[Distribution.System]: 516.57 683.82 696.46 961.977
[Distribution.SPDX.LicenseReference]: 102.58 140.621 150.35 215.603
[Distribution.SPDX.LicenseId]: 2146.7 2807.36 2566.5 3485.856
[Distribution.SPDX.LicenseExceptionId]: 313.33 384.905 361.65 503.07
[Distribution.SPDX.LicenseExpression]: 279.85 377.74 386.41 571.041
[Distribution.SPDX.License]: 75.79 89.355 90.57 132.515
[Distribution.SPDX]: 0.53 0.526 0.64 0.749
[Distribution.ReadE]: 9.77 10.061 11.13 14.521
[Distribution.ModuleName]: 58.72 70.711 75.41 108.394
[Distribution.Types.ModuleRenaming]: 153.65 223.724 228.82 336.648
[Distribution.Types.IncludeRenaming]: 78.81 109.508 114.44 169.797
[Distribution.Types.Mixin]: 124.44 164.081 180.81 261.057
[Distribution.Types.ModuleReexport]: 104.39 136.326 154.06 220.803
[Distribution.Compat.Graph]: 125.61 174.29 175.6 261.32
[Distribution.Utils.UnionFind]: 15.29 20.764 18.3 25.975
[Distribution.Verbosity.Internal]: 220.63 284.129 282.77 419.772
[Distribution.Verbosity]: 250.71 351.079 347.09 516.742
[Distribution.Version]: 7.13 10.042 8.34 12.145
[Distribution.Types.TestType]: 108.87 139.264 157.44 221.857
[Distribution.Types.TestSuiteInterface]: 124.53 161.081 184.46 265.05
[Distribution.Types.PackageId]: 88.61 123.118 136.68 192.032
[Distribution.Types.UnitId]: 82.13 108.192 124.79 170.31
[Distribution.Types.Module]: 73.95 102.131 110.75 158.897
[Distribution.Backpack]: 226.15 305.795 321.53 469.569
[Distribution.Types.ExposedModule]: 54.43 73.379 78.16 115.284
[Distribution.Backpack.ModSubst]: 17.36 26.101 21.69 33.223
[Distribution.Backpack.ModuleScope]: 39.51 55.396 51.04 78.645
[Distribution.Backpack.FullUnitId]: 8.64 10.675 11.46 15.782
[Distribution.Types.PackageVersionConstraint]: 67.23 90.993 98.89 146.835
[Distribution.Types.PackageName.Magic]: 2.03 2.24 2.61 3.232
[Distribution.Types.PackageId.Lens]: 3.07 3.637 4.43 5.781
[Distribution.Types.MungedPackageId]: 95.63 129.659 133.8 194.804
[Distribution.Types.LegacyExeDependency]: 73.75 100.957 112.69 163.463
[Distribution.Types.ExeDependency]: 91.49 121.251 141.82 194.821
[Distribution.Types.Dependency]: 129.01 189.048 187.04 290.698
[Distribution.Types.SetupBuildInfo]: 78.93 105.657 123.2 170.883
[Distribution.Types.SetupBuildInfo.Lens]: 3.09 3.64 4.3 5.81
[Distribution.Types.DependencyMap]: 47.66 72.032 62.55 98.081
[Distribution.Types.BenchmarkType]: 90.67 114.826 130.69 184.297
[Distribution.Types.BenchmarkInterface]: 93.19 119.579 137.03 194.767
[Distribution.Simple.Utils]: 338.35 454.65 460.64 666.212
[Distribution.Utils.NubList]: 42.4 53.648 66.16 92.487
[Distribution.Utils.LogProgress]: 26.73 34.819 34.51 49.649
[Distribution.Simple.Program.ResponseFile]: 7.46 10.776 9.41 14.823
[Distribution.Simple.Program.Find]: 51.68 67.056 68.15 101.883
[Distribution.Simple.Glob]: 81.44 118.815 114.24 168.866
[Distribution.Simple.Command]: 142.58 192.933 202.29 296.571
[Distribution.Fields.Pretty]: 75.16 98.656 106.53 148.755
[Distribution.Backpack.DescribeUnitId]: 13.94 22.094 19.71 32.883
[Distribution.Package]: 8.34 9.653 9.23 11.292
[Distribution.Types.AnnotatedId]: 21.92 28.416 31.89 46.448
[Distribution.Types.ComponentInclude]: 4.8 5.702 5.78 6.867
[Distribution.Types.AbiDependency]: 44.26 60.424 64.95 95.804
[Distribution.License]: 320.81 411.461 413.26 590.589
[Distribution.Types.InstalledPackageInfo]: 423.44 664.418 600.95 960.367
[Distribution.Types.InstalledPackageInfo.Lens]: 103.34 178.373 125.16 229.153
[Distribution.Fields.ParseResult]: 32.32 44.729 43.02 63.048
[Distribution.Fields]: 0.53 0.528 0.66 0.755
[Distribution.ZinzaPrelude]: 10.12 12.809 15.56 22.066
[Distribution.Simple.Build.Macros.Z]: 52.7 77.288 77.14 116.828
[Language.Haskell.Extension]: 1341.03 1544.767 1521.03 2064.572
[Distribution.Compiler]: 397.86 515.834 573.11 788.621
[Distribution.Types.ConfVar]: 121.28 158.3 179.32 259.698
[Distribution.Fields.ConfVar]: 120.04 172.014 166.7 243.456
[Distribution.Types.BuildInfo]: 590.28 928.662 805.85 1313.382
[Distribution.Types.HookedBuildInfo]: 0.57 0.637 0.72 0.894
[Distribution.Types.BuildInfo.Lens]: 162.52 238.329 213.93 339.82
[Distribution.Types.TestSuite]: 292.2 381.535 396.87 563.322
[Distribution.Types.TestSuite.Lens]: 4.29 5.263 6.24 8.359
[Distribution.Types.Library]: 335.94 481.614 521.09 731.1
[Distribution.Types.Library.Lens]: 9.13 12.421 12.98 19.297
[Distribution.Types.ForeignLib]: 448.41 625.338 624.19 941.695
[Distribution.Types.ForeignLib.Lens]: 9 12.423 13.52 19.326
[Distribution.Types.Executable]: 293.42 409.096 409.59 609.49
[Distribution.Types.Executable.Lens]: 5.57 6.96 7.66 11.009
[Distribution.Types.Benchmark]: 248.64 356.696 354.94 528.499
[Distribution.Types.Component]: 191.17 275.236 254.23 388.231
[Distribution.Types.ComponentRequestedSpec]: 60.26 82.067 88.23 130.948
[Distribution.Types.PackageDescription]: 481.08 718.188 672.07 1040.211
[Distribution.Types.GenericPackageDescription]: 231.68 319.67 351.79 527.002
[Distribution.Types.GenericPackageDescription.Lens]: 37.58 53.729 59.07 90.795
[Distribution.Types.Benchmark.Lens]: 4.26 5.262 6.07 8.371
[Distribution.Types.PackageDescription.Lens]: 124.96 187.022 166.39 264.795
[Distribution.Types.Lens]: 0.54 0.538 0.61 0.774
[Distribution.PackageDescription]: 0.54 0.539 0.67 0.787
[Distribution.Simple.Program.Types]: 132.91 184.04 205.64 291.957
[Distribution.Simple.Program.Run]: 60.17 88.938 76.58 118.308
[Distribution.Simple.Program.Script]: 31.17 43.205 45.99 69.752
[Distribution.Simple.Program.Hpc]: 19.2 27.096 27.5 42.263
[Distribution.Simple.BuildToolDepends]: 32.94 50.922 43.17 68.592
[Distribution.Simple.InstallDirs]: 287.84 402.588 436.29 642.41
[Distribution.Simple.Compiler]: 434.54 519.587 551.92 769.471
[Distribution.Simple.GHC.ImplInfo]: 22.03 30.504 27.95 41.434
[Distribution.Simple.Program.GHC]: 571.62 902.465 770.07 1196.358
[Distribution.Simple.Program.Builtin]: 61.88 76.598 74.13 97.74
[Distribution.Simple.Program.Db]: 115.34 153.611 145.6 211.703
[Distribution.Simple.Program]: 9.02 11.629 11.76 16.431
[Distribution.Simple.Setup]: 1880.75 2914.657 2595.21 4050.72
[Distribution.Simple.Program.Strip]: 13.51 18.854 17.07 25.597
[Distribution.PackageDescription.Configuration]: 209.92 323.089 293.76 474
[Distribution.FieldGrammar.Newtypes]: 89.13 119.837 125.99 184.591
[Distribution.FieldGrammar.Class]: 14.43 18.71 17.65 23.831
[Distribution.FieldGrammar.Pretty]: 26.38 36.83 34.87 51.367
[Distribution.FieldGrammar.Parsec]: 306.28 404.91 408.48 615.518
[Distribution.FieldGrammar]: 13.8 20.658 17.45 26.657
[Distribution.PackageDescription.FieldGrammar]: 1106.25 1759.197 1621.5 2496.271
[Distribution.PackageDescription.PrettyPrint]: 91.78 128.199 126.17 193.152
[Distribution.PackageDescription.Parsec]: 721.14 1041.83 1073.94 1539.453
[Distribution.FieldGrammar.FieldDescrs]: 70.71 101.403 106.93 155.969
[Distribution.Types.InstalledPackageInfo.FieldGrammar]: 462.67 665.338 621.62 948.277
[Distribution.InstalledPackageInfo]: 30.36 47.136 37.14 60.488
[Distribution.Types.ComponentLocalBuildInfo]: 299.94 384.484 455.21 652.838
[Distribution.Types.TargetInfo]: 4.57 5.566 5.18 6.511
[Distribution.Simple.Program.HcPkg]: 136.71 188.559 168.83 263.664
[Distribution.Simple.PackageIndex]: 359.23 531.59 458.48 716.822
[Distribution.Types.LocalBuildInfo]: 408.53 600.226 580.71 897.731
[Distribution.Simple.LocalBuildInfo]: 70.33 113.796 91.85 150.882
[Distribution.Simple.Test.Log]: 139.06 178.699 180.48 274.635
[Distribution.Simple.Program.Ld]: 11.77 17.416 17.21 27.11
[Distribution.Simple.Program.Ar]: 52.84 79.298 74.74 117.125
[Distribution.Simple.Hpc]: 80.08 114.328 111.26 170.38
[Distribution.Simple.BuildTarget]: 559.78 744.801 770.45 1111.787
[Distribution.Simple.BuildPaths]: 46.76 64.181 61.18 90.494
[Distribution.Simple.UHC]: 86.4 114.224 106.07 163.523
[Distribution.PackageDescription.Check]: 855.78 1232.167 1147.6 1770.948
[Distribution.Simple.Build.PathsModule]: 90.59 128.139 135.45 202.681
[Distribution.Simple.Test.LibV09]: 90.57 126.505 122.43 183.361
[Distribution.Simple.PreProcess]: 269.31 369.372 366.43 559.482
[Distribution.Simple.UserHooks]: 49.39 52.181 45.54 58.551
[Distribution.Simple.Test.ExeV10]: 37.81 57.162 53.21 82.512
[Distribution.Simple.Test]: 32.99 49.826 44.29 70.626
[Distribution.Simple.Build.Macros]: 17.09 24.684 21 33.095
[Distribution.Simple.Bench]: 30.57 45.461 43.42 67.24
[Distribution.Backpack.Id]: 14.9 23.556 20 32.809
[Distribution.Backpack.ConfiguredComponent]: 167.51 252.634 210.61 336.754
[Distribution.Backpack.ComponentsGraph]: 43.74 61.904 55.46 88.997
[Distribution.Simple.HaskellSuite]: 92.15 122.986 126.39 180.8
[Distribution.Simple.GHC.Internal]: 232.93 327.422 305.63 469.481
[Distribution.Simple.GHC.EnvironmentParser]: 87.68 113.632 120.47 166.562
[Distribution.Simple.GHCJS]: 423.54 614.747 533.54 794.947
[Distribution.Simple.GHC]: 562.49 822.403 751.58 1070.331
[Distribution.Simple.ShowBuildInfo]: 36.1 55.071 53.44 80.134
[Distribution.Simple.Register]: 137.57 193.402 183.36 266.677
[Distribution.Simple.Install]: 62.28 97.632 92.91 140.991
[Distribution.Backpack.ModuleShape]: 46.19 66.412 66.1 94.219
[Distribution.Backpack.UnifyM]: 176.15 270.815 243.11 358.972
[Distribution.Backpack.MixLink]: 95.26 149.479 138.74 211.39
[Distribution.Backpack.PreModuleShape]: 37.63 56.837 53 75.511
[Distribution.Backpack.PreExistingComponent]: 22.42 34.34 29.72 43.294
[Distribution.Backpack.LinkedComponent]: 170.95 251.687 251.94 354.561
[Distribution.Backpack.ReadyComponent]: 118.04 176.76 166.27 262.878
[Distribution.Backpack.Configure]: 181.14 289.322 271.23 392.479
[Distribution.Simple.Configure]: 672.66 930.553 856.39 1293.88
[Distribution.Simple.SrcDist]: 124.24 173.614 168.85 256.386
[Distribution.Simple.Build]: 147.49 238.606 197.96 321.693
[Distribution.Simple.Haddock]: 336.32 486.522 426.22 662.089
[Distribution.Simple.Doctest]: 46.2 71.481 58.83 95.005
[Distribution.Simple]: 224.24 361.83 304.9 486.018
[Main]: 1.12 1.027 1.34 1.312

It would be nice to know why this is the case.

Edited Nov 13, 2020 by Ben Gamari
Assignee
Assign to
None
Milestone
None
Assign milestone
Time tracking
None
Due date
None
Reference: ghc/ghc#18947