lib: Add ability to track time in individual routemaps

Add the abilty to track how much time is spent in routemaps.
Example of the new output:

eva# show route-map
ZEBRA:
route-map: FOO Invoked: 1000000 (323 milliseconds total) Optimization: enabled Processed Change: false
 deny, sequence 10 Invoked 1000000 (320 milliseconds total)
  Match clauses:
  Set clauses:
  Call clause:
  Action:
    Exit routemap

Signed-off-by: Donald Sharp <sharpd@nvidia.com>

8 files changed, 63 insertions, 28 deletions

diff --git a/doc/user/routemap.rst b/doc/user/routemap.rst
index 02d674dff0..1481a1bbe8 100644
--- a/doc/user/routemap.rst
+++ b/doc/user/routemap.rst
@@ -101,9 +101,10 @@ cont
 
 .. clicmd:: clear route-map counter [WORD]
 
-   Clear counters that are being stored about the route-map utilization
-   so that subsuquent show commands will indicate since the last clear.
-   If WORD is specified clear just that particular route-map's counters.
+   Clear counters as well as cpu time spent that are being stored about
+   the route-map utilization so that subsequent show commands will indicate
+   since the last clear. If WORD is specified clear just that particular
+   route-map's counters.
 
 .. _route-map-command:
 
diff --git a/lib/routemap.c b/lib/routemap.c
index ea917ebd8c..27c0f80440 100644
--- a/lib/routemap.c
+++ b/lib/routemap.c
@@ -941,11 +941,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);
 	} else {
 		vty_out(vty,
 			"route-map: %s Invoked: %" PRIu64
-			" Optimization: %s Processed Change: %s\n",
-			map->name, map->applied - map->applied_clear,
+			" (%zu milliseconds total) Optimization: %s Processed Change: %s\n",
+			map->name, map->applied - map->applied_clear, map->cputime / 1000,
 			map->optimization_disabled ? "disabled" : "enabled",
 			map->to_be_processed ? "true" : "false");
 	}
@@ -967,6 +968,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);
 
 			/* Description */
 			if (index->description)
@@ -1018,9 +1020,10 @@ static void vty_show_route_map_entry(struct vty *vty, struct route_map *map,
 				json_object_string_add(json_rule, "action",
 						       action);
 		} else {
-			vty_out(vty, " %s, sequence %d Invoked %" PRIu64 "\n",
+			vty_out(vty,
+				" %s, sequence %d Invoked %" PRIu64 " (%zu milliseconds total)\n",
 				route_map_type_str(index->type), index->pref,
-				index->applied - index->applied_clear);
+				index->applied - index->applied_clear, index->cputime / 1000);
 
 			/* Description */
 			if (index->description)
@@ -2548,6 +2551,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;
 
 	if (recursion > RMAP_RECURSION_LIMIT) {
 		if (map)
@@ -2570,6 +2576,9 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
 
 	map->applied++;
 
+	GETRUSAGE(&mbefore);
+	ibefore = mbefore;
+
 	if (prefix->family == AF_EVPN) {
 		index = map->head;
 	} else {
@@ -2580,6 +2589,12 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
 
 	if (index) {
 		index->applied++;
+
+		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",
@@ -2718,6 +2733,10 @@ route_map_result_t route_map_apply_ext(struct route_map *map,
 				goto route_map_apply_end;
 			}
 		}
+		GETRUSAGE(&iafter);
+		event_consumed_time(&iafter, &ibefore, &cputime);
+		index->cputime += cputime;
+		ibefore = iafter;
 	}
 
 route_map_apply_end:
@@ -2733,6 +2752,12 @@ route_map_apply_end:
 			*pref = 65536;
 	}
 
+	if (map) {
+		GETRUSAGE(&mafter);
+		event_consumed_time(&mafter, &mbefore, &cputime);
+		map->cputime += cputime;
+	}
+
 	return (ret);
 }
 
@@ -3090,8 +3115,11 @@ static void clear_route_map_helper(struct route_map *map)
 	struct route_map_index *index;
 
 	map->applied_clear = map->applied;
