openvmm_entry: disable span output in tracing by default

Guide/src/reference/openvmm/logging.md

@@ -2,82 +2,96 @@
 
 ## Configuring OpenVMM logging messages to emit
 
-To configure logging, use the `OPENVMM_LOG` environment variable. For example:
+To configure logging, set the `OPENVMM_LOG` environment variable. The default
+level is `info`. For example:
 
-Enables debug events from all modules:
-
-```cmd
-set OPENVMM_LOG=debug
-```
-
-Enables trace events from the `mesh` crate and info events from everything else:
-
-```cmd
-set OPENVMM_LOG=info,mesh=trace
-```
+- `OPENVMM_LOG=debug` — enable debug events from all modules
+- `OPENVMM_LOG=info,mesh=trace` — enable trace events from the `mesh` crate
+  and info events from everything else
 
 This is backed by the
 [`EnvFilter`](https://docs.rs/tracing-subscriber/0.2.17/tracing_subscriber/struct.EnvFilter.html)
 type; see the associated documentation for more details.
 
-## Configuring OpenHCL Trace Logging
+### Span events
 
-If OpenHCL is used, it also supports an [`EnvFilter`](https://docs.rs/tracing-subscriber/0.2.17/tracing_subscriber/struct.EnvFilter.html) style trace logging options that can be configured using the `OPENVMM_LOG=` command line variable passed during OpenHCL startup with `-c OPENVMM_LOG=`. The `-c` argument in OpenVMM passes a string of command line arguments to OpenHCL initialization.
+By default, OpenVMM does not log span enter/exit events. To enable them, set
+`OPENVMM_LOG_SPANS=1`.
 
-The environment variable configuration and style of `OPENVMM_LOG` for OpenHCL is the same for configuring tracing for OpenVMM.
+### Rate limiting
 
-OpenHCL tracing can also be configured and dumped at runtime with `ohcldiag-dev`. See: [OpenHCL Diagnostics](../openhcl/diag/ohcldiag_dev.md)
+Trace events that can be triggered repeatedly by guest interactions are
+rate-limited by default. To disable rate limiting (useful for debugging), set
+`OPENVMM_DISABLE_TRACING_RATELIMITS=1`.
 
-To retrieve OpenHCL log output at runtime, an output console or file must attach to the OpenHCL logging COM port. By default, OpenHCL outputs to `COM3`.
+## Configuring OpenHCL Trace Logging
+
+OpenHCL also supports `EnvFilter`-style trace logging, configured via the
+`-c OPENVMM_LOG=` command line argument. The `-c` flag passes arguments to
+OpenHCL initialization. The filter syntax is the same as for OpenVMM.
+
+OpenHCL tracing can also be configured and dumped at runtime with
+`ohcldiag-dev`. See: [OpenHCL Diagnostics](../openhcl/diag/ohcldiag_dev.md)
+
+To retrieve OpenHCL log output at runtime, an output console or file must
+attach to the OpenHCL logging COM port. By default, OpenHCL outputs to `COM3`.
 
 To open a new terminal window with global OpenHCL debug level tracing enabled:
 
-```cmd
-openvmm.exe -c "OPENVMM_LOG=debug" --com3 "term,name=VTL2 OpenHCL" [...]
+```shell
+openvmm -c "OPENVMM_LOG=debug" --com3 "term,name=VTL2 OpenHCL" [...]
 ```
 
 Configure log levels of only a given module name:
 
-```cmd
-openvmm.exe -c "OPENVMM_LOG=mesh=trace" --com3 "term,name=VTL2 OpenHCL" [...]
+```shell
+openvmm -c "OPENVMM_LOG=mesh=trace" --com3 "term,name=VTL2 OpenHCL" [...]
 ```
 
 Multiple modules can be specified by separating them with a comma:
 
-```cmd
-openvmm.exe -c "OPENVMM_LOG=mesh=trace,nvme_driver=trace" --com3 "term,name=VTL2 OpenHCL" [...]
+```shell
+openvmm -c "OPENVMM_LOG=mesh=trace,nvme_driver=trace" \
+    --com3 "term,name=VTL2 OpenHCL" [...]
 ```
 
 ```admonish tip
-For more configuration examples of serial ports and the OpenVMM CLI, see the [Running OpenHCL Guide](../../../user_guide/openhcl/run/openvmm.md) and CLI `--help` output.
+For more configuration examples of serial ports and the OpenVMM CLI, see the
+[Running OpenHCL Guide](../../../user_guide/openhcl/run/openvmm.md) and CLI
+`--help` output.
 ```
 
 ## Capturing the ETW traces on the host
 
 On Windows, OpenVMM also logs to ETW, via the Microsoft.HvLite provider.
 
-To capture the trace first need to start the session:
+To capture the trace, start a session:
 
-```cmd
-logman.exe start trace <SessionName> -ow -o FileName0.etl -p "{22bc55fe-2116-5adc-12fb-3fadfd7e360c}" 0xffffffffffffffff 0xff -nb 16 16 -bs 16 -mode 0x2 -ets
+```powershell
+logman start trace <SESSION_NAME> -ow -o trace.etl `
+    -p "{22bc55fe-2116-5adc-12fb-3fadfd7e360c}" 0xffffffffffffffff 0xff `
+    -nb 16 16 -bs 16 -mode 0x2 -ets
 ```
 
- > For OpenHCL traces, use `{AA5DE534-D149-487A-9053-05972BA20A7C}` as the provider GUID.
+```admonish note
+For OpenHCL traces, use `{AA5DE534-D149-487A-9053-05972BA20A7C}` as the
+provider GUID.
+```
 
 To flush:
 
-```cmd
-logman.exe update <SessionName> -ets -fd
+```powershell
+logman update <SESSION_NAME> -ets -fd
 ```
 
 To stop:
 
-```cmd
-logman.exe stop <SessionName> -ets
+```powershell
+logman stop <SESSION_NAME> -ets
 ```
 
 To decode as CSV:
 
-```cmd
-tracerpt.exe <FileName0>.etl -y -of csv -o <FileName1>.csv -summary <FileName2>.summary
+```powershell
+tracerpt trace.etl -y -of csv -o trace.csv -summary trace-summary.txt
 ```

openvmm/openvmm_entry/src/tracing_init.rs

@@ -30,6 +30,10 @@ pub fn enable_tracing() -> anyhow::Result<()> {
     use tracing_subscriber::layer::SubscriberExt;
     use tracing_subscriber::util::SubscriberInitExt;
 
+    fn env_bool(result: Result<String, std::env::VarError>) -> bool {
+        result.is_ok_and(|v| !v.is_empty() && v != "0")
+    }
+
     // Enable tracing for paravisor_log by default since this is passed through
     // from the guest (but still allow it to be disabled via OPENVMM_LOG).
     let base = "paravisor_log=trace";
@@ -42,7 +46,7 @@ pub fn enable_tracing() -> anyhow::Result<()> {
             .add_directive(base.parse().unwrap())
     };
 
-    if legacy_openvmm_env("OPENVMM_DISABLE_TRACING_RATELIMITS").is_ok_and(|v| !v.is_empty()) {
+    if env_bool(legacy_openvmm_env("OPENVMM_DISABLE_TRACING_RATELIMITS")) {
         tracelimit::disable_rate_limiting(true);
     }
 
@@ -54,12 +58,18 @@ pub fn enable_tracing() -> anyhow::Result<()> {
         BoxMakeWriter::new(std::io::stderr)
     };
 
+    let span_events = if env_bool(std::env::var("OPENVMM_LOG_SPANS")) {
+        FmtSpan::NEW | FmtSpan::CLOSE
+    } else {
+        FmtSpan::NONE
+    };
+
     let format = Format::default()
         .with_timer(uptime())
         .with_ansi(is_terminal);
     let fmt_layer = tracing_subscriber::fmt::layer()
         .event_format(format)
-        .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
+        .with_span_events(span_events)
         .fmt_fields(tracing_helpers::formatter::FieldFormatter)
         .log_internal_errors(true)
         .with_writer(writer);