diff --git a/CHANGELOG.md b/CHANGELOG.md --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,12 @@ # Change Log +## 0.14.0 - 2020-11-17 + +* Add support for non-moving GC events [#60](https://github.com/haskell/ghc-events/pull/60) +* Fix the parser error under GHC 9.0 [#64](https://github.com/haskell/ghc-events/pull/64) +* Fix string encodings [#62](https://github.com/haskell/ghc-events/pull/62) +* Switch to GitHub Actions [#65](https://github.com/haskell/ghc-events/pull/65), dropping GHC 7.8.4 from the support range + ## 0.13.0 - 2020-04-04 * Fix broken UTF-8 decoding ([#55](https://github.com/haskell/ghc-events/pull/55)) diff --git a/ghc-events.cabal b/ghc-events.cabal --- a/ghc-events.cabal +++ b/ghc-events.cabal @@ -1,11 +1,12 @@ +cabal-version: 2.2 name: ghc-events -version: 0.13.0 +version: 0.14.0 synopsis: Library and tool for parsing .eventlog files from GHC description: Parses .eventlog files emitted by GHC 6.12.1 and later. Includes the ghc-events tool permitting, in particular, to dump an event log file as text. category: Development, GHC, Debug, Profiling, Trace -license: BSD3 +license: BSD-3-Clause license-file: LICENSE author: Donnie Jones , Simon Marlow , @@ -20,15 +21,13 @@ maintainer: Simon Marlow bug-reports: https://github.com/haskell/ghc-events/issues build-type: Simple -tested-with: GHC == 7.8.4 - GHC == 7.10.3 +tested-with: GHC == 7.10.3 GHC == 8.0.2 GHC == 8.2.2 GHC == 8.4.4 GHC == 8.6.5 GHC == 8.8.3 - GHC == 8.10.1 -cabal-version: >= 1.8 + GHC == 8.10.2 extra-source-files: include/EventLogFormat.h test/queens-ghc-6.12.1.eventlog test/queens-ghc-6.12.1.eventlog.reference @@ -36,6 +35,10 @@ test/queens-ghc-7.0.2.eventlog.reference test/mandelbrot-mmc-2011-06-14.eventlog test/mandelbrot-mmc-2011-06-14.eventlog.reference + test/nonmoving-gc.eventlog + test/nonmoving-gc.eventlog.reference + test/nonmoving-gc-census.eventlog + test/nonmoving-gc-census.eventlog.reference test/parallelTest.eventlog test/parallelTest.eventlog.reference test/pre77stop.eventlog @@ -77,8 +80,17 @@ type: git location: git@github.com:haskell/ghc-events.git +common default + default-extensions: + BangPatterns + NamedFieldPuns + PatternGuards + RecordWildCards + default-language: Haskell2010 + library - build-depends: base >= 4.7 && < 4.15, + import: default + build-depends: base >= 4.7 && < 4.16, containers >= 0.5 && < 0.7, binary >= 0.7 && < 0.11, bytestring >= 0.10.4, @@ -97,28 +109,38 @@ GHC.RTS.Events.Binary hs-source-dirs: src include-dirs: include - extensions: RecordWildCards, NamedFieldPuns, BangPatterns, PatternGuards other-extensions: FlexibleContexts, CPP ghc-options: -Wall executable ghc-events + import: default main-is: GhcEvents.hs build-depends: ghc-events, base, containers - extensions: RecordWildCards, NamedFieldPuns, BangPatterns, PatternGuards test-suite test-versions + import: default type: exitcode-stdio-1.0 main-is: TestVersions.hs other-modules: Utils hs-source-dirs: ., test build-depends: ghc-events, base - extensions: RecordWildCards, NamedFieldPuns, BangPatterns, PatternGuards test-suite write-merge + import: default type: exitcode-stdio-1.0 main-is: WriteMerge.hs other-modules: Utils hs-source-dirs: ., test build-depends: ghc-events, base, bytestring - extensions: RecordWildCards, NamedFieldPuns, BangPatterns, PatternGuards + -- disabled until #14 is fixed + buildable: False + +test-suite roundtrip + import: default + type: exitcode-stdio-1.0 + main-is: Roundtrip.hs + other-modules: Utils + hs-source-dirs: ., test + build-depends: ghc-events, base + -- disabled until #14 is fixed buildable: False diff --git a/include/EventLogFormat.h b/include/EventLogFormat.h --- a/include/EventLogFormat.h +++ b/include/EventLogFormat.h @@ -202,12 +202,21 @@ #define EVENT_USER_BINARY_MSG 181 +#define EVENT_CONC_MARK_BEGIN 200 +#define EVENT_CONC_MARK_END 201 +#define EVENT_CONC_SYNC_BEGIN 202 +#define EVENT_CONC_SYNC_END 203 +#define EVENT_CONC_SWEEP_BEGIN 204 +#define EVENT_CONC_SWEEP_END 205 +#define EVENT_CONC_UPD_REM_SET_FLUSH 206 +#define EVENT_NONMOVING_HEAP_CENSUS 207 + /* * The highest event code +1 that ghc itself emits. Note that some event * ranges higher than this are reserved but not currently emitted by ghc. * This must match the size of the EventDesc[] array in EventLog.c */ -#define NUM_GHC_EVENT_TAGS 182 +#define NUM_GHC_EVENT_TAGS 208 /* DEPRECATED EVENTS: */ diff --git a/src/GHC/RTS/EventTypes.hs b/src/GHC/RTS/EventTypes.hs --- a/src/GHC/RTS/EventTypes.hs +++ b/src/GHC/RTS/EventTypes.hs @@ -180,7 +180,7 @@ } | SparkCounters { sparksCreated, sparksDud, sparksOverflowed, sparksConverted, sparksFizzled, sparksGCd, - sparksRemaining :: {-# UNPACK #-}! Word64 + sparksRemaining :: {-# UNPACK #-} !Word64 } | SparkCreate { } | SparkDud { } @@ -430,6 +430,22 @@ } | UserBinaryMessage { payload :: !B.ByteString + } + + | ConcMarkBegin + | ConcMarkEnd { concMarkedObjectCount :: !Word32 + } + | ConcSyncBegin + | ConcSyncEnd + | ConcSweepBegin + | ConcSweepEnd + | ConcUpdRemSetFlush { cap :: {-# UNPACK #-}!Int + } + | NonmovingHeapCensus + { nonmovingCensusBlkSize :: !Word8 + , nonmovingCensusActiveSegs :: !Word32 + , nonmovingCensusFilledSegs :: !Word32 + , nonmovingCensusLiveBlocks :: !Word32 } deriving Show diff --git a/src/GHC/RTS/Events.hs b/src/GHC/RTS/Events.hs --- a/src/GHC/RTS/Events.hs +++ b/src/GHC/RTS/Events.hs @@ -492,6 +492,27 @@ UserBinaryMessage {..} -> "binary message " <> TB.fromText (replaceUnprintableWith '.' payload) + ConcMarkBegin -> + "concurrent mark began" + ConcMarkEnd {..} -> + "concurrent mark ended: " + <> "marked " <> TB.decimal concMarkedObjectCount <> " objects" + ConcSyncBegin -> + "post-mark synchronization began" + ConcSyncEnd -> + "post-mark synchronization ended" + ConcSweepBegin -> + "concurrent sweep began" + ConcSweepEnd -> + "concurrent sweep ended" + ConcUpdRemSetFlush {..} -> + "update remembered set flushed by " <> TB.decimal cap + NonmovingHeapCensus {..} -> + "nonmoving heap census " <> TB.decimal (2^nonmovingCensusBlkSize :: Int) + <> ": " <> TB.decimal nonmovingCensusActiveSegs <> " active segments" + <> ", " <> TB.decimal nonmovingCensusFilledSegs <> " filled segments" + <> ", " <> TB.decimal nonmovingCensusLiveBlocks <> " live blocks" + -- | Replace unprintable bytes in the message with the replacement character replaceUnprintableWith :: Char -- ^ Replacement character diff --git a/src/GHC/RTS/Events/Binary.hs b/src/GHC/RTS/Events/Binary.hs --- a/src/GHC/RTS/Events/Binary.hs +++ b/src/GHC/RTS/Events/Binary.hs @@ -1,5 +1,6 @@ {-# LANGUAGE CPP #-} {-# LANGUAGE OverloadedStrings #-} +{-# LANGUAGE ViewPatterns #-} module GHC.RTS.Events.Binary ( -- * Readers getHeader @@ -317,6 +318,27 @@ str <- getText (num - sz_tid) return ThreadLabel{ thread = tid , threadlabel = str } + )), + + (simpleEvent EVENT_CONC_MARK_BEGIN ConcMarkBegin), + (FixedSizeParser EVENT_CONC_MARK_END 4 (do -- (marked_object_count) + num <- get :: Get Word32 + return ConcMarkEnd{ concMarkedObjectCount = num } + )), + (simpleEvent EVENT_CONC_SYNC_BEGIN ConcSyncBegin), + (simpleEvent EVENT_CONC_SYNC_END ConcSyncEnd), + (simpleEvent EVENT_CONC_SWEEP_BEGIN ConcSweepBegin), + (simpleEvent EVENT_CONC_SWEEP_END ConcSweepEnd), + (FixedSizeParser EVENT_CONC_UPD_REM_SET_FLUSH sz_cap (do -- (cap) + cap <- get :: Get CapNo + return ConcUpdRemSetFlush{ cap = fromIntegral cap } + )), + (FixedSizeParser EVENT_NONMOVING_HEAP_CENSUS 13 (do -- (blk_size, active_segs, filled_segs, live_blks) + nonmovingCensusBlkSize <- get :: Get Word8 + nonmovingCensusActiveSegs <- get :: Get Word32 + nonmovingCensusFilledSegs <- get :: Get Word32 + nonmovingCensusLiveBlocks <- get :: Get Word32 + return NonmovingHeapCensus{..} )) ] @@ -891,12 +913,12 @@ putMarker EVENT_HET_END putMarker EVENT_HEADER_END where - putEventType (EventType n d msz) = do + putEventType (EventType n (TE.encodeUtf8 -> d) msz) = do putMarker EVENT_ET_BEGIN putType n putE $ fromMaybe 0xffff msz - putE (fromIntegral $ T.length d :: EventTypeDescLen) - putE d + putE (fromIntegral $ B.length d :: EventTypeDescLen) + putByteString d -- the event type header allows for extra data, which we don't use: putE (0 :: Word32) putMarker EVENT_ET_END @@ -1002,6 +1024,14 @@ ProfSampleCostCentre {} -> EVENT_PROF_SAMPLE_COST_CENTRE ProfBegin {} -> EVENT_PROF_BEGIN UserBinaryMessage {} -> EVENT_USER_BINARY_MSG + ConcMarkBegin {} -> EVENT_CONC_MARK_BEGIN + ConcMarkEnd {} -> EVENT_CONC_MARK_END + ConcSyncBegin {} -> EVENT_CONC_SYNC_BEGIN + ConcSyncEnd {} -> EVENT_CONC_SYNC_END + ConcSweepBegin {} -> EVENT_CONC_SWEEP_BEGIN + ConcSweepEnd {} -> EVENT_CONC_SWEEP_END + ConcUpdRemSetFlush {} -> EVENT_CONC_UPD_REM_SET_FLUSH + NonmovingHeapCensus {} -> EVENT_NONMOVING_HEAP_CENSUS nEVENT_PERF_NAME, nEVENT_PERF_COUNTER, nEVENT_PERF_TRACEPOINT :: EventTypeNum nEVENT_PERF_NAME = EVENT_PERF_NAME @@ -1106,10 +1136,10 @@ putE t putCap c -putEventSpec (ThreadLabel t l) = do - putE (fromIntegral (T.length l) + sz_tid :: Word16) +putEventSpec (ThreadLabel t (TE.encodeUtf8 -> l)) = do + putE (fromIntegral (B.length l) + sz_tid :: Word16) putE t - putE l + putByteString l putEventSpec Shutdown = return () @@ -1215,22 +1245,22 @@ putE cs putCap cp -putEventSpec (RtsIdentifier cs rts) = do - putE (fromIntegral (T.length rts) + sz_capset :: Word16) +putEventSpec (RtsIdentifier cs (TE.encodeUtf8 -> rts)) = do + putE (fromIntegral (B.length rts) + sz_capset :: Word16) putE cs - putE rts + putByteString rts -putEventSpec (ProgramArgs cs as) = do - let sz_args = sum $ map ((+ 1) {- for \0 -} . T.length) as +putEventSpec (ProgramArgs cs (map TE.encodeUtf8 -> as)) = do + let sz_args = sum (map ((+ 1) {- for \0 -} . B.length) as) - 1 putE (fromIntegral sz_args + sz_capset :: Word16) putE cs - mapM_ putE (intersperse "\0" as) + mapM_ putByteString (intersperse "\0" as) -putEventSpec (ProgramEnv cs es) = do - let sz_env = sum $ map ((+ 1) {- for \0 -} . T.length) es +putEventSpec (ProgramEnv cs (map TE.encodeUtf8 -> es)) = do + let sz_env = sum (map ((+ 1) {- for \0 -} . B.length) es) - 1 putE (fromIntegral sz_env + sz_capset :: Word16) putE cs - mapM_ putE $ intersperse "\0" es + mapM_ putByteString $ intersperse "\0" es putEventSpec (OsProcessPid cs pid) = do putE cs @@ -1245,17 +1275,17 @@ putE sec putE nsec -putEventSpec (Message s) = do - putE (fromIntegral (T.length s) :: Word16) - putE s +putEventSpec (Message (TE.encodeUtf8 -> s)) = do + putE (fromIntegral (B.length s) :: Word16) + putByteString s -putEventSpec (UserMessage s) = do - putE (fromIntegral (T.length s) :: Word16) - putE s +putEventSpec (UserMessage (TE.encodeUtf8 -> s)) = do + putE (fromIntegral (B.length s) :: Word16) + putByteString s -putEventSpec (UserMarker s) = do - putE (fromIntegral (T.length s) :: Word16) - putE s +putEventSpec (UserMarker (TE.encodeUtf8 -> s)) = do + putE (fromIntegral (B.length s) :: Word16) + putByteString s putEventSpec (UnknownEvent {}) = error "putEventSpec UnknownEvent" @@ -1358,10 +1388,10 @@ putEventSpec MerCapSleeping = return () putEventSpec MerCallingMain = return () -putEventSpec PerfName{..} = do - putE (fromIntegral (T.length name) + sz_perf_num :: Word16) +putEventSpec PerfName{name = (TE.encodeUtf8 -> name), ..} = do + putE (fromIntegral (B.length name) + sz_perf_num :: Word16) putE perfNum - putE name + putByteString name putEventSpec PerfCounter{..} = do putE perfNum @@ -1427,3 +1457,18 @@ putEventSpec UserBinaryMessage {..} = do putE (fromIntegral (B.length payload) :: Word16) putByteString payload + +putEventSpec ConcMarkBegin = return () +putEventSpec ConcMarkEnd {..} = do + putE concMarkedObjectCount +putEventSpec ConcSyncBegin = return () +putEventSpec ConcSyncEnd = return () +putEventSpec ConcSweepBegin = return () +putEventSpec ConcSweepEnd = return () +putEventSpec ConcUpdRemSetFlush {..} = do + putCap cap +putEventSpec NonmovingHeapCensus {..} = do + putE nonmovingCensusBlkSize + putE nonmovingCensusActiveSegs + putE nonmovingCensusFilledSegs + putE nonmovingCensusLiveBlocks diff --git a/test/Roundtrip.hs b/test/Roundtrip.hs new file mode 100644 --- /dev/null +++ b/test/Roundtrip.hs @@ -0,0 +1,21 @@ +import Control.Monad +import System.Exit + +import GHC.RTS.Events +import GHC.RTS.Events.Incremental +import Utils (files) + +-- | Check that an eventlog round-trips through encoding/decoding. +checkRoundtrip :: FilePath -> IO Bool +checkRoundtrip logFile = do + putStrLn logFile + Right eventlog <- readEventLogFromFile logFile + let Right (roundtripped, _) = readEventLog $ serialiseEventLog eventlog + if show roundtripped == show eventlog + then return True + else putStrLn "bad" >> return False + +main :: IO () +main = do + successes <- mapM checkRoundtrip files + unless (and successes) exitFailure diff --git a/test/Utils.hs b/test/Utils.hs --- a/test/Utils.hs +++ b/test/Utils.hs @@ -5,6 +5,8 @@ [ "queens-ghc-6.12.1.eventlog" , "queens-ghc-7.0.2.eventlog" , "mandelbrot-mmc-2011-06-14.eventlog" + , "nonmoving-gc.eventlog" + , "nonmoving-gc-census.eventlog" , "parallelTest.eventlog" , "pre77stop.eventlog", "782stop.eventlog", "783stop.eventlog" , "sleep.h.eventlog" diff --git a/test/nonmoving-gc-census.eventlog b/test/nonmoving-gc-census.eventlog new file mode 100644 Binary files /dev/null and b/test/nonmoving-gc-census.eventlog differ diff --git a/test/nonmoving-gc-census.eventlog.reference b/test/nonmoving-gc-census.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/nonmoving-gc-census.eventlog.reference @@ -0,0 +1,340 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 58) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) +165: End of heap profile sample (size 8) +166: Start of heap profile (biographical) sample (size 16) +167: Time profile cost-centre stack (size variable) +168: Start of a time profile (size 8) +181: User binary message (size variable) +200: Begin concurrent mark phase (size 0) +201: End concurrent mark phase (size 4) +202: Begin concurrent GC synchronisation (size 0) +203: End concurrent GC synchronisation (size 0) +204: Begin concurrent sweep (size 0) +205: End concurrent sweep (size 0) +206: Update remembered set flushed (size 2) +207: Nonmoving heap census (size 13) + +Events: +227855: capset 1: wall clock time 1587597517s 544758000ns (unix epoch) +229418: capset 0: pid 1158 +231368: capset 0: parent pid 25700 +233264: capset 0: RTS version "GHC-8.11.0.20200422 rts_thr_l" +233773: capset 0: args: ["nofib/shootout/binary-trees/Main","15","11","+RTS","-xn","-l-an"] +2789899: Starting nonmoving GC preparation +2811955: Marking roots for nonmoving GC +2813333: Finished marking roots for nonmoving GC +2813512: Finished nonmoving GC preparation +2872560: concurrent mark began +3320668: concurrent mark ended: marked 2869 objects +3337805: post-mark synchronization began +3337996: post-mark synchronization began +3682910: cap 0: update remembered set flushed by 0 +3683825: concurrent mark began +3692251: concurrent mark ended: marked 1042 objects +3692392: concurrent mark began +3692462: concurrent mark ended: marked 1 objects +3692552: concurrent mark began +3692621: concurrent mark ended: marked 1 objects +3716334: post-mark synchronization ended +3716512: post-mark synchronization ended +3720779: concurrent sweep began +3721599: concurrent sweep ended +3726029: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +3728053: nonmoving heap census 16: 0 active segments, 0 filled segments, 54 live blocks +3729679: nonmoving heap census 32: 0 active segments, 0 filled segments, 128 live blocks +3730314: nonmoving heap census 64: 0 active segments, 0 filled segments, 0 live blocks +3730776: nonmoving heap census 128: 0 active segments, 0 filled segments, 0 live blocks +3731036: nonmoving heap census 256: 0 active segments, 0 filled segments, 0 live blocks +3731339: nonmoving heap census 512: 0 active segments, 0 filled segments, 0 live blocks +3731574: nonmoving heap census 1024: 0 active segments, 0 filled segments, 0 live blocks +3731786: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +3731990: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +3732268: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +3732469: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +32362284: Starting nonmoving GC preparation +32371855: Marking roots for nonmoving GC +32373519: Finished marking roots for nonmoving GC +32373686: Finished nonmoving GC preparation +32557821: concurrent mark began +33910745: concurrent mark ended: marked 16928 objects +33914172: concurrent mark began +33916300: concurrent mark ended: marked 13 objects +33924796: post-mark synchronization began +33925033: post-mark synchronization began +34219802: cap 0: update remembered set flushed by 0 +34221200: concurrent mark began +34240845: concurrent mark ended: marked 1084 objects +34241350: concurrent mark began +34241419: concurrent mark ended: marked 1 objects +34241632: concurrent mark began +34241702: concurrent mark ended: marked 1 objects +34271446: post-mark synchronization ended +34271858: post-mark synchronization ended +34283960: concurrent sweep began +34559614: concurrent sweep ended +34563964: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +34576318: nonmoving heap census 16: 3 active segments, 0 filled segments, 1259 live blocks +34591543: nonmoving heap census 32: 6 active segments, 4 filled segments, 6385 live blocks +34596442: nonmoving heap census 64: 4 active segments, 1 filled segments, 1031 live blocks +34597260: nonmoving heap census 128: 0 active segments, 0 filled segments, 42 live blocks +34597718: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +34598055: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +34598375: nonmoving heap census 1024: 0 active segments, 0 filled segments, 4 live blocks +34598666: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +34598997: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +34599265: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +34599501: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +67279769: Starting nonmoving GC preparation +67281581: Marking roots for nonmoving GC +67282874: Finished marking roots for nonmoving GC +67283133: Finished nonmoving GC preparation +67370910: concurrent mark began +68397276: concurrent mark ended: marked 16875 objects +68398499: concurrent mark began +68399339: concurrent mark ended: marked 13 objects +68402178: post-mark synchronization began +68402344: post-mark synchronization began +68682534: cap 0: update remembered set flushed by 0 +68683459: concurrent mark began +68688876: concurrent mark ended: marked 352 objects +68689271: concurrent mark began +68689388: concurrent mark ended: marked 1 objects +68689515: concurrent mark began +68689626: concurrent mark ended: marked 1 objects +68704339: post-mark synchronization ended +68704591: post-mark synchronization ended +68710131: concurrent sweep began +68830040: concurrent sweep ended +68834054: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +68843935: nonmoving heap census 16: 3 active segments, 1 filled segments, 2855 live blocks +68858424: nonmoving heap census 32: 6 active segments, 3 filled segments, 5846 live blocks +68862979: nonmoving heap census 64: 4 active segments, 0 filled segments, 703 live blocks +68863622: nonmoving heap census 128: 0 active segments, 0 filled segments, 43 live blocks +68863967: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +68864313: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +68864669: nonmoving heap census 1024: 0 active segments, 0 filled segments, 5 live blocks +68865004: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +68865354: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +68865670: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +68865931: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +119827283: Starting nonmoving GC preparation +119830728: Marking roots for nonmoving GC +119831795: Finished marking roots for nonmoving GC +119831988: Finished nonmoving GC preparation +119938842: concurrent mark began +121053293: concurrent mark ended: marked 16438 objects +121056540: concurrent mark began +121057919: concurrent mark ended: marked 13 objects +121066516: post-mark synchronization began +121066859: post-mark synchronization began +121154737: cap 0: update remembered set flushed by 0 +121161224: concurrent mark began +121186040: concurrent mark ended: marked 1079 objects +121186533: concurrent mark began +121186646: concurrent mark ended: marked 1 objects +121186774: concurrent mark began +121186841: concurrent mark ended: marked 1 objects +121231348: post-mark synchronization ended +121231969: post-mark synchronization ended +121242597: concurrent sweep began +121385240: concurrent sweep ended +121390264: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +121405730: nonmoving heap census 16: 3 active segments, 0 filled segments, 1568 live blocks +121430287: nonmoving heap census 32: 7 active segments, 3 filled segments, 6270 live blocks +121436146: nonmoving heap census 64: 4 active segments, 1 filled segments, 897 live blocks +121437265: nonmoving heap census 128: 0 active segments, 0 filled segments, 43 live blocks +121437840: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +121438948: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +121439371: nonmoving heap census 1024: 0 active segments, 0 filled segments, 5 live blocks +121439723: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +121440083: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +121440368: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +121441292: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +148361407: Starting nonmoving GC preparation +148365127: Marking roots for nonmoving GC +148366468: Finished marking roots for nonmoving GC +148366670: Finished nonmoving GC preparation +148527085: concurrent mark began +149775840: concurrent mark ended: marked 15225 objects +149778324: concurrent mark began +149779513: concurrent mark ended: marked 13 objects +149810324: post-mark synchronization began +149810665: post-mark synchronization began +149850617: cap 0: update remembered set flushed by 0 +149851300: concurrent mark began +149866270: concurrent mark ended: marked 1049 objects +149866671: concurrent mark began +149866848: concurrent mark ended: marked 1 objects +149867039: concurrent mark began +149867202: concurrent mark ended: marked 1 objects +149874824: post-mark synchronization ended +149875168: post-mark synchronization ended +149901246: concurrent sweep began +150026135: concurrent sweep ended +150031083: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +150045140: nonmoving heap census 16: 3 active segments, 1 filled segments, 3342 live blocks +150066310: nonmoving heap census 32: 8 active segments, 3 filled segments, 5613 live blocks +150071204: nonmoving heap census 64: 4 active segments, 0 filled segments, 567 live blocks +150071885: nonmoving heap census 128: 0 active segments, 0 filled segments, 44 live blocks +150073125: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +150073558: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +150074077: nonmoving heap census 1024: 0 active segments, 0 filled segments, 6 live blocks +150074414: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +150074832: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +150075820: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +150076102: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +176942302: Starting nonmoving GC preparation +176945061: Marking roots for nonmoving GC +176946066: Finished marking roots for nonmoving GC +176946253: Finished nonmoving GC preparation +177039035: concurrent mark began +177741825: concurrent mark ended: marked 15542 objects +177744446: concurrent mark began +177745256: concurrent mark ended: marked 13 objects +177750528: post-mark synchronization began +177750635: post-mark synchronization began +177896570: cap 0: update remembered set flushed by 0 +177896939: concurrent mark began +177910616: concurrent mark ended: marked 1082 objects +177911218: concurrent mark began +177911307: concurrent mark ended: marked 1 objects +177911422: concurrent mark began +177911493: concurrent mark ended: marked 1 objects +177919949: post-mark synchronization ended +177920053: post-mark synchronization ended +177925925: concurrent sweep began +178017822: concurrent sweep ended +178020408: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +178026736: nonmoving heap census 16: 1 active segments, 1 filled segments, 2963 live blocks +178041784: nonmoving heap census 32: 7 active segments, 3 filled segments, 5977 live blocks +178045269: nonmoving heap census 64: 4 active segments, 1 filled segments, 757 live blocks +178045812: nonmoving heap census 128: 0 active segments, 0 filled segments, 44 live blocks +178046142: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +178046413: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +178046632: nonmoving heap census 1024: 0 active segments, 0 filled segments, 6 live blocks +178047048: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +178047379: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +178047876: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +178048246: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +202506857: Starting nonmoving GC preparation +202508058: Marking roots for nonmoving GC +202517509: Finished marking roots for nonmoving GC +202517677: Finished nonmoving GC preparation +202566458: concurrent mark began +203074473: concurrent mark ended: marked 16604 objects +203074950: concurrent mark began +203075547: concurrent mark ended: marked 13 objects +203078118: post-mark synchronization began +203078232: post-mark synchronization began +203131205: cap 0: update remembered set flushed by 0 +203131506: concurrent mark began +203140444: concurrent mark ended: marked 1083 objects +203140572: concurrent mark began +203140635: concurrent mark ended: marked 1 objects +203140714: concurrent mark began +203140783: concurrent mark ended: marked 1 objects +203149980: post-mark synchronization ended +203150083: post-mark synchronization ended +203153609: concurrent sweep began +203241257: concurrent sweep ended +203243717: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +203252554: nonmoving heap census 16: 3 active segments, 1 filled segments, 3188 live blocks +203263495: nonmoving heap census 32: 7 active segments, 4 filled segments, 6373 live blocks +203266345: nonmoving heap census 64: 4 active segments, 1 filled segments, 947 live blocks +203266828: nonmoving heap census 128: 0 active segments, 0 filled segments, 45 live blocks +203267099: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +203267302: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +203267563: nonmoving heap census 1024: 0 active segments, 0 filled segments, 7 live blocks +203267805: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +203268121: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +203268260: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +203268439: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +224422635: Starting nonmoving GC preparation +224424065: Marking roots for nonmoving GC +224424970: Finished marking roots for nonmoving GC +224425126: Finished nonmoving GC preparation +224506119: concurrent mark began +225279214: concurrent mark ended: marked 15033 objects +225280063: concurrent mark began +225280703: concurrent mark ended: marked 13 objects +225283313: post-mark synchronization began +225283479: post-mark synchronization began +225341600: cap 0: update remembered set flushed by 0 +225342335: concurrent mark began +225351353: concurrent mark ended: marked 1049 objects +225351605: concurrent mark began +225351675: concurrent mark ended: marked 1 objects +225351773: concurrent mark began +225351842: concurrent mark ended: marked 1 objects +225383632: post-mark synchronization ended +225383831: post-mark synchronization ended +225388468: concurrent sweep began +225553609: concurrent sweep ended +225557870: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +225572051: nonmoving heap census 16: 3 active segments, 0 filled segments, 1860 live blocks +225587504: nonmoving heap census 32: 6 active segments, 3 filled segments, 5705 live blocks +225592583: nonmoving heap census 64: 4 active segments, 0 filled segments, 621 live blocks +225593429: nonmoving heap census 128: 0 active segments, 0 filled segments, 46 live blocks +225593797: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +225594147: nonmoving heap census 512: 0 active segments, 0 filled segments, 1 live blocks +225594554: nonmoving heap census 1024: 0 active segments, 0 filled segments, 8 live blocks +225594804: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +225595452: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +225596376: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +225597481: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks + diff --git a/test/nonmoving-gc.eventlog b/test/nonmoving-gc.eventlog new file mode 100644 Binary files /dev/null and b/test/nonmoving-gc.eventlog differ diff --git a/test/nonmoving-gc.eventlog.reference b/test/nonmoving-gc.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/nonmoving-gc.eventlog.reference @@ -0,0 +1,95 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 58) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) +165: End of heap profile sample (size 8) +166: Start of heap profile (biographical) sample (size 16) +167: Time profile cost-centre stack (size variable) +168: Start of a time profile (size 8) +181: User binary message (size variable) +200: Begin concurrent mark phase (size 0) +201: End concurrent mark phase (size 4) +202: Begin concurrent GC synchronisation (size 0) +203: End concurrent GC synchronisation (size 0) +204: Begin concurrent sweep (size 0) +205: End concurrent sweep (size 0) +206: Update remembered set flushed (size 2) +207: Nonmoving heap census (size 13) + +Events: +620636: capset 1: wall clock time 1587578331s 829795000ns (unix epoch) +627395: capset 0: pid 20807 +636419: capset 0: parent pid 18766 +644544: capset 0: RTS version "GHC-8.10.1 rts_thr_debug" +649853: capset 0: args: ["./Main","10","+RTS","-l-an","-xn"] +20282519: Starting nonmoving GC preparation +20305849: Marking roots for nonmoving GC +20331402: Finished marking roots for nonmoving GC +20333822: Finished nonmoving GC preparation +20810540: concurrent mark began +30089152: concurrent mark ended: marked 6677 objects +30210049: post-mark synchronization began +32582336: cap 0: update remembered set flushed by 0 +32608578: concurrent mark began +35122177: concurrent mark ended: marked 7758 objects +35126012: concurrent mark began +35127755: concurrent mark ended: marked 1 objects +35129046: concurrent mark began +35129935: concurrent mark ended: marked 1 objects +35203888: post-mark synchronization ended +35258771: concurrent sweep began +35263947: concurrent sweep ended +