-	for (index = map->head; index; index = index->next)
+	map->cputime = 0;
+	for (index = map->head; index; index = index->next) {
 		index->applied_clear = index->applied;
+		index->cputime = 0;
+	}
 }
 
 DEFPY (rmap_clear_counters,
diff --git a/lib/routemap.h b/lib/routemap.h
index ef9b3cb160..e0f738502b 100644
--- a/lib/routemap.h
+++ b/lib/routemap.h
@@ -176,6 +176,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;
 
 	/* List of match/sets contexts. */
 	TAILQ_HEAD(, routemap_hook_context) rhclist;
@@ -210,6 +211,7 @@ struct route_map {
 	/* How many times have we applied this route-map */
 	uint64_t applied;
 	uint64_t applied_clear;
+	size_t cputime;
 
 	/* Counter to track active usage of this route-map */
 	uint16_t use_count;
diff --git a/tests/topotests/all_protocol_startup/r1/show_route_map.ref b/tests/topotests/all_protocol_startup/r1/show_route_map.ref
index 612d0a729d..894ea59677 100644
--- a/tests/topotests/all_protocol_startup/r1/show_route_map.ref
+++ b/tests/topotests/all_protocol_startup/r1/show_route_map.ref
@@ -1,6 +1,6 @@
 ZEBRA:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
@@ -8,8 +8,8 @@ route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
   Action:
     Exit routemap
 RIP:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
@@ -17,8 +17,8 @@ route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
   Action:
     Exit routemap
 RIPNG:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
@@ -26,8 +26,8 @@ route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
   Action:
     Exit routemap
 OSPF:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
@@ -35,8 +35,8 @@ route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
   Action:
     Exit routemap
 OSPF6:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
@@ -44,16 +44,16 @@ route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
   Action:
     Exit routemap
 BGP:
-route-map: LIES Invoked: 0 Optimization: enabled Processed Change: false
- deny, sequence 10 Invoked 0
+route-map: LIES Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ deny, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
     interface notpresent
   Set clauses:
   Call clause:
   Action:
     Exit routemap
-route-map: bgp-map Invoked: 0 Optimization: enabled Processed Change: false
- permit, sequence 10 Invoked 0
+route-map: bgp-map Invoked: 0 (X milliseconds total) Optimization: enabled Processed Change: false
+ permit, sequence 10 Invoked 0 (X milliseconds total)
   Match clauses:
   Set clauses:
     community 100:100 additive
@@ -61,7 +61,7 @@ route-map: bgp-map Invoked: 0 Optimization: enabled Processed Change: false
   Call clause:
   Action:
     Exit routemap
- permit, sequence 20 Invoked 0
+ permit, sequence 20 Invoked 0 (X milliseconds total)
   Match clauses:
   Set clauses:
     metric 10
diff --git a/tests/topotests/all_protocol_startup/test_all_protocol_startup.py b/tests/topotests/all_protocol_startup/test_all_protocol_startup.py
index 80bd2505a7..0ffd762734 100644
--- a/tests/topotests/all_protocol_startup/test_all_protocol_startup.py
+++ b/tests/topotests/all_protocol_startup/test_all_protocol_startup.py
@@ -37,6 +37,7 @@ from lib.topogen import Topogen, get_topogen
 from lib.common_config import (
     required_linux_kernel_version,
 )
+from lib.topolog import logger
 
 import json
 import functools
@@ -1422,6 +1423,7 @@ def test_route_map():
                 .cmd('vtysh -c "show route-map" 2> /dev/null')
                 .rstrip()
             )
+            actual = re.sub(r"\([0-9].* milli", "(X milli", actual)
             actual = ("\n".join(actual.splitlines()) + "\n").splitlines(1)
 
             diff = topotest.get_textdiff(
diff --git a/tests/topotests/zebra_rib/r1/sharp_rmap.ref b/tests/topotests/zebra_rib/r1/sharp_rmap.ref
index 47a9eb6a49..d80a5f661e 100644
--- a/tests/topotests/zebra_rib/r1/sharp_rmap.ref
+++ b/tests/topotests/zebra_rib/r1/sharp_rmap.ref
@@ -1,6 +1,6 @@
 ZEBRA:
-route-map: sharp Invoked: 500 Optimization: enabled Processed Change: false
- permit, sequence 10 Invoked 244
+route-map: sharp Invoked: 500 (X milliseconds total) Optimization: enabled Processed Change: false
+ permit, sequence 10 Invoked 244 (X milliseconds total)
   Match clauses:
     ip address 10
   Set clauses:
@@ -8,7 +8,7 @@ route-map: sharp Invoked: 500 Optimization: enabled Processed Change: false
   Call clause:
   Action:
     Exit routemap
- permit, sequence 20 Invoked 256
+ permit, sequence 20 Invoked 256 (X milliseconds total)
   Match clauses:
   Set clauses:
     src 192.168.213.1
diff --git a/tests/topotests/zebra_rib/r1/static_rmap.ref b/tests/topotests/zebra_rib/r1/static_rmap.ref
index 2de98bd514..68e4a5f7b6 100644
--- a/tests/topotests/zebra_rib/r1/static_rmap.ref
+++ b/tests/topotests/zebra_rib/r1/static_rmap.ref
@@ -1,6 +1,6 @@
 ZEBRA:
-route-map: static Invoked: 2 Optimization: enabled Processed Change: false
- permit, sequence 10 Invoked 2
+route-map: static Invoked: 2 (X milliseconds total) Optimization: enabled Processed Change: false
+ permit, sequence 10 Invoked 2 (X milliseconds total)
   Match clauses:
   Set clauses:
     src 192.168.215.1
diff --git a/tests/topotests/zebra_rib/test_zebra_rib.py b/tests/topotests/zebra_rib/test_zebra_rib.py
index c0a79ed79d..d1aee46b40 100644
--- a/tests/topotests/zebra_rib/test_zebra_rib.py
+++ b/tests/topotests/zebra_rib/test_zebra_rib.py
@@ -246,6 +246,7 @@ def test_route_map_usage():
 
     def check_static_map_correct_runs():
         actual = r1.vtysh_cmd("show route-map static")
+        actual = re.sub(r"\([0-9].* milli", "(X milli", actual)
         actual = ("\n".join(actual.splitlines()) + "\n").rstrip()
         return topotest.get_textdiff(
             actual,
@@ -266,6 +267,7 @@ def test_route_map_usage():
 
     def check_sharp_map_correct_runs():
         actual = r1.vtysh_cmd("show route-map sharp")
+        actual = re.sub(r"\([0-9].* milli", "(X milli", actual)
         actual = ("\n".join(actual.splitlines()) + "\n").rstrip()
         return topotest.get_textdiff(
             actual,