Preserve EventBlock events

src/GHC/RTS/Events.hs

@@ -113,7 +113,7 @@ printEventsIncremental
   :: Bool -- ^ Follow the file or not
   -> FilePath
   -> IO ()
-printEventsIncremental follow path =
+printEventsIncremental follow path = do
   withFile path ReadMode (hPrintEventsIncremental follow)
 
 -- | Read an event log from the Handle and pretty print it to stdout
@@ -151,9 +151,8 @@ serialiseEventLog el@(EventLog _ (Data events)) =
   P.runPut $ putEventLog blockedEl
   where
     eventsMap = capSplitEvents events
-    blockedEventsMap = IM.mapWithKey addBlockMarker eventsMap
+    blockedEvents = joinCapEvents eventsMap
     blockedEl = el{dat = Data blockedEvents}
-    blockedEvents = IM.foldr (++) [] blockedEventsMap
 
 -- Gets the Capability of an event in numeric form
 getIntCap :: Event -> Int
@@ -165,26 +164,41 @@ getIntCap Event{evCap = cap} =
 -- Creates an IntMap of the events with capability number as the key.
 -- Key -1 indicates global (capless) event
 capSplitEvents :: [Event] -> IM.IntMap [Event]
-capSplitEvents evts = capSplitEvents' evts IM.empty
+capSplitEvents evts = IM.map reverse $ capSplitEvents' evts IM.empty
 
 capSplitEvents' :: [Event] -> IM.IntMap [Event] -> IM.IntMap [Event]
 capSplitEvents' evts imap =
   case evts of
   (x:xs) -> capSplitEvents' xs (IM.insertWith (++) (getIntCap x) [x] imap)
   []     -> imap
 
--- Adds a block marker to the beginning of a list of events, annotated with
--- its capability. All events are expected to belong to the same cap.
-addBlockMarker :: Int -> [Event] -> [Event]
-addBlockMarker cap evts =
-  (Event startTime (EventBlock endTime cap sz) (mkCap cap)) : sortedEvts
+-- | Join events labelled by capability into one sorted valid eventlog.
+joinCapEvents :: IM.IntMap [Event] -> [Event]
+joinCapEvents eventMap = go capEventsByStartTime
   where
