Merge pull request FRRouting#22 from pushpasis/cmgd_show_timer

cmgd: Changes to support profiling data of commit-apply

cmgd/cmgd.c

@@ -74,6 +74,8 @@ static struct cmgd_master cmgd_master;
 /* CMGD process wide configuration pointer to export. */
 struct cmgd_master *cm;
 
+cmgd_cli_profiling_t *g_prof_cmt_apply = NULL;
+
 #if 0
 /* handle main socket creation or deletion */
 static int cmgd_check_main_socket(bool create, struct cmgd *cmgd)

cmgd/cmgd.h

@@ -66,6 +66,27 @@ extern bool cmgd_debug_frntnd;
 extern bool cmgd_debug_db;
 extern bool cmgd_debug_trxn;
 
+typedef struct cmgd_cli_profiling_ {
+ struct timeval start;
+ struct timeval validate_st;
+ struct timeval prep_cfg_st;
+ struct timeval trxn_create_st;
+ struct timeval send_cfg_st;
+ struct timeval apply_cfg_st;
+ struct timeval apply_cfg_nd;
+ struct timeval trxn_del_st;
+ struct timeval end;
+ unsigned long last_exec_tm;
+ unsigned long max_tm;
+ unsigned long min_tm;
+ unsigned long last_batch_cnt;
+ unsigned long max_batch_cnt;
+ unsigned long min_batch_cnt;
+ unsigned long commit_cnt;
+} cmgd_cli_profiling_t;
+
+extern cmgd_cli_profiling_t *g_prof_cmt_apply;
+
 /* CMGD master for system wide configurations and variables. */
 struct cmgd_master {
  /* CMGD instance list. */
@@ -255,6 +276,26 @@ static inline void cmgd_vrf_unlink(struct cmgd *cmgd, struct vrf *vrf)
  cmgd->vrf_id = VRF_UNKNOWN;
 }
 
+static inline void cmgd_get_realtime(struct timeval *tv)
+{
+ gettimeofday(tv, NULL);
+}
+
+static inline char *cmgd_realtime_to_string(struct timeval *tv,
+ char *buf, size_t sz)
+{
+ char tmp[50];
+ struct tm *lm;
+
+ lm = localtime((const time_t *) &tv->tv_sec);
+ if (lm) {
+ strftime(tmp, sizeof(tmp), "%Y-%m-%d %H:%M:%S", lm);
+ snprintf(buf, sz, "%s.%06lu", tmp, tv->tv_usec);
+ }
+
+ return buf;
+}
+
 extern void cmgd_unset_redist_vrf_bitmaps(struct cmgd *, vrf_id_t);
 
 

cmgd/cmgd_bcknd_adapter.c

@@ -389,6 +389,7 @@ static int cmgd_bcknd_adapter_handle_msg(
  cfg_apply_reply->batch_ids,
  bcknd_msg->cfg_apply_reply->n_batch_ids,
  bcknd_msg->cfg_apply_reply->error_if_any, adptr);
+ cmgd_get_realtime(&g_prof_cmt_apply->apply_cfg_nd);
  break;
  default:
  break;

cmgd/cmgd_frntnd_adapter.c

@@ -63,6 +63,7 @@ typedef struct cmgd_frntnd_sessn_ctxt_ {
  uint8_t db_locked_implict[CMGD_DB_MAX_ID];
  struct thread *proc_cfg_trxn_clnp;
  struct thread *proc_show_trxn_clnp;
+ cmgd_cli_profiling_t prof_cmt_apply;
 
  struct cmgd_frntnd_sessn_list_item list_linkage;
 } cmgd_frntnd_sessn_ctxt_t;
@@ -193,6 +194,21 @@ static void cmgd_frntnd_sessn_show_trxn_cleanup(cmgd_frntnd_sessn_ctxt_t *sessn)
  cmgd_destroy_trxn(&sessn->trxn_id);
 }
 
