Browse Source

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>
Dinesh G Dutt 5 years ago
parent
commit
50f38b3500
11 changed files with 161 additions and 27 deletions
  1. 1 1
      lib/thread.c
  2. 1 0
      lib/thread.h
  3. 1 0
      ospfd/ospf_abr.c
  4. 1 0
      ospfd/ospf_asbr.c
  5. 9 0
      ospfd/ospf_ase.c
  6. 14 7
      ospfd/ospf_dump.c
  7. 11 5
      ospfd/ospf_lsa.c
  8. 102 13
      ospfd/ospf_spf.c
  9. 13 0
      ospfd/ospf_spf.h
  10. 3 0
      ospfd/ospf_vty.c
  11. 5 1
      ospfd/ospfd.h

+ 1 - 1
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)

+ 1 - 0
lib/thread.h

@@ -211,6 +211,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 *);

+ 1 - 0
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);

+ 1 - 0
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);
 }

+ 9 - 0
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;
 }

+ 14 - 7
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;
 }
 

+ 11 - 5
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;
           }

+ 102 - 13
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);
 }

+ 13 - 0
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 */

+ 3 - 0
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);

+ 5 - 1
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. */