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 <ddutt@cumulusnetworks.com>
Reviewed-by: JR Rivers <jrrivers@cumulusnetworks.com>
Reviewed-by: Scott Feldman <sfeldma@cumulusnetworks.com>
Reviewed-by: Ayan Banerjee <ayan@cumulusnetworks.com>

diff --git a/lib/thread.c b/lib/thread.c
index 468edd90c0d635c081f53884b9f7e7764d09a958..97448894e558f25c54f6ff915a70963164656b8c 100644 (file)
--- 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 dbf5f25b8036f3a00065effd328763fb1793dd0f..bc7eaef4478c209e1e15ad40e734de3564dc4bfb 100644 (file)
--- 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 4bb70b6a9eec72171a6adabd75ef6452837f16bf..ca1af2c4a1b5898e208c781fb4e40859e00b5be2 100644 (file)
--- 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 7e9412c8889b9028acf4d5bb4181cd55acaf1570..dbf7f11f53e82f0ce1bf1d0b243568c3603ac7e0 100644 (file)
--- 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 6a72e31dc41773696b14ebbc13ec1e080685cdba..9038b3a5c69597594463861466b04a7044f2b7aa 100644 (file)
--- 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 ef023366a057746a5cb28eb9f7562ae2c20c0eae..ebcc717ff319e472b46f97fcc3f1e4edfeb1604a 100644 (file)
--- 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 fef6b162fc2d9e608c90a9508f77c6ee0ff73ee2..31cbaaef24e8c96566e5af830f090051c91f8d12 100644 (file)
--- 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 c40fc33ef76e2bea1705f4d9d31844c71cba5004..a7155bc64a70ffc501f4bad03c5139515a9d3ea7 100644 (file)
--- 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 c1316e4ccf04490388c9f48af6bd549bd481a0ac..c9c539ad7a77f2be23ee73351c454cfa2ee67c9e 100644 (file)
--- 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 8bfcaa829ff81d63c3c671a8ec6170ee6beb7bfd..561d8114995d1f0ae789de1ac184f51210f78dfc 100644 (file)
--- 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 4242aa01b919acf2c8a4940ad831b97326d0c5b0..bf70d022753d2507ca9cb159b221b03941dc710a 100644 (file)
--- 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. */