-    sz = fromIntegral . BL.length $ P.runPut $ mapM_ putEvent evts
-    startTime = case sortedEvts of
-      (x:_) -> evTime x
-      [] -> error "Cannot add block marker to an empty list of events"
-    sortedEvts = sortEvents evts
-    endTime = evTime $ last sortedEvts
+    capEvents :: [[Event]]
+    capEvents = map snd $ IM.toList eventMap
+    -- Create a map keyed by start time
+    capEventsByStartTime = IM.fromList [(fromIntegral (evTime x), x:xs) | (x:xs) <- capEvents]
+    insertEvs (e:evs) evMap = IM.insert (fromIntegral (evTime e)) (e:evs) evMap
+    insertEvs [] evMap = evMap
+    go :: IM.IntMap [Event] -> [Event]
+    go events =
+      -- Pop the capability with the earliest event
+      case IM.minView events of
+        Nothing -> []
+        Just (evs, events') ->
+          let (chunk, rest) = splitEventBlock evs
+          in chunk ++ go (insertEvs rest events') -- place the remaining chunk back into the map
+
+-- | Split a block of events out from a stream of events.
+-- Invariant: The first event is of type EventBlock
+splitEventBlock :: [Event] -> ([Event], [Event])
+splitEventBlock [] = ([],[])
+splitEventBlock (ev@Event{evSpec = EventBlock{end_time = end}}:evs) = (ev:ls, rs)
+  where
+    (ls, rs) = span (\e -> evTime e <= end) evs
+splitEventBlock xs = error "Each block of events must start with an EventBlock event but one wasn't found"
 
 -- -----------------------------------------------------------------------------
 -- Utilities
@@ -206,7 +220,7 @@ buildEventInfo spec' =
     case spec' of
         EventBlock end_time cap _block_events ->
           "event block: cap " <> TB.decimal cap
-          <> ", end time: " <> TB.decimal end_time <> "\n"
+          <> ", end time: " <> buildTime RawTime end_time <> "\n"
         Startup n_caps ->
           "startup: " <> TB.decimal n_caps <> " capabilities"
         CreateThread thread ->

src/GHC/RTS/Events/Incremental.hs

@@ -83,7 +83,7 @@ decodeEvents header = go (0 :: Int) Nothing decoder0
         case r of
           Just event -> case evSpec event of
             EventBlock {..} ->
-              go (fromIntegral block_size) (mkCap cap) decoder'
+              Produce (event { evCap = mkCap cap }) $ go (fromIntegral block_size) (mkCap cap) decoder'
             _ -> do
               let
                 !remaining' = remaining - fromIntegral consumed

test/WriteMerge.hs

@@ -32,8 +32,8 @@ testFile f = do
   case e of
     Left m -> oops m
     Right log -> do
-      let old = ppEventLog log
-      let new = ppEventLog $ rewriteLog log
+      let old = ppEventLog RawTime log
+      let new = ppEventLog RawTime $ rewriteLog log
       if old == new
         then putStrLn (f ++ ": success") >> return True
         else do

test/biographical-samples.eventlog.reference

@@ -60,6 +60,10 @@ Event Types:
 181: User binary message (size variable)
 
 Events:
+167696: event block: cap 65535, end time: 4710903537
+
+168294: cap 0: event block: cap 0, end time: 4710902731
+
 169333: created capset 0 of type CapsetOsProcess
 169544: created capset 1 of type CapsetClockDomain
 170610: created cap 0

test/ghc-9.2-events.eventlog.reference

@@ -76,6 +76,10 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+16349: cap 0: event block: cap 0, end time: 95662
+
+65158: event block: cap 65535, end time: 93773
+
 89741: created capset 0 of type CapsetOsProcess
 89791: created capset 1 of type CapsetClockDomain
 90910: created cap 0
@@ -86,6 +90,10 @@ Events:
 92154: capset 0: parent pid 10335
 92924: capset 0: RTS version "GHC-9.1.20210309 rts_l"
 93365: capset 0: args: ["./Test","+RTS","-l-agu"]
+95590: event block: cap 65535, end time: 168704549
+
+96827: cap 0: event block: cap 0, end time: 168652009
+
 135189: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 4194304 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
 146361: Info Table: 409f78:21:sat_s154_info - Test.hs:5:1-30
 146642: Info Table: 409fd8:21:sat_s157_info - Test.hs:5:1-30

test/hello-ghc-8.2.2.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+685400: event block: cap 65535, end time: 2127400
+
+685500: cap 0: event block: cap 0, end time: 2126300
+
 693200: created capset 0 of type CapsetOsProcess
 693300: created capset 1 of type CapsetClockDomain
 693800: created cap 0

test/hello-ghc-8.6.5.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+586900: event block: cap 65535, end time: 3020700
+
+587000: cap 0: event block: cap 0, end time: 3019800
+
 595100: created capset 0 of type CapsetOsProcess
 595200: created capset 1 of type CapsetClockDomain
 596200: created cap 0

test/nonmoving-gc-census-T23340.eventlog.reference

@@ -77,11 +77,19 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+22000: cap 0: event block: cap 0, end time: 227298
+
+165299: event block: cap 65535, end time: 222798
+
 219698: capset 1: wall clock time 1694431580s 894343000ns (unix epoch)
 220498: capset 0: pid 2073360
 221298: capset 0: parent pid 1906706
 222298: capset 0: RTS version "GHC-9.9.20230901 rts_v"
 222498: capset 0: args: ["nofib/shootout/binary-trees/Main","15","11","+RTS","-xn","-l-an"]
+227198: event block: cap 65535, end time: 60523906
+
+228998: cap 0: event block: cap 0, end time: 60490507
+
 3158969: Starting nonmoving GC preparation
 3161769: Marking roots for nonmoving GC
 3162369: Finished marking roots for nonmoving GC

test/nonmoving-gc-census.eventlog.reference

@@ -70,6 +70,10 @@ Event Types:
 207: Nonmoving heap census (size 13)
 
 Events:
+202792: event block: cap 65535, end time: 240776872
+
+203138: cap 0: event block: cap 0, end time: 240773783
+
 227855: capset 1: wall clock time 1587597517s 544758000ns (unix epoch)
 229418: capset 0: pid 1158
 231368: capset 0: parent pid 25700

test/nonmoving-gc-pruned-segments.eventlog.reference

@@ -78,11 +78,19 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+16507: cap 0: event block: cap 0, end time: 104991
+
+71577: event block: cap 65535, end time: 103639
+
 101786: capset 1: wall clock time 1723223845s 324076000ns (unix epoch)
 102167: capset 0: pid 1828277
 102377: capset 0: parent pid 74621
 103208: capset 0: RTS version "GHC-9.11.20240805 rts_v"
 103419: capset 0: args: ["nofib/shootout/binary-trees/Main","15","11","+RTS","-xn","-l-an"]
+104951: event block: cap 65535, end time: 253628994
+
+105712: cap 0: event block: cap 0, end time: 253582257
+
 2555721: Starting nonmoving GC preparation
 2557364: Marking roots for nonmoving GC
 2557755: Finished marking roots for nonmoving GC

test/nonmoving-gc.eventlog.reference

@@ -70,6 +70,10 @@ Event Types:
 207: Nonmoving heap census (size 13)
 
 Events:
+586175: event block: cap 65535, end time: 152601164
+
+588752: cap 0: event block: cap 0, end time: 152599709
+
 620636: capset 1: wall clock time 1587578331s 829795000ns (unix epoch)
 627395: capset 0: pid 20807
 636419: capset 0: parent pid 18766

test/parallelTest.eventlog.reference

@@ -66,6 +66,10 @@ Event Types:
 
 Events:
 965: creating machine 2 at 143714457434916300
+1016685948: event block: cap 65535, end time: 1038027965
+
+1016686389: cap 0: event block: cap 0, end time: 1037995887
+
 1016690453: startup: 1 capabilities
 1016695409: compiler version is 7.10.20150612
 1016698802: program invocation: /opt/Eden/test/./jost=ChainDep 2 3 +RTS -l -RTS

test/sleep.h.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+153018: event block: cap 65535, end time: 5008831028
+
+154205: cap 0: event block: cap 0, end time: 5008828444
+
 158325: created capset 0 of type CapsetOsProcess
 160770: created capset 1 of type CapsetClockDomain
 165658: created cap 0

test/sleep.hC.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+125082: event block: cap 65535, end time: 5008074669
+
+126199: cap 0: event block: cap 0, end time: 5008070199
+
 130320: created capset 0 of type CapsetOsProcess
 132904: created capset 1 of type CapsetClockDomain
 151342: created cap 0

test/sleep.hd.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+104061: event block: cap 65535, end time: 5007722540
+
+104969: cap 0: event block: cap 0, end time: 5007719607
+
 108251: created capset 0 of type CapsetOsProcess
 110486: created capset 1 of type CapsetClockDomain
 114676: created cap 0

test/sleep.hm.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+59992: event block: cap 65535, end time: 5007638802
+
+60970: cap 0: event block: cap 0, end time: 5007635031
+
 63274: created capset 0 of type CapsetOsProcess
 64951: created capset 1 of type CapsetClockDomain
 67604: created cap 0

test/sleep.hy.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+143659: event block: cap 65535, end time: 5009206903
+
+144917: cap 0: event block: cap 0, end time: 5009202782
+
 148828: created capset 0 of type CapsetOsProcess
 151691: created capset 1 of type CapsetClockDomain
 156999: created cap 0

test/stop.hT.eventlog.reference

@@ -57,6 +57,10 @@ Event Types:
 164: Heap profile string sample (size variable)
 
 Events:
+237000: event block: cap 65535, end time: 2284839000
+
+240000: cap 0: event block: cap 0, end time: 2057408000
+
 254000: created capset 0 of type CapsetOsProcess
 261000: created capset 1 of type CapsetClockDomain
 264000: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
@@ -111964,6 +111968,8 @@ Events:
 2057387000: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
 2057387000: cap 0: running thread 5
 2057407000: cap 0: stopping thread 5 (stack overflow, size 0)
+2058459000: cap 0: event block: cap 0, end time: 2284740000
+
 2058459000: cap 0: running thread 5
 2058535000: cap 0: stopping thread 5 (stack overflow, size 0)
 2058536000: cap 0: running thread 5

test/ticky-begin-sample.eventlog.reference

@@ -76,6 +76,10 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+91000: cap 0: event block: cap 0, end time: 409000
+
+285000: event block: cap 65535, end time: 390000
+
 364000: created capset 0 of type CapsetOsProcess
 364000: created capset 1 of type CapsetClockDomain
 367000: created cap 0
@@ -86,6 +90,10 @@ Events:
 379000: capset 0: parent pid 62660
 386000: capset 0: RTS version "GHC-9.3.20210422 rts_debug"
 389000: capset 0: args: ["./Test","+RTS","-lT"]
+409000: event block: cap 65535, end time: 21113000
+
+413000: cap 0: event block: cap 0, end time: 21046000
+
 4695000: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 4194304 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
 4782000: task 0x7f8905405ea0 created on cap 0 with OS kernel thread 14286148
 4784000: cap 0: creating thread 1

test/ticky-json.eventlog.reference

@@ -77,6 +77,10 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+95534: cap 0: event block: cap 0, end time: 638781
+
+380097: event block: cap 65535, end time: 611858
+
 585533: created capset 0 of type CapsetOsProcess
 586678: created capset 1 of type CapsetClockDomain
 589432: created cap 0
@@ -87,6 +91,10 @@ Events:
 602782: capset 0: parent pid 9371
 607308: capset 0: RTS version "GHC-9.5.20220630 rts_debug"
 610371: capset 0: args: ["./Hello","+RTS","-lT"]
+637172: event block: cap 65535, end time: 10804332
+
+651627: cap 0: event block: cap 0, end time: 10711508
+
 968293: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 4194304 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
 1056712: task 0x1053b90 created on cap 0 with OS kernel thread 31880
 1071542: cap 0: creating thread 1

test/ticky-new.eventlog.reference

@@ -77,6 +77,10 @@ Event Types:
 212: Ticky-ticky entry counter begin sample (size 0)
 
 Events:
+15640: cap 0: event block: cap 0, end time: 129555
+
+79407: event block: cap 65535, end time: 126588
+
 123024: created capset 0 of type CapsetOsProcess
 123171: created capset 1 of type CapsetClockDomain
 123832: created cap 0
@@ -87,6 +91,10 @@ Events:
 125068: capset 0: parent pid 689980
 126079: capset 0: RTS version "GHC-9.3.20220422 rts_debug"
 126348: capset 0: args: ["./Main","+RTS","-lT"]
+129344: event block: cap 65535, end time: 410268694
+
+130469: cap 0: event block: cap 0, end time: 410206357
+
 209108: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 4194304 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
 238400: task 0x11f1570 created on cap 0 with OS kernel thread 2347594
 241377: cap 0: creating thread 1

test/ticky-ticky.eventlog.reference

@@ -72,6 +72,10 @@ Event Types:
 211: Ticky-ticky entry counter sample (size 32)
 
 Events:
+237000: event block: cap 65535, end time: 316000
+
+239000: cap 0: event block: cap 0, end time: 12471000
+
 292000: created capset 0 of type CapsetOsProcess
 292000: created capset 1 of type CapsetClockDomain
 293000: created cap 0
@@ -82,6 +86,8 @@ Events:
 305000: capset 0: parent pid 9239
 312000: capset 0: RTS version "GHC-9.1.0.20201210 rts_debug"
 315000: capset 0: args: ["./HelloWorld","+RTS","-lT"]
+326000: event block: cap 65535, end time: 12499000
+
 3772000: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
 3857000: task 0x7fd27f405e90 created on cap 0 with OS kernel thread 32996106
 3861000: cap 0: creating thread 1