X-Git-Url: http://www.chiark.greenend.org.uk/ucgi/~ianmdlvl/git?a=blobdiff_plain;f=src%2Flibelogind%2Fsd-event%2Fsd-event.c;h=5ca8c48c82db8d4b15c7617426cb57e140daa624;hb=dbee7798ab5f9e9f0671fd2f39ae9509a2123fd2;hp=5380d2178b126027965aa5c5f9233dc3d0f870fd;hpb=da2587d5154e11d4e643e326793f3ce2cc48dee6;p=elogind.git diff --git a/src/libelogind/sd-event/sd-event.c b/src/libelogind/sd-event/sd-event.c index 5380d2178..5ca8c48c8 100644 --- a/src/libelogind/sd-event/sd-event.c +++ b/src/libelogind/sd-event/sd-event.c @@ -37,6 +37,7 @@ #include "process-util.h" #include "set.h" #include "signal-util.h" +#include "string-table.h" #include "string-util.h" #include "time-util.h" #include "util.h" @@ -60,6 +61,23 @@ typedef enum EventSourceType { _SOURCE_EVENT_SOURCE_TYPE_INVALID = -1 } EventSourceType; +static const char* const event_source_type_table[_SOURCE_EVENT_SOURCE_TYPE_MAX] = { + [SOURCE_IO] = "io", + [SOURCE_TIME_REALTIME] = "realtime", + [SOURCE_TIME_BOOTTIME] = "bootime", + [SOURCE_TIME_MONOTONIC] = "monotonic", + [SOURCE_TIME_REALTIME_ALARM] = "realtime-alarm", + [SOURCE_TIME_BOOTTIME_ALARM] = "boottime-alarm", + [SOURCE_SIGNAL] = "signal", + [SOURCE_CHILD] = "child", + [SOURCE_DEFER] = "defer", + [SOURCE_POST] = "post", + [SOURCE_EXIT] = "exit", + [SOURCE_WATCHDOG] = "watchdog", +}; + +DEFINE_PRIVATE_STRING_TABLE_LOOKUP_TO_STRING(event_source_type, int); + /* All objects we use in epoll events start with this value, so that * we know how to dispatch it */ typedef enum WakeupType { @@ -207,6 +225,7 @@ struct sd_event { bool exit_requested:1; bool need_process_child:1; bool watchdog:1; + bool profile_delays:1; int exit_code; @@ -218,6 +237,9 @@ struct sd_event { unsigned n_sources; LIST_HEAD(sd_event_source, sources); + + usec_t last_run, last_log; + unsigned delays[sizeof(usec_t) * 8]; }; static void source_disconnect(sd_event_source *s); @@ -416,11 +438,9 @@ _public_ int sd_event_new(sd_event** ret) { e->original_pid = getpid(); e->perturb = USEC_INFINITY; - e->pending = prioq_new(pending_prioq_compare); - if (!e->pending) { - r = -ENOMEM; + r = prioq_ensure_allocated(&e->pending, pending_prioq_compare); + if (r < 0) goto fail; - } e->epoll_fd = epoll_create1(EPOLL_CLOEXEC); if (e->epoll_fd < 0) { @@ -428,6 +448,11 @@ _public_ int sd_event_new(sd_event** ret) { goto fail; } + if (secure_getenv("SD_EVENT_PROFILE_DELAYS")) { + log_debug("Event loop profiling enabled. Logarithmic histogram of event loop iterations in the range 2^0 ... 2^63 us will be logged every 5s."); + e->profile_delays = true; + } + *ret = e; return 0; @@ -482,7 +507,8 @@ static void source_io_unregister(sd_event_source *s) { r = epoll_ctl(s->event->epoll_fd, EPOLL_CTL_DEL, s->io.fd, NULL); if (r < 0) - log_debug_errno(errno, "Failed to remove source %s from epoll: %m", strna(s->description)); + log_debug_errno(errno, "Failed to remove source %s (type %s) from epoll: %m", + strna(s->description), event_source_type_to_string(s->type)); s->io.registered = false; } @@ -1052,17 +1078,13 @@ _public_ int sd_event_add_time( d = event_get_clock_data(e, type); assert(d); - if (!d->earliest) { - d->earliest = prioq_new(earliest_time_prioq_compare); - if (!d->earliest) - return -ENOMEM; - } + r = prioq_ensure_allocated(&d->earliest, earliest_time_prioq_compare); + if (r < 0) + return r; - if (!d->latest) { - d->latest = prioq_new(latest_time_prioq_compare); - if (!d->latest) - return -ENOMEM; - } + r = prioq_ensure_allocated(&d->latest, latest_time_prioq_compare); + if (r < 0) + return r; if (d->fd < 0) { r = event_setup_timer_fd(e, d, clock); @@ -1315,11 +1337,9 @@ _public_ int sd_event_add_exit( assert_return(e->state != SD_EVENT_FINISHED, -ESTALE); assert_return(!event_pid_changed(e), -ECHILD); - if (!e->exit) { - e->exit = prioq_new(exit_prioq_compare); - if (!e->exit) - return -ENOMEM; - } + r = prioq_ensure_allocated(&e->exit, exit_prioq_compare); + if (r < 0) + return r; s = source_new(e, !ret, SOURCE_EXIT); if (!s) @@ -2305,12 +2325,9 @@ static int source_dispatch(sd_event_source *s) { s->dispatching = false; - if (r < 0) { - if (s->description) - log_debug_errno(r, "Event source '%s' returned error, disabling: %m", s->description); - else - log_debug_errno(r, "Event source %p returned error, disabling: %m", s); - } + if (r < 0) + log_debug_errno(r, "Event source %s (type %s) returned error, disabling: %m", + strna(s->description), event_source_type_to_string(s->type)); if (s->n_ref == 0) source_free(s); @@ -2343,12 +2360,9 @@ static int event_prepare(sd_event *e) { r = s->prepare(s, s->userdata); s->dispatching = false; - if (r < 0) { - if (s->description) - log_debug_errno(r, "Prepare callback of event source '%s' returned error, disabling: %m", s->description); - else - log_debug_errno(r, "Prepare callback of event source %p returned error, disabling: %m", s); - } + if (r < 0) + log_debug_errno(r, "Prepare callback of event source %s (type %s) returned error, disabling: %m", + strna(s->description), event_source_type_to_string(s->type)); if (s->n_ref == 0) source_free(s); @@ -2453,7 +2467,9 @@ _public_ int sd_event_prepare(sd_event *e) { e->iteration++; + e->state = SD_EVENT_PREPARING; r = event_prepare(e); + e->state = SD_EVENT_INITIAL; if (r < 0) return r; @@ -2631,6 +2647,18 @@ _public_ int sd_event_dispatch(sd_event *e) { return 1; } +static void event_log_delays(sd_event *e) { + char b[ELEMENTSOF(e->delays) * DECIMAL_STR_MAX(unsigned) + 1]; + unsigned i; + int o; + + for (i = o = 0; i < ELEMENTSOF(e->delays); i++) { + o += snprintf(&b[o], sizeof(b) - o, "%u ", e->delays[i]); + e->delays[i] = 0; + } + log_debug("Event loop iterations: %.*s", o, b); +} + _public_ int sd_event_run(sd_event *e, uint64_t timeout) { int r; @@ -2639,11 +2667,30 @@ _public_ int sd_event_run(sd_event *e, uint64_t timeout) { assert_return(e->state != SD_EVENT_FINISHED, -ESTALE); assert_return(e->state == SD_EVENT_INITIAL, -EBUSY); + if (e->profile_delays && e->last_run) { + usec_t this_run; + unsigned l; + + this_run = now(CLOCK_MONOTONIC); + + l = u64log2(this_run - e->last_run); + assert(l < sizeof(e->delays)); + e->delays[l]++; + + if (this_run - e->last_log >= 5*USEC_PER_SEC) { + event_log_delays(e); + e->last_log = this_run; + } + } + r = sd_event_prepare(e); if (r == 0) /* There was nothing? Then wait... */ r = sd_event_wait(e, timeout); + if (e->profile_delays) + e->last_run = now(CLOCK_MONOTONIC); + if (r > 0) { /* There's something now, then let's dispatch it */ r = sd_event_dispatch(e); @@ -2725,6 +2772,12 @@ _public_ int sd_event_now(sd_event *e, clockid_t clock, uint64_t *usec) { assert_return(e, -EINVAL); assert_return(usec, -EINVAL); assert_return(!event_pid_changed(e), -ECHILD); + assert_return(IN_SET(clock, + CLOCK_REALTIME, + CLOCK_REALTIME_ALARM, + CLOCK_MONOTONIC, + CLOCK_BOOTTIME, + CLOCK_BOOTTIME_ALARM), -EOPNOTSUPP); if (!dual_timestamp_is_set(&e->timestamp)) { /* Implicitly fall back to now() if we never ran @@ -2744,8 +2797,7 @@ _public_ int sd_event_now(sd_event *e, clockid_t clock, uint64_t *usec) { *usec = e->timestamp.monotonic; break; - case CLOCK_BOOTTIME: - case CLOCK_BOOTTIME_ALARM: + default: *usec = e->timestamp_boottime; break; }