From cf744958ba2c89b5670ac3a0ee1aa92be630cf15 Mon Sep 17 00:00:00 2001 From: Donald Sharp Date: Tue, 19 May 2015 16:36:05 -0700 Subject: [PATCH] ospfd-spf-stats.patch Compute and display SPF execution statistics Detailed SPF statistics, all around time spent executing various pieces of SPF such as the SPF algorithm itself, installing routes, pruning unreachable networks etc. Reason codes for firing up SPF are: R - Router LSA, N - Network LSA, S - Summary LSA, ABR - ABR status change, ASBR - ASBR Status Change, AS - ASBR Summary, M - MaxAge Signed-off-by: Dinesh G Dutt Reviewed-by: JR Rivers Reviewed-by: Scott Feldman Reviewed-by: Ayan Banerjee --- lib/thread.c | 2 +- lib/thread.h | 1 + ospfd/ospf_abr.c | 1 + ospfd/ospf_asbr.c | 1 + ospfd/ospf_ase.c | 9 ++++ ospfd/ospf_dump.c | 21 ++++++--- ospfd/ospf_lsa.c | 16 +++++-- ospfd/ospf_spf.c | 115 ++++++++++++++++++++++++++++++++++++++++------ ospfd/ospf_spf.h | 13 ++++++ ospfd/ospf_vty.c | 3 ++ ospfd/ospfd.h | 6 ++- 11 files changed, 161 insertions(+), 27 deletions(-) diff --git a/lib/thread.c b/lib/thread.c index 468edd90c0..97448894e5 100644 --- a/lib/thread.c +++ b/lib/thread.c @@ -102,7 +102,7 @@ timeval_cmp (struct timeval a, struct timeval b) ? a.tv_usec - b.tv_usec : a.tv_sec - b.tv_sec); } -static unsigned long +unsigned long timeval_elapsed (struct timeval a, struct timeval b) { return (((a.tv_sec - b.tv_sec) * TIMER_SECOND_MICRO) diff --git a/lib/thread.h b/lib/thread.h index dbf5f25b80..bc7eaef447 100644 --- a/lib/thread.h +++ b/lib/thread.h @@ -208,6 +208,7 @@ extern struct thread *thread_fetch (struct thread_master *, struct thread *); extern void thread_call (struct thread *); extern unsigned long thread_timer_remain_second (struct thread *); extern int thread_should_yield (struct thread *); +extern unsigned long timeval_elapsed (struct timeval a, struct timeval b); /* Internal libzebra exports */ extern void thread_getrusage (RUSAGE_T *); diff --git a/ospfd/ospf_abr.c b/ospfd/ospf_abr.c index 4bb70b6a9e..ca1af2c4a1 100644 --- a/ospfd/ospf_abr.c +++ b/ospfd/ospf_abr.c @@ -556,6 +556,7 @@ ospf_check_abr_status (struct ospf *ospf) if (new_flags != ospf->flags) { + ospf_flag_spf_reason (SPF_FLAG_ABR_STATUS_CHANGE); ospf_spf_calculate_schedule (ospf); if (IS_DEBUG_OSPF_EVENT) zlog_debug ("ospf_check_abr_status(): new router flags: %x",new_flags); diff --git a/ospfd/ospf_asbr.c b/ospfd/ospf_asbr.c index 7e9412c888..dbf7f11f53 100644 --- a/ospfd/ospf_asbr.c +++ b/ospfd/ospf_asbr.c @@ -264,6 +264,7 @@ ospf_asbr_status_update (struct ospf *ospf, u_char status) } /* Transition from/to status ASBR, schedule timer. */ + ospf_flag_spf_reason (SPF_FLAG_ASBR_STATUS_CHANGE); ospf_spf_calculate_schedule (ospf); ospf_router_lsa_update (ospf); } diff --git a/ospfd/ospf_ase.c b/ospfd/ospf_ase.c index 6a72e31dc4..9038b3a5c6 100644 --- a/ospfd/ospf_ase.c +++ b/ospfd/ospf_ase.c @@ -636,6 +636,7 @@ ospf_ase_calculate_timer (struct thread *t) struct route_node *rn; struct listnode *node; struct ospf_area *area; + struct timeval start_time, stop_time; ospf = THREAD_ARG (t); ospf->t_ase_calc = NULL; @@ -644,6 +645,8 @@ ospf_ase_calculate_timer (struct thread *t) { ospf->ase_calc = 0; + quagga_gettime(QUAGGA_CLK_MONOTONIC, &start_time); + /* Calculate external route for each AS-external-LSA */ LSDB_LOOP (EXTERNAL_LSDB (ospf), rn, lsa) ospf_ase_calculate_route (ospf, lsa); @@ -673,6 +676,12 @@ ospf_ase_calculate_timer (struct thread *t) ospf_route_table_free (ospf->old_external_route); ospf->old_external_route = ospf->new_external_route; ospf->new_external_route = route_table_init (); + + quagga_gettime(QUAGGA_CLK_MONOTONIC, &stop_time); + + zlog_info ("SPF Processing Time(usecs): External Routes: %d\n", + (stop_time.tv_sec - start_time.tv_sec)*1000000L+ + (stop_time.tv_usec - start_time.tv_usec)); } return 0; } diff --git a/ospfd/ospf_dump.c b/ospfd/ospf_dump.c index ef023366a0..ebcc717ff3 100644 --- a/ospfd/ospf_dump.c +++ b/ospfd/ospf_dump.c @@ -247,16 +247,21 @@ ospf_timeval_dump (struct timeval *t, char *buf, size_t size) #define HOUR_IN_SECONDS (60*MINUTE_IN_SECONDS) #define DAY_IN_SECONDS (24*HOUR_IN_SECONDS) #define WEEK_IN_SECONDS (7*DAY_IN_SECONDS) - unsigned long w, d, h, m, s, ms; + unsigned long w, d, h, m, s, ms, us; if (!t) return "inactive"; - w = d = h = m = s = ms = 0; + w = d = h = m = s = ms = us = 0; memset (buf, 0, size); - - ms = t->tv_usec / 1000; - + + us = t->tv_usec; + if (us >= 1000) + { + ms = us / 1000; + us %= 1000; + } + if (ms >= 1000) { t->tv_sec += ms / 1000; @@ -297,9 +302,11 @@ ospf_timeval_dump (struct timeval *t, char *buf, size_t size) snprintf (buf, size, "%ldh%02ldm%02lds", h, m, t->tv_sec); else if (m) snprintf (buf, size, "%ldm%02lds", m, t->tv_sec); - else + else if (ms) snprintf (buf, size, "%ld.%03lds", t->tv_sec, ms); - + else + snprintf (buf, size, "%ld usecs", t->tv_usec); + return buf; } diff --git a/ospfd/ospf_lsa.c b/ospfd/ospf_lsa.c index fef6b162fc..31cbaaef24 100644 --- a/ospfd/ospf_lsa.c +++ b/ospfd/ospf_lsa.c @@ -2409,8 +2409,10 @@ ospf_router_lsa_install (struct ospf *ospf, struct ospf_lsa *new, ospf_refresher_register_lsa (ospf, new); } if (rt_recalc) - ospf_spf_calculate_schedule (ospf); - + { + ospf_flag_spf_reason (SPF_FLAG_ROUTER_LSA_INSTALL); + ospf_spf_calculate_schedule (ospf); + } return new; } @@ -2444,7 +2446,10 @@ ospf_network_lsa_install (struct ospf *ospf, ospf_refresher_register_lsa (ospf, new); } if (rt_recalc) - ospf_spf_calculate_schedule (ospf); + { + ospf_flag_spf_reason (SPF_FLAG_NETWORK_LSA_INSTALL); + ospf_spf_calculate_schedule (ospf); + } return new; } @@ -2467,11 +2472,10 @@ ospf_summary_lsa_install (struct ospf *ospf, struct ospf_lsa *new, /* This doesn't exist yet... */ ospf_summary_incremental_update(new); */ #else /* #if 0 */ + ospf_flag_spf_reason (SPF_FLAG_SUMMARY_LSA_INSTALL); ospf_spf_calculate_schedule (ospf); #endif /* #if 0 */ - if (IS_DEBUG_OSPF (lsa, LSA_INSTALL)) - zlog_debug ("ospf_summary_lsa_install(): SPF scheduled"); } if (IS_LSA_SELF (new)) @@ -2500,6 +2504,7 @@ ospf_summary_asbr_lsa_install (struct ospf *ospf, struct ospf_lsa *new, - RFC 2328 Section 16.5 implies it should be */ /* ospf_ase_calculate_schedule(); */ #else /* #if 0 */ + ospf_flag_spf_reason (SPF_FLAG_ASBR_SUMMARY_LSA_INSTALL); ospf_spf_calculate_schedule (ospf); #endif /* #if 0 */ } @@ -3022,6 +3027,7 @@ ospf_lsa_maxage_walker_remover (struct ospf *ospf, struct ospf_lsa *lsa) ospf_ase_incremental_update (ospf, lsa); break; default: + ospf_flag_spf_reason (SPF_FLAG_MAXAGE); ospf_spf_calculate_schedule (ospf); break; } diff --git a/ospfd/ospf_spf.c b/ospfd/ospf_spf.c index c40fc33ef7..a7155bc64a 100644 --- a/ospfd/ospf_spf.c +++ b/ospfd/ospf_spf.c @@ -46,6 +46,50 @@ Software Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA #include "ospfd/ospf_abr.h" #include "ospfd/ospf_dump.h" +/* Variables to ensure a SPF scheduled log message is printed only once */ + +static unsigned int spf_reason_flags = 0; + +static void ospf_clear_spf_reason_flags () +{ + spf_reason_flags = 0; +} + +void ospf_flag_spf_reason (unsigned int reason) +{ + if (reason <= SPF_FLAG_MAX_VALUE) + spf_reason_flags |= reason; + else + spf_reason_flags |= SPF_FLAG_MISC; +} + +static void +ospf_get_spf_reason_str (char *buf) +{ + if (buf) + { + buf[0] = '\0'; + if (spf_reason_flags) + { + if (spf_reason_flags & SPF_FLAG_ROUTER_LSA_INSTALL) + strcat (buf, "R, "); + if (spf_reason_flags & SPF_FLAG_NETWORK_LSA_INSTALL) + strcat (buf, "N, "); + if (spf_reason_flags & SPF_FLAG_SUMMARY_LSA_INSTALL) + strcat (buf, "S, "); + if (spf_reason_flags & SPF_FLAG_ASBR_SUMMARY_LSA_INSTALL) + strcat (buf, "AS, "); + if (spf_reason_flags & SPF_FLAG_ABR_STATUS_CHANGE) + strcat (buf, "ABR, "); + if (spf_reason_flags & SPF_FLAG_ASBR_STATUS_CHANGE) + strcat (buf, "ASBR, "); + if (spf_reason_flags & SPF_FLAG_MAXAGE) + strcat (buf, "M, "); + } + buf[strlen(buf)-2] = '\0'; /* skip the last ", " */ + } +} + static void ospf_vertex_free (void *); /* List of allocated vertices, to simplify cleanup of SPF. * Not thread-safe obviously. If it ever needs to be, it'd have to be @@ -1232,27 +1276,28 @@ ospf_spf_calculate (struct ospf_area *area, struct route_table *new_table, /* Free candidate queue. */ pqueue_delete (candidate); - + ospf_vertex_dump (__func__, area->spf, 0, 1); /* Free nexthop information, canonical versions of which are attached * the first level of router vertices attached to the root vertex, see * ospf_nexthop_calculation. */ ospf_canonical_nexthops_free (area->spf); - - /* Free SPF vertices, but not the list. List has ospf_vertex_free - * as deconstructor. - */ - list_delete_all_node (&vertex_list); - + /* Increment SPF Calculation Counter. */ area->spf_calculation++; quagga_gettime (QUAGGA_CLK_MONOTONIC, &area->ospf->ts_spf); + area->ts_spf = area->ospf->ts_spf; if (IS_DEBUG_OSPF_EVENT) zlog_debug ("ospf_spf_calculate: Stop. %ld vertices", mtype_stats_alloc(MTYPE_OSPF_VERTEX)); + + /* Free SPF vertices, but not the list. List has ospf_vertex_free + * as deconstructor. + */ + list_delete_all_node (&vertex_list); } /* Timer for SPF calculation. */ @@ -1263,12 +1308,18 @@ ospf_spf_calculate_timer (struct thread *thread) struct route_table *new_table, *new_rtrs; struct ospf_area *area; struct listnode *node, *nnode; + struct timeval start_time, stop_time, spf_start_time; + int areas_processed = 0; + unsigned long ia_time, prune_time, rt_time; + unsigned long abr_time, total_spf_time, spf_time; + char rbuf[32]; /* reason_buf */ if (IS_DEBUG_OSPF_EVENT) zlog_debug ("SPF: Timer (SPF calculation expire)"); ospf->t_spf_calc = NULL; + quagga_gettime (QUAGGA_CLK_MONOTONIC, &spf_start_time); /* Allocate new table tree. */ new_table = route_table_init (); new_rtrs = route_table_init (); @@ -1283,21 +1334,36 @@ ospf_spf_calculate_timer (struct thread *thread) */ if (ospf->backbone && ospf->backbone == area) continue; - + ospf_spf_calculate (area, new_table, new_rtrs); + areas_processed++; } - + /* SPF for backbone, if required */ if (ospf->backbone) - ospf_spf_calculate (ospf->backbone, new_table, new_rtrs); - + { + ospf_spf_calculate (ospf->backbone, new_table, new_rtrs); + areas_processed++; + } + + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + spf_time = timeval_elapsed (stop_time, spf_start_time); + ospf_vl_shut_unapproved (ospf); + start_time = stop_time; /* saving a call */ + ospf_ia_routing (ospf, new_table, new_rtrs); + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + ia_time = timeval_elapsed (stop_time, start_time); + + quagga_gettime (QUAGGA_CLK_MONOTONIC, &start_time); ospf_prune_unreachable_networks (new_table); ospf_prune_unreachable_routers (new_rtrs); + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + prune_time = timeval_elapsed (stop_time, start_time); /* AS-external-LSA calculation should not be performed here. */ /* If new Router Route is installed, @@ -1307,9 +1373,13 @@ ospf_spf_calculate_timer (struct thread *thread) ospf_ase_calculate_timer_add (ospf); + quagga_gettime (QUAGGA_CLK_MONOTONIC, &start_time); + /* Update routing table. */ ospf_route_install (ospf, new_table); + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + rt_time = timeval_elapsed (stop_time, start_time); /* Update ABR/ASBR routing table */ if (ospf->old_rtrs) { @@ -1321,11 +1391,28 @@ ospf_spf_calculate_timer (struct thread *thread) ospf->old_rtrs = ospf->new_rtrs; ospf->new_rtrs = new_rtrs; + quagga_gettime (QUAGGA_CLK_MONOTONIC, &start_time); if (IS_OSPF_ABR (ospf)) ospf_abr_task (ospf); - if (IS_DEBUG_OSPF_EVENT) - zlog_debug ("SPF: calculation complete"); + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + abr_time = timeval_elapsed (stop_time, start_time); + + quagga_gettime (QUAGGA_CLK_MONOTONIC, &stop_time); + total_spf_time = timeval_elapsed (stop_time, spf_start_time); + ospf->ts_spf_duration.tv_sec = total_spf_time/1000000; + ospf->ts_spf_duration.tv_usec = total_spf_time % 1000000; + + ospf_get_spf_reason_str (rbuf); + + if (IS_OSPF_ABR (ospf)) + zlog_info ("SPF Processing Time(usecs): # Areas: %d, SPF Time: %ld, InterArea: %ld, Prune: %ld, RouteInstall: %ld, ABR: %ld, Total: %ld, Reason: %s\n", + areas_processed, spf_time, ia_time, prune_time, rt_time, abr_time, total_spf_time, rbuf); + else + zlog_info ("SPF Processing Time(usecs): SPF Time: %ld, InterArea: %ld, Prune: %ld, RouteInstall: %ld, Total: %ld, Reason: %s\n", + spf_time, ia_time, prune_time, rt_time, total_spf_time, rbuf); + + ospf_clear_spf_reason_flags (); return 0; } @@ -1389,6 +1476,8 @@ ospf_spf_calculate_schedule (struct ospf *ospf) if (IS_DEBUG_OSPF_EVENT) zlog_debug ("SPF: calculation timer delay = %ld", delay); + zlog_info ("SPF: Scheduled in %ld msec", delay); + ospf->t_spf_calc = thread_add_timer_msec (master, ospf_spf_calculate_timer, ospf, delay); } diff --git a/ospfd/ospf_spf.h b/ospfd/ospf_spf.h index c1316e4ccf..c9c539ad7a 100644 --- a/ospfd/ospf_spf.h +++ b/ospfd/ospf_spf.h @@ -64,4 +64,17 @@ extern void ospf_rtrs_free (struct route_table *); /* void ospf_spf_calculate_timer_add (); */ +/* What triggered the SPF ? Can have at most 32 reasons with this */ +#define SPF_FLAG_ROUTER_LSA_INSTALL 0x1 +#define SPF_FLAG_NETWORK_LSA_INSTALL 0x2 +#define SPF_FLAG_SUMMARY_LSA_INSTALL 0x4 +#define SPF_FLAG_ASBR_SUMMARY_LSA_INSTALL 0x8 +#define SPF_FLAG_MAXAGE 0x10 +#define SPF_FLAG_ABR_STATUS_CHANGE 0x20 +#define SPF_FLAG_ASBR_STATUS_CHANGE 0x40 +#define SPF_FLAG_MAX_VALUE 0x40 /* Update this when adding flags */ +#define SPF_FLAG_MISC 0x1000000 /* Keep this last */ + +extern void ospf_flag_spf_reason (unsigned int reason); + #endif /* _QUAGGA_OSPF_SPF_H */ diff --git a/ospfd/ospf_vty.c b/ospfd/ospf_vty.c index 8bfcaa829f..561d811499 100644 --- a/ospfd/ospf_vty.c +++ b/ospfd/ospf_vty.c @@ -2749,6 +2749,9 @@ DEFUN (show_ip_ospf, vty_out (vty, "last executed %s ago%s", ospf_timeval_dump (&result, timebuf, sizeof (timebuf)), VTY_NEWLINE); + vty_out (vty, " Last SPF duration %s%s", + ospf_timeval_dump (&ospf->ts_spf_duration, timebuf, sizeof (timebuf)), + VTY_NEWLINE); } else vty_out (vty, "has not been run%s", VTY_NEWLINE); diff --git a/ospfd/ospfd.h b/ospfd/ospfd.h index 4242aa01b9..bf70d02275 100644 --- a/ospfd/ospfd.h +++ b/ospfd/ospfd.h @@ -194,8 +194,9 @@ struct ospf struct route_table *external_lsas; /* Database of external LSAs, prefix is LSA's adv. network*/ - /* Time stamps. */ + /* Time stamps */ struct timeval ts_spf; /* SPF calculation time stamp. */ + struct timeval ts_spf_duration; /* Execution time of last SPF */ struct route_table *maxage_lsa; /* List of MaxAge LSA for deletion. */ int redistribute; /* Num of redistributed protocols. */ @@ -393,6 +394,9 @@ struct ospf_area /* Statistics field. */ u_int32_t spf_calculation; /* SPF Calculation Count. */ + /* Time stamps. */ + struct timeval ts_spf; /* SPF calculation time stamp. */ + /* Router count. */ u_int32_t abr_count; /* ABR router in this area. */ u_int32_t asbr_count; /* ASBR router in this area. */ -- 2.39.5