+static void cmgd_compute_timers(cmgd_cli_profiling_t *prof_cmt_apply)
+{
+ prof_cmt_apply->last_exec_tm = timeval_elapsed(prof_cmt_apply->end,
+ prof_cmt_apply->start);
+ if (prof_cmt_apply->last_exec_tm > prof_cmt_apply->max_tm) {
+ prof_cmt_apply->max_tm = prof_cmt_apply->last_exec_tm;
+ prof_cmt_apply->max_batch_cnt = prof_cmt_apply->last_batch_cnt;
+ }
+
+ if (prof_cmt_apply->last_exec_tm < prof_cmt_apply->min_tm) {
+ prof_cmt_apply->min_tm = prof_cmt_apply->last_exec_tm;
+ prof_cmt_apply->min_batch_cnt = prof_cmt_apply->last_batch_cnt;
+ }
+}
+
 static void cmgd_frntnd_cleanup_session(cmgd_frntnd_sessn_ctxt_t **sessn)
 {
  if ((*sessn)->adptr) {
@@ -237,6 +253,7 @@ static cmgd_frntnd_sessn_ctxt_t *cmgd_frntnd_create_session(
  sessn->trxn_id = CMGD_TRXN_ID_NONE;
  sessn->cfg_trxn_id = CMGD_TRXN_ID_NONE;
  cmgd_frntnd_adapter_lock(adptr);
+ sessn->prof_cmt_apply.min_tm = ULONG_MAX;
  cmgd_frntnd_sessn_list_add_tail(&adptr->frntnd_sessns, sessn);
 
  return sessn;
@@ -412,6 +429,8 @@ static int cmgd_frntnd_send_commitcfg_reply(cmgd_frntnd_sessn_ctxt_t *sessn,
  cmgd_frntnd_session_register_event(
  sessn, CMGD_FRNTND_SESSN_CFG_TRXN_CLNUP);
 
+ cmgd_get_realtime(&sessn->prof_cmt_apply.end);
+ cmgd_compute_timers(&sessn->prof_cmt_apply);
  return cmgd_frntnd_adapter_send_msg(sessn->adptr, &frntnd_msg);
 }
 
@@ -980,6 +999,9 @@ static int cmgd_frntnd_session_handle_commit_config_req_msg(
 {
  cmgd_db_hndl_t src_db_hndl, dst_db_hndl;
 
+ cmgd_get_realtime(&sessn->prof_cmt_apply.start);
+ g_prof_cmt_apply = &sessn->prof_cmt_apply;
+ sessn->prof_cmt_apply.commit_cnt++;
  /*
  * Get the source DB handle.
  */
@@ -1463,7 +1485,6 @@ cmgd_frntnd_client_adapter_t *cmgd_frntnd_create_adapter(
 
  /* Make client socket non-blocking. */
  set_nonblocking(adptr->conn_fd);
-
  return adptr;
 }
 
@@ -1544,7 +1565,68 @@ int cmgd_frntnd_send_data_notify(
  return 0;
 }
 
-void cmgd_frntnd_adapter_status_write(struct vty *vty)
+static void cmgd_frntnd_adapter_status_detail(struct vty *vty,
+ cmgd_frntnd_sessn_ctxt_t *sessn)
+{
+ char buf[100] = {0};
+
+ if (sessn->prof_cmt_apply.commit_cnt > 0) {
+ vty_out(vty, " Num-Commits: \t\t%lu\n",
+ sessn->prof_cmt_apply.commit_cnt);
+ vty_out(vty, " Max-Commit-Duration: \t\t%zu uSecs\n",
+ sessn->prof_cmt_apply.max_tm);
+ vty_out(vty, " Max-Commit-Batch-Size: \t\t%lu\n",
+ sessn->prof_cmt_apply.max_batch_cnt);
+ vty_out(vty, " Min-Commit-Duration: \t\t%zu uSecs\n",
+ sessn->prof_cmt_apply.min_tm);
+ vty_out(vty, " Min-Commit-Batch-Size: \t\t%lu\n",
+ sessn->prof_cmt_apply.min_batch_cnt);
+ vty_out(vty, " Last-Commit-Duration: \t\t%zu uSecs\n",
+ sessn->prof_cmt_apply.last_exec_tm);
+ vty_out(vty, " Last-Commit-Batch-Size: \t%lu\n",
+ sessn->prof_cmt_apply.last_batch_cnt);
+ vty_out(vty, " Last-Commit-Details:\n");
+
+ vty_out(vty, " Commit Start: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.start,
+ buf, sizeof(buf)));
+ vty_out(vty, " Config-Validate Start: \t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.validate_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Prep-Config Start: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.prep_cfg_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Trxn-Create Start: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.trxn_create_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Send-Config Start: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.send_cfg_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Apply-Config Start: \t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.apply_cfg_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Apply-Config End: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.apply_cfg_nd,
+ buf, sizeof(buf)));
+ vty_out(vty, " Trxn-Del Start: \t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.trxn_del_st,
+ buf, sizeof(buf)));
+ vty_out(vty, " Commit End: \t\t\t%s\n",
+ cmgd_realtime_to_string(
+ &sessn->prof_cmt_apply.end,
+ buf, sizeof(buf)));
+ }
+}
+
+void cmgd_frntnd_adapter_status_write(struct vty *vty, bool detail)
 {
  cmgd_frntnd_client_adapter_t *adptr;
  cmgd_frntnd_sessn_ctxt_t *sessn;
@@ -1572,6 +1654,9 @@ void cmgd_frntnd_adapter_status_write(struct vty *vty)
  "Implicit" : "Explicit");
  }
  }
