GitLab

Unfortunately the template support in this GitLab instance seems to be broken - I hope to provide all needed information.

Description

+RTS -va does not show all events that +RTS -la would show. I recognized this while working on Info Table Provenance (IPE) events. These are part of +RTS -la, but not of +RTS -va.

Example

Consider this simple Haskell program (any Haskell program would work):

main = pure (1 + 1)

Build it:

ghc -debug -finfo-table-map -rtsopts -fdistinct-constructor-tables -v0 EventlogOutput_IPE.hs

Run it and show the events from the event file:

./EventlogOutput_IPE +RTS -la
ghc-events show EventlogOutput_IPE.eventlog
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 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: Memory return statistics (size 16)
91: Current heap size (size of allocated blocks) (size 12)
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)
169: Info Table Source Position (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 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)
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:
39708: created capset 0 of type CapsetOsProcess
39838: created capset 1 of type CapsetClockDomain
40248: created cap 0
40348: assigned cap 0 to capset 0
40448: assigned cap 0 to capset 1
40838: capset 1: wall clock time 1622972801s 32367000ns (unix epoch)
41138: capset 0: pid 10684
41338: capset 0: parent pid 10488
41877: capset 0: RTS version "GHC-9.3.20210530 rts_debug"
42067: capset 0: args: ["./EventlogOutput_IPE","+RTS","-la"]
87355: 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
99954: Info Table Source Position
100224: Info Table Source Position
100434: Info Table Source Position
100634: Info Table Source Position
100834: Info Table Source Position
101034: Info Table Source Position
101254: Info Table Source Position
101414: Info Table Source Position
105214: task 0xceca70 created on cap 0 with OS kernel thread 10684
107843: cap 0: creating thread 1
109523: cap 0: running thread 1
122943: cap 0: stopping thread 1 (thread finished)
123872: task 0xceca70 deleted
124442: task 0xceca70 created on cap 0 with OS kernel thread 10684
124632: cap 0: creating thread 2
124872: cap 0: running thread 2
157310: cap 0: stopping thread 2 (thread finished)
157560: task 0xceca70 deleted
159210: cap 0: starting GC
164220: cap 0: GC working
312461: cap 0: GC idle
312541: cap 0: GC done
315311: cap 0: GC idle
315371: cap 0: GC done
315891: cap 0: GC idle
315951: cap 0: GC done
326670: cap 0: Memory return statistics
329120: cap 0: allocated on heap capset 0: 40840 total bytes till now
329520: cap 0: finished GC
329660: cap 0: all caps stopped for GC
329760: cap 0: GC stats for heap capset 0: generation 1, 3144 bytes copied, 21360 bytes slop, 905216 bytes fragmentation, 1 par threads, 0 bytes max par copied, 3144 bytes total par copied, 0 bytes balanced par copied
330080: cap 0: live data in heap capset 0: 35984 bytes
330200: cap 0: size of heap capset 0: 5242880 bytes
330310: cap 0: Current heap size (size of allocated blocks)
333760: cap 0: allocated on heap capset 0: 40840 total bytes till now
338579: removed cap 0 from capset 0
338699: removed cap 0 from capset 1
338809: deleted cap 0
338929: deleted capset 0
339029: deleted capset 1

Run it with +RTS -va:

./EventlogOutput_IPE +RTS -va
created capset 0 of type 2
created capset 1 of type 3
cap 0: initialised
assigned cap 0 to capset 0
assigned cap 0 to capset 1
cap 0: created thread 1[""]
cap 0: running thread 1[""] (ThreadRunGHC)
cap 0: thread 1[""] stopped (finished)
cap 0: created thread 2[""]
cap 0: running thread 2[""] (ThreadRunGHC)
cap 0: thread 2[""] stopped (finished)
cap 0: starting GC
cap 0: GC working
cap 0: GC idle
cap 0: GC done
cap 0: GC idle
cap 0: GC done
cap 0: GC idle
cap 0: GC done
cap 0: Memory Return (Current: 5) (Needed: 8) (Returned: 0)
cap 0: all caps stopped for GC
cap 0: finished GC
removed cap 0 from capset 0
removed cap 0 from capset 1
cap 0: shutting down
deleted capset 0
deleted capset 1

First Analyses

• +RTS -va itself does not enable event logging. The condition if event logging should be started is missing a case for TRACE_STDERR.

    if (RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG
            && rtsConfig.eventlog_writer != NULL) {
        startEventLogging(rtsConfig.eventlog_writer);
    }

https://gitlab.haskell.org/ghc/ghc/-/blob/5e1a224435fc6ebd34d02566f17fe1eaf5475bab/rts/Trace.c#L99

• There is (to my best knowledge) no EventLogWriter instance that would write to the console (stderr). There's only an implementation for writing to files.

Possible solutions

• Remove the +RTS -va option or adjust it's documentation/description.
• Fix this issue by implementing for event logging to stderr. This might be non-trivial, as event log files are written in binary while the console needs (meaningful) text output.