<div dir="ltr">Thanks Thomas,<div><br></div><div>I tried in Linux and the behavior of the time tool seems more reasonable now:</div><div><div>real<span style="white-space:pre-wrap"> </span>0m46.743s</div><div>user<span style="white-space:pre-wrap"> </span>0m45.888s</div><div>sys<span style="white-space:pre-wrap"> </span>0m0.160s</div></div><div><br></div><div>After checking some of the RTS documentation, it turns out the GC's cost centre is not included by default, in order to include I had to change the -p to -pa which results in:</div><div><div><span class="" style="white-space:pre"> </span> fast-fib +RTS -pa -RTS</div><div><br></div><div><span class="" style="white-space:pre"> </span>total time = 47.43 secs (47433 ticks @ 1000 us, 1 processor)</div><div><span class="" style="white-space:pre"> </span>total alloc = 44,128,957,088 bytes (excludes profiling overheads)</div><div><br></div><div>COST CENTRE MODULE %time %alloc ticks bytes</div><div><br></div><div>GC GC 86.0 0.0 40778 0</div><div>fastFibs.nextFib Main 13.1 99.6 6228 43952857104</div></div><div><br></div><div>This clearly states where that 86% difference was coming from, the GC, which means the world makes sense again :)</div><div><br></div><div>Does someone know how to add the cost centre for GC without having to use -pa?</div><div><br></div><div>Best regards,</div><div>Javier de Vega Ruiz.</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Oct 23, 2015 at 1:27 AM, Thomas Koster <span dir="ltr"><<a href="mailto:tkoster@gmail.com" target="_blank">tkoster@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Javier,<br>
<br>
On 23 October 2015 at 03:00, Javier de Vega Ruiz<br>
<div><div class="h5"><<a href="mailto:javier.devega.ruiz@gmail.com">javier.devega.ruiz@gmail.com</a>> wrote:<br>
> I am messing around with bang patterns and noticed some huge differences<br>
> between the total time as reported by the time tool and the .prof file.<br>
> Below is the code used.<br>
> Without bang patterns:<br>
> module Main where<br>
><br>
> import Data.List<br>
><br>
> fastFibs =<br>
> unfoldr nextFib (1, 1)<br>
> where nextFib (x, y) = Just $ (x, (y, (x + y)))<br>
><br>
> main =<br>
> putStrLn $ (show n) ++ "th fib is: " ++ (show $ fastFibs !! (n - 1))<br>
> where n = 1000000<br>
><br>
> With bang patterns:<br>
> {-# LANGUAGE BangPatterns #-}<br>
><br>
> module Main where<br>
><br>
> import Data.List<br>
><br>
> fastFibs =<br>
> unfoldr nextFib (1, 1)<br>
> where nextFib (!x, !y) = Just $ (x, (y, (x + y)))<br>
><br>
> main =<br>
> putStrLn $ (show n) ++ "th fib is: " ++ (show $ fastFibs !! (n - 1))<br>
> where n = 1000000<br>
><br>
> when looking at the first through time and prof I get the following.<br>
> Without:<br>
> real 0m53.501s<br>
> user 0m0.015s<br>
> sys 0m0.328s<br>
> Thu Oct 22 16:46 2015 Time and Allocation Profiling Report (Final)<br>
><br>
> fast-fib.exe +RTS -p -RTS<br>
><br>
> total time = 9.52 secs (9520 ticks @ 1000 us, 1 processor)<br>
> total alloc = 43,500,223,152 bytes (excludes profiling overheads)<br>
><br>
> Please note the huge difference 53 vs 9 seconds.<br>
><br>
> With:<br>
> real 0m10.095s<br>
> user 0m0.031s<br>
> sys 0m0.344s<br>
> Thu Oct 22 16:50 2015 Time and Allocation Profiling Report (Final)<br>
><br>
> fast-fib.exe +RTS -p -RTS<br>
><br>
> total time = 8.97 secs (8971 ticks @ 1000 us, 1 processor)<br>
> total alloc = 43,500,309,960 bytes (excludes profiling overheads)<br>
><br>
> Here differences seem to be much smaller.<br>
><br>
> I am using Windows 8.1 64 bit, GHC 7.8.3 and measuring with the following<br>
> line:<br>
> ghc Main.hs -o fast-fib.exe -O2 -prof && time ./fast-fib.exe +RTS -p && cat<br>
> fast-fib.prof<br>
><br>
> Could someone please explain where the big difference is coming from and how<br>
> to change the measuring approach to get more consistent results?<br>
<br>
</div></div>Before going into why the numbers are what they are, I think there is<br>
something wrong with your time tool on Windows. Your "user" time is<br>
suspiciously low in both measurements. When I ran your program on<br>
Linux, the report from the -s RTS option and the "real" and "user"<br>
numbers from the time tool were within milliseconds of each other<br>
(qualification: I used GHC 7.10.2).<br>
<br>
Apart from that, I am pretty sure the -p RTS option and the time tool<br>
are not measuring the same thing. I think the profiler samples "ticks"<br>
in the runtime, whereas the time tool and the -s option probably use<br>
CPU performance counters. Somebody more familiar with the GHC runtime<br>
should be able to give you more detail.<br>
<br>
--<br>
Thomas Koster<br>
_______________________________________________<br>
Beginners mailing list<br>
<a href="mailto:Beginners@haskell.org">Beginners@haskell.org</a><br>
<a href="http://mail.haskell.org/cgi-bin/mailman/listinfo/beginners" rel="noreferrer" target="_blank">http://mail.haskell.org/cgi-bin/mailman/listinfo/beginners</a><br>
</blockquote></div><br></div>