+
+ if (detail)
+ cmgd_frntnd_adapter_status_detail(vty, sessn);
  }
  vty_out(vty, " Total: %d\n",
  (int) cmgd_frntnd_sessn_list_count(&adptr->frntnd_sessns));

cmgd/cmgd_frntnd_adapter.h

@@ -102,6 +102,6 @@ extern int cmgd_frntnd_send_get_data_reply(cmgd_session_id_t session_id,
 extern int cmgd_frntnd_send_data_notify(
  cmgd_database_id_t db_id, cmgd_yang_data_t *data_resp[], int num_data);
 
-extern void cmgd_frntnd_adapter_status_write(struct vty *vty);
+extern void cmgd_frntnd_adapter_status_write(struct vty *vty, bool detail);
 
 #endif /* _FRR_CMGD_FRNTND_ADAPTER_H_ */

cmgd/cmgd_trxn.c

@@ -976,6 +976,7 @@ static int cmgd_trxn_create_config_batches(cmgd_trxn_req_t *trxn_req,
  }
  }
 
+ g_prof_cmt_apply->last_batch_cnt = num_chgs;
  if (!num_chgs) {
  (void) cmgd_trxn_send_commit_cfg_reply(
  trxn_req->trxn, false, "No changes found to commit!");
@@ -1068,6 +1069,7 @@ static int cmgd_trxn_prepare_config(cmgd_trxn_ctxt_t *trxn)
  }
 
 #ifdef CMGD_LOCAL_VALIDATIONS_ENABLED
+ cmgd_get_realtime(&g_prof_cmt_apply->validate_st);
  /*
  * Perform application level validations locally on the CMGD 
  * process by calling application specific validation routines
@@ -1408,15 +1410,18 @@ static int cmgd_trxn_process_commit_cfg(struct thread *thread)
  cmtcfg_req = &trxn->commit_cfg_req->req.commit_cfg;
  switch (cmtcfg_req->curr_phase) {
  case CMGD_COMMIT_PHASE_PREPARE_CFG:
+ cmgd_get_realtime(&g_prof_cmt_apply->prep_cfg_st);
  cmgd_trxn_prepare_config(trxn);
  break;
  case CMGD_COMMIT_PHASE_TRXN_CREATE:
+ cmgd_get_realtime(&g_prof_cmt_apply->trxn_create_st);
  /*
  * Send TRXN_CREATE_REQ to all Backend now.
  */
  cmgd_trxn_send_bcknd_trxn_create(trxn);
  break;
  case CMGD_COMMIT_PHASE_SEND_CFG:
