Refactor #22

maoe · 2017-03-12T20:56:50Z

This PR aims to

implement a lazy eventlog reader API that supports streaming
make the GHC.RTS.Events API closer to v0.4

In order to achieve these, I did

rewrite the incremental API as GHC.RTS.Events.Incremental
factor out the parser/serializer to GHC.RTS.Events.Binary, which is a hidden module (for now)

Also I did some small cleanup and fixed a space leak.

As for reviews, I guess it's easier to understand if you look at each commit in order. The first 9 commits implement the new incremental API, then 3dd58cf and bcb4595 make the API closer to v0.4. Other commits are small cleanup etc.

GHC.RTS.Events.Incremental

While I'm implementing ghc-events gc (pause|interval) commands in my gc-stats branch, I found that the current incremental API is a bit awkward to use because readEventLogFromFile has been deprecated and it cannot stream output as it reads events. It cannot stream output because it has to reverse events.

The new incremental API allows readEventLogFromFile to stream output and events don't have to be reversed. Also I've retracted the deprecation on readEventLogFromFile as it's now able to stream output.

GHC.RTS.Events.Binary

This module was necessary to make the API closer to the previous version of ghc-events. I found it a bit strange that the Incremental (and EventsIncremental) module exports eventlog serializers because the serializers don't have anything to do with the incremental decoder.

I made the GHC.RTS.Events.Binary module and moved all serializers/deserializers into it so it can be used either from GHC.RTS.Events and GHC.RTS.Events.Incremental.

Now that we can move the I/O interface (read/writeEventLogFromFile) back to GHC.RTS.Events.

Breaking changes

GHC.RTS.EventsIncremental has been rewritten as GHC.RTS.Events.Incremental
Some format has changed in ghc-events show
- No leading whitespace in timestamps
- No indication of incomplete eventlog
GHC.RTS.Events doesn't export the parsers

Performance

The performance characteristics of ghc-events show has changed. Heap allocation has been greatly reduced. Unfortunately due to the use of sortEvents, ghc-events show still can't run in constant space though.

