Index out of range in `ghc-events show` and dependencies of `ghc-events`

[MangoIV]

Hi! I have had a couple of problems with eventlog2html and hs-speedscope recently and they seem to be a problem either with the library or the eventlog that the ghc RTS emits. I can more or less (sometimes it doesn't happen) reliably reproduce this error with the following program:

module Main where

import Data.ByteString (ByteString)
import qualified Data.ByteString as BS
import Data.Foldable (for_)
import Data.Monoid (Endo (..))

largeEndo :: Endo ByteString
largeEndo = Endo \x -> BS.replicate 100 97 <> x

manyEndos :: Endo ByteString -> Endo ByteString
manyEndos = mconcat . replicate 10_000

main :: IO ()
main = for_ [1 .. 30] \_ ->
  BS.putStr $ appEndo (manyEndos largeEndo) mempty 

compile with
ghc -rtsopts -prof -fprof-late -O0 ./bla.hs
run with
./bla +RTS -hc -p -l-au

I have not tried to further reduce the example.

This happens on ghc 9.6, 9.8 and 9.10 at least, according to @TeofilC on ghc-events HEAD, and then at least on ghc-events 0.19.0.1.

It affects not only ghc-events but also hs-speedscope and eventlog2html.

related issue on eventlog2html issue tracker:
mpickering/eventlog2html#136

[MangoIV]

I think we're failing in GHC.RTS.Events.Binary.getEvent :: EventParsers -> Get (Maybe Event) where we try to index into the parsers and instead of getting an EventTypeNum within range, we get a really big one.

[TeofilC]

Running ghc-events with an eventlog from the reproducer triggers an assertion failure at this line:

ghc-events/src/GHC/RTS/Events/Binary.hs

Lines 758 to 765 in 2168f61

	assert
	((fromIntegral payloadLen :: Int) == sum
	[ 4
	, 8 -- ticks
	, 1 -- stack depth
	, fromIntegral profStackDepth * 4
	])
	(return ())

It seems like the payloadLen is wrong for certain EVENT_PROF_SAMPLE_COST_CENTRE events

[MangoIV]

jup, the last four parses before it blows up look like this:

evSpec: HeapProfSampleCostCentre {heapProfId = 0, heapProfResidency = 912, heapProfStackDepth = 1, heapProfStack = [78]}, etRef: 163
evSpec: ProfSampleCostCentre {profCapset = 369098752, profTicks = 4333765376, profStackDepth = 0, profCcsStack = []}, etRef: 167
evSpec: HeapProfSampleString {heapProfId = 0, heapProfResidency = 2029359963648, heapProfLabel = "\SO"}, etRef: 164
evSpec: CreateThread {thread = 22784}, etRef: 0

It looks like the parse of ProfSampleCostCentre introducest the corruption.

[MangoIV]

@TeofilC is it possible that this is the Ccs stack being too deep for the profStackDepth Word8? And then it overflows and we don't read the Vector to end?

[MangoIV]

That doesn't seem to be it, you're right, the payloadLen before that is already completely off.

[TeofilC]

Yes on the GHC side we truncate to 255, which should be fine

[MangoIV]

So afaiu this means that either the parsing of the header on the ghc-events side or the writing of the header on ghc RTS side goes wrong. (At least the previous events look fine, so I'm not assuming that they're already introducing the corruption)

[TeofilC]

Strangely enough I can't seem to reproduce this with -threaded. I get the impression that an EVENT_PROF_SAMPLE_COST_CENTRE and an EVENT_HEAP_PROF_SAMPLE_COST_CENTRE event being written at the same time is the cause of this. Yet, I'm not sure how that would be possible with the non-threaded runtime!

[MangoIV]

Also don’t they acquire the global eventBuf lock before writing?

[TeofilC]

I also can't reproduce if I only do heap profiling or time profiling with the non-threaded RTS.

So it seems like we need to be doing both with the non-threaded RTS.

I think it's highly likely that somehow we try to write both a heap sample and a time sample at the same time to the eventlog

[TeofilC]

Also don’t they acquire the global eventBuf lock before writing?

Ah but that only exists for the threaded RTS

[MangoIV]

I think it's highly likely that somehow we try to write both a heap sample and a time sample at the same time to the eventlog

and the -threaded safe guards against that because it does proper locking while the non-threaded RTS doesn’t but is still somehow concurrent? That’s weird

[TeofilC]

What seems to be happening is:

1. we are running a heap profile
2. we write half of a heap sample event
3. the time profile timer triggers
4. we pause what we are doing, and write a time sample event in the middle of our heap event
5. we unpause and finish writing our heap event

So we end up with something garbled.

This story is backed up by putting a bunch of traces inside the eventlog printing functions in the RTS. This is the order of events they suggest

[MangoIV]

So there must be a context switch somewhere in dumpCensus, even with the non-threaded RTS?

[MangoIV]

Is it possible that this is happening because the time profile is running asynchronously? (see initTimer -> initTicker -> createAttachedOSThread with handle_tick -> handleProfTick -> traceProfSampleCostCentre) maybe there should be a lock for writing to the eventlog?