+ cmgd_get_realtime(&g_prof_cmt_apply->send_cfg_st);
  /*
  * All CFGDATA_CREATE_REQ should have been sent to Backend by now.
  */
@@ -1432,6 +1437,7 @@ static int cmgd_trxn_process_commit_cfg(struct thread *thread)
  break;
 #ifndef CMGD_LOCAL_VALIDATIONS_ENABLED
  case CMGD_COMMIT_PHASE_VALIDATE_CFG:
+ cmgd_get_realtime(&g_prof_cmt_apply->validate_st);
  /*
  * We should have received successful CFFDATA_CREATE_REPLY from all
  * concerned Backend Clients by now. Send out the CFG_VALIDATE_REQs
@@ -1441,6 +1447,7 @@ static int cmgd_trxn_process_commit_cfg(struct thread *thread)
  break;
 #endif /* ifndef CMGD_LOCAL_VALIDATIONS_ENABLED */
  case CMGD_COMMIT_PHASE_APPLY_CFG:
+ cmgd_get_realtime(&g_prof_cmt_apply->apply_cfg_st);
  /*
  * We should have received successful CFG_VALIDATE_REPLY from all
  * concerned Backend Clients by now. Send out the CFG_APPLY_REQs
@@ -1449,6 +1456,7 @@ static int cmgd_trxn_process_commit_cfg(struct thread *thread)
  cmgd_trxn_send_bcknd_cfg_apply(trxn);
  break;
  case CMGD_COMMIT_PHASE_TRXN_DELETE:
+ cmgd_get_realtime(&g_prof_cmt_apply->trxn_del_st);
  /*
  * We would have sent TRXN_DELETE_REQ to all backend by now.
  * Send a successful CONFIG_COMMIT_REPLY back to front-end.

cmgd/cmgd_vty.c

@@ -179,7 +179,20 @@ DEFPY(show_cmgd_frntnd_adapter,
  CMGD_FRNTND_ADPTR_STR
  "Display all Frontend Adapters\n")
 {
- cmgd_frntnd_adapter_status_write(vty);
+ cmgd_frntnd_adapter_status_write(vty, false);
+
+ return CMD_SUCCESS;
+}
+
+DEFPY(show_cmgd_frntnd_adapter_detail,
+ show_cmgd_frntnd_adapter_detail_cmd,
+ "show cmgd frontend-adapter all detail",
+ SHOW_STR
+ CMGD_STR
+ CMGD_FRNTND_ADPTR_STR
+ "Display all Frontend Adapters\n")
+{
+ cmgd_frntnd_adapter_status_write(vty, true);
 
  return CMD_SUCCESS;
 }
@@ -451,6 +464,7 @@ void cmgd_vty_init(void)
  install_element(VIEW_NODE, &show_cmgd_bcknd_adapter_cmd);
  install_element(VIEW_NODE, &show_cmgd_bcknd_xpath_reg_cmd);
  install_element(VIEW_NODE, &show_cmgd_frntnd_adapter_cmd);
+ install_element(VIEW_NODE, &show_cmgd_frntnd_adapter_detail_cmd);
  install_element(VIEW_NODE, &show_cmgd_trxn_cmd);
  install_element(VIEW_NODE, &show_cmgd_db_all_cmd);
  install_element(VIEW_NODE, &show_cmgd_db_runn_cmd);

lib/thread.c

@@ -1734,7 +1734,7 @@ struct thread *thread_fetch(struct thread_master *m, struct thread *fetch)
  return fetch;
 }
 
-static unsigned long timeval_elapsed(struct timeval a, struct timeval b)
+unsigned long timeval_elapsed(struct timeval a, struct timeval b)
 {
  return (((a.tv_sec - b.tv_sec) * TIMER_SECOND_MICRO)
  + (a.tv_usec - b.tv_usec));

lib/thread.h

@@ -264,6 +264,7 @@ extern char *thread_timer_to_hhmmss(char *buf, int buf_size,
 
 /* Debug signal mask */
 void debug_signals(const sigset_t *sigs);
+unsigned long timeval_elapsed(struct timeval a, struct timeval b);
 
 #ifdef __cplusplus
 }