% ls -lh small.eventlog
-rw-r--r--  1 maoe  staff   2.0M Feb 18 07:24 small.eventlog
% ./ghc-events.master show small.eventlog > master.out +RTS -sstderr
Warning: The event log was not fully parsed. It could have been malformed or incomplete.
   1,564,294,056 bytes allocated in the heap
     135,686,952 bytes copied during GC
      22,383,952 bytes maximum residency (7 sample(s))
       1,502,000 bytes maximum slop
              66 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0      2122 colls,     0 par    0.06s    0.07s     0.0000s    0.0009s
  Gen  1         7 colls,     0 par    0.05s    0.06s     0.0092s    0.0254s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    0.22s  (  0.23s elapsed)
  GC      time    0.11s  (  0.13s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    0.33s  (  0.37s elapsed)

  %GC     time      32.9%  (36.2% elapsed)

  Alloc rate    7,052,755,224 bytes per MUT second

  Productivity  67.0% of total user, 60.1% of total elapsed

% ./ghc-events.refactor show small.eventlog > refactor.out +RTS -sstderr
     438,965,280 bytes allocated in the heap
     326,603,680 bytes copied during GC
       8,016,040 bytes maximum residency (57 sample(s))
         361,144 bytes maximum slop
              25 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0       766 colls,     0 par    0.11s    0.11s     0.0002s    0.0005s
  Gen  1        57 colls,     0 par    0.10s    0.11s     0.0019s    0.0105s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    0.10s  (  0.10s elapsed)
  GC      time    0.21s  (  0.22s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    0.31s  (  0.33s elapsed)

  %GC     time      68.7%  (68.1% elapsed)

  Alloc rate    4,578,468,855 bytes per MUT second

  Productivity  31.3% of total user, 29.5% of total elapsed
% diff -w master.out refactor.out
111017d111016
<

The runtime of ghc-events inc has been improved a bit:

% ls -lh app.eventlog
-rw-r--r--  1 maoe  staff    36M Feb 18 07:24 app.eventlog
% ./ghc-events.master inc app.eventlog > master.out +RTS -sstderr
   4,614,234,640 bytes allocated in the heap
       5,488,672 bytes copied during GC
          90,080 bytes maximum residency (2 sample(s))
          35,472 bytes maximum slop
               1 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0      8787 colls,     0 par    0.04s    0.04s     0.0000s    0.0001s
  Gen  1         2 colls,     0 par    0.00s    0.00s     0.0002s    0.0003s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    1.33s  (  1.49s elapsed)
  GC      time    0.04s  (  0.04s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    1.37s  (  1.53s elapsed)

  %GC     time       2.8%  (2.9% elapsed)

  Alloc rate    3,468,658,229 bytes per MUT second

  Productivity  97.2% of total user, 86.9% of total elapsed

% ./ghc-events.refactor inc app.eventlog > refactor.out +RTS -sstderr
   4,297,141,368 bytes allocated in the heap
       5,085,992 bytes copied during GC
          86,104 bytes maximum residency (2 sample(s))
          29,776 bytes maximum slop
               1 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0      8113 colls,     0 par    0.03s    0.04s     0.0000s    0.0001s
  Gen  1         2 colls,     0 par    0.00s    0.00s     0.0002s    0.0003s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time    1.24s  (  1.38s elapsed)
  GC      time    0.03s  (  0.04s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time    1.27s  (  1.42s elapsed)

  %GC     time       2.6%  (2.7% elapsed)

  Alloc rate    3,479,314,562 bytes per MUT second

  Productivity  97.4% of total user, 87.3% of total elapsed
% diff -w master.out refactor.out
2244442d2244441
< Finished (file was parsed successfully)

maoe · 2017-03-12T21:06:11Z

@kvelicka Would you mind reviewing this PR because it does break your incremental parser API?

kvelicka · 2017-03-13T21:03:00Z

I've only had a first pass at the code but the first impression is 👍

I'll try to look into it more later in the week.

See haskell/ghc-events#22 for the changes in ghc-events.

maoe · 2017-03-30T02:04:34Z

I made a change in threadscope for this refactor: haskell/ThreadScope@master...maoe:ghc-events-refactor. Basically nothing has changed.

kvelicka · 2017-04-08T11:06:00Z

src/GHC/RTS/Events/Incremental.hs

+          Done leftover -> Right (header, BL.Chunk leftover bytes)
+          _ -> fail "readHeader: unexpected decoder"
+        Consume k -> case bytes of
+          BL.Empty -> fail "readHeader: not enough bytes"


Does this mean that a caller has to supply a ByteString containing (at least) all of the header in one go? In other words, is reading the header non-incremental?

That's right. For incremental parsing of a header, one should use decodeHeader. Maybe I should mention this behavior in the Haddock comment.

Added a note about this in 53f2872.

kvelicka

Looks very nice, good job!

Admittedly I haven't tested this myself but given that the tests pass (and the fact that you seem to be using the library in your own code), I am quite confident in the correctness of the patch. I've had a couple of questions here and there but they're mostly minor things.

kvelicka · 2017-04-08T11:21:52Z

src/GHC/RTS/Events/Incremental.hs

+-- | Serialises an 'EventLog' back to a 'ByteString', usually for writing it
+-- back to a file.
+serialiseEventLog :: EventLog -> BL.ByteString
+serialiseEventLog el@(EventLog _ (Data events)) =


Have you tested serialising at all? I think it'd be a good thing to write some tests for!

No, not really because it hasn't changed aside some code formatting and renaming (isCap -> mkCap).

I agree that it's a good thing to write some tests. I guess we start by fixing #14.

I suppose this test would be a good intermediate step to fixing it -- currently I'm not sure whether the bug is in the writing or merging code (or both!)

kvelicka · 2017-04-08T11:27:27Z

src/GHC/RTS/Events.hs

@@ -1,6 +1,7 @@
 {-# LANGUAGE CPP,BangPatterns #-}
 {-# LANGUAGE OverloadedStrings #-}
 {-# LANGUAGE MultiWayIf #-}
+{-# OPTIONS_GHC -fsimpl-tick-factor=150 #-}


I couldn't find much on what this means -- can you elaborate?

If we delete this line, GHC fails to compile this module like this:

ghc: panic! (the 'impossible' happened) (GHC version 8.0.2 for x86_64-apple-darwin): Simplifier ticks exhausted When trying UnfoldingDone $fNumInt_$c+ To increase the limit, use -fsimpl-tick-factor=N (default 100) If you need to do this, let GHC HQ know, and what factor you needed To see detailed counts use -ddump-simpl-stats Total ticks: 196000

See -fsimpl-tick-factor for the explanation of this flag. I've increased it from 100 to 150 to avoid this panic. https://ghc.haskell.org/trac/ghc/ticket/11263 is a similar issue.

I haven't tracked down the root cause but I think it's benign as we have neither custom RULES nor INLINEs in the code.

maoe

Thanks for reviewing this. I'm going to extend the Haddock comment on readHeader.

maoe · 2017-04-08T21:11:13Z

src/GHC/RTS/Events/Incremental.hs

+          Done leftover -> Right (header, BL.Chunk leftover bytes)
+          _ -> fail "readHeader: unexpected decoder"
+        Consume k -> case bytes of
+          BL.Empty -> fail "readHeader: not enough bytes"


That's right. For incremental parsing of a header, one should use decodeHeader. Maybe I should mention this behavior in the Haddock comment.

maoe · 2017-04-08T21:21:15Z

src/GHC/RTS/Events/Incremental.hs

+-- | Serialises an 'EventLog' back to a 'ByteString', usually for writing it
+-- back to a file.
+serialiseEventLog :: EventLog -> BL.ByteString
+serialiseEventLog el@(EventLog _ (Data events)) =


No, not really because it hasn't changed aside some code formatting and renaming (isCap -> mkCap).

I agree that it's a good thing to write some tests. I guess we start by fixing #14.

maoe · 2017-04-08T21:36:14Z

src/GHC/RTS/Events.hs

@@ -1,6 +1,7 @@
 {-# LANGUAGE CPP,BangPatterns #-}
 {-# LANGUAGE OverloadedStrings #-}
 {-# LANGUAGE MultiWayIf #-}
+{-# OPTIONS_GHC -fsimpl-tick-factor=150 #-}


If we delete this line, GHC fails to compile this module like this:

ghc: panic! (the 'impossible' happened) (GHC version 8.0.2 for x86_64-apple-darwin): Simplifier ticks exhausted When trying UnfoldingDone $fNumInt_$c+ To increase the limit, use -fsimpl-tick-factor=N (default 100) If you need to do this, let GHC HQ know, and what factor you needed To see detailed counts use -ddump-simpl-stats Total ticks: 196000

See -fsimpl-tick-factor for the explanation of this flag. I've increased it from 100 to 150 to avoid this panic. https://ghc.haskell.org/trac/ghc/ticket/11263 is a similar issue.

I haven't tracked down the root cause but I think it's benign as we have neither custom RULES nor INLINEs in the code.

kvelicka · 2017-04-09T14:50:06Z

Thanks for adding the comment. 👍 from me

maoe · 2017-04-09T21:00:08Z

Thanks! I'm going to merge this.

Mitsutoshi Aoe added 16 commits March 12, 2017 06:31

Add GHC.RTS.Events.Incremental

8054d24

Move mkEventDecoder from EventsIncremental

b9962e5

ghc-events: Switch to the new incremental API

4186e09

test: Switch to the new incremental API

7e16284

Strictify status to prevent space leak

b402895

Use bytestring builder for ppEventLog

6bddb6f

Implement following mode in printEventsIncremental

bda6ac3

Move writeEventLogToFile and serialiseEventLog to Incremental

585bbca

Delete GHC.RTS.EventsIncremental

2c39fc7

Add Haddock comments

fd234b6

Enable -Wall and fix warnings

1fef97a

Remove trailing space in code

2265915

Move all decoders and encoders to the Binary module

3dd58cf

Move I/O interface in Incremental to Events

bcb4595

Remove unnecessary GHC_OPTIONS and add -fsimpl-tick-factor=150 to Events

61ffacf

Improve Haddock

d3a2789

maoe pushed a commit to maoe/ThreadScope that referenced this pull request Mar 30, 2017

Changes for the refactored ghc-events

c25feb8

See haskell/ghc-events#22 for the changes in ghc-events.

maoe requested a review from kvelicka March 30, 2017 02:05

kvelicka reviewed Apr 8, 2017

View reviewed changes

kvelicka approved these changes Apr 8, 2017

View reviewed changes

maoe commented Apr 8, 2017

View reviewed changes

Add note about non-incremental parsing of readHeader

53f2872

maoe merged commit 58aefed into haskell:master Apr 9, 2017

maoe deleted the refactor branch April 9, 2017 21:00

maoe mentioned this pull request Apr 10, 2017

Change for the latest ghc-events haskell/ThreadScope#61

Merged

maoe mentioned this pull request May 29, 2017

Make write-merge test buildable #28

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor #22

Refactor #22

maoe commented Mar 12, 2017 •

edited

Loading

maoe commented Mar 12, 2017

kvelicka commented Mar 13, 2017

maoe commented Mar 30, 2017

kvelicka Apr 8, 2017

maoe Apr 8, 2017

maoe Apr 8, 2017

kvelicka left a comment

kvelicka Apr 8, 2017

maoe Apr 8, 2017

kvelicka Apr 9, 2017

kvelicka Apr 8, 2017

maoe Apr 8, 2017

maoe left a comment

maoe Apr 8, 2017

maoe Apr 8, 2017

maoe Apr 8, 2017

kvelicka commented Apr 9, 2017

maoe commented Apr 9, 2017

Refactor #22

Refactor #22

Conversation

maoe commented Mar 12, 2017 • edited Loading

GHC.RTS.Events.Incremental

GHC.RTS.Events.Binary

Breaking changes

Performance

maoe commented Mar 12, 2017

kvelicka commented Mar 13, 2017

maoe commented Mar 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kvelicka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maoe left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kvelicka commented Apr 9, 2017

maoe commented Apr 9, 2017

maoe commented Mar 12, 2017 •

edited

Loading