haskell / 9 / users_guide / eventlog-formats.html

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 (EventType) present in the file. The header is followed by the event records (Event) themselves, each of which start with the event type id and a 64-bit timestamp:

EventLog :
      EVENT_HEADER_BEGIN
      EventType*
      EVENT_HEADER_END
      EVENT_DATA_BEGIN
      Event*
      EVENT_DATA_END

EventType :
      EVENT_ET_BEGIN
      Word16         -- event type id, unique identifier for this event
      Int16          -- >=0  size of the event record in bytes (minus the event type id and timestamp fields)
                     -- -1   variable size
      Word32         -- size of the event description in bytes
      Word8*         -- event description, UTF8 encoded string describing the event
      Word32         -- size of the extra info in bytes
      Word8*         -- extra info (for future extensions)
      EVENT_ET_END

Event :
      Word16         -- event type id, as included in the event log header
      Word64         -- timestamp (nanoseconds)
      [Word16]       -- length of the rest (optional, for variable-sized events only)
      ... 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, the size 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:

  1. 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 or REQUEST_PAR_GC.
  2. As other capabilities reach yield points and suspend execution they emit STOP_THREAD events.
  3. When all capabilities have suspended execution, collection will begin, marked by a GC_START event.
  4. As individual parallel GC threads commence with scavenging they will emit GC_WORK events.
  5. 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 another GC_WORK event.
  6. Eventually when scavenging has finished a GC_DONE event will be emitted by each GC thread.
  7. A bit of book-keeping is performed.
  8. A GC_END event will be emitted marking the end of the GC cycle.
  9. A HEAP_SIZE event will be emitted giving the current size of the heap, in bytes, calculated by how many megablocks are allocated.
  10. A BLOCKS_SIZE event will be emitted giving the current size of the heap, in bytes, calculated by how many blocks are allocated.
  11. A GC_STATS_GHC event will be emitted containing various details of the collection and heap state.
  12. In the case of a major collection, a HEAP_LIVE event will be emitted describing the current size of the live on-heap data.
  13. In the case of the -threaded RTS, a SPARK_COUNTERS event will be emitted giving details on how many sparks have been created, evaluated, and GC’d.
  14. As mutator threads resume execution they will emit RUN_THREAD events.
  15. 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 KernelThreadId:
The thread-id of the kernel thread which created the task.

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.3.1.6. String break-down

A variable-length event encoding a heap sample broken down by,

  • type description (-hy)
  • closure description (-hd)
  • module (-hm)
HEAP_PROF_SAMPLE_STRING
Tag: 164
Length: variable
Field Word8: profile ID
Field Word64: heap residency in bytes
Field String: type or closure description, or module name

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.4.1. Profile begin event

PROF_BEGIN
Tag: 168
Length: fixed
Field Word64: tick interval, in nanoseconds

Marks the beginning of a time profile.

15.4.2. Profile sample event

A variable-length packet encoding a profile sample.

PROF_SAMPLE_COST_CENTRE
Tag: 167
Length: variable
Field Word32: capability
Field Word64: current profiling tick
Field Word8: stack depth
Field Word32[]: cost centre stack starting with inner-most (cost centre numbers)

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:

  1. The preparatory phase of collection will emit the usual events associated with a moving collection. See Garbage collector events for details.
  2. 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.
  3. Concurrent marking begins, denoted by a CONC_MARK_BEGIN event.
  4. When the mark queue is depleted a CONC_MARK_END is emitted.
  5. If necessary (e.g. due to weak pointer marking), the marking process will continue, returning to step (3) above.
  6. 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.
  7. Mutator threads will suspend execution and, if necessary, flush their update remembered sets (indicated by CONC_UPD_REM_SET_FLUSH events).
  8. The collector will do any final marking necessary (indicated by CONC_MARK_BEGIN and CONC_MARK_END events).
  9. The collector will do a small amount of sweeping, disable the write barrier, emit a CONC_SYNC_END event, and allow mutators to resume
  10. The collector will begin the concurrent sweep phase, indicated by a CONC_SWEEP_BEGIN event.
  11. Once sweeping has concluded a CONC_SWEEP_END event will be emitted and the concurrent collector thread will terminate.
  12. 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
Field Word32: number of objects which were marked in this marking phase.

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.

© 2002–2007 The University Court of the University of Glasgow. All rights reserved.
Licensed under the Glasgow Haskell Compiler License.
https://downloads.haskell.org/~ghc/9.4.2/docs/users_guide/eventlog-formats.html