From 4298dfa334491f04f03c089e04668992deeedf20 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Johannes=20M=C3=BCller?= Date: Fri, 5 Jul 2024 13:10:41 +0200 Subject: [PATCH] Add documentation for runtime tracing (#768) --- docs/SUMMARY.md | 1 + docs/guides/runtime_tracing.md | 51 +++++++++++++++++++ .../compile_time_flags.md | 1 + 3 files changed, 53 insertions(+) create mode 100644 docs/guides/runtime_tracing.md diff --git a/docs/SUMMARY.md b/docs/SUMMARY.md index cb0cb4d9f..a00b0050b 100644 --- a/docs/SUMMARY.md +++ b/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) diff --git a/docs/guides/runtime_tracing.md b/docs/guides/runtime_tracing.md new file mode 100644 index 000000000..9750f9ca3 --- /dev/null +++ b/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`). diff --git a/docs/syntax_and_semantics/compile_time_flags.md b/docs/syntax_and_semantics/compile_time_flags.md index 9d4dc3068..40873d0a2 100644 --- a/docs/syntax_and_semantics/compile_time_flags.md +++ b/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.