diff --git a/CHANGELOG.md b/CHANGELOG.md --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Change Log +## 0.10.0 - 2019-10-01 + +* Add support for HeapProfSampleEnd and HeapBioProfSampleBegin ([#52](https://github.com/haskell/ghc-events/pull/52)) + ## 0.9.1 - 2019-09-03 * Relax upper version bounds to support GHC 8.8.1 ([#49](https://github.com/haskell/ghc-events/pull/49) and [#51](https://github.com/haskell/ghc-events/pull/51)) diff --git a/ghc-events.cabal b/ghc-events.cabal --- a/ghc-events.cabal +++ b/ghc-events.cabal @@ -1,5 +1,5 @@ name: ghc-events -version: 0.9.1 +version: 0.10.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, @@ -59,6 +59,8 @@ test/hello-ghc-8.2.2.eventlog.reference test/hello-ghc-8.6.5.eventlog test/hello-ghc-8.6.5.eventlog.reference + test/biographical-samples.eventlog + test/biographical-samples.eventlog.reference test/Utils.hs test/stop.hs README.md diff --git a/include/EventLogFormat.h b/include/EventLogFormat.h --- a/include/EventLogFormat.h +++ b/include/EventLogFormat.h @@ -3,16 +3,16 @@ * (c) The GHC Team, 2008-2012 * * Event log format - * + * * The log format is designed to be extensible: old tools should be * able to parse (but not necessarily understand all of) new versions * of the format, and new tools will be able to understand old log * files. - * + * * Each event has a specific format. If you add new events, give them * new numbers: we never re-use old event numbers. * - * - The format is endian-independent: all values are represented in + * - The format is endian-independent: all values are represented in * bigendian order. * * - The format is extensible: @@ -51,7 +51,7 @@ * Word8* -- extra info (for future extensions) * EVENT_ET_END * - * Event : + * Event : * Word16 -- event_type * Word64 -- time (nanosecs) * [Word16] -- length of the rest (for variable-sized events only) @@ -195,13 +195,15 @@ #define EVENT_HEAP_PROF_SAMPLE_BEGIN 162 #define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163 #define EVENT_HEAP_PROF_SAMPLE_STRING 164 +#define EVENT_HEAP_PROF_SAMPLE_END 165 +#define EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN 166 /* * 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 165 +#define NUM_GHC_EVENT_TAGS 167 /* DEPRECATED EVENTS: */ @@ -282,9 +284,9 @@ * #define BlockedOnMsgThrowTo 16 * NOTE: 16 because unused GUM states ignored in ghc-events lib * Otherwise it would be 18, following would be 19, 20 - * TODO: verify the above is what GHC does (16/17 could be 18/19) + * TODO: verify the above is what GHC does (16/17 could be 18/19) * #define ThreadMigrating 17 - * #define BlockedOnMsgGlobalise 18 + * #define BlockedOnMsgGlobalise 18 * NOTE: not present in GHC. Mercury-Event? */ #define THREAD_SUSPENDED_FOREIGN_CALL 6 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 @@ -399,6 +399,14 @@ | HeapProfSampleBegin { heapProfSampleEra :: !Word64 } + | HeapProfSampleEnd + { heapProfSampleEra :: !Word64 + } + + | HeapBioProfSampleBegin + { heapProfSampleEra :: !Word64 + , heapProfSampleTime :: !Word64 + } | HeapProfSampleCostCentre { heapProfId :: !Word8 , heapProfResidency :: !Word64 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 @@ -461,6 +461,13 @@ <> if isCaf heapProfFlags then " CAF" else "" HeapProfSampleBegin {..} -> "start heap prof sample " <> TB.decimal heapProfSampleEra + HeapProfSampleEnd {..} -> + "end prof sample " <> TB.decimal heapProfSampleEra + HeapBioProfSampleBegin {..} -> + "start heap prof sample " <> TB.decimal heapProfSampleEra + <> " at time " <> TB.decimal heapProfSampleTime + + HeapProfSampleCostCentre {..} -> "heap prof sample " <> TB.decimal heapProfId <> ", residency " <> TB.decimal heapProfResidency 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 @@ -792,6 +792,13 @@ , FixedSizeParser EVENT_HEAP_PROF_SAMPLE_BEGIN 8 $ do heapProfSampleEra <- get return $! HeapProfSampleBegin {..} + , FixedSizeParser EVENT_HEAP_PROF_SAMPLE_END 8 $ do + heapProfSampleEra <- get + return $! HeapProfSampleEnd {..} + , FixedSizeParser EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN 16 $ do + heapProfSampleEra <- get + heapProfSampleTime <- get + return $! HeapBioProfSampleBegin {..} , VariableSizeParser EVENT_HEAP_PROF_SAMPLE_COST_CENTRE $ do payloadLen <- get :: Get Word16 heapProfId <- get @@ -961,6 +968,8 @@ HeapProfBegin {} -> EVENT_HEAP_PROF_BEGIN HeapProfCostCentre {} -> EVENT_HEAP_PROF_COST_CENTRE HeapProfSampleBegin {} -> EVENT_HEAP_PROF_SAMPLE_BEGIN + HeapProfSampleEnd {} -> EVENT_HEAP_PROF_SAMPLE_END + HeapBioProfSampleBegin {} -> EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN HeapProfSampleCostCentre {} -> EVENT_HEAP_PROF_SAMPLE_COST_CENTRE HeapProfSampleString {} -> EVENT_HEAP_PROF_SAMPLE_STRING @@ -1356,6 +1365,13 @@ putEventSpec HeapProfSampleBegin {..} = putE heapProfSampleEra + +putEventSpec HeapProfSampleEnd {..} = + putE heapProfSampleEra + +putEventSpec HeapBioProfSampleBegin {..} = do + putE heapProfSampleEra + putE heapProfSampleTime putEventSpec HeapProfSampleCostCentre {..} = do putE heapProfId diff --git a/test/Utils.hs b/test/Utils.hs --- a/test/Utils.hs +++ b/test/Utils.hs @@ -14,6 +14,7 @@ , "sleep.hy.eventlog" , "stop.hT.eventlog" , "hello-ghc-8.2.2.eventlog", "hello-ghc-8.6.5.eventlog" + , "biographical-samples.eventlog" ] diff --git a/test/biographical-samples.eventlog b/test/biographical-samples.eventlog new file mode 100644 Binary files /dev/null and b/test/biographical-samples.eventlog differ diff --git a/test/biographical-samples.eventlog.reference b/test/biographical-samples.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/biographical-samples.eventlog.reference @@ -0,0 +1,240 @@ +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) +181: User binary message (size variable) + +Events: +169333: created capset 0 of type CapsetOsProcess +169544: created capset 1 of type CapsetClockDomain +170610: created cap 0 +170796: assigned cap 0 to capset 0 +170992: assigned cap 0 to capset 1 +171937: capset 1: wall clock time 1567931398s 509066000ns (unix epoch) +173588: capset 0: pid 31969 +174939: capset 0: parent pid 10639 +177812: capset 0: RTS version "GHC-8.9.0.20190907 rts_p" +178578: capset 0: args: ["./Test","+RTS","-hb","-l-au"] +31392757: start heap profiling 0 at sampling period 100000000 broken down by biography +31394184: cost centre 119 IDLE in IDLE at +31395244: cost centre 118 PINNED in SYSTEM at +31407386: cost centre 117 DONT_CARE in MAIN at +31407903: cost centre 116 OVERHEAD_of in PROFILING at +31408542: cost centre 115 GC in GC at +31409070: cost centre 114 SYSTEM in SYSTEM at +31409545: cost centre 113 MAIN in MAIN at +31418864: cost centre 112 CAF in GHC.Types at CAF +31419667: cost centre 111 CAF in GHC.Tuple at CAF +31420469: cost centre 110 CAF in GHC.PrimopWrappers at CAF +31428485: cost centre 109 CAF in GHC.Classes at CAF +31428997: cost centre 108 CAF in GHC.CString at CAF +31429601: cost centre 107 CAF in GHC.Integer.Type at CAF +31430128: cost centre 106 CAF in GHC.Integer.Logarithms.Internals at CAF +31430691: cost centre 105 CAF in GHC.Integer.Logarithms at CAF +31431318: cost centre 104 CAF in GHC.Event.Array at CAF +31431622: cost centre 103 CAF in GHC.Event.Arr at CAF +31432097: cost centre 102 CAF in System.Posix.Types at CAF +31432661: cost centre 101 CAF in GHC.Event.Poll at CAF +31433140: cost centre 100 CAF in GHC.Event.PSQ at CAF +31433663: cost centre 99 CAF in GHC.Event.Manager at CAF +31434201: cost centre 98 CAF in GHC.Event.Internal at CAF +31434663: cost centre 97 CAF in GHC.Event.IntTable at CAF +31435133: cost centre 96 CAF in GHC.Event.EPoll at CAF +31435653: cost centre 95 CAF in GHC.Event.Control at CAF +31443721: cost centre 94 CAF in GHC.Storable at CAF +31444197: cost centre 93 CAF in GHC.IO.Unsafe at CAF +31444906: cost centre 92 CAF in GHC.IO.IOMode at CAF +31445411: cost centre 91 CAF in GHC.IO.Handle.Text at CAF +31445869: cost centre 90 CAF in GHC.IO.FD at CAF +31446390: cost centre 89 CAF in GHC.IO.Device at CAF +31446934: cost centre 88 CAF in GHC.IO.BufferedIO at CAF +31447494: cost centre 87 CAF in GHC.Float.RealFracMethods at CAF +31447802: cost centre 86 CAF in GHC.Float.ConversionUtils at CAF +31448323: cost centre 85 CAF in GHC.Float at CAF +31448843: cost centre 84 CAF in GHC.Fingerprint.Type at CAF +31449296: cost centre 83 CAF in GHC.Fingerprint at CAF +31449625: cost centre 82 CAF in GHC.Char at CAF +31450153: cost centre 81 CAF in Foreign.Storable at CAF +31450756: cost centre 80 CAF in Foreign.Marshal.Array at CAF +31451306: cost centre 79 CAF in Foreign.Marshal.Alloc at CAF +31451871: cost centre 78 CAF in Foreign.C.Types at CAF +31452378: cost centre 77 CAF in Foreign.C.String at CAF +31452937: cost centre 76 CAF in Foreign.C.Error at CAF +31453478: cost centre 75 CAF in Data.Type.Equality at CAF +31453871: cost centre 74 CAF in Data.Tuple at CAF +31454313: cost centre 73 CAF in Data.Proxy at CAF +31454744: cost centre 72 CAF in Data.Maybe at CAF +31455173: cost centre 71 CAF in Data.Dynamic at CAF +31455677: cost centre 70 CAF in Data.Bits at CAF +31456087: cost centre 69 CAF in Control.Monad.Fail at CAF +31463389: cost centre 68 CAF in GHC.Event.Unique at CAF +31463855: cost centre 67 CAF in GHC.Event.TimerManager at CAF +31464340: cost centre 66 CAF in GHC.Event.Thread at CAF +31465122: cost centre 65 CAF in Data.Typeable.Internal at CAF +31465744: cost centre 64 CAF in Data.Semigroup.Internal at CAF +31466240: cost centre 63 CAF in Data.OldList at CAF +31466732: cost centre 62 CAF in Data.Functor.Utils at CAF +31467208: cost centre 61 CAF in Text.Read.Lex at CAF +31467721: cost centre 60 CAF in Text.ParserCombinators.ReadPrec at CAF +31468212: cost centre 59 CAF in Text.ParserCombinators.ReadP at CAF +31468673: cost centre 58 CAF in System.Posix.Internals at CAF +31469160: cost centre 57 CAF in System.IO at CAF +31469684: cost centre 56 CAF in Numeric at CAF +31470694: cost centre 55 CAF in GHC.Word at CAF +31471264: cost centre 54 CAF in GHC.Weak at CAF +31471733: cost centre 53 CAF in GHC.Unicode at CAF +31472232: cost centre 52 CAF in GHC.TypeNats at CAF +31472794: cost centre 51 CAF in GHC.TypeLits at CAF +31473276: cost centre 50 CAF in GHC.TopHandler at CAF +31473659: cost centre 49 CAF in GHC.Stack.Types at CAF +31474048: cost centre 48 CAF in GHC.Stack.CCS at CAF +31474486: cost centre 47 CAF in GHC.Stable at CAF +31482298: cost centre 46 CAF in GHC.Show at CAF +31482887: cost centre 45 CAF in GHC.STRef at CAF +31483377: cost centre 44 CAF in GHC.ST at CAF +31490773: cost centre 43 CAF in GHC.Real at CAF +31491247: cost centre 42 CAF in GHC.Read at CAF +31491645: cost centre 41 CAF in GHC.Ptr at CAF +31492243: cost centre 40 CAF in GHC.Pack at CAF +31492760: cost centre 39 CAF in GHC.Num at CAF +31493257: cost centre 38 CAF in GHC.Natural at CAF +31493736: cost centre 37 CAF in GHC.MVar at CAF +31494342: cost centre 36 CAF in GHC.Maybe at CAF +31494857: cost centre 35 CAF in GHC.List at CAF +31495381: cost centre 34 CAF in GHC.Int at CAF +31496151: cost centre 33 CAF in GHC.IORef at CAF +31496720: cost centre 32 CAF in GHC.IO.Handle.Types at CAF +31497222: cost centre 31 CAF in GHC.IO.Handle.Internals at CAF +31497685: cost centre 30 CAF in GHC.IO.Handle.FD at CAF +31504927: cost centre 29 CAF in GHC.IO.Handle at CAF +31505610: cost centre 28 CAF in GHC.IO.Exception at CAF +31506077: cost centre 27 CAF in GHC.IO.Encoding.UTF8 at CAF +31506496: cost centre 26 CAF in GHC.IO.Encoding.UTF32 at CAF +31507003: cost centre 25 CAF in GHC.IO.Encoding.UTF16 at CAF +31507583: cost centre 24 CAF in GHC.IO.Encoding.Types at CAF +31508035: cost centre 23 CAF in GHC.IO.Encoding.Latin1 at CAF +31508493: cost centre 22 CAF in GHC.IO.Encoding.Iconv at CAF +31508910: cost centre 21 CAF in GHC.IO.Encoding.Failure at CAF +31509429: cost centre 20 CAF in GHC.IO.Encoding at CAF +31509888: cost centre 19 CAF in GHC.IO.Buffer at CAF +31510384: cost centre 18 CAF in GHC.IO at CAF +31516785: cost centre 17 CAF in GHC.Generics at CAF +31517461: cost centre 16 CAF in GHC.ForeignPtr at CAF +31517919: cost centre 15 CAF in GHC.Foreign at CAF +31518406: cost centre 14 CAF in GHC.Exception.Type at CAF +31518840: cost centre 13 CAF in GHC.Exception at CAF +31519595: cost centre 12 CAF in GHC.Err at CAF +31520090: cost centre 11 CAF in GHC.Enum at CAF +31520663: cost centre 10 CAF in GHC.Conc.Sync at CAF +31521144: cost centre 9 CAF in GHC.Conc.Signal at CAF +31521606: cost centre 8 CAF in GHC.Conc.IO at CAF +31522099: cost centre 7 CAF in GHC.Base at CAF +31522596: cost centre 6 CAF in GHC.Arr at CAF +31523134: cost centre 5 CAF in Data.Monoid at CAF +31523621: cost centre 4 CAF in Data.Foldable at CAF +31524050: cost centre 3 CAF in Data.Either at CAF +31524535: cost centre 2 CAF in Control.Exception.Base at CAF +31525043: cost centre 1 CAF in Main at CAF +4710848398: removed cap 0 from capset 0 +4710848571: removed cap 0 from capset 1 +4710848777: deleted cap 0 +4710848928: deleted capset 0 +4710848972: deleted capset 1 +4710856797: start heap prof sample 7 at time 866544061 +4710858622: heap prof sample 0, residency 65379400, label VOID +4710858814: heap prof sample 0, residency 163449936, label LAG +4710858905: heap prof sample 0, residency 120, label USE +4710858989: heap prof sample 0, residency 37656, label INHERENT_USE +4710859120: heap prof sample 0, residency 0, label DRAG +4710859224: end prof sample 7 +4710871439: start heap prof sample 7 at time 1892144224 +4710871873: heap prof sample 0, residency 132361288, label VOID +4710871941: heap prof sample 0, residency 330904656, label LAG +4710872002: heap prof sample 0, residency 120, label USE +4710872059: heap prof sample 0, residency 37656, label INHERENT_USE +4710872127: heap prof sample 0, residency 0, label DRAG +4710872202: end prof sample 7 +4710873620: start heap prof sample 7 at time 2671749143 +4710873913: heap prof sample 0, residency 194095536, label VOID +4710873959: heap prof sample 0, residency 314763008, label LAG +4710874007: heap prof sample 0, residency 144, label USE +4710874067: heap prof sample 0, residency 37656, label INHERENT_USE +4710874115: heap prof sample 0, residency 0, label DRAG +4710874161: end prof sample 7 +4710875374: start heap prof sample 7 at time 3372819397 +4710875663: heap prof sample 0, residency 260169216, label VOID +4710875711: heap prof sample 0, residency 149578808, label LAG +4710875761: heap prof sample 0, residency 144, label USE +4710875807: heap prof sample 0, residency 37656, label INHERENT_USE +4710875854: heap prof sample 0, residency 0, label DRAG +4710875900: end prof sample 7 +4710877077: start heap prof sample 7 at time 4040839252 +4710877399: heap prof sample 0, residency 308465712, label VOID +4710877444: heap prof sample 0, residency 1672, label LAG +4710877490: heap prof sample 0, residency 120, label USE +4710877536: heap prof sample 0, residency 37656, label INHERENT_USE +4710877580: heap prof sample 0, residency 0, label DRAG +4710877635: end prof sample 7 +4710878860: start heap prof sample 7 at time 4512086494 +4710879189: heap prof sample 0, residency 91410480, label VOID +4710879235: heap prof sample 0, residency 1672, label LAG +4710879280: heap prof sample 0, residency 120, label USE +4710879338: heap prof sample 0, residency 37656, label INHERENT_USE +4710879385: heap prof sample 0, residency 0, label DRAG +4710879429: end prof sample 7 +