summary |
shortlog |
log |
commit | commitdiff |
tree
raw |
patch |
inline | side by side (from parent 1:
5f6ccb5)
Set SD_EVENT_PROFILE_DELAYS to activate accounting and periodic logging
of the distribution of delays between sd_event_run() calls.
Time spent in dispatching as well as time spent outside of
sd_event_run() is measured and accounted for. Every 5 seconds a
logarithmic histogram loop iteration delays since 5 seconds previous is
logged.
This is useful in identifying the frequency and magnitude of latencies
affecting the event loop, which should be kept to a minimum.
bool exit_requested:1;
bool need_process_child:1;
bool watchdog:1;
bool exit_requested:1;
bool need_process_child:1;
bool watchdog:1;
unsigned n_sources;
LIST_HEAD(sd_event_source, sources);
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);
};
static void source_disconnect(sd_event_source *s);
+ if (secure_getenv("SD_EVENT_PROFILE_DELAYS")) {
+ log_info("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;
+ }
+
+static void event_log_delays(sd_event *e) {
+ char b[ELEMENTSOF(e->delays) * DECIMAL_STR_MAX(unsigned) + 1];
+ int i, 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_info("Event loop iterations: %.*s", o, b);
+}
+
_public_ int sd_event_run(sd_event *e, uint64_t timeout) {
int r;
_public_ int sd_event_run(sd_event *e, uint64_t timeout) {
int r;
assert_return(e->state != SD_EVENT_FINISHED, -ESTALE);
assert_return(e->state == SD_EVENT_INITIAL, -EBUSY);
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);
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);
if (r > 0) {
/* There's something now, then let's dispatch it */
r = sd_event_dispatch(e);