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 <ddutt@cumulusnetworks.com>
Reviewed-by: JR Rivers <jrrivers@cumulusnetworks.com>
Reviewed-by: Scott Feldman <sfeldma@cumulusnetworks.com>
Reviewed-by: Ayan Banerjee <ayan@cumulusnetworks.com>
Reviewed-by: Paul Jakma <paul@opensourcerouting.org>
diff --git a/ospfd/ospf_spf.c b/ospfd/ospf_spf.c
index c40fc33..a7155bc 100644
--- a/ospfd/ospf_spf.c
+++ b/ospfd/ospf_spf.c
@@ -46,6 +46,50 @@
#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 @@
/* 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 @@
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 @@
*/
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_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->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 @@
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);
}