Update docs and lib

docs/enabling-perf-counters.md

@@ -0,0 +1,19 @@
+## Enable Linux perf counters
+
+Enable unrestricted use of perf counters:
+
+```
+# echo -1 > /proc/sys/kernel/perf_event_paranoid
+```
+
+## Disable CPU scaling
+
+Set the scaling governer of all your cpus to `performance`:
+
+```
+echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
+echo performance > /sys/devices/system/cpu/cpu1/cpufreq/scaling_governor
+...
+...
+echo performance > /sys/devices/system/cpu/cpu7/cpufreq/scaling_governor
+```

docs/eventlog-performance-analysis.md

@@ -1,12 +1,13 @@
-# GHC Event logging
+# Haskell Perf Analysis using Eventlog
 
-Available in GHC 9.2.8 RTS patch. Can be ported to later GHCs.
+The GHC RTS instrumentation for accurate and thread-aware event logging
+is available in GHC 9.2.8 RTS patch. Can be ported to later GHCs.
 
 <!--
 GHC Patch: https://github.com/composewell/ghc/tree/ghc-8.10.7-eventlog-enhancements
 -->
 
-Eventlog based Haskell thread aware time and allocation analysis is
+Eventlog based Haskell-thread aware time and allocation analysis is
 possible with stock GHC but there are some limitations and drawbacks
 which are fixed in the RTS patch described below. The patch adds
 accurate timing and allocation information and hardware performance
@@ -18,53 +19,57 @@ program not just the current thread.
 TBD: document the exact limitations and differences.
 -->
 
-## Enable Linux perf counters
+## Generating the eventlog
 
-Enable unrestricted use of perf counters:
+To generate the event log, we need to enable event log at compile time
+(on modern GHCs it is always enabled) and the run the program with
+eventlog enabled at run-time, we use the `-l` rts option to do that.
 
-```
-# echo -1 > /proc/sys/kernel/perf_event_paranoid
-```
+There are multiple ways of running your program with eventlog enabled at
+run-time:
 
-## Disable CPU scaling
-
-Set the scaling governer of all your cpus to `performance`:
+__GHC Command Line__:
 
+Compiling:
 ```
-echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
-echo performance > /sys/devices/system/cpu/cpu1/cpufreq/scaling_governor
-...
-...
-echo performance > /sys/devices/system/cpu/cpu7/cpufreq/scaling_governor
+ghc Main.hs -rtsopts
 ```
 
-## Generating the eventlog
-
-To generate the event log, we need to compile the program with the eventlog enabled
-and run the program setting the `-l` rts option.
-
-There are multiple ways of doing this.
-
-__Using plain GHC__:
-
+Running:
 ```
-ghc Main.hs -rtsopts -eventlog
 ./Main +RTS -l -RTS
 ```
 
-__Using Cabal__:
+You can bake in the rts options during compilation itself:
+```
+ghc Main.hs -with-rtsopts=-l
+```
 
-The `.cabal` file should contain the following ghc options
+Now you can run without any explicit RTS options:
 ```
-ghc-options: -eventlog "-with-rtsopts=-l"
+./Main
 ```
 
-If the `-threaded` option is used while compiling. You may want to use the `-N1`
-rts option.
+After we run the above program a "Main.eventlog" file will be generated. This
+file can be analyzed using the `hperf` executable in this package to
+generate an analysis report. To be able to find anything in the report you need
+to first instrument your program which is described in the following sections.
+
+Note 1: For older compilers you need `-eventlog` GHC flag as well when building
+
+Note 2: If the `-threaded` option is used while compiling. You may want
+to use the `-N1` rts option.
 
-## Creating windows
+## Measurement instrumentation
 
-Helper function to create windows:
+See the example in [examples/traceEventIO.hs](examples/traceEventIO.hs) .
+
+Use the `traceEventIO` function to log events. Add an event before and
+after the code block you want to measure. The event message before the block
+should be in the format "START: <label>", and the message after it should be
+"END: <label>" where the label for start and end must match.
+
+You can create a helper function as below:
 
 ```
 {-# LANGUAGE BangPatterns #-}
@@ -84,10 +89,15 @@ withTracingFlow tag action = do
 We can wrap parts of the flow we want to analyze with `withTracingFlow` using a
 tag to help us identify it.
 
-## End of Window
+Our analyzer program will analyze the windows between START and END.
+
+## End of Window Instrumentation
+
+START and END of the same label can be placed anywhere in the program, if any
+code path goes from START to END, it will be reported under the same label.
 
-You can put the END of the window in different paths but ensure that all paths
-are covered:
+Usually we should put an END event in all possible exit paths where multiple
+exit paths are possible.
 
 ```
   r <- f x
