Initial compile time benchmarks

[Ömer Sinan Ağacan]

I just benchmarked another set of packages, this time using -O2 optimized libs
+ stage 2 (6ea42c7):

https://gist.githubusercontent.com/osa1/b483216953e3b02c0c79f9e4c8f8f931/raw/64001a1bfb71c0c4441c07f9f195bf5629095a6f/gistfile1.txt

For me the most surprising part is that CodeGen is sometimes taking 86% of the
time. It seems like we can start looking for improvements there. (I'll do that
myself but I'm too busy for a few more days)


Joachim, I think the difference is because of how thunk evaluation and cost
centers work. If you generate a thunk with cost-center "X", you attribute the
evaluation costs of that thunk to the cost-center "X". This is unlike how GHC
currently printing the timing information: We essentially measure the time of
thunk creation, not normalization of thunks. So the numbers you get from the
profiling output may be more correct.

We should try actually forcing the values in `withTiming` and see how it'll
effect the timings. I feel like some of the costs attributed to CodeGen step
is because of thunks we generate in previous steps. It's probably not possible
to completely evaluate the values (because of cycles), but we can still do a
better job probably.

One last thing is that profiling can prevent some optimizations and cause
different runtime behavior. Problems with instrumentation ...

2016-03-31 12:01 GMT-04:00 Ömer Sinan Ağacan <omeragacan at gmail.com>:
> Forgot to mention that I use `cabal install <package name>
> --ghc-options="-v3" -v3` to install the packages.
>
> 2016-03-31 12:00 GMT-04:00 Ömer Sinan Ağacan <omeragacan at gmail.com>:
>> Hi Joachim,
>>
>> That's GHC HEAD at the time with -O1 for stage 2 + libs.
>>
>> The way I generate the logs is:
>>
>> - I create a cabal sandbox and run `cabal exec zsh` to set up the env
>>   variables.
>>
>> - I install packages in that shell.
>>
>> - $ (cat  .cabal-sandbox/logs/*.log | analyze-ghc-timings) > output
>>
>> I don't know why there would be that much difference. Note that my setup was
>> not perfect, I run some other (although lightweight) processes on the side.
>>
>> 2016-03-31 4:49 GMT-04:00 Joachim Breitner <mail at joachim-breitner.de>:
>>> Hi Ömer,
>>>
>>> thanks for the log. This is roughly GHC HEAD, right?
>>>
>>> I wanted to check for low-hanging fruit in “my” code, so I compiled
>>> Data.Reflection, where your tool reports 12% time spent in Call Arity.
>>>
>>> But if I run it with profiling, it says 3.5% of time is spent in that
>>> pass, and if I run your tool on the timing output produced by a
>>> profiled GHC, I get 8.3%, and on the output of a a development build, I
>>> get 3.8%.
>>>
>>>
>>> So what is your setup: How did you compile GHC, and with what options
>>> are you running it?
>>>
>>> Greetings,
>>> Joachim
>>>
>>>
>>>
>>> --
>>> Joachim “nomeata” Breitner
>>>   mail at joachim-breitner.de • https://www.joachim-breitner.de/
>>>   XMPP: nomeata at joachim-breitner.de • OpenPGP-Key: 0xF0FBF51F
>>>   Debian Developer: nomeata at debian.org
>>>
>>>
>>> _______________________________________________
>>> ghc-devs mailing list
>>> ghc-devs at haskell.org
>>> http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs
>>>