I fell into another rabbit hole: logging. Here's my trip report.
We have:
* util/error-report.c
- To stderr (or current monitor, but that's not relevant here)
- Format:
[TIME ][GUEST-NAME ]PROGNAME:LOCATION: (|warning: |info: )MESSAGE
where the optional parts are controlled by -msg
- Maintained: see MAINTAINERS "Error reporting"
* util/log.c
- Control:
· Some logging is always on
· Some logging is off by default, enabled per "log item" with -d
· Some can additionally be limited to address ranges with -dfilter
- To the file given by -D (default stderr), or with -d tid to files
with names derived from the pattern given by -D (%d is replaced by
the thread ID)
- Format:
[TIME ]MESSAGE
where the optional part is controlled by -msg timestamp (-msg
guest-name has no effect here)
- Not covered by MAINTAINERS
* Tracing
- Control: off by default, enabled with -trace per trace point (and
also -d trace: --- I find that duplication bizarre)
- Run time control with HMP commands trace-event, trace-file, QMP
commands trace-event-get-state, trace-event-set-state
- To whatever backends are compiled in:
· "log" wraps around util/log.c's always-on logging
· "simple" logs to a binary file given by -trace file=
· "syslog" logs to POSIX syslog
· "ftrace", "dtrace", "ust" integrate with Linux ftrace, DTrace /
SystemTap, and LTTng userspace tracing, respectively
- Maintained: see MAINTAINERS "Traicing"
* Unstructured ad hoc printing to stdout or stderr
I think that's it.
Observations:
* Mixing logs with different formats in one destination makes them
needlessly hard to read and parse.
Daniel's "util: sync error_report & qemu_log output more closely"
series makes util/error-report.c and util/log.c use a common message
prefix
[TIME ][GUEST-NAME ]PROGNAME\(THREAD-NAME\):...
where the optional parts are controlled by -msg. Continues prior work
in that direction: commit 012842c0755 (log: make '-msg timestamp=on'
apply to all qemu_log usage).
* Spreading logs over multiple destinations can make the order hard to
determine.
-D splits util/log.c from util/error-report.c.
-d tid further splits per thread.
Splitting per thread feels fairly redundant once the prefix includes
the thread name. Thread names is easier to make sense of than numeric
thread IDs in the split filenames.
To keep the complete log in one place, avoid -D, and enable trace
backend "log".
* In my view, util/log.c consists of three layers. Form bottom to top:
* Logging messages: qemu_log()
* Control of what to log ("log items"): qemu_log_mask()
* Address filtering: qemu_log_in_addr_range()
The bottom layer is also used by trace backend "log".
* Tracing vs. "log items"
Tracing and "log items" both provide opt-in logging.
Why do we have two? Feels like an accident to me.
When to use which? I guess people pick whatever they're familiar
with.
Would we be better off with just one? I wish...
Which one? Clearly tracing, because tracing backends provide plenty
of useful functionality "log items" lack.
"Log items" support per-thread log files. With tracing, you could
instead split by thread names once Daniel's series is in.
Address range filtering is only used with "log items". It could just
as easily be used with tracing.
Thoughts?
