core: Add wall clock duration to CPU usage logging

Enhance CPU time logging to include wall clock duration alongside
CPU consumption. When a unit transitions to inactive/failed state,
the log message now shows both CPU time consumed and the total wall
clock time since activation.

Changes:
- Calculate wall clock duration using active_enter_timestamp
- Update log format: "Consumed Xs CPU time over Ys wall clock time"
- Fallback to original format if no activation timestamp available
- Use monotonic clock for accurate duration calculation

This addresses issue #35738 by providing administrators better context
about service performance and resource efficiency.

Example output:
- With wall clock: "service: Consumed 30s CPU time over 5min wall clock time"
- Without timestamp: "service: Consumed 30s CPU time"
This commit is contained in:
gvenugo3
2025-07-16 05:31:46 +00:00
committed by Zbigniew Jędrzejewski-Szmek
parent d7c7af28fb
commit df6ccb0496

View File

@@ -2411,10 +2411,20 @@ static int unit_log_resources(Unit *u) {
iovec[n_iovec++] = IOVEC_MAKE_STRING(TAKE_PTR(t));
/* Format the CPU time for inclusion in the human language message string */
if (strextendf_with_separator(&message, ", ",
"Consumed %s CPU time",
FORMAT_TIMESPAN(cpu_nsec / NSEC_PER_USEC, USEC_PER_MSEC)) < 0)
return log_oom();
if (dual_timestamp_is_set(&u->inactive_exit_timestamp) &&
dual_timestamp_is_set(&u->inactive_enter_timestamp)) {
usec_t wall_clock_usec = usec_sub_unsigned(u->inactive_enter_timestamp.monotonic, u->inactive_exit_timestamp.monotonic);
if (strextendf_with_separator(&message, ", ",
"Consumed %s CPU time over %s wall clock time",
FORMAT_TIMESPAN(cpu_nsec / NSEC_PER_USEC, USEC_PER_MSEC),
FORMAT_TIMESPAN(wall_clock_usec, USEC_PER_MSEC)) < 0)
return log_oom();
} else {
if (strextendf_with_separator(&message, ", ",
"Consumed %s CPU time",
FORMAT_TIMESPAN(cpu_nsec / NSEC_PER_USEC, USEC_PER_MSEC)) < 0)
return log_oom();
}
log_level = raise_level(log_level,
cpu_nsec > MENTIONWORTHY_CPU_NSEC,