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/lib/thread.c b/lib/thread.c
index 9c3ee82..cb51332 100644
--- a/lib/thread.c
+++ b/lib/thread.c
@@ -102,7 +102,7 @@
? 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 9743a22..4856dec 100644
--- a/lib/thread.h
+++ b/lib/thread.h
@@ -211,6 +211,7 @@
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 4bb70b6..ca1af2c 100644
--- a/ospfd/ospf_abr.c
+++ b/ospfd/ospf_abr.c
@@ -556,6 +556,7 @@
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 7e9412c..dbf7f11 100644
--- a/ospfd/ospf_asbr.c
+++ b/ospfd/ospf_asbr.c
@@ -264,6 +264,7 @@
}
/* 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 6a72e31..9038b3a 100644
--- a/ospfd/ospf_ase.c
+++ b/ospfd/ospf_ase.c
@@ -636,6 +636,7 @@
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_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_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 ef02336..ebcc717 100644
--- a/ospfd/ospf_dump.c
+++ b/ospfd/ospf_dump.c
@@ -247,16 +247,21 @@
#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 @@
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 fef6b16..31cbaae 100644
--- a/ospfd/ospf_lsa.c
+++ b/ospfd/ospf_lsa.c
@@ -2409,8 +2409,10 @@
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_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 @@
/* 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 @@
- 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_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 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);
}
diff --git a/ospfd/ospf_spf.h b/ospfd/ospf_spf.h
index c1316e4..c9c539a 100644
--- a/ospfd/ospf_spf.h
+++ b/ospfd/ospf_spf.h
@@ -64,4 +64,17 @@
/* 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 97fcffd..5674da0 100644
--- a/ospfd/ospf_vty.c
+++ b/ospfd/ospf_vty.c
@@ -2749,6 +2749,9 @@
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 4242aa0..bf70d02 100644
--- a/ospfd/ospfd.h
+++ b/ospfd/ospfd.h
@@ -194,8 +194,9 @@
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 @@
/* 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. */