summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorBen Gamari <ben@smart-cactus.org>2020-04-23 22:57:24 -0400
committerMarge Bot <ben+marge-bot@smart-cactus.org>2020-05-03 04:41:33 -0400
commitc560dd07f506810eaabae2f582491138aa224819 (patch)
tree012ef93bd92386f8ea5cd2207285fa5ff07006af
parent7bfe9ac514e18c0b0e24ff55230fe98ec9db894c (diff)
downloadhaskell-c560dd07f506810eaabae2f582491138aa224819.tar.gz
users guide: Move eventlog documentation users guide
-rw-r--r--docs/users_guide/conf.py10
-rw-r--r--docs/users_guide/eventlog-formats.rst616
-rw-r--r--docs/users_guide/runtime_control.rst5
-rw-r--r--includes/rts/EventLogFormat.h58
4 files changed, 585 insertions, 104 deletions
diff --git a/docs/users_guide/conf.py b/docs/users_guide/conf.py
index 6fd94db74f..d69c84f914 100644
--- a/docs/users_guide/conf.py
+++ b/docs/users_guide/conf.py
@@ -284,7 +284,17 @@ def setup(app):
parse_node=parse_flag,
indextemplate='pair: %s; RTS option',
doc_field_types=[
+ Field('since', label='Introduced in GHC version', names=['since'])
+ ])
+
+ app.add_object_type('event-type', 'event-type',
+ objname='event log event type',
+ indextemplate='pair: %s; eventlog event type',
+ doc_field_types=[
Field('since', label='Introduced in GHC version', names=['since']),
+ Field('tag', label='Event type ID', names=['tag']),
+ Field('length', label='Record length', names=['length']),
+ TypedField('fields', label='Fields', names='field', typenames=('fieldtype', 'type'))
])
app.add_object_type('pragma', 'pragma',
diff --git a/docs/users_guide/eventlog-formats.rst b/docs/users_guide/eventlog-formats.rst
index 2f418b836a..f50285890a 100644
--- a/docs/users_guide/eventlog-formats.rst
+++ b/docs/users_guide/eventlog-formats.rst
@@ -1,3 +1,5 @@
+.. _eventlog-encodings:
+
Eventlog encodings
==================
@@ -7,6 +9,481 @@ 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.
+
+
+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
+
+.. code-block:: none
+
+ 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.
+
+Runtime system diagnostics
+--------------------------
+
+ * ``ThreadId ~ Word32``
+ * ``CapNo ~ Word16``
+ * ``CapSetId ~ Word32``
+
+Capability sets
+~~~~~~~~~~~~~~~
+
+TODO
+
+Environment information
+~~~~~~~~~~~~~~~~~~~~~~~
+
+These events are typically produced during program startup and describe the
+environment which the program is being run in.
+
+.. event-type:: 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.
+
+.. event-type:: 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.
+
+.. event-type:: 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.
+
+Thread and scheduling events
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+.. event-type:: CREATE_THREAD
+
+ :tag: 0
+ :length: fixed
+ :field ThreadId: thread id
+
+ Marks the creation of a Haskell thread.
+
+
+.. event-type:: RUN_THREAD
+
+ :tag: 1
+ :length: fixed
+ :field ThreadId: thread id
+
+ The indicated thread has started running.
+
+
+.. event-type:: 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``.
+
+
+.. event-type:: THREAD_RUNNABLE
+
+ :tag: 3
+ :length: fixed
+ :field ThreadId: thread id
+
+ The indicated thread is has been marked as ready to run.
+
+
+.. event-type:: MIGRATE_THREAD
+
+ :tag: 4
+ :length: fixed
+ :field ThreadId: thread id
+ :field CapNo: capability
+
+ The indicated thread has been migrated to a new capability.
+
+
+.. event-type:: THREAD_WAKEUP
+
+ :tag: 8
+ :length: fixed
+ :field ThreadId: thread id
+ :field CapNo: other capability
+
+ The indicated thread has been been woken up on another capability.
+
+.. event-type:: THREAD_LABEL
+
+ :tag: 44
+ :length: fixed
+ :field ThreadId: thread id
+ :field String: label
+
+ The indicated thread has been given a label (e.g. with
+ :base-ref:`Control.Concurrent.setThreadLabel`).
+
+
+Garbage collector events
+~~~~~~~~~~~~~~~~~~~~~~~~
+
+.. event-type:: GC_START
+
+ :tag: 9
+ :length: fixed
+
+ A garbage collection pass has been started.
+
+.. event-type:: GC_END
+
+ :tag: 10
+ :length: fixed
+
+ A garbage collection pass has been finished.
+
+.. event-type:: REQUEST_SEQ_GC
+
+ :tag: 11
+ :length: fixed
+
+ A sequential garbage collection has been requested by a capability.
+
+.. event-type:: REQUEST_PAR_GC
+
+ :tag: 12
+ :length: fixed
+
+ A parallel garbage collection has been requested by a capability.
+
+.. event-type:: GC_IDLE
+
+ :tag: 20
+ :length: fixed
+
+ An idle-time garbage collection has been started.
+
+.. event-type:: GC_WORK
+
+ :tag: 21
+ :length: fixed
+
+ Marks the start of concurrent scavenging.
+
+.. event-type:: GC_DONE
+
+ :tag: 22
+ :length: fixed
+
+ Marks the end of concurrent scavenging.
+
+.. event-type:: 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: TODO
+ :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 the heap configuration. Typically produced
+ during RTS initialization..
+
+.. event-type:: GC_GLOBAL_SYNC
+
+ :tag: 54
+ :length: fixed
+
+ TODO
+
+Heap events and statistics
+~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+.. event-type:: 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.
+
+.. event-type:: HEAP_SIZE
+
+ :tag: 50
+ :length: fixed
+ :field CapSetId: heap capability set
+ :field Word64: heap size in bytes
+
+ Report the heap size.
+
+.. event-type:: HEAP_LIVE
+
+ :tag: 51
+ :length: fixed
+ :field CapSetId: heap capability set
+ :field Word64: heap size in bytes
+
+ Report the live heap size.
+
+.. event-type:: 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..
+
+Spark events
+~~~~~~~~~~~~
+
+.. event-type:: CREATE_SPARK_THREAD
+
+ :tag: 15
+ :length: fixed
+
+ A thread has been created to perform spark evaluation.
+
+.. event-type:: SPARK_COUNTERS
+
+ :tag: 34
+ :length: fixed
+
+ A periodic reporting of various statistics of spark evaluation.
+
+.. event-type:: SPARK_CREATE
+
+ :tag: 35
+ :length: fixed
+
+ A spark has been added to the spark pool.
+
+.. event-type:: SPARK_DUD
+
+ :tag: 36
+ :length: fixed
+
+ TODO
+
+.. event-type:: SPARK_OVERFLOW
+
+ :tag: 37
+ :length: fixed
+
+ TODO
+
+.. event-type:: SPARK_RUN
+
+ :tag: 38
+ :length: fixed
+
+ Evaluation has started on a spark.
+
+.. event-type:: 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.
+
+.. event-type:: SPARK_FIZZLE
+
+ :tag: 40
+ :length: fixed
+
+ A spark has been GC'd before being evaluated.
+
+.. event-type:: SPARK_GC
+
+ :tag: 41
+ :length: fixed
+
+ An unevaluated spark has been garbage collected.
+
+Capability events
+~~~~~~~~~~~~~~~~~
+
+.. event-type:: CAP_CREATE
+
+ :tag: 45
+ :length: fixed
+ :field CapNo: the capability number
+
+ A capability has been started.
+
+.. event-type:: CAP_DELETE
+
+ :tag: 46
+ :length: fixed
+
+ A capability has been deleted.
+
+.. event-type:: CAP_DISABLE
+
+ :tag: 47
+ :length: fixed
+
+ A capability has been disabled.
+
+.. event-type:: CAP_ENABLE
+
+ :tag: 48
+ :length: fixed
+
+ A capability has been enabled.
+
+Task events
+~~~~~~~~~~~
+
+.. event-type:: TASK_CREATE
+
+ :tag: 55
+ :length: fixed
+ :field TaskId: task id
+ :field CapNo: capability number
+ :field ThreadId: TODO
+
+ Marks the creation of a task.
+
+.. event-type:: 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.
+
+Tracing events
+~~~~~~~~~~~~~~
+
+.. event-type:: LOG_MSG
+
+ :tag: 16
+ :length: variable
+ :field String: The message
+
+ A log message from the runtime system.
+
+.. event-type:: BLOCK_MARKER
+
+ :tag: 18
+ :length: variable
+ :field Word32: size
+ :field Word64: end time in nanoseconds
+ :field String: marker name
+
+ TODO
+
+.. event-type:: USER_MSG
+
+ :tag: 19
+ :length: variable
+ :field String: message
+
+ A user log message (from, e.g., :base-ref:`Control.Concurrent.traceEvent`).
+
+.. event-type:: USER_MARKER
+
+ :tag: 58
+ :length: variable
+ :field String: marker name
+
+ A user marker (from :base-ref:`Debug.Trace.traceMarker`).
.. _heap-profiler-events:
@@ -28,11 +505,13 @@ Beginning of sample stream
A single fixed-width event emitted during program start-up describing the samples that follow.
- * ``EVENT_HEAP_PROF_BEGIN``
+.. event-type:: HEAP_PROF_BEGIN
- * ``Word8``: Profile ID
- * ``Word64``: Sampling period in nanoseconds
- * ``Word32``: Sample break-down type. One of,
+ :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 :rts-flag:`-hc`)
* ``HEAP_PROF_BREAKDOWN_CLOSURE_DESCR`` (output from :rts-flag:`-hd`)
@@ -42,32 +521,34 @@ A single fixed-width event emitted during program start-up describing the sample
* ``HEAP_PROF_BREAKDOWN_BIOGRAPHY`` (output from :rts-flag:`-hb`)
* ``HEAP_PROF_BREAKDOWN_CLOSURE_TYPE`` (output from :rts-flag:`-hT`)
- * ``String``: Module filter
- * ``String``: Closure description filter
- * ``String``: Type description filter
- * ``String``: Cost centre filter
- * ``String``: Cost centre stack filter
- * ``String``: Retainer filter
- * ``String``: Biography filter
+ :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
Cost centre definitions
^^^^^^^^^^^^^^^^^^^^^^^
A variable-length packet produced once for each cost centre,
- * ``EVENT_HEAP_PROF_COST_CENTRE``
+.. event-type:: HEAP_PROF_COST_CENTRE
- * ``Word32``: cost centre number
- * ``String``: label
- * ``String``: module
- * ``String``: source location
- * ``Word8``: flags
+ :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?
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.
@@ -75,9 +556,12 @@ 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,
- * ``EVENT_HEAP_PROF_SAMPLE_BEGIN``
+.. event-type:: HEAP_PROF_SAMPLE_BEGIN
+
+ :length: fixed
+ :field Word64: sample number
- * ``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
@@ -85,11 +569,12 @@ 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.
- * ``EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN``
-
- * ``Word64``: sample number
- * ``Word64``: eventlog timestamp in ns
+.. event-type:: 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
@@ -101,23 +586,29 @@ emitted. This is useful to properly delimit the sampling period and to record
the total time spent profiling.
- * ``EVENT_HEAP_PROF_SAMPLE_END``
- * ``Word64``: sample number
+.. event-type:: HEAP_PROF_SAMPLE_END
+
+ :tag: 165
+ :length: fixed
+ :field Word64: sample number
+ Marks the end of a heap profile sample.
Cost-centre break-down
^^^^^^^^^^^^^^^^^^^^^^
A variable-length packet encoding a heap profile sample broken down by,
- * cost-centre (``-hc``)
+ * cost-centre (:rts-flag:`-hc`)
- * ``EVENT_HEAP_PROF_SAMPLE_COST_CENTRE``
+.. event-type:: HEAP_PROF_SAMPLE_COST_CENTRE
- * ``Word8``: Profile ID
- * ``Word64``: heap residency in bytes
- * ``Word8``: stack depth
- * ``Word32[]``: cost centre stack starting with inner-most (cost centre numbers)
+ :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)
String break-down
@@ -125,42 +616,63 @@ String break-down
A variable-length event encoding a heap sample broken down by,
- * type description (``-hy``)
- * closure description (``-hd``)
- * module (``-hm``)
+ * type description (:rts-flag:`-hy`)
+ * closure description (:rts-flag:`-hd`)
+ * module (:rts-flag:`-hm`)
- * ``EVENT_HEAP_PROF_SAMPLE_STRING``
+.. event-type:: HEAP_PROF_SAMPLE_STRING
- * ``Word8``: Profile ID
- * ``Word64``: heap residency in bytes
- * ``String``: type or closure description, or module name
+ :tag: 164
+ :length: variable
+ :field Word8: profile ID
+ :field Word64: heap residency in bytes
+ :field String: type or closure description, or module name
.. _time-profiler-events:
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.
+The time profiling mode enabled by :rts-flag:`-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.
Profile begin event
~~~~~~~~~~~~~~~~~~~
- * ``EVENT_PROF_BEGIN``
+.. event-type:: PROF_BEGIN
- * ``Word64``: Tick interval, in nanoseconds
+ :tag: 168
+ :length: fixed
+ :field Word64: tick interval, in nanoseconds
+ Marks the beginning of a time profile.
-Tick sample event
-~~~~~~~~~~~~~~~~~
+Profile sample event
+~~~~~~~~~~~~~~~~~~~~
A variable-length packet encoding a profile sample.
- * ``EVENT_PROF_SAMPLE_COST_CENTRE``
+.. event-type:: 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)
+
+Biographical profile sample event
+---------------------------------
+
+A variable-length packet encoding a profile sample.
+
+.. event-type:: BIO_PROF_SAMPLE_BEGIN
+
+ :tag: 166
+
+ TODO
- * ``Word32``: Capability
- * ``Word64``: Current profiling tick
- * ``Word8``: stack depth
- * ``Word32[]``: cost centre stack starting with inner-most (cost centre numbers)
diff --git a/docs/users_guide/runtime_control.rst b/docs/users_guide/runtime_control.rst
index 2cf277176d..6d60eb507e 100644
--- a/docs/users_guide/runtime_control.rst
+++ b/docs/users_guide/runtime_control.rst
@@ -1190,9 +1190,8 @@ When the program is linked with the :ghc-flag:`-eventlog` option
accurate mode every spark event is logged individually. The latter
has a higher runtime overhead and is not enabled by default.
- The format of the log file is described by the header
- ``EventLogFormat.h`` that comes with GHC, and it can be parsed in
- Haskell using the
+ The format of the log file is described in this users guide in
+ :ref:`eventlog-encodings` It can be parsed in Haskell using the
`ghc-events <http://hackage.haskell.org/package/ghc-events>`__
library. To dump the contents of a ``.eventlog`` file as text, use
the tool ``ghc-events show`` that comes with the
diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index d5ed01a864..89a07bf5e1 100644
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -9,65 +9,25 @@
* of the format, and new tools will be able to understand old log
* files.
*
- * Each event has a specific format. If you add new events, give them
- * new numbers: we never re-use old event numbers.
- *
- * - The format is endian-independent: all values are represented in
- * bigendian 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.
- *
- * - Old event type ids are never re-used; just take a new identifier.
- *
- *
- * The format
- * ----------
- *
- * 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 ...
- *
+ * The canonical documentation for the event log format and record layouts is
+ * the "Eventlog encodings" section of the GHC User's Guide.
*
* To add a new event
* ------------------
*
* - In this file:
- * - give it a new number, add a new #define EVENT_XXX below
+ * - give it a new number, add a new #define EVENT_XXX
+ * below. Do not reuse event ids from deprecated event types.
+ *
* - In EventLog.c
* - add it to the EventDesc array
* - emit the event type in initEventLogging()
* - emit the new event in postEvent_()
* - generate the event itself by calling postEvent() somewhere
+ *
+ * - Describe the meaning and encoding of the event in the users guide
+ * (docs/user_guide/eventlog-formats.rst)
+ *
* - In the Haskell code to parse the event log file:
* - add types and code to read the new event
*