SymbX/systemd
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

core: whenever a unit terminates, log its consumed resources to the journal

Browse Source 
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.
This commit is contained in:
Lennart Poettering
2017-09-22 15:28:05 +02:00
parent 8e5430c4bd
commit 915b1d0174
4 changed files with 235 additions and 17 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/basic/log.c
+67
View File
@@ -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;
src/basic/log.h
+14
View File
@@ -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), \
src/core/unit.c
+151 -17
View File
@@ -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);
}
}
src/systemd/sd-messages.h
+3
View File
@@ -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)