diff --git a/doc/user/routemap.rst b/doc/user/routemap.rst index 1d2f4e352f38..74e739d47a16 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 ea917ebd8c73..fff634cf49c9 100644 --- a/lib/routemap.c +++ b/lib/routemap.c @@ -941,11 +941,13 @@ 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", + " (%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 +969,8 @@ 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 +1022,12 @@ 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 +2555,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 +2580,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 +2593,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 +2737,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 +2756,12 @@ route_map_result_t route_map_apply_ext(struct route_map *map, *pref = 65536; } + if (map) { + GETRUSAGE(&mafter); + event_consumed_time(&mafter, &mbefore, &cputime); + map->cputime += cputime; + } + return (ret); } @@ -3090,8 +3119,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 dfb84ced5bae..98615ba664b4 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 612d0a729dfb..194100679d8f 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + deny, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Optimization: enabled Processed Change: false + permit, sequence 10 Invoked 0 (0 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 (0 milliseconds total) Match clauses: Set clauses: metric 10 diff --git a/tests/topotests/zebra_rib/r1/sharp_rmap.ref b/tests/topotests/zebra_rib/r1/sharp_rmap.ref index 47a9eb6a4925..99dde90fb5f8 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 (0 milliseconds total) Optimization: enabled Processed Change: false + permit, sequence 10 Invoked 244 (0 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 (0 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 2de98bd51444..c38e2dedbf95 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 (0 milliseconds total) Optimization: enabled Processed Change: false + permit, sequence 10 Invoked 2 (0 milliseconds total) Match clauses: Set clauses: src 192.168.215.1