From cce6a35677f5f99b44c21d86febd295b909ef1ce Mon Sep 17 00:00:00 2001 From: Teo Camarasu Date: Mon, 11 Sep 2023 11:33:12 +0100 Subject: [PATCH] Add parsing code for new version of nonmoving heap census See: https://gitlab.haskell.org/ghc/ghc/-/issues/23340 and the GHC MR: https://gitlab.haskell.org/ghc/ghc/-/merge_requests/10659 --- src/GHC/RTS/EventTypes.hs | 2 +- src/GHC/RTS/Events.hs | 2 +- src/GHC/RTS/Events/Binary.hs | 11 +- test/Utils.hs | 1 + test/nonmoving-gc-census-T23340.eventlog | Bin 0 -> 6740 bytes ...moving-gc-census-T23340.eventlog.reference | 231 ++++++++++++++++++ 6 files changed, 244 insertions(+), 3 deletions(-) create mode 100644 test/nonmoving-gc-census-T23340.eventlog create mode 100644 test/nonmoving-gc-census-T23340.eventlog.reference diff --git a/src/GHC/RTS/EventTypes.hs b/src/GHC/RTS/EventTypes.hs index 779c959..e38efaf 100644 --- a/src/GHC/RTS/EventTypes.hs +++ b/src/GHC/RTS/EventTypes.hs @@ -457,7 +457,7 @@ data EventInfo | ConcUpdRemSetFlush { cap :: {-# UNPACK #-}!Int } | NonmovingHeapCensus - { nonmovingCensusBlkSize :: !Word8 + { nonmovingCensusBlkSize :: !Word16 , nonmovingCensusActiveSegs :: !Word32 , nonmovingCensusFilledSegs :: !Word32 , nonmovingCensusLiveBlocks :: !Word32 diff --git a/src/GHC/RTS/Events.hs b/src/GHC/RTS/Events.hs index 8723495..fc5d7f4 100644 --- a/src/GHC/RTS/Events.hs +++ b/src/GHC/RTS/Events.hs @@ -515,7 +515,7 @@ buildEventInfo spec' = ConcUpdRemSetFlush {..} -> "update remembered set flushed by " <> TB.decimal cap NonmovingHeapCensus {..} -> - "nonmoving heap census " <> TB.decimal (2^nonmovingCensusBlkSize :: Int) + "nonmoving heap census " <> TB.decimal nonmovingCensusBlkSize <> ": " <> TB.decimal nonmovingCensusActiveSegs <> " active segments" <> ", " <> TB.decimal nonmovingCensusFilledSegs <> " filled segments" <> ", " <> TB.decimal nonmovingCensusLiveBlocks <> " live blocks" diff --git a/src/GHC/RTS/Events/Binary.hs b/src/GHC/RTS/Events/Binary.hs index 2d647dc..0866ea6 100644 --- a/src/GHC/RTS/Events/Binary.hs +++ b/src/GHC/RTS/Events/Binary.hs @@ -343,8 +343,17 @@ standardParsers = [ cap <- get :: Get CapNo return ConcUpdRemSetFlush{ cap = fromIntegral cap } )), + -- Before GHC issue 23340 event where we are given the logarithm of the block size (FixedSizeParser EVENT_NONMOVING_HEAP_CENSUS 13 (do -- (blk_size, active_segs, filled_segs, live_blks) - nonmovingCensusBlkSize <- get :: Get Word8 + nonmovingCensusLogBlkSize <- get :: Get Word8 + let nonmovingCensusBlkSize = 2^nonmovingCensusLogBlkSize + nonmovingCensusActiveSegs <- get :: Get Word32 + nonmovingCensusFilledSegs <- get :: Get Word32 + nonmovingCensusLiveBlocks <- get :: Get Word32 + return NonmovingHeapCensus{..} + )), + (FixedSizeParser EVENT_NONMOVING_HEAP_CENSUS 14 (do -- (blk_size, active_segs, filled_segs, live_blks) + nonmovingCensusBlkSize <- get :: Get Word16 nonmovingCensusActiveSegs <- get :: Get Word32 nonmovingCensusFilledSegs <- get :: Get Word32 nonmovingCensusLiveBlocks <- get :: Get Word32 diff --git a/test/Utils.hs b/test/Utils.hs index b8f0caa..06de4c9 100644 --- a/test/Utils.hs +++ b/test/Utils.hs @@ -4,6 +4,7 @@ files :: [FilePath] files = map ("test/"++) [ "nonmoving-gc.eventlog" , "nonmoving-gc-census.eventlog" + , "nonmoving-gc-census-T23340.eventlog" , "parallelTest.eventlog" , "sleep.h.eventlog" , "sleep.hC.eventlog" diff --git a/test/nonmoving-gc-census-T23340.eventlog b/test/nonmoving-gc-census-T23340.eventlog new file mode 100644 index 0000000000000000000000000000000000000000..927e14dc523254a5f3896fb6ee8fea4280000c6c GIT binary patch literal 6740 zcmb7|YitzP702&*T-Wh~hlyS6V7R;-8?tx}-GE(!jE%u4vE$mNq%NV%?#_A#@6K#z zW^HV$fbb+zBJv?0T2GrQO-fQA1yZRhYAdxLDpewVB+5gP3){3psj9YWnnYC}QCoWM znVI$8^)+2qcxUE+&pC4+=XdU1l5sPdRP8AIBk(DQzuI0?Rcw{oNw~(Ds@f|2fq{eu zRl`|b)LKTWz_@zEHZr1S8J(ApVpwWsbzO<3R4#rwsetEY1KPN`L=P&_qV}*dp=O0| zxr+s4ols0$)5qz7UiO?H0qY?&@7HwAN~-bV=4x!NA6CDVRV|xZ?5f+Ek}5W=LBmyn zVMZ~PR7zcBwj9U2%AZjS%qB!rv*Ok*)~kn%ahg^wOBv^${gc{&iAPi7oy%D zSxm_&Q7xs}(=cZ?7o!QMpnjj4g0S>9hWB7Zx;Gv#w6cxDr{dsi&}Z|onl>i6;0e=6 z-_Efar|jz6wCDT+f$Fph32#YgXhepkTk*ZH> zrlB)CI;of%OLN|Vl1d0r1r9M-ZhCMZ7j8Yat{hTK79k@x+CX-J)3OmvshE+~ZRkB0 zW+QtdHNFKh&9!gB_Pf0Hc$O!9GdB9+VQ$St%9!HZTMFHQX0GvGQU=e}UTn)&l@!<9 zioSl=657m6QC7BLd!^@IMDP}z?An8Dz&f>Tvp8wDk`>^-{4fAXV~C8crTOH&4`bB$ zr6{FDRla{A?EcC{$;}O7n`g8ru{oo5G^*RDSu6_*GLo|jd!hQUA}(drL0HkDqlOLT zD5)wLU_EV^(^Q4!p)gt_21S!!#_j0S-kUWsm(a`7W>ng$XVXz|GZG7)G#zErW#R1S zYrqZ+(ZGdBX+T?Cu@!CL08IP@6DJ8qJQ=jh*4}4ldRhrf0`!Ql+f= zD7LMFA8bWX=}gtmLQ)qlE~qeQ`tS%B-^TUWD(-%3RAYrdlhk5Ls!im69=o=7 z6iN&$)odR5(b!6Cf?I+M*u78XU#L)4p8{vj^dbhY*{jooLw%I3!Zg?ZeQaNac^TDo z1&V>_{BVsqk$Za7aY%}op~w7kz>X3$lT<9eI=+fKb|ag=|8M+rjJ}HjQeriRlnjy9uZhY&Btmapzu& zt+xn;_tB;O1hBl#x=31<_K9L1@SgA+KuyMBtO}g-St%u??D6lx_fPR&P7J~bwtDwt z+uni>4=by4zd+W zDG8m>NhlRk;3(pafE@Y&qOJBKPThp7r^}B$5$N)>GCTA8`qX2vD-AMx`Ps+Mz=+vN zf{^fzACmRRD_dhdzuJ)F8B=9@9Ok!gyyqfWI{;)cTNCP=E zxvbB-6vpIw;sGCi@M-cY4j|Hc9gds7C!QYJQW5BI$CfhCkLUH{sC&3YdiD?xq)2ZC zdEJXR@OLa@_<&!&KJunNIPk zH@^Pc{oTBd?$UhZ$&%5L=DVj$Lr0qLN#7wl;PM736&-2*=m#DO(v3gBQFY5dJVfB> zxj_HZPhh+?f&S+Wfev?hq@)`KI;%MnL8PP`f35P6l5$U-@s>i$J<}pWO3Ho3R73G2c!bcoZQlOtZ!yzRH`ioaYNJ+Vuu5(D01@`AFL`X@w z^RJ1Jl5!V579l0&UTzT~1^W9Uq@>(;u8NS7a+hw3kdktjU*?d?&%>2v98wFqDMCuh zU3rH?DsTTvmk22-_sVl3q@>(;6BL%J;Dbmpy}Lk!TXdICeKTG%Qu3*bt)(F)pSpDE z4v~^iU50(W#N9|f^+w!7M4mkZTkMv_omMLP~aaekejpcDgr{i+Bl**Wlx2r1d=|FH-u**W+}5mK`A;Is%S*?DNM2r1baNQ;n?oxz9*DbW8T zLP~ZX{+S3V*%@jRAqD!=BBVh7P=u81eD;tCDcKorrjRlPA4H1j-321tdPvQEzO8hm z=8jx05vjSO58NqI%%xKk$)qk8BbmT45nluJunLQtsrC5Gi+RwGb(H>UTn<+!GgsNV(G) zAyV$lE+JCx%r}HcxhL`0Jey+t_`8(so{S5Ta!+0pA_Y42L--dDDfi3wb#wZyTmJ)< Ch^eLk literal 0 HcmV?d00001 diff --git a/test/nonmoving-gc-census-T23340.eventlog.reference b/test/nonmoving-gc-census-T23340.eventlog.reference new file mode 100644 index 0000000..e7637b8 --- /dev/null +++ b/test/nonmoving-gc-census-T23340.eventlog.reference @@ -0,0 +1,231 @@ +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) +42: Intern string (size variable) +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 memory ever allocated (size 12) +50: Current heap size (number of allocated mblocks) (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) +90: The RTS attempted to return heap memory to the OS (size 16) +91: Report the size of the heap in blocks (size 12) +160: Start of heap profile (size variable) +161: Cost-centre 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) +169: An IPE entry (size variable) +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 mark synchronisation (size 0) +204: Begin concurrent sweep phase (size 0) +205: End concurrent sweep phase (size 0) +206: Update remembered set flushed (size 2) +207: Nonmoving heap census (size 14) +210: Ticky-ticky entry counter definition (size variable) +211: Ticky-ticky entry counter sample (size 32) +212: Ticky-ticky entry counter begin sample (size 0) + +Events: +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"] +3158969: Starting nonmoving GC preparation +3161769: Marking roots for nonmoving GC +3162369: Finished marking roots for nonmoving GC +3162369: Finished nonmoving GC preparation +3165069: concurrent mark began +3483866: concurrent mark ended: marked 2789 objects +3484166: concurrent mark began +3484166: concurrent mark ended: marked 1 objects +3484266: concurrent mark began +3484266: concurrent mark ended: marked 1 objects +3490366: concurrent sweep began +3490566: concurrent sweep ended +3493366: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +3494866: nonmoving heap census 16: 0 active segments, 0 filled segments, 38 live blocks +3495766: nonmoving heap census 24: 0 active segments, 0 filled segments, 99 live blocks +3496466: nonmoving heap census 32: 0 active segments, 0 filled segments, 5 live blocks +3496966: nonmoving heap census 40: 0 active segments, 0 filled segments, 0 live blocks +3497466: nonmoving heap census 48: 0 active segments, 0 filled segments, 0 live blocks +3498166: nonmoving heap census 56: 0 active segments, 0 filled segments, 0 live blocks +3499866: nonmoving heap census 64: 0 active segments, 0 filled segments, 0 live blocks +3500366: nonmoving heap census 72: 0 active segments, 0 filled segments, 0 live blocks +3527666: nonmoving heap census 80: 0 active segments, 0 filled segments, 0 live blocks +3527866: nonmoving heap census 88: 0 active segments, 0 filled segments, 0 live blocks +3528366: nonmoving heap census 96: 0 active segments, 0 filled segments, 0 live blocks +3528766: nonmoving heap census 104: 0 active segments, 0 filled segments, 0 live blocks +3529066: nonmoving heap census 112: 0 active segments, 0 filled segments, 0 live blocks +3529366: nonmoving heap census 120: 0 active segments, 0 filled segments, 0 live blocks +3529566: nonmoving heap census 128: 0 active segments, 0 filled segments, 0 live blocks +3529866: nonmoving heap census 256: 0 active segments, 0 filled segments, 0 live blocks +3529966: nonmoving heap census 512: 0 active segments, 0 filled segments, 0 live blocks +3530066: nonmoving heap census 1024: 0 active segments, 0 filled segments, 0 live blocks +3530166: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +3530266: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +3530466: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +3530566: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +30946697: Starting nonmoving GC preparation +30949497: Marking roots for nonmoving GC +30949997: Finished marking roots for nonmoving GC +30950097: Finished nonmoving GC preparation +30957296: concurrent mark began +31188794: concurrent mark ended: marked 10999 objects +31188894: concurrent mark began +31189694: concurrent mark ended: marked 12 objects +31189794: concurrent mark began +31189794: concurrent mark ended: marked 1 objects +31189794: concurrent mark began +31189894: concurrent mark ended: marked 1 objects +31190794: concurrent sweep began +31230594: concurrent sweep ended +31232294: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +31233394: nonmoving heap census 16: 0 active segments, 0 filled segments, 54 live blocks +31234094: nonmoving heap census 24: 0 active segments, 0 filled segments, 120 live blocks +31236194: nonmoving heap census 32: 2 active segments, 4 filled segments, 4100 live blocks +31236594: nonmoving heap census 40: 0 active segments, 0 filled segments, 1 live blocks +31236994: nonmoving heap census 48: 0 active segments, 0 filled segments, 3 live blocks +31237294: nonmoving heap census 56: 0 active segments, 0 filled segments, 0 live blocks +31237594: nonmoving heap census 64: 0 active segments, 0 filled segments, 2 live blocks +31237894: nonmoving heap census 72: 0 active segments, 0 filled segments, 0 live blocks +31238094: nonmoving heap census 80: 0 active segments, 0 filled segments, 0 live blocks +31238394: nonmoving heap census 88: 0 active segments, 0 filled segments, 0 live blocks +31238694: nonmoving heap census 96: 0 active segments, 0 filled segments, 0 live blocks +31238894: nonmoving heap census 104: 0 active segments, 0 filled segments, 0 live blocks +31239094: nonmoving heap census 112: 0 active segments, 0 filled segments, 0 live blocks +31239394: nonmoving heap census 120: 0 active segments, 0 filled segments, 0 live blocks +31239594: nonmoving heap census 128: 0 active segments, 0 filled segments, 1 live blocks +31239694: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +31239794: nonmoving heap census 512: 0 active segments, 0 filled segments, 0 live blocks +31239894: nonmoving heap census 1024: 0 active segments, 0 filled segments, 1 live blocks +31239994: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +31240094: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +31240294: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +31240294: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +58695524: Starting nonmoving GC preparation +58698024: Marking roots for nonmoving GC +58698924: Finished marking roots for nonmoving GC +58699024: Finished nonmoving GC preparation +58708324: concurrent mark began +58950222: concurrent mark ended: marked 10996 objects +58950422: concurrent mark began +58951222: concurrent mark ended: marked 12 objects +58951222: concurrent mark began +58951322: concurrent mark ended: marked 1 objects +58951322: concurrent mark began +58951322: concurrent mark ended: marked 1 objects +58952922: concurrent sweep began +58992921: concurrent sweep ended +58995021: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +58996121: nonmoving heap census 16: 0 active segments, 0 filled segments, 54 live blocks +58996721: nonmoving heap census 24: 0 active segments, 0 filled segments, 120 live blocks +58998821: nonmoving heap census 32: 2 active segments, 4 filled segments, 4100 live blocks +58999321: nonmoving heap census 40: 0 active segments, 0 filled segments, 1 live blocks +58999821: nonmoving heap census 48: 0 active segments, 0 filled segments, 3 live blocks +59000121: nonmoving heap census 56: 0 active segments, 0 filled segments, 0 live blocks +59000421: nonmoving heap census 64: 0 active segments, 0 filled segments, 2 live blocks +59000721: nonmoving heap census 72: 0 active segments, 0 filled segments, 0 live blocks +59001021: nonmoving heap census 80: 0 active segments, 0 filled segments, 0 live blocks +59001321: nonmoving heap census 88: 0 active segments, 0 filled segments, 0 live blocks +59001721: nonmoving heap census 96: 0 active segments, 0 filled segments, 0 live blocks +59001921: nonmoving heap census 104: 0 active segments, 0 filled segments, 0 live blocks +59002221: nonmoving heap census 112: 0 active segments, 0 filled segments, 0 live blocks +59002421: nonmoving heap census 120: 0 active segments, 0 filled segments, 0 live blocks +59002621: nonmoving heap census 128: 0 active segments, 0 filled segments, 1 live blocks +59002821: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +59002921: nonmoving heap census 512: 0 active segments, 0 filled segments, 0 live blocks +59003021: nonmoving heap census 1024: 0 active segments, 0 filled segments, 1 live blocks +59003121: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +59003221: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +59003421: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +59003421: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +60250409: Starting nonmoving GC preparation +60251309: Marking roots for nonmoving GC +60251709: Finished marking roots for nonmoving GC +60251709: Finished nonmoving GC preparation +60252909: concurrent mark began +60308008: concurrent mark ended: marked 1897 objects +60308108: concurrent mark began +60308508: concurrent mark ended: marked 8 objects +60308608: concurrent mark began +60308708: concurrent mark ended: marked 1 objects +60308708: concurrent mark began +60308808: concurrent mark ended: marked 2 objects +60309608: concurrent sweep began +60314808: concurrent sweep ended +60316708: nonmoving heap census 8: 0 active segments, 0 filled segments, 0 live blocks +60317708: nonmoving heap census 16: 0 active segments, 0 filled segments, 55 live blocks +60318408: nonmoving heap census 24: 0 active segments, 0 filled segments, 121 live blocks +60320508: nonmoving heap census 32: 2 active segments, 0 filled segments, 37 live blocks +60320908: nonmoving heap census 40: 0 active segments, 0 filled segments, 1 live blocks +60321408: nonmoving heap census 48: 0 active segments, 0 filled segments, 3 live blocks +60321708: nonmoving heap census 56: 0 active segments, 0 filled segments, 0 live blocks +60322008: nonmoving heap census 64: 0 active segments, 0 filled segments, 2 live blocks +60322308: nonmoving heap census 72: 0 active segments, 0 filled segments, 0 live blocks +60322608: nonmoving heap census 80: 0 active segments, 0 filled segments, 0 live blocks +60322808: nonmoving heap census 88: 0 active segments, 0 filled segments, 0 live blocks +60323408: nonmoving heap census 96: 0 active segments, 0 filled segments, 0 live blocks +60323608: nonmoving heap census 104: 0 active segments, 0 filled segments, 0 live blocks +60323808: nonmoving heap census 112: 0 active segments, 0 filled segments, 0 live blocks +60324008: nonmoving heap census 120: 0 active segments, 0 filled segments, 0 live blocks +60324208: nonmoving heap census 128: 0 active segments, 0 filled segments, 1 live blocks +60324408: nonmoving heap census 256: 0 active segments, 0 filled segments, 1 live blocks +60324508: nonmoving heap census 512: 0 active segments, 0 filled segments, 0 live blocks +60324608: nonmoving heap census 1024: 0 active segments, 0 filled segments, 1 live blocks +60324708: nonmoving heap census 2048: 0 active segments, 0 filled segments, 0 live blocks +60324808: nonmoving heap census 4096: 0 active segments, 0 filled segments, 0 live blocks +60324808: nonmoving heap census 8192: 0 active segments, 0 filled segments, 0 live blocks +60324908: nonmoving heap census 16384: 0 active segments, 0 filled segments, 0 live blocks +