Haskell: How to accurately measure calculations with deepseq / force

Question

I have a web server written in Haskell that calculates some data in a few steps.

I want to accurately measure and show how much time each action takes.

In the presence of laziness, what is a good way to do this?

---

Please note that benchmarking is not a completely correct terminology, since I only want to measure time in the production system, and not an example of many runs. I know that in this case I can use criterion .

Answer 1

You can use force from Control.DeepSeq to fully evaluate the data structure (and therefore ask and measure its calculation).

One of the problems is that forcing a large data structure takes some time!

This is because deepseq (used by force ) will go down with your algebraic data type tree, visiting each node (but not doing anything with it).

When you perform only a cheap operation for each node, for example map (*2) mylist , and try to measure how long it will take, this overhead can suddenly become significant, ruining your measurements.

 import Control.DeepSeq import Control.Exception (evaluate) import Data.Time (diffUTCTime, getCurrentTime) -- | Measures how long a computation takes, printing both the time and the -- overhead of `force` to stdout. So it forces *twice*. benchmarkForce :: NFData a => String -> IO a -> IO a benchmarkForce msg action = do before <- getCurrentTime -- Force the first time to measure computation + forcing result <- evaluate . force =<< action after <- getCurrentTime -- Force again to see how long forcing itself takes _ <- evaluate . force $ result afterAgain <- getCurrentTime putStrLn $ msg ++ ": " ++ show (diffTimeMs before after) ++ " ms" ++ " (force time: " ++ show (diffTimeMs after afterAgain) ++ " ms)" return result where -- Time difference `t2 - t1` in milliseconds diffTimeMs t1 t2 = realToFrac (t2 `diffUTCTime` t1) * 1000.0 :: Double 

First run evaluate . force evaluate . force ensures that your action and its return value are fully appreciated.

Having done the second force run of the result, we can measure how much overhead was added to the first round.

This, of course, is due to two rounds; Being able to measure how much time deepseq waste requires you to waste this time twice.

Here is an example to measure some pure functions with:

 main :: IO () main = do l <- benchmarkForce "create list" $ return [1..10000000 :: Integer] _ <- benchmarkForce "double each list element" $ return $ map (*2) l _ <- benchmarkForce "map id l" $ return $ map id l return () 

(Of course, it also works with functions in IO.)

Output:

 create list: 1091.936 ms (force time: 71.33200000000001 ms) double each list element: 1416.0569999999998 ms (force time: 96.808 ms) map id l: 484.493 ms (force time: 67.232 ms) 

As we can see, force creates about 13% of the overhead in the case of map id l .