diff --git a/src/GHC/RTS/Events.hs b/src/GHC/RTS/Events.hs index d38750a..6b847bf 100644 --- a/src/GHC/RTS/Events.hs +++ b/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,7 +164,7 @@ 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 = @@ -173,18 +172,33 @@ capSplitEvents' evts imap = (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 -> diff --git a/src/GHC/RTS/Events/Incremental.hs b/src/GHC/RTS/Events/Incremental.hs index c962059..0798000 100644 --- a/src/GHC/RTS/Events/Incremental.hs +++ b/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 diff --git a/test/WriteMerge.hs b/test/WriteMerge.hs index aac78e7..22edfe9 100644 --- a/test/WriteMerge.hs +++ b/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 diff --git a/test/biographical-samples.eventlog.reference b/test/biographical-samples.eventlog.reference index f0bebcf..9c893c2 100644 --- a/test/biographical-samples.eventlog.reference +++ b/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 diff --git a/test/ghc-9.2-events.eventlog.reference b/test/ghc-9.2-events.eventlog.reference index b1d3a1f..db84e9f 100644 --- a/test/ghc-9.2-events.eventlog.reference +++ b/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 diff --git a/test/hello-ghc-8.2.2.eventlog.reference b/test/hello-ghc-8.2.2.eventlog.reference index 87e1431..813bd82 100644 --- a/test/hello-ghc-8.2.2.eventlog.reference +++ b/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 diff --git a/test/hello-ghc-8.6.5.eventlog.reference b/test/hello-ghc-8.6.5.eventlog.reference index 0ccd6d1..8a68d64 100644 --- a/test/hello-ghc-8.6.5.eventlog.reference +++ b/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 diff --git a/test/nonmoving-gc-census-T23340.eventlog.reference b/test/nonmoving-gc-census-T23340.eventlog.reference index e7637b8..3639e80 100644 --- a/test/nonmoving-gc-census-T23340.eventlog.reference +++ b/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 diff --git a/test/nonmoving-gc-census.eventlog.reference b/test/nonmoving-gc-census.eventlog.reference index ab99800..2def404 100644 --- a/test/nonmoving-gc-census.eventlog.reference +++ b/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 diff --git a/test/nonmoving-gc-pruned-segments.eventlog.reference b/test/nonmoving-gc-pruned-segments.eventlog.reference index 0509afd..f38b02b 100644 --- a/test/nonmoving-gc-pruned-segments.eventlog.reference +++ b/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 diff --git a/test/nonmoving-gc.eventlog.reference b/test/nonmoving-gc.eventlog.reference index 8c73e2d..1ad4230 100644 --- a/test/nonmoving-gc.eventlog.reference +++ b/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 diff --git a/test/parallelTest.eventlog.reference b/test/parallelTest.eventlog.reference index 2afedef..84fa1ce 100644 --- a/test/parallelTest.eventlog.reference +++ b/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 diff --git a/test/sleep.h.eventlog.reference b/test/sleep.h.eventlog.reference index d5b2dcb..8930285 100644 --- a/test/sleep.h.eventlog.reference +++ b/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 diff --git a/test/sleep.hC.eventlog.reference b/test/sleep.hC.eventlog.reference index 5e55255..0966941 100644 --- a/test/sleep.hC.eventlog.reference +++ b/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 diff --git a/test/sleep.hd.eventlog.reference b/test/sleep.hd.eventlog.reference index 576d6f8..9924664 100644 --- a/test/sleep.hd.eventlog.reference +++ b/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 diff --git a/test/sleep.hm.eventlog.reference b/test/sleep.hm.eventlog.reference index 9664bb0..7115076 100644 --- a/test/sleep.hm.eventlog.reference +++ b/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 diff --git a/test/sleep.hy.eventlog.reference b/test/sleep.hy.eventlog.reference index e7f7a71..1156ad0 100644 --- a/test/sleep.hy.eventlog.reference +++ b/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 diff --git a/test/stop.hT.eventlog.reference b/test/stop.hT.eventlog.reference index 490de9e..e5fd07d 100644 --- a/test/stop.hT.eventlog.reference +++ b/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 diff --git a/test/ticky-begin-sample.eventlog.reference b/test/ticky-begin-sample.eventlog.reference index 5b7312d..4c93f21 100644 --- a/test/ticky-begin-sample.eventlog.reference +++ b/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 diff --git a/test/ticky-json.eventlog.reference b/test/ticky-json.eventlog.reference index c7dfaf7..85e3ed4 100644 --- a/test/ticky-json.eventlog.reference +++ b/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 diff --git a/test/ticky-new.eventlog.reference b/test/ticky-new.eventlog.reference index adef8e3..fce2e10 100644 --- a/test/ticky-new.eventlog.reference +++ b/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 diff --git a/test/ticky-ticky.eventlog.reference b/test/ticky-ticky.eventlog.reference index 3a538de..bc6c475 100644 --- a/test/ticky-ticky.eventlog.reference +++ b/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 diff --git a/test/time-prof.eventlog.reference b/test/time-prof.eventlog.reference index 0a169e8..101490b 100644 --- a/test/time-prof.eventlog.reference +++ b/test/time-prof.eventlog.reference @@ -62,6 +62,10 @@ Event Types: 181: User binary message (size variable) Events: +60066: event block: cap 65535, end time: 374234993 + +60135: cap 0: event block: cap 0, end time: 374234555 + 60526: created capset 0 of type CapsetOsProcess 60597: created capset 1 of type CapsetClockDomain 61788: created cap 0 diff --git a/test/trace-binary-event.eventlog.reference b/test/trace-binary-event.eventlog.reference index 5c91614..e1b0929 100644 --- a/test/trace-binary-event.eventlog.reference +++ b/test/trace-binary-event.eventlog.reference @@ -58,6 +58,10 @@ Event Types: 181: User binary message (size variable) Events: +193739: event block: cap 65535, end time: 15702781 + +196128: cap 0: event block: cap 0, end time: 15700802 + 199116: created capset 0 of type CapsetOsProcess 199197: created capset 1 of type CapsetClockDomain 199989: created cap 0 diff --git a/test/trace-binary-nonutf.eventlog.reference b/test/trace-binary-nonutf.eventlog.reference index dbd6793..e3357a8 100644 --- a/test/trace-binary-nonutf.eventlog.reference +++ b/test/trace-binary-nonutf.eventlog.reference @@ -70,6 +70,10 @@ Event Types: 207: Nonmoving heap census (size 13) Events: +102137: event block: cap 65535, end time: 272398 + +102237: cap 0: event block: cap 0, end time: 269897 + 106238: created capset 0 of type CapsetOsProcess 106338: created capset 1 of type CapsetClockDomain 106739: created cap 0 diff --git a/test/unicode.eventlog.reference b/test/unicode.eventlog.reference index 8de4081..2b835f2 100644 --- a/test/unicode.eventlog.reference +++ b/test/unicode.eventlog.reference @@ -58,6 +58,10 @@ Event Types: 181: User binary message (size variable) Events: +192893: event block: cap 65535, end time: 14575608 + +195185: cap 0: event block: cap 0, end time: 14574206 + 199023: created capset 0 of type CapsetOsProcess 199124: created capset 1 of type CapsetClockDomain 199641: created cap 0