@@ -110,8 +120,9 @@ timing and allocations reported because of the measurement overhead.
     _ <- traceEventIO $ "END:emptyWindow"
 ```
 
-The timing is due to the time measurement system call itself. The allocations
-are due to the traceEventIO haskell code execution. TODO: fix the allocations.
+The time reported in this case is attributed to the time measurement system
+call itself which is invoked by traceEventIO. The allocations are also
+attributed to the traceEventIO haskell code execution.
 
 ## Measurement with Lazy Evaluation
 
@@ -133,10 +144,11 @@ For correct measurement use the following code:
     return v
 ```
 
-## Labelling Threads
+## Thread Labels
 
-We should label our threads to identify the thread to scrutinize while reading
-the stats.
+To be able to identify the threads in the eventlogs we should label the Haskell
+threads, the labels will be reported in the analysis, if there is no label we
+will not be able to know where that thread was spawned from.
 
 For example,
 
@@ -174,7 +186,7 @@ eventlogMiddleware app request respond = do
 
 We can use `eventlogMiddleware` as the outermost layer.
 
-## Reading the results
+## Analyzing the Eventlog Output
 
 We get a lot of output currently. We are in the process of simplifying the
 statistics and making the details controllable via options.

docs/ghc-rts-performance-analysis.md

@@ -1,48 +1,51 @@
-<!--
 # GHC RTS Stats
 
+GHC RTS has a builtin stats reporting mechanism which can be accessed
+using `+RTS -s` flag to print the stats when the program has terminated
+or if compiled with `-T` flag then we can access it programmatically via
+the `getRTSStats` API. It reports the CPU time used by the program and
+allocations among other things.
+
 RTS Stats give entire OS process level (not OS thread level) cpu time
-and not Haskell thread cpu time. When multiple OS threads are used, the
-cpu time recorded is the cpu time of all the threads combined. Also, the
-way kernel accounts this time it could be off by a little (microseconds)
-because each thread's cpu time is recorded at the last accounting
-event. Allocations are recorded by the GHC RTS only at the GC boundary,
-so the allocations reported are from the point when the last GC
-happened. So we need to be careful when using or interpreting these
-stats.
-
-If we built the program without -threaded and we are using a single
-Haskell thread then we can get cpu time between any two points in the
-program accurately. Accurate accounting of allocations will require a GC
-to be forced which is not usually practical.
+and not Haskell thread-wise cpu time. When multiple OS threads are
+used, the cpu time reported is the cpu time of all the Haskell threads
+combined, and all the OS threads combined.
+
+<!--
+Also, the way kernel accounts this time it could be off by a little
+(microseconds) because each thread's cpu time is recorded at the last
+kernel accounting event. Allocations are recorded by the GHC RTS only at
+the GC boundary, so the allocations reported are from the point when the
+last GC happened. So we need to be careful when using or interpreting
+these stats.
+-->
 
 In a multithreaded program using RTS stats we can only tell time how
 much total CPU time (and allocations) the entire Haskell process (all
 threads) spent between two points, but we cannot tell which Haskell
-thread spent how much time.
--->
+thread spent how much time or how much time was actually spent by the
+instructions between those two points.
 
-# Components of a Haskell Process
+## Components of a Haskell Process
 
 * An OS level process
 * Multiple OS level threads in the OS process
 * Multiple Haskell green threads that are scheduled on the OS threads. Haskell
   threads can run on any of the available OS threads every time it is ready to
   run.
 
-# A prototypical program
+## A prototypical program
 
-A simple yet comprehensive program to understand different components of
+[This example](examples/console-loop-multi-thread.hs) is a
+a simple yet comprehensive program to understand different components of
 performance analysis and stats. You can play with this to understand how things
 work, how the stats add up and what they mean.
 
-See examples/console-loop-multi-thread.hs .
+## How many OS threads do we have?
 
-# How many OS threads do we have?
-
-To see how may OS threads a haskell process is using on Linux.
-Run examples/console-loop-multi-thread.hs , note its pid printed in the output.
-All of its OS threads are:
+To see how many OS threads a Haskell process is using on Linux.  Run
+[this example](examples/console-loop-multi-thread.hs), note its pid
+printed in the output.  All of its OS threads can be printed by:
 ```
 ls /proc/<PID>/task
 ```
