From: Lennart Poettering Date: Thu, 21 Sep 2017 12:05:35 +0000 (+0200) Subject: core: whenever a unit terminates, log its consumed resources to the journal X-Git-Tag: v235~60^2~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=915b1d0174af808dd4cbea1357490febfba7cdc0;p=thirdparty%2Fsystemd.git core: whenever a unit terminates, log its consumed resources to the journal This adds a new recognizable log message for each unit invocation that contains structured information about consumed resources of the unit as a whole after it terminated. This is particular useful for apps that want to figure out what the resource consumption of a unit given a specific invocation ID was. The log message is only generated for units that have at least one XyzAccounting= property turned on, and currently only covers IP traffic and CPU time metrics. --- diff --git a/src/basic/log.c b/src/basic/log.c index a43e8206779..591c6d2a13e 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -975,6 +975,73 @@ int log_struct_internal( return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, buf + 8); } +int log_struct_iovec_internal( + int level, + int error, + const char *file, + int line, + const char *func, + const struct iovec input_iovec[], + size_t n_input_iovec) { + + LogRealm realm = LOG_REALM_REMOVE_LEVEL(level); + PROTECT_ERRNO; + size_t i; + char *m; + + if (error < 0) + error = -error; + + if (_likely_(LOG_PRI(level) > log_max_level[realm])) + return -error; + + if (log_target == LOG_TARGET_NULL) + return -error; + + if ((level & LOG_FACMASK) == 0) + level = log_facility | LOG_PRI(level); + + if (IN_SET(log_target, LOG_TARGET_AUTO, + LOG_TARGET_JOURNAL_OR_KMSG, + LOG_TARGET_JOURNAL) && + journal_fd >= 0) { + + struct iovec iovec[1 + n_input_iovec*2]; + char header[LINE_MAX]; + struct msghdr mh = { + .msg_iov = iovec, + .msg_iovlen = 1 + n_input_iovec*2, + }; + + log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); + iovec[0] = IOVEC_MAKE_STRING(header); + + for (i = 0; i < n_input_iovec; i++) { + iovec[1+i*2] = input_iovec[i]; + iovec[1+i*2+1] = IOVEC_MAKE_STRING("\n"); + } + + if (sendmsg(journal_fd, &mh, MSG_NOSIGNAL) >= 0) + return -errno; + } + + for (i = 0; i < n_input_iovec; i++) { + if (input_iovec[i].iov_len < strlen("MESSAGE=")) + continue; + + if (memcmp(input_iovec[i].iov_base, "MESSAGE=", strlen("MESSAGE=")) == 0) + break; + } + + if (_unlikely_(i >= n_input_iovec)) /* Couldn't find MESSAGE=? */ + return -error; + + m = strndupa(input_iovec[i].iov_base + strlen("MESSAGE="), + input_iovec[i].iov_len - strlen("MESSAGE=")); + + return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, m); +} + int log_set_target_from_string(const char *e) { LogTarget t; diff --git a/src/basic/log.h b/src/basic/log.h index 186747ff8e2..e3fd3203d04 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -187,6 +187,15 @@ int log_format_iovec( const char *format, va_list ap) _printf_(6, 0); +int log_struct_iovec_internal( + int level, + int error, + const char *file, + int line, + const char *func, + const struct iovec input_iovec[], + size_t n_input_iovec); + /* This modifies the buffer passed! */ int log_dump_internal( int level, @@ -270,6 +279,11 @@ void log_assert_failed_return_realm( error, __FILE__, __LINE__, __func__, __VA_ARGS__) #define log_struct(level, ...) log_struct_errno(level, 0, __VA_ARGS__) +#define log_struct_iovec_errno(level, error, iovec, n_iovec) \ + log_struct_iovec_internal(LOG_REALM_PLUS_LEVEL(LOG_REALM, level), \ + error, __FILE__, __LINE__, __func__, iovec, n_iovec) +#define log_struct_iovec(level, iovec, n_iovec) log_struct_iovec_errno(level, 0, iovec, n_iovec) + /* This modifies the buffer passed! */ #define log_dump(level, buffer) \ log_dump_internal(LOG_REALM_PLUS_LEVEL(LOG_REALM, level), \ diff --git a/src/core/unit.c b/src/core/unit.c index 65a8c77f86f..5526dd805cf 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -39,6 +39,7 @@ #include "fileio-label.h" #include "format-util.h" #include "id128-util.h" +#include "io-util.h" #include "load-dropin.h" #include "load-fragment.h" #include "log.h" @@ -2001,6 +2002,134 @@ void unit_trigger_notify(Unit *u) { UNIT_VTABLE(other)->trigger_notify(other, u); } +static int unit_log_resources(Unit *u) { + + struct iovec iovec[1 + _CGROUP_IP_ACCOUNTING_METRIC_MAX + 4]; + size_t n_message_parts = 0, n_iovec = 0; + char* message_parts[3 + 1], *t; + nsec_t nsec = NSEC_INFINITY; + CGroupIPAccountingMetric m; + size_t i; + int r; + const char* const ip_fields[_CGROUP_IP_ACCOUNTING_METRIC_MAX] = { + [CGROUP_IP_INGRESS_BYTES] = "IP_METRIC_INGRESS_BYTES", + [CGROUP_IP_INGRESS_PACKETS] = "IP_METRIC_INGRESS_PACKETS", + [CGROUP_IP_EGRESS_BYTES] = "IP_METRIC_EGRESS_BYTES", + [CGROUP_IP_EGRESS_PACKETS] = "IP_METRIC_EGRESS_PACKETS", + }; + + assert(u); + + /* Invoked whenever a unit enters failed or dead state. Logs information about consumed resources if resource + * accounting was enabled for a unit. It does this in two ways: a friendly human readable string with reduced + * information and the complete data in structured fields. */ + + (void) unit_get_cpu_usage(u, &nsec); + if (nsec != NSEC_INFINITY) { + char buf[FORMAT_TIMESPAN_MAX] = ""; + + /* Format the CPU time for inclusion in the structured log message */ + if (asprintf(&t, "CPU_USAGE_NSEC=%" PRIu64, nsec) < 0) { + r = log_oom(); + goto finish; + } + iovec[n_iovec++] = IOVEC_MAKE_STRING(t); + + /* Format the CPU time for inclusion in the human language message string */ + format_timespan(buf, sizeof(buf), nsec / NSEC_PER_USEC, USEC_PER_MSEC); + t = strjoin(n_message_parts > 0 ? "consumed " : "Consumed ", buf, " CPU time"); + if (!t) { + r = log_oom(); + goto finish; + } + + message_parts[n_message_parts++] = t; + } + + for (m = 0; m < _CGROUP_IP_ACCOUNTING_METRIC_MAX; m++) { + char buf[FORMAT_BYTES_MAX] = ""; + uint64_t value = UINT64_MAX; + + assert(ip_fields[m]); + + (void) unit_get_ip_accounting(u, m, &value); + if (value == UINT64_MAX) + continue; + + /* Format IP accounting data for inclusion in the structured log message */ + if (asprintf(&t, "%s=%" PRIu64, ip_fields[m], value) < 0) { + r = log_oom(); + goto finish; + } + iovec[n_iovec++] = IOVEC_MAKE_STRING(t); + + /* Format the IP accounting data for inclusion in the human language message string, but only for the + * bytes counters (and not for the packets counters) */ + if (m == CGROUP_IP_INGRESS_BYTES) + t = strjoin(n_message_parts > 0 ? "received " : "Received ", + format_bytes(buf, sizeof(buf), value), + " IP traffic"); + else if (m == CGROUP_IP_EGRESS_BYTES) + t = strjoin(n_message_parts > 0 ? "sent " : "Sent ", + format_bytes(buf, sizeof(buf), value), + " IP traffic"); + else + continue; + if (!t) { + r = log_oom(); + goto finish; + } + + message_parts[n_message_parts++] = t; + } + + /* Is there any accounting data available at all? */ + if (n_iovec == 0) { + r = 0; + goto finish; + } + + if (n_message_parts == 0) + t = strjoina("MESSAGE=", u->id, ": Completed"); + else { + _cleanup_free_ char *joined; + + message_parts[n_message_parts] = NULL; + + joined = strv_join(message_parts, ", "); + if (!joined) { + r = log_oom(); + goto finish; + } + + t = strjoina("MESSAGE=", u->id, ": ", joined); + } + + /* The following four fields we allocate on the stack or are static strings, we hence don't want to free them, + * and hence don't increase n_iovec for them */ + iovec[n_iovec] = IOVEC_MAKE_STRING(t); + iovec[n_iovec + 1] = IOVEC_MAKE_STRING("MESSAGE_ID=" SD_MESSAGE_UNIT_RESOURCES_STR); + + t = strjoina(u->manager->unit_log_field, u->id); + iovec[n_iovec + 2] = IOVEC_MAKE_STRING(t); + + t = strjoina(u->manager->invocation_log_field, u->invocation_id_string); + iovec[n_iovec + 3] = IOVEC_MAKE_STRING(t); + + log_struct_iovec(LOG_INFO, iovec, n_iovec + 4); + r = 0; + +finish: + for (i = 0; i < n_message_parts; i++) + free(message_parts[i]); + + for (i = 0; i < n_iovec; i++) + free(iovec[i].iov_base); + + return r; + +} + void unit_notify(Unit *u, UnitActiveState os, UnitActiveState ns, bool reload_success) { Manager *m; bool unexpected; @@ -2172,28 +2301,33 @@ void unit_notify(Unit *u, UnitActiveState os, UnitActiveState ns, bool reload_su manager_send_unit_plymouth(m, u); } else { + /* We don't care about D-Bus going down here, since we'll get an asynchronous notification for it + * anyway. */ - /* We don't care about D-Bus here, since we'll get an - * asynchronous notification for it anyway. */ + if (UNIT_IS_INACTIVE_OR_FAILED(ns) && + !UNIT_IS_INACTIVE_OR_FAILED(os) + && !MANAGER_IS_RELOADING(m)) { - if (u->type == UNIT_SERVICE && - UNIT_IS_INACTIVE_OR_FAILED(ns) && - !UNIT_IS_INACTIVE_OR_FAILED(os) && - !MANAGER_IS_RELOADING(m)) { + /* This unit just stopped/failed. */ + if (u->type == UNIT_SERVICE) { - /* Hmm, if there was no start record written - * write it now, so that we always have a nice - * pair */ - if (!u->in_audit) { - manager_send_unit_audit(m, u, AUDIT_SERVICE_START, ns == UNIT_INACTIVE); + /* Hmm, if there was no start record written + * write it now, so that we always have a nice + * pair */ + if (!u->in_audit) { + manager_send_unit_audit(m, u, AUDIT_SERVICE_START, ns == UNIT_INACTIVE); - if (ns == UNIT_INACTIVE) - manager_send_unit_audit(m, u, AUDIT_SERVICE_STOP, true); - } else - /* Write audit record if we have just finished shutting down */ - manager_send_unit_audit(m, u, AUDIT_SERVICE_STOP, ns == UNIT_INACTIVE); + if (ns == UNIT_INACTIVE) + manager_send_unit_audit(m, u, AUDIT_SERVICE_STOP, true); + } else + /* Write audit record if we have just finished shutting down */ + manager_send_unit_audit(m, u, AUDIT_SERVICE_STOP, ns == UNIT_INACTIVE); + + u->in_audit = false; + } - u->in_audit = false; + /* Write a log message about consumed resources */ + unit_log_resources(u); } } diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index 4bc248a4b16..8c23486779f 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -103,6 +103,9 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_UNIT_RESTART_SCHEDULED_STR \ SD_ID128_MAKE_STR(5e,b0,34,94,b6,58,48,70,a5,36,b3,37,29,08,09,b3) +#define SD_MESSAGE_UNIT_RESOURCES SD_ID128_MAKE(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) +#define SD_MESSAGE_UNIT_RESOURCES_STR SD_ID128_MAKE_STR(ae,8f,7b,86,6b,03,47,b9,af,31,fe,1c,80,b1,27,c0) + #define SD_MESSAGE_SPAWN_FAILED SD_ID128_MAKE(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7) #define SD_MESSAGE_SPAWN_FAILED_STR SD_ID128_MAKE_STR(64,12,57,65,1c,1b,4e,c9,a8,62,4d,7a,40,a9,e1,e7)