Commit 6c289ca5a2 for frr
commit 6c289ca5a2bd473e52d8001c420170e3a20380d7
Author: Donatas Abraitis <donatas@opensourcerouting.org>
Date: Thu Oct 29 10:03:24 2026 +0200
lib: Use monotonic clock for route-map time accounting
route_map_apply_ext() called GETRUSAGE() at least 4 times per run.
I did some performance tests and noticed that it's around 16-17% improvement
in terms of bgpd CPU time with 1-2 full feeds.
Signed-off-by: Donatas Abraitis <donatas@opensourcerouting.org>
diff --git a/lib/monotime.h b/lib/monotime.h
index 74f5a70612..8b5f1e8c25 100644
--- a/lib/monotime.h
+++ b/lib/monotime.h
@@ -73,6 +73,23 @@ static inline time_t monotime(struct timeval *tvo)
return ts.tv_sec;
}
+/*
+ * Monotonic timestamp in nanoseconds, meant for cheap duration accounting
+ * in hot paths (subtract two values to get elapsed ns).
+ *
+ * CLOCK_MONOTONIC is served from the vDSO on Linux (~20-30ns, no syscall),
+ * unlike CLOCK_THREAD_CPUTIME_ID / getrusage() which are real syscalls
+ * (~250-400ns). Prefer this for per-item accounting (e.g. per prefix);
+ * for short non-blocking code, wall time is a good proxy for CPU time.
+ */
+static inline uint64_t monotime_ns(void)
+{
+ struct timespec ts;
+
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ return (uint64_t)ts.tv_sec * 1000000000ULL + (uint64_t)ts.tv_nsec;
+}
+
#define ONE_DAY_SECOND (60 * 60 * 24)
#define ONE_WEEK_SECOND (ONE_DAY_SECOND * 7)
#define ONE_YEAR_SECOND (ONE_DAY_SECOND * 365)
diff --git a/lib/routemap.c b/lib/routemap.c
index 839a746cb0..e72b03c2fc 100644
--- a/lib/routemap.c
+++ b/lib/routemap.c
@@ -963,12 +963,12 @@ static void vty_show_route_map_entry(struct vty *vty, struct route_map *map,
json_object_boolean_add(json_rmap, "processedChange",
map->to_be_processed);
json_object_object_add(json_rmap, "rules", json_rules);
- json_object_int_add(json_rmap, "cpuTimeMS", map->cputime / 1000);
+ json_object_int_add(json_rmap, "cpuTimeMS", map->time_ns / 1000000);
} else {
vty_out(vty,
- "route-map: %s Invoked: %" PRIu64
- " (%zu milliseconds total) Optimization: %s Processed Change: %s\n",
- map->name, map->applied - map->applied_clear, map->cputime / 1000,
+ "route-map: %s Invoked: %" PRIu64 " (%" PRIu64
+ " milliseconds total) Optimization: %s Processed Change: %s\n",
+ map->name, map->applied - map->applied_clear, map->time_ns / 1000000,
map->optimization_disabled ? "disabled" : "enabled",
map->to_be_processed ? "true" : "false");
}
@@ -990,7 +990,7 @@ static void vty_show_route_map_entry(struct vty *vty, struct route_map *map,
json_object_int_add(json_rule, "invoked",
index->applied
- index->applied_clear);
- json_object_int_add(json_rule, "cpuTimeMS", index->cputime / 1000);
+ json_object_int_add(json_rule, "cpuTimeMS", index->time_ns / 1000000);
/* Description */
if (index->description)
@@ -1043,9 +1043,10 @@ static void vty_show_route_map_entry(struct vty *vty, struct route_map *map,
action);
} else {
vty_out(vty,
- " %s, sequence %d Invoked %" PRIu64 " (%zu milliseconds total)\n",
+ " %s, sequence %d Invoked %" PRIu64 " (%" PRIu64
+ " milliseconds total)\n",
route_map_type_str(index->type), index->pref,
- index->applied - index->applied_clear, index->cputime / 1000);
+ index->applied - index->applied_clear, index->time_ns / 1000000);
/* Description */
if (index->description)
@@ -1919,8 +1920,13 @@ route_map_get_index(struct route_map *map, const struct prefix *prefix,
if (best_index && (best_index->pref < index->pref))
break;
- ret = route_map_apply_match(&index->match_list, prefix,
- object);
+ if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING))) {
+ uint64_t match_start_ns = monotime_ns();
+
+ ret = route_map_apply_match(&index->match_list, prefix, object);
+ index->time_ns += monotime_ns() - match_start_ns;
+ } else
+ ret = route_map_apply_match(&index->match_list, prefix, object);
if (ret == RMAP_MATCH) {
*match_ret = ret;
@@ -2581,9 +2587,9 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
struct route_map_index *index = NULL;
struct route_map_rule *set = NULL;
bool skip_match_clause = false;
- RUSAGE_T mbefore, mafter;
- RUSAGE_T ibefore, iafter;
- unsigned long cputime;
+ uint64_t start_ns = 0;
+ struct route_map_index *timed_index = NULL;
+ uint64_t seq_start_ns = 0;
enum route_map_action_reason reason = route_map_action_none;
if (recursion > RMAP_RECURSION_LIMIT) {
@@ -2599,11 +2605,8 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
}
if (map == NULL || map->head == NULL) {
- if (map) {
- if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING)))
- GETRUSAGE(&mbefore);
+ if (map)
map->applied++;
- }
ret = RMAP_DENYMATCH;
reason = route_map_action_map_null;
goto route_map_apply_end;
@@ -2611,10 +2614,8 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
map->applied++;
- if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING))) {
- GETRUSAGE(&mbefore);
- ibefore = mbefore;
- }
+ if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING)))
+ start_ns = monotime_ns();
if (prefix->family != AF_INET && prefix->family != AF_INET6) {
/* LPM tries are IPv4/IPv6-only; non-IP families (AF_EVPN,
@@ -2631,13 +2632,6 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
if (index) {
index->applied++;
- if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING))) {
- GETRUSAGE(&iafter);
- event_consumed_time(&iafter, &ibefore, &cputime);
- index->cputime += cputime;
- ibefore = iafter;
- }
-
if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP)))
zlog_debug(
"Best match route-map: %s, sequence: %d for pfx: %pFX, result: %s",
@@ -2662,6 +2656,15 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
}
for (; index; index = index->next) {
+ if (start_ns) {
+ uint64_t now = monotime_ns();
+
+ if (timed_index)
+ timed_index->time_ns += now - seq_start_ns;
+ timed_index = index;
+ seq_start_ns = now;
+ }
+
if (!skip_match_clause) {
index->applied++;
/* Apply this index. */
@@ -2782,12 +2785,6 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
goto route_map_apply_end;
}
}
- if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING))) {
- GETRUSAGE(&iafter);
- event_consumed_time(&iafter, &ibefore, &cputime);
- index->cputime += cputime;
- ibefore = iafter;
- }
}
route_map_apply_end:
@@ -2803,12 +2800,12 @@ route_map_apply_end:
*pref = 65536;
}
- if (map) {
- if (unlikely(CHECK_FLAG(rmap_debug, DEBUG_ROUTEMAP_TIMING))) {
- GETRUSAGE(&mafter);
- event_consumed_time(&mafter, &mbefore, &cputime);
- map->cputime += cputime;
- }
+ if (start_ns) {
+ uint64_t now = monotime_ns();
+
+ map->time_ns += now - start_ns;
+ if (timed_index)
+ timed_index->time_ns += now - seq_start_ns;
}
return (ret);
@@ -3192,10 +3189,10 @@ static void clear_route_map_helper(struct route_map *map)
struct route_map_index *index;
map->applied_clear = map->applied;
- map->cputime = 0;
+ map->time_ns = 0;
for (index = map->head; index; index = index->next) {
index->applied_clear = index->applied;
- index->cputime = 0;
+ index->time_ns = 0;
}
}
diff --git a/lib/routemap.h b/lib/routemap.h
index 72afecb0f2..8711a15955 100644
--- a/lib/routemap.h
+++ b/lib/routemap.h
@@ -188,7 +188,7 @@ struct route_map_index {
/* Keep track how many times we've try to apply */
uint64_t applied;
uint64_t applied_clear;
- size_t cputime;
+ uint64_t time_ns;
/* List of match/sets contexts. */
TAILQ_HEAD(, routemap_hook_context) rhclist;
@@ -223,7 +223,7 @@ struct route_map {
/* How many times have we applied this route-map */
uint64_t applied;
uint64_t applied_clear;
- size_t cputime;
+ uint64_t time_ns;
/* Counter to track active usage of this route-map */
uint16_t use_count;