@@ -62,7 +65,7 @@ specified with the -N rts option.
 Usually we see 3 threads plus 2 threads per capability when compiled
 with `-threaded` option.
 
-# GHC RTS stats
+## GHC RTS stats
 
 The getRTSStats call gives us the CPU time (essentially get_clocktime
 or getrusage under the hood to get the CPU time) of the process and
@@ -72,7 +75,7 @@ getRTSStats at point B and diff them?
 There are two problems with this. (1) the allocation count is recorded
 from the last GC which does not correspond to point A or point B unless
 we force a GC at both the points which is not practical and is going to
-change the performance characterstics of the program drastically. (2)
+change the performance characteristics of the program drastically. (2)
 the CPU time that we get is for the entire process which includes all
 the OS threads, if the program is built with `-threaded` option then
 this is always going to be inaccurate; even if we get OS thread level
@@ -91,17 +94,10 @@ This is used in this way in micro-benchmarking programs but it is very
 restrictive and useless in practice.
 
 For small programs though the `+RTS -s` options is very useful to assess the
-performance characterstics. I often take out the small piece that I want to
+performance characteristics. I often take out the small piece that I want to
 measure and run it with `+RTS -s`.
 
-# Using it
-
-In the haskell-perf library we do have a convenient way to wrap a function
-around and use getRTSStats before and after it. If the function passes the
-criterion mentioned above then we can get a decent measurement, not very
-accurate but workable. We automatically perform a GC before and after.
-
-# Interpreting the RTS Stats
+## Interpreting the RTS Stats
 
 We divide the stats in two categories.  The first category is the non-gc
 stats, these stats are accurate up to the time of the `getRTSStats`
@@ -125,20 +121,53 @@ in this category.
 Note that the GC cpu time should be computed by adding the `gc_cpu_ns`
 and `nonmoving_gc_cpu_ns` when the non-moving gc is enabled.
 
-# Variability of Measurements
+## Variability of Measurements
 
 Performance measurement is tricky and there are many factors to take care of if
 you want to get reliable results:
 
-* cannot use wall-clock time, need to use process cpu time
-* disable CPU frequency scaling
-* Memory contention can affect the measurement, do not run other things on the
-  same machine.
-* cache effect due to context switching can affect it, do not run other things
-  on the same machine.
+* Disable CPU frequency scaling, can cause run-to-run or variability in the
+  same run.
+* Do not run other things on the same machine. interrupts, kernel
+  activity, background daemons can also affect:
+  * Memory contention can affect the measurement.
+  * cache effects due to context switching can affect it.
+* Discard first runs, first runs are usually outliers because of warm up effects,
+  instruction cache cold, data cache cold, page faults, branch predictor
+  not trained.
+* Use thread affinity. Thread migration to another CPU: causes cache
+  invalidation, different core state, timing noise.
+* Use larger measurements. In smaller one measurement overhead and
+  variance may dominate: timing calls (clock_gettime), counters, RTS
+  stats.
 * Different CPUs running at different frequencies can make the results
   unpredictable.
-* The clocks of different CPUs may not be in sync.
+* The clocks of different CPUs may not be perfectly in sync.
+
+To counter the last two factors we should use instruction count or
+allocation count rather than time as a more reliable measure. Even
+the instruction count might vary because of measurement overhead adds
+instruction count, which can vary depending on how many times the thread
+is context switched.
+
+## Haskell specific variability
+
+* Lazy evaluation, may defer work which might get evaluated later in the
+  context of some other measurement window.
+
+## Using getRTSStats with haskell-perf
+
+In the `haskell-perf` library we do have a convenient way to wrap a
+function around to use `getRTSStats` before and after it and print the
+resulting stats. If the function passes the criterion mentioned above
+then we can get a decent measurement, not very accurate but workable. We
+automatically perform a GC before and after.
+
+## Summary:
 
-To counter the last two factors we should use instruction count or allocation
-count rather than time as a reliable measure.
+* `+RTS -s` option is very useful in assessing the behavior of the entire
+  program.
+* `getRTSStats` can be used to measure the timing of a piece of code if we are
+  single threaded, the thread does not yield during the measurement, we are
+  forcing GCs for roughly correct allocation counts. GCs happening in the
+  middle of the measurement can add to the noise.

examples/README.md

@@ -5,7 +5,7 @@ console-loop.hs -- console echo loop
 delay-loop.hs -- threadDelay in a loop
 ffi.hs -- fork one thread + FFI c_sleep
 
-# In memory collection
+# In-memory collection
 
 threadCPUTime.hs -- single threaded stat collection