15. Eventlog encodings¶
This section documents the encodings of the events emitted to GHC’s event log. These events can include information about the thread scheduling events, garbage collection statistics, profiling information, user-defined tracing events.
This section is intended for implementors of tooling which consume these events.
GHC ships with a C header file (EventlogFormat.h
) which provides symbolic
names for the event type IDs described in this file.
15.1. 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.
The format is endian-independent: all values are represented in big-endian order.
The format is extensible:
The header describes each event type and its length. Tools that don’t recognise a particular event type can skip those events.
There is room for extra information in the event type specification, which can be ignored by older tools.
Events can have extra information added, but existing fields cannot be changed. Tools should ignore extra fields at the end of the event record.
The event-log stream begins with a header describing the event types present in the file. The header is followed by the event records themselves, each of which consist of a 64-bit timestamp
log : EVENT_HEADER_BEGIN
EventType*
EVENT_HEADER_END
EVENT_DATA_BEGIN
Event*
EVENT_DATA_END
EventType :
EVENT_ET_BEGIN
Word16 -- unique identifier for this event
Int16 -- >=0 size of the event in bytes (minus the header)
-- -1 variable size
Word32 -- length of the next field in bytes
Word8* -- string describing the event
Word32 -- length of the next field in bytes
Word8* -- extra info (for future extensions)
EVENT_ET_END
Event :
Word16 -- event_type
Word64 -- time (nanosecs)
[Word16] -- length of the rest (for variable-sized events only)
... extra event-specific info ...
There are two classes of event types:
Fixed size: All event records of a fixed-sized type are of the same length, given in the header event-log header.
Variable size: Each event record includes a length field.
15.2. Runtime system diagnostics¶
ThreadId ~ Word32
CapNo ~ Word16
CapSetId ~ Word32
15.2.1. Capability sets¶
TODO
15.2.2. Environment information¶
These events are typically produced during program startup and describe the environment which the program is being run in.
-
RTS_IDENTIFIER
¶ - Tag
29
- Length
variable
- Field CapSetId
Capability set
- Field String
Runtime system name and version.
Describes the name and version of the runtime system responsible for the indicated capability set.
-
PROGRAM_ARGS
¶ - Tag
30
- Length
variable
- Field CapSetId
Capability set
- Field [String]
The command-line arguments passed to the program
Describes the command-line used to start the program.
-
PROGRAM_ENV
¶ - Tag
31
- Length
variable
- Field CapSetId
Capability set
- Field [String]
The environment variable name/value pairs. (TODO: encoding?)
Describes the environment variables present in the program’s environment.
15.2.3. Thread and scheduling events¶
-
CREATE_THREAD
¶ - Tag
0
- Length
fixed
- Field ThreadId
thread id
Marks the creation of a Haskell thread.
-
RUN_THREAD
¶ - Tag
1
- Length
fixed
- Field ThreadId
thread id
The indicated thread has started running.
-
STOP_THREAD
¶ - Tag
2
- Length
fixed
- Field ThreadId
thread id
- Field Word16
status
1: HeapOverflow
2: StackOverflow
3: ThreadYielding
4: ThreadBlocked
5: ThreadFinished
6: ForeignCall
7: BlockedOnMVar
8: BlockedOnBlackHole
9: BlockedOnRead
10: BlockedOnWrite
11: BlockedOnDelay
12: BlockedOnSTM
13: BlockedOnDoProc
16: BlockedOnMsgThrowTo
- Field ThreadId
thread id of thread being blocked on (only for some status values)
The indicated thread has stopped running for the reason given by
status
.
-
THREAD_RUNNABLE
¶ - Tag
3
- Length
fixed
- Field ThreadId
thread id
The indicated thread is has been marked as ready to run.
-
MIGRATE_THREAD
¶ - Tag
4
- Length
fixed
- Field ThreadId
thread id
- Field CapNo
capability
The indicated thread has been migrated to a new capability.
-
THREAD_WAKEUP
¶ - Tag
8
- Length
fixed
- Field ThreadId
thread id
- Field CapNo
other capability
The indicated thread has been woken up on another capability.
-
THREAD_LABEL
¶ - Tag
44
- Length
fixed
- Field ThreadId
thread id
- Field String
label
The indicated thread has been given a label (e.g. with GHC.Conc.labelThread).
15.2.4. Garbage collector events¶
The following events mark various points of the lifecycle of a moving garbage collection.
A typical garbage collection will look something like the following:
A capability realizes that it needs a garbage collection (e.g. as a result of running out of nursery) and requests a garbage collection. This is marked by
REQUEST_SEQ_GC
orREQUEST_PAR_GC
.As other capabilities reach yield points and suspend execution they emit
STOP_THREAD
events.When all capabilities have suspended execution, collection will begin, marked by a
GC_START
event.As individual parallel GC threads commence with scavenging they will emit
GC_WORK
events.If a parallel GC thread runs out of work it will emit a
GC_IDLE
event. If it is later handed more work it will emit anotherGC_WORK
event.Eventually when scavenging has finished a
GC_DONE
event will be emitted by each GC thread.A bit of book-keeping is performed.
A
GC_END
event will be emitted marking the end of the GC cycle.A
HEAP_SIZE
event will be emitted giving the current size of the heap, in bytes, calculated by how many megablocks are allocated.A
BLOCKS_SIZE
event will be emitted giving the current size of the heap, in bytes, calculated by how many blocks are allocated.A
GC_STATS_GHC
event will be emitted containing various details of the collection and heap state.In the case of a major collection, a
HEAP_LIVE
event will be emitted describing the current size of the live on-heap data.In the case of the
-threaded
RTS, aSPARK_COUNTERS
event will be emitted giving details on how many sparks have been created, evaluated, and GC’d.As mutator threads resume execution they will emit
RUN_THREAD
events.A
MEM_RETURN
event will be emitted containing details about currently live mblocks, how many we think we need and whether we could return excess to the OS.
Note that in the case of the concurrent non-moving collector additional events will be emitted during the concurrent phase of collection. These are described in Non-moving GC event output.
-
GC_START
¶ - Tag
9
- Length
fixed
A garbage collection pass has been started.
-
GC_END
¶ - Tag
10
- Length
fixed
A garbage collection pass has been finished.
-
REQUEST_SEQ_GC
¶ - Tag
11
- Length
fixed
A sequential garbage collection has been requested by a capability.
-
REQUEST_PAR_GC
¶ - Tag
12
- Length
fixed
A parallel garbage collection has been requested by a capability.
-
GC_IDLE
¶ - Tag
20
- Length
fixed
An idle-time garbage collection has been started.
-
GC_WORK
¶ - Tag
21
- Length
fixed
Marks the start of concurrent scavenging.
-
GC_DONE
¶ - Tag
22
- Length
fixed
Marks the end of concurrent scavenging.
-
GC_STATS_GHC
¶ - Tag
53
- Length
fixed
- Field CapSetId
heap capability set
- Field Word16
generation of collection
- Field Word64
bytes copied
- Field Word64
bytes of slop found
- Field Word64
bytes of fragmentation, the difference between total mblock size and total block size. When all mblocks are full of full blocks, this number is 0.
- Field Word64
number of parallel garbage collection threads
- Field Word64
maximum number of bytes copied by any single collector thread
- Field Word64
total bytes copied by all collector threads
Report various information about a major collection.
-
GC_GLOBAL_SYNC
¶ - Tag
54
- Length
fixed
TODO
-
MEM_RETURN
¶ - Tag
90
- Length
fixed
- Field CapSetId
heap capability set
- Field Word32
currently allocated mblocks
- Field Word32
the number of mblocks we would like to retain
- Field Word32
the number of mblocks which we returned to the OS
Report information about currently allocation megablocks and attempts made to return them to the operating system. If your heap is fragmented then the current value will be greater than needed value but returned will be less than the difference between the two.
15.2.5. Heap events and statistics¶
-
HEAP_ALLOCATED
¶ - Tag
49
- Length
fixed
- Field CapSetId
heap capability set
- Field Word64
allocated bytes
A new chunk of heap has been allocated by the indicated capability set.
-
HEAP_SIZE
¶ - Tag
50
- Length
fixed
- Field CapSetId
heap capability set
- Field Word64
heap size in bytes
Report the heap size, calculated by the number of megablocks currently allocated.
-
BLOCKS_SIZE
¶ - Tag
91
- Length
fixed
- Field CapSetId
heap capability set
- Field Word64
heap size in bytes
Report the heap size, calculated by the number of blocks currently allocated.
-
HEAP_LIVE
¶ - Tag
51
- Length
fixed
- Field CapSetId
heap capability set
- Field Word64
heap size in bytes
Report the live heap size.
-
HEAP_INFO_GHC
¶ - Tag
52
- Length
fixed
- Field CapSetId
heap capability set
- Field Word16
number of garbage collection generations
- Field Word64
maximum heap size
- Field Word64
allocation area size
- Field Word64
MBlock size
- Field Word64
Block size
Report various information about the heap configuration. Typically produced during RTS initialization..
15.2.6. Spark events¶
-
CREATE_SPARK_THREAD
¶ - Tag
15
- Length
fixed
A thread has been created to perform spark evaluation.
-
SPARK_COUNTERS
¶ - Tag
34
- Length
fixed
A periodic reporting of various statistics of spark evaluation.
-
SPARK_CREATE
¶ - Tag
35
- Length
fixed
A spark has been added to the spark pool.
-
SPARK_DUD
¶ - Tag
36
- Length
fixed
TODO
-
SPARK_OVERFLOW
¶ - Tag
37
- Length
fixed
TODO
-
SPARK_RUN
¶ - Tag
38
- Length
fixed
Evaluation has started on a spark.
-
SPARK_STEAL
¶ - Tag
39
- Length
fixed
- Field Word16
capability from which the spark was stolen
A spark has been stolen from another capability for evaluation.
-
SPARK_FIZZLE
¶ - Tag
40
- Length
fixed
A spark has been GC’d before being evaluated.
-
SPARK_GC
¶ - Tag
41
- Length
fixed
An unevaluated spark has been garbage collected.
15.2.7. Capability events¶
-
CAP_CREATE
¶ - Tag
45
- Length
fixed
- Field CapNo
the capability number
A capability has been started.
-
CAP_DELETE
¶ - Tag
46
- Length
fixed
A capability has been deleted.
-
CAP_DISABLE
¶ - Tag
47
- Length
fixed
A capability has been disabled.
-
CAP_ENABLE
¶ - Tag
48
- Length
fixed
A capability has been enabled.
15.2.8. Task events¶
-
TASK_CREATE
¶ - Tag
55
- Length
fixed
- Field TaskId
task id
- Field CapNo
capability number
- Field ThreadId
TODO
Marks the creation of a task.
-
TASK_MIGRATE
¶ - Tag
56
- Length
fixed
- Field TaskId
task id
- Field CapNo
old capability
- Field CapNo
new capability
Marks the migration of a task to a new capability.
15.2.9. Tracing events¶
-
LOG_MSG
¶ - Tag
16
- Length
variable
- Field String
The message
A log message from the runtime system.
-
BLOCK_MARKER
¶ - Tag
18
- Length
variable
- Field Word32
size
- Field Word64
end time in nanoseconds
- Field String
marker name
TODO
-
USER_MSG
¶ - Tag
19
- Length
variable
- Field String
message
A user log message (from, e.g., Control.Concurrent.traceEvent).
-
USER_MARKER
¶ - Tag
58
- Length
variable
- Field String
marker name
A user marker (from Debug.Trace.traceMarker).
15.3. Heap profiler event log output¶
The heap profiler can produce output to GHC’s event log, allowing samples to be correlated with other event log events over the program’s lifecycle.
This section defines the layout of these events. The String
type below is
defined to be a UTF-8 encoded NUL-terminated string.
15.3.1. Metadata event types¶
15.3.1.1. Beginning of sample stream¶
A single fixed-width event emitted during program start-up describing the samples that follow.
-
HEAP_PROF_BEGIN
¶ - Tag
160
- Length
variable
- Field Word8
profile ID
- Field Word64
sampling period in nanoseconds
- Field Word32
sample breadown type. One of,
HEAP_PROF_BREAKDOWN_COST_CENTER
(output from-hc
)HEAP_PROF_BREAKDOWN_CLOSURE_DESCR
(output from-hd
)HEAP_PROF_BREAKDOWN_RETAINER
(output from-hr
)HEAP_PROF_BREAKDOWN_MODULE
(output from-hm
)HEAP_PROF_BREAKDOWN_TYPE_DESCR
(output from-hy
)HEAP_PROF_BREAKDOWN_BIOGRAPHY
(output from-hb
)HEAP_PROF_BREAKDOWN_CLOSURE_TYPE
(output from-hT
)
- Field String
module filter
- Field String
closure description filter
- Field String
type description filter
- Field String
cost centre filter
- Field String
cost centre stack filter
- Field String
retainer filter
- Field String
biography filter
15.3.1.2. Cost centre definitions¶
A variable-length packet produced once for each cost centre,
-
HEAP_PROF_COST_CENTRE
¶ - Tag
161
- Length
fixed
- Field Word32
cost centre number
- Field String
label
- Field String
module
- Field String
source location
- Field Word8
flags:
bit 0: is the cost-centre a CAF?
15.3.1.3. Info Table Provenance definitions¶
A message which describes an approximate source position for
info tables. See -finfo-table-map
for more information.
-
IPE
¶ - Tag
169
- Length
fixed
- Field Word64
info table address
- Field String
table name
- Field String
closure type
- Field String
type
- Field String
source position label
- Field String
source position module
- Field String
source position location
15.3.1.4. Sample event types¶
A sample (consisting of a list of break-down classes, e.g. cost centres, and heap residency sizes), is to be encoded in the body of one or more events.
We normally mark the beginning of a new sample with an EVENT_HEAP_PROF_SAMPLE_BEGIN
event,
-
HEAP_PROF_SAMPLE_BEGIN
¶ - Length
fixed
- Field Word64
sample number
Marks the beginning of a heap profile sample.
Biographical profiling samples start with the EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN
event. These events also include a timestamp which indicates when the sample
was taken. This is because all these samples will appear at the end of
the eventlog due to how the biographical profiling mode works. You can
use the timestamp to reorder the samples relative to the other events.
-
HEAP_BIO_PROF_SAMPLE_BEGIN
¶ - Tag
166
- Length
fixed
- Field Word64
sample number
- Field Word64
eventlog timestamp in ns
A heap residency census will follow. Since events may only be up to 2^16^ bytes
in length a single sample may need to be split among multiple
EVENT_HEAP_PROF_SAMPLE
events. The precise format of the census entries is
determined by the break-down type.
At the end of the sample period the EVENT_HEAP_PROF_SAMPLE_END
event if
emitted. This is useful to properly delimit the sampling period and to record
the total time spent profiling.
-
HEAP_PROF_SAMPLE_END
¶ - Tag
165
- Length
fixed
- Field Word64
sample number
Marks the end of a heap profile sample.
15.3.1.5. Cost-centre break-down¶
- A variable-length packet encoding a heap profile sample broken down by,
cost-centre (
-hc
)
-
HEAP_PROF_SAMPLE_COST_CENTRE
¶ - Tag
163
- Length
variable
- Field Word8
profile ID
- Field Word64
heap residency in bytes
- Field Word8
stack depth
- Field Word32[]
cost centre stack starting with inner-most (cost centre numbers)
15.4. Time profiler event log output¶
The time profiling mode enabled by -p
also emits
sample events to the eventlog. At the start of profiling the
tick interval is emitted to the eventlog and then on each tick
the current cost centre stack is emitted. Together these
enable a user to construct an approximate track of the
executation of their program.
15.5. Biographical profile sample event¶
A variable-length packet encoding a profile sample.
-
BIO_PROF_SAMPLE_BEGIN
¶ - Tag
166
TODO
15.6. Non-moving GC event output¶
These events mark various stages of the
non-moving collection
lifecycle. These are enabled
with the +RTS -lg
event-set.
A typical non-moving collection cycle will look something like the following:
The preparatory phase of collection will emit the usual events associated with a moving collection. See Garbage collector events for details.
The concurrent write barrier is enabled and the concurrent mark thread is started. From this point forward mutator threads may emit
CONC_UPD_REM_SET_FLUSH
events, indicating that they have flushed their capability-local update remembered sets.Concurrent marking begins, denoted by a
CONC_MARK_BEGIN
event.When the mark queue is depleted a
CONC_MARK_END
is emitted.If necessary (e.g. due to weak pointer marking), the marking process will continue, returning to step (3) above.
When the collector has done as much concurrent marking as it can it will enter the post-mark synchronization phase of collection, denoted by a
CONC_SYNC_BEGIN
event.Mutator threads will suspend execution and, if necessary, flush their update remembered sets (indicated by
CONC_UPD_REM_SET_FLUSH
events).The collector will do any final marking necessary (indicated by
CONC_MARK_BEGIN
andCONC_MARK_END
events).The collector will do a small amount of sweeping, disable the write barrier, emit a
CONC_SYNC_END
event, and allow mutators to resumeThe collector will begin the concurrent sweep phase, indicated by a
CONC_SWEEP_BEGIN
event.Once sweeping has concluded a
CONC_SWEEP_END
event will be emitted and the concurrent collector thread will terminate.A
NONMOVING_HEAP_CENSUS
event will be emitted describing the fragmentation state of the non-moving heap.
-
CONC_MARK_BEGIN
¶ - Tag
200
- Length
fixed
Marks the beginning of marking by the concurrent collector.
-
CONC_MARK_END
¶ - Tag
201
- Length
fixed
Marks the end of marking by the concurrent collector.
-
CONC_SYNC_BEGIN
¶ - Tag
202
- Length
fixed
Marks the beginning of the concurrent garbage collector’s post-mark synchronization phase.
-
CONC_SYNC_END
¶ - Tag
203
- Length
fixed
Marks the end of the concurrent garbage collector’s post-mark synchronization phase.
-
CONC_SWEEP_BEGIN
¶ - Tag
204
- Length
fixed
Marks the beginning of the concurrent garbage collector’s sweep phase.
-
CONC_SWEEP_END
¶ - Tag
205
- Length
fixed
Marks the end of the concurrent garbage collector’s sweep phase.
-
CONC_UPD_REM_SET_FLUSH
¶ - Tag
206
- Length
fixed
Marks a capability flushing its local update remembered set accumulator.
15.6.1. Non-moving heap census¶
The non-moving heap census events (enabled with the +RTS -ln
event-set) are intended to provide insight into fragmentation of the non-moving
heap.
-
NONMOVING_HEAP_CENSUS
¶ - Tag
207
- Length
fixed
- Field Word8
base-2 logarithm of blk_sz.
- Field Word32
number of active segments.
- Field Word32
number of filled segments.
- Field Word32
number of live blocks.
Describes the occupancy of the blk_sz sub-heap.
15.6.2. Ticky counters¶
Programs compiled with -ticky
and -eventlog
and invoked
with +RTS -lT
will emit periodic samples of the ticky
entry counters to the eventlog.
-
TICKY_COUNTER_DEF
¶ - Tag
210
- Length
variable
- Field Word64
counter ID
- Field Word16
arity/field count
- Field String
argument kinds. This is the same as the synonymous field in the textual ticky summary.
- Field String
counter name
Defines a ticky counter.
-
TICKY_COUNTER_BEGIN_SAMPLE
¶ - Tag
212
- Length
fixed
Denotes the beginning of an atomic set of ticky-ticky profiler counter samples.
-
TICKY_COUNTER_SAMPLE
¶ - Tag
211
- Length
fixed
- Field Word64
counter ID
- Field Word64
number of times closures of this type has been entered.
- Field Word64
number of allocations (words)
- Field Word64
number of times this has been allocated (words). Only produced for modules compiled with
-ticky-allocd
.
Records the number of “ticks” recorded by a ticky-ticky counter single the last sample.