sd-event: instrument sd_event_run() for profiling delays
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.
This commit is contained in:
parent
cf6c8c46fc
commit
34b8751774
|
@ -225,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;
|
||||
|
||||
|
@ -236,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);
|
||||
|
@ -444,6 +448,11 @@ _public_ int sd_event_new(sd_event** ret) {
|
|||
goto fail;
|
||||
}
|
||||
|
||||
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;
|
||||
}
|
||||
|
||||
*ret = e;
|
||||
return 0;
|
||||
|
||||
|
@ -2622,6 +2631,17 @@ _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];
|
||||
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;
|
||||
|
||||
|
@ -2630,11 +2650,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);
|
||||
|
|
Loading…
Reference in New Issue