qemu/util
Daniel P. Berrangé 012842c075 log: make '-msg timestamp=on' apply to all qemu_log usage
Currently the tracing 'log' back emits special code to add timestamps
to trace points sent via qemu_log(). This current impl is a bad design
for a number of reasons.

 * It changes the QEMU headers, such that 'error-report.h' content
   is visible to all files using tracing, but only when the 'log'
   backend is enabled. This has led to build failure bugs as devs
   rarely test without the (default) 'log' backend enabled, and
   CI can't cover every scenario for every trace backend.

 * It bloats the trace points definitions which are inlined into
   every probe location due to repeated inlining of timestamp
   formatting code, adding MBs of overhead to QEMU.

 * The tracing subsystem should not be treated any differently
   from other users of qemu_log. They all would benefit from
   having timestamps present.

 * The timestamp emitted with the tracepoints is in a needlessly
   different format to that used by error_report() in response
   to '-msg timestamp=on'.

This fixes all these issues simply by moving timestamp formatting
into qemu_log, using the same approach as for error_report.

The code before:

  static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
  {
      if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
          if (message_with_timestamp) {
              struct timeval _now;
              gettimeofday(&_now, NULL);
              qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
                       qemu_get_thread_id(),
                       (size_t)_now.tv_sec, (size_t)_now.tv_usec
                       , creds, filename, path);
          } else {
              qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
          }
      }
  }

and after:

  static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
  {
      if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
          qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
      }
  }

The log and error messages before:

  $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
  2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
  2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
  2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory

and after:

  $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
  2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
  2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
  2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory

The binary size before:

  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
  $ strip qemu-system-x86_64
  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64

