ratelimit,sd-journal: don't read the clock once per journal file per entry

sd_journal_next() sweeps every open journal file to find the next entry, and
next_beyond_location() rate-limits its tail timestamp refresh per file. Since
ratelimit_below() reads the clock itself, iterating a journal spread over a
hundred files meant a hundred clock_gettime() calls for every single entry,
nearly all of them only to conclude that the one second interval had not
elapsed yet. On a 730M journal in 100 files this was the single largest cost in
journalctl, over a fifth of the run.

Add ratelimit_below_at(), which takes the timestamp from the caller, and read
the clock once per sweep in real_journal_next() instead. ratelimit_below()
keeps its behaviour and becomes a wrapper.

The timestamp is now sampled once for the whole sweep rather than once per
file. The interval being rate-limited is a second and a sweep takes
microseconds, so this makes no practical difference.

On that journal, journalctl -o export goes from 4.02s to 2.93s, and the default
journalctl -o short from 3.30s to 2.14s.

src/basic/ratelimit.c

@@ -6,16 +6,12 @@
 /* Modelled after Linux' lib/ratelimit.c by Dave Young
  * <hidave.darkstar@gmail.com>, which is licensed GPLv2. */
 
-bool ratelimit_below(RateLimit *rl) {
-        usec_t ts;
-
+bool ratelimit_below_at(RateLimit *rl, usec_t ts) {
         assert(rl);
 
         if (!ratelimit_configured(rl))
                 return true;
 
-        ts = now(CLOCK_BOOTTIME);
-
         if (rl->begin <= 0 ||
             usec_sub_unsigned(ts, rl->begin) > rl->interval) {
                 rl->begin = ts;  /* Start a new time window */
@@ -30,6 +26,16 @@ bool ratelimit_below(RateLimit *rl) {
         return rl->num <= rl->burst;
 }
 
+bool ratelimit_below(RateLimit *rl) {
+        assert(rl);
+
+        if (!ratelimit_configured(rl)) /* Keep this check here too: the argument below is evaluated
+                                        * before the callee could short-circuit on it. */
+                return true;
+
+        return ratelimit_below_at(rl, now(CLOCK_BOOTTIME));
+}
+
 unsigned ratelimit_num_dropped(const RateLimit *rl) {
         assert(rl);
 

src/basic/ratelimit.h

@@ -21,6 +21,11 @@ static inline bool ratelimit_configured(const RateLimit *rl) {
 }
 
 bool ratelimit_below(RateLimit *rl);
+/* Like ratelimit_below(), but takes the current CLOCK_BOOTTIME timestamp from the caller, for callers
+ * that check many rate limits in a row and should not read the clock for each of them. The timestamps
+ * passed for a given RateLimit must not go backwards: a ts before the one that opened the current
+ * window makes usec_sub_unsigned() return 0, i.e. the window looks like it just started. */
+bool ratelimit_below_at(RateLimit *rl, usec_t ts);
 
 unsigned ratelimit_num_dropped(const RateLimit *rl);
 

src/libsystemd/sd-journal/sd-journal.c

@@ -996,7 +996,7 @@ static int next_with_matches(
                               direction, ret, ret_offset);
 }
 
-static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direction) {
+static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direction, usec_t ts) {
         Object *c;
         uint64_t cp, n_entries;
         int r;
@@ -1008,7 +1008,7 @@ static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direc
          * O(N x files) volatile mmap overhead that makes large 'journalctl -n N' queries unusably
          * slow. Periodic refresh keeps cross-boot ordering reasonably fresh and provides a fallback
          * for any missed inotify events. */
-        if (ratelimit_below(&f->tail_timestamp_ratelimit))
+        if (ratelimit_below_at(&f->tail_timestamp_ratelimit, ts))
                 (void) journal_file_read_tail_timestamp(j, f);
 
         n_entries = le64toh(f->header->n_entries);
@@ -1134,6 +1134,10 @@ static int real_journal_next(sd_journal *j, direction_t direction) {
         assert_return(j, -EINVAL);
         assert_return(!journal_origin_changed(j), -ECHILD);
 
+        /* Read the clock once for the whole call: next_beyond_location() rate-limits its tail timestamp
+         * refresh, which would otherwise be one clock read per file for every entry. */
+        usec_t ts = now(CLOCK_BOOTTIME);
+
         for (;;) {
                 JournalFile *new_file = NULL, *exact_match = NULL;
                 Object *o;
@@ -1146,7 +1150,7 @@ static int real_journal_next(sd_journal *j, direction_t direction) {
                         JournalFile *f = (JournalFile*) *_f;
                         bool found;
 
-                        r = next_beyond_location(j, f, direction);
+                        r = next_beyond_location(j, f, direction, ts);
                         if (r < 0) {
                                 log_debug_errno(r, "Can't iterate through %s, ignoring: %m", f->path);
                                 remove_file_real(j, f);