Add documentation for runtime tracing (#768)

docs/SUMMARY.md

@@ -135,6 +135,7 @@
         * [Connection pool](database/connection_pool.md)
         * [Transactions](database/transactions.md)
     * [Coding style](conventions/coding_style.md)
+    * [Runtime Tracing](guides/runtime_tracing.md)
 * [Tutorials](tutorials/README.md)
     * [Getting started](getting_started/README.md)
         * [An HTTP Server](getting_started/http_server.md)

docs/guides/runtime_tracing.md

@@ -0,0 +1,51 @@
+# Runtime Tracing
+
+The Crystal runtime has a tracing feature for low level functionality. It prints diagnostic info about runtime internals.
+
+A program must be built with the flag `-Dtracing` to support tracing.
+At runtime, the individual tracing components can be enabled via the environment variable `CRYSTAL_TRACE`. It receives a comma separated list of sections to enable.
+
+* `CRYSTAL_TRACE=none` Disable tracing (default)
+* `CRYSTAL_TRACE=gc`: Enable tracing for the garbage collector
+* `CRYSTAL_TRACE=sched`: Enable tracing for the scheduler
+* `CRYSTAL_TRACE=gc,sched`: Enable tracing for the garbage collector and scheduler
+* `CRYSTAL_TRACE=all` Enable all tracing (equivalent to `gc,sched`)
+
+Example:
+
+```console
+$ crystal build -Dtracing hello-world.cr
+$ CRYSTAL_TRACE=sched ./hello-world
+sched.spawn 70569399740240 thread=0x7f48d7dc9740:? fiber=0x7f48d7cd0f00:main fiber=0x7f48d7cd0dc0:Signal Loop
+sched.enqueue 70569399831716 thread=0x7f48d7dc9740:? fiber=0x7f48d7cd0f00:main fiber=0x7f48d7cd0dc0:Signal Loop duration=163
+Hello World
+```
+
+The traces are printed to the standard error by default.
+This can be changed at runtime with the `CRYSTAL_TRACE_FILE` environment variable.
+
+For example, `CRYSTAL_TRACE_FILE=trace.log` prints all tracing output to a file `trace.log`.
+
+## Tracing Format
+
+Each trace entry stands on a single line, terminated by linefeed, and is at most 512 bytes long.
+
+Each entry starts with an identifier consisting of section and operation names, separated by a dot (e.g. `gc.malloc`).
+Then comes a timestamp represented as an integer in nanoseconds.
+Finally, a list of metadata properties in the form `key=value` separated by single spaces.
+
+The first two properties are always the originating `thread` and `fiber`. Both are identified by id and name, separated by a colon (e.g `0x7f48d7cd0f00:main`).
+
+* The thread id is the OS handle, so we can match a thread to a debugger session for example.
+* The fiber id is an internal address in the Crystal runtime. Names are optional and not necessarily unique.
+
+Trace items from early in the runtime startup may be missing fiber metadata and thread names.
+
+More metadata properties can follow depending on the specific trace entry.
+
+For example, `gc.malloc` indicates how much memory is being allocated.
+
+Reported values are typically represented as integers with the following semantics:
+
+* Times and durations are in nanoseconds as per the monotonic clock of the operating system (e.g. `123` is `123ns`, `5000000000` is `5s`).
+* Memory sizes are in bytes (e.g. `1024` is `1KB`).

docs/syntax_and_semantics/compile_time_flags.md

@@ -136,6 +136,7 @@ Crystal program.
 | `debug_raise` | Debugging flag for `raise` logic. Prints the backtrace before raising.
 | `preview_mt` | Enables multithreading preview. Introduced in 0.28.0 ([#7546](https://github.com/crystal-lang/crystal/pull/7546))
 | `skip_crystal_compiler_rt` | Exclude Crystal's native `compiler-rt` implementation.
+| `tracing` | Build with support for [runtime tracing](../guides/runtime_tracing.md).
 | `use_libiconv` | Use `libiconv` instead of the `iconv` system library
 | `use_pcre2` | Use PCRE2 as regex engine (instead of legacy PCRE). Introduced in 1.7.0.
 | `use_pcre` | Use PCRE as regex engine (instead of PCRE2). Introduced in 1.8.0.