and after:

  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
  $ strip qemu-system-x86_64
  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Markus Armbruster <armbru@redhat.com>
Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
Message-id: 20250721185452.3016488-1-berrange@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
2025-07-24 10:12:21 -04:00
..
aio-posix.c aio-posix: Adjust polling time also for new handlers 2025-03-13 17:57:23 +01:00
aio-posix.h aio-posix: Separate AioPolledEvent per AioHandler 2025-03-13 17:57:23 +01:00
aio-wait.c aio-wait: avoid AioContext lock in aio_wait_bh_oneshot() 2023-05-10 14:15:13 +02:00
aio-win32.c include: Move QemuLockCnt APIs to their own header 2024-10-15 15:16:17 +01:00
aiocb.c
async.c include/exec: Split out icount.h 2025-04-23 14:08:44 -07:00
atomic64.c osdep: Move memalign-related functions to their own header 2022-03-07 13:16:49 +00:00
base64.c nomaintainer: Fix Lesser GPL version number 2020-11-15 17:04:40 +01:00
bitmap.c migration: Use non-atomic ops for clear log bitmap 2022-11-21 11:58:10 +01:00
bitops.c replace TABs with spaces 2023-03-20 12:43:50 +01:00
block-helpers.c block: Adjust check_block_size() signature 2024-10-18 15:03:35 +02:00
block-helpers.h block: Adjust check_block_size() signature 2024-10-18 15:03:35 +02:00
buffer.c nomaintainer: Fix Lesser GPL version number 2020-11-15 17:04:40 +01:00
bufferiszero.c util/bufferiszero: Split out host include files 2024-06-19 12:47:11 -07:00
cacheflush.c util/cacheflush.c: Update cache flushing mechanism for Emscripten 2025-05-06 16:02:04 +02:00
chardev_open.c util/char_dev: Add open_cdev() 2023-12-19 19:03:38 +01:00
compatfd.c util: replace pipe()+cloexec with g_unix_open_pipe() 2022-05-03 15:18:14 +04:00
coroutine-sigaltstack.c osdep: set _FORTIFY_SOURCE=2 when optimization is enabled 2023-10-04 09:52:06 -04:00
coroutine-ucontext.c coroutine-ucontext: Save fake stack for pooled coroutine 2024-01-22 11:00:12 -05:00
coroutine-wasm.c util: Add coroutine backend for emscripten 2025-05-06 16:02:04 +02:00
coroutine-windows.c build: move coroutine backend selection to meson 2023-05-18 08:53:52 +02:00
cpuinfo-aarch64.c util/cpuinfo: Make use of elf_aux_info(3) on OpenBSD 2024-07-30 07:59:23 +10:00
cpuinfo-i386.c target/i386/hvf: fix handling of XSAVE-related CPUID bits 2024-10-31 18:28:32 +01:00
cpuinfo-loongarch.c util/loongarch64: Detect LASX vector support 2024-06-19 10:55:12 -07:00
cpuinfo-ppc.c util/cpuinfo: Make use of elf_aux_info(3) on OpenBSD 2024-07-30 07:59:23 +10:00
cpuinfo-riscv.c util/cpuinfo-riscv: Detect Zbs 2025-01-16 20:57:17 -08:00
crc32c.c igb: Implement Rx SCTP CSO 2023-05-23 15:20:15 +08:00
crc-ccitt.c util: Add CRC16 (CCITT) calculation routines 2021-01-24 20:10:54 +01:00
cutils.c util/cutils: Remove unused qemu_get_exec_dir 2024-09-20 10:04:34 +03:00
dbus.c util: add dbus helper unit 2020-01-06 18:41:32 +04:00
defer-call.c util/defer-call: move defer_call() to util/ 2023-10-31 15:41:42 +01:00
drm.c util/drm: make portable by avoiding struct dirent d_type 2020-07-13 14:36:10 +01:00
envlist.c envlist: Remove unused envlist_parse 2024-09-20 10:00:27 +03:00
error-report.c Remove glib compatibility code that is not required anymore 2024-05-14 12:46:39 +02:00
error.c util/error: make func optional 2025-06-05 20:24:51 +02:00
event_notifier-posix.c Replace qemu_pipe() with g_unix_open_pipe() 2022-05-03 15:17:56 +04:00
event_notifier-win32.c Remove qemu-common.h include from most units 2022-04-06 14:31:55 +02:00
event.c qemu-thread: Use futex for QemuEvent on Windows 2025-06-06 14:32:55 +02:00
fdmon-epoll.c include: Move QemuLockCnt APIs to their own header 2024-10-15 15:16:17 +01:00
fdmon-io_uring.c remove unnecessary casts from uintptr_t 2024-01-18 10:43:51 +01:00
fdmon-poll.c aio: remove aio_disable_external() API 2023-05-30 17:37:26 +02:00
fifo8.c fifo8: introduce fifo8_peek() function 2024-09-13 20:11:13 +02:00
filemonitor-inotify.c util/filemonitor-inotify.c: spelling fix: kenel 2023-11-15 12:06:05 +03:00
filemonitor-stub.c nomaintainer: Fix Lesser GPL version number 2020-11-15 17:04:40 +01:00
getauxval.c util/cpuinfo: Make use of elf_aux_info(3) on OpenBSD 2024-07-30 07:59:23 +10:00
guest-random.c util/guest-random: Clean up global variable shadowing 2023-10-06 13:27:48 +02:00
hbitmap.c qapi/crypto: Rename QCryptoHashAlgorithm to *Algo, and drop prefix 2024-09-10 14:02:16 +02:00
hexdump.c hw/vmapple/aes: Introduce aes engine 2025-03-04 14:45:34 +01:00
host-utils.c host-utils: Implemented signed 256-by-128 division 2022-06-20 08:38:58 -03:00
id.c net: Use id_generate() in the network subsystem, too 2021-03-09 21:47:45 +01:00
int128.c include/qemu/int128: Use Int128 structure for TCI 2023-02-04 06:19:42 -10:00
interval-tree.c util/interval-tree: Check root for null in interval_tree_iter_first 2023-08-09 09:26:32 -07:00
iov.c util/iov: Do not assert offset is in iov 2025-03-10 17:07:16 +08:00
iova-tree.c vhost-iova-tree, svq: Implement GPA->IOVA & partial IOVA->HVA trees 2025-02-21 07:18:42 -05:00
keyval.c qapi: Move include/qapi/qmp/ to include/qobject/ 2025-02-10 15:33:16 +01:00
lockcnt.c qemu-thread: Use futex if available for QemuLockCnt 2025-06-06 14:32:55 +02:00
log.c log: make '-msg timestamp=on' apply to all qemu_log usage 2025-07-24 10:12:21 -04:00
main-loop.c qom: Have class_init() take a const data argument 2025-04-25 17:00:41 +02:00
memalign.c osdep: Move memalign-related functions to their own header 2022-03-07 13:16:49 +00:00
memfd.c physmem: fd-based shared memory 2025-01-29 11:43:04 -03:00
meson.build qemu-thread: Use futex for QemuEvent on Windows 2025-06-06 14:32:55 +02:00
mmap-alloc.c util/mmap-alloc: qemu_fd_getfs() 2023-04-24 11:29:00 +02:00
module.c overall: Remove unnecessary g_strdup_printf() calls 2025-02-14 08:49:06 +03:00
notify.c notify: pass error to notifier with return 2024-02-28 11:31:28 +08:00
nvdimm-utils.c Clean up includes 2020-12-10 17:16:44 +01:00
osdep.c migration: Add direct-io parameter 2024-06-21 09:47:22 -03:00
oslib-posix.c util: exclude mmap-alloc.c from compilation target on Emscripten 2025-05-06 16:02:04 +02:00
oslib-win32.c backends/hostmem-shm: factor out allocation of "anonymous shared memory with an fd" 2025-01-29 11:43:03 -03:00
path.c util/path: Do not cache all filenames at startup 2019-06-24 22:19:30 +02:00
qdist.c util: spelling fixes 2023-08-31 19:47:43 +02:00
qemu-co-shared-resource.c util/co-shared-resource: Remove unused co_try_get_from_shres 2024-09-30 10:53:18 +03:00
qemu-co-timeout.c util: add qemu-co-timeout 2022-06-29 10:56:12 +03:00
qemu-config.c qapi: Move include/qapi/qmp/ to include/qobject/ 2025-02-10 15:33:16 +01:00
qemu-coroutine-io.c aio: remove aio_disable_external() API 2023-05-30 17:37:26 +02:00
qemu-coroutine-lock.c atomics: eliminate mb_read/mb_set 2023-06-06 09:42:14 +02:00
qemu-coroutine-sleep.c coroutine: Clean up superfluous inclusion of qemu/coroutine.h 2023-01-19 10:18:28 +01:00
qemu-coroutine.c util/coroutine: fix -Werror=maybe-uninitialized false-positive 2024-10-02 16:14:29 +04:00
qemu-option.c qapi: Move include/qapi/qmp/ to include/qobject/ 2025-02-10 15:33:16 +01:00
qemu-print.c monitor: Use getter/setter functions for cur_mon 2020-10-09 07:08:19 +02:00
qemu-progress.c include: move progress API to qemu-progress.h 2022-04-06 14:31:43 +02:00
qemu-sockets.c util/qemu-sockets: Introduce inet socket options controlling TCP keep-alive 2025-05-22 11:24:41 +01:00
qemu-thread-common.h
qemu-thread-posix.c qemu-thread: Use futex for QemuEvent on Windows 2025-06-06 14:32:55 +02:00
qemu-thread-win32.c qemu-thread: Use futex for QemuEvent on Windows 2025-06-06 14:32:55 +02:00
qemu-timer-common.c semihosting: Implement SYS_ELAPSED and SYS_TICKFREQ 2021-01-18 10:05:06 +00:00
qemu-timer.c include/exec: Split out icount.h 2025-04-23 14:08:44 -07:00
qht.c cleanup: Drop pointless return at end of function 2025-04-24 09:33:42 +02:00
qsp.c system/cpus: rename qemu_mutex_lock_iothread() to bql_lock() 2024-01-08 10:45:43 -05:00
qtree.c tcg: use QTree instead of GTree 2023-03-28 15:23:10 -07:00
range.c util/range.c: spelling fix: inbetween 2023-11-15 12:06:05 +03:00
rcu.c util/rcu.c: replace FSF postal address with licenses URL 2025-06-26 00:42:37 +02:00
readline.c util/readline: Add C-u shortcut 2024-06-19 12:42:03 +02:00
reserved-region.c util/reserved-region: Add new ReservedRegion helpers 2023-11-03 09:20:31 +01:00
s390x_pci_mmio.c util: Add functions for s390x mmio read/write 2025-05-08 10:03:07 -04:00
selfmap.c util/selfmap: Use dev_t and ino_t in MapInfo 2023-09-01 13:34:03 -07:00
stats64.c stat64: Add stat64_set() operation 2023-04-27 16:39:43 +02:00
sys_membarrier.c
systemd.c systemd: Also clear LISTEN_FDNAMES during systemd socket activation 2023-05-03 14:00:08 -05:00
thread-context.c qom: Make InterfaceInfo[] uses const 2025-04-25 17:00:41 +02:00
thread-pool.c thread-pool: Implement generic (non-AIO) pool support 2025-03-06 06:47:33 +01:00
throttle.c throttle: use THROTTLE_MAX/ARRAY_SIZE for hard code 2023-08-29 10:49:24 +02:00
timed-average.c license: Simplify GPL-2.0-or-later license descriptions 2024-09-20 10:11:59 +03:00
trace-events thread-pool: Rename AIO pool functions to *_aio() and data types to *Aio 2025-03-06 06:47:33 +01:00
trace.h trace: switch position of headers to what Meson requires 2020-08-21 06:18:24 -04:00
transactions.c transactions: Invoke clean() after everything else 2021-11-16 09:43:44 +01:00
unicode.c
userfaultfd.c util/userfaultfd: Remove unused uffd_poll_events 2024-10-08 15:28:55 -04:00
uuid.c util/uuid: Add UUID_STR_LEN definition 2023-11-03 09:20:31 +01:00
vfio-helpers.c include/system: Move exec/memory.h to system/memory.h 2025-04-23 14:08:21 -07:00
vhost-user-server.c vhost-user-server: do not set memory fd non-blocking 2024-07-02 09:27:56 -04:00
yank.c qapi: Fix dangling references to docs/devel/qapi-code-gen.txt 2024-01-26 07:04:53 +01:00