src/vnet/session/session_debug.h

   1 /*
   2  * Copyright (c) 2017-2019 Cisco and/or its affiliates.
   3  * Licensed under the Apache License, Version 2.0 (the "License");
   4  * you may not use this file except in compliance with the License.
   5  * You may obtain a copy of the License at:
   6  *
   7  *     http://www.apache.org/licenses/LICENSE-2.0
   8  *
   9  * Unless required by applicable law or agreed to in writing, software
  10  * distributed under the License is distributed on an "AS IS" BASIS,
  11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12  * See the License for the specific language governing permissions and
  13  * limitations under the License.
  14  */
  15 #ifndef SRC_VNET_SESSION_SESSION_DEBUG_H_
  16 #define SRC_VNET_SESSION_SESSION_DEBUG_H_
  17
  18 #include <vnet/session/transport.h>
  19 #include <vlib/vlib.h>
  20 #include <vpp/vnet/config.h>
  21
  22 #define foreach_session_dbg_evt                                               \
  23   _ (ENQ, DEQ_EVTS, 1, "enqueue")                                             \
  24   _ (DEQ, DEQ_EVTS, 1, "dequeue")                                             \
  25   _ (DEQ_NODE, DISPATCH_DBG, 1, "dequeue")                                    \
  26   _ (POLL_GAP_TRACK, EVT_POLL_DBG, 1, "poll gap track")                       \
  27   _ (POLL_DISPATCH_TIME, EVT_POLL_DBG, 1, "dispatch time")                    \
  28   _ (DISPATCH_START, CLOCKS_EVT_DBG, 1, "dispatch start")                     \
  29   _ (DISPATCH_END, CLOCKS_EVT_DBG, 1, "dispatch end")                         \
  30   _ (DSP_CNTRS, CLOCKS_EVT_DBG, 1, "dispatch counters")                       \
  31   _ (STATE_CHANGE, SM, 1, "session state change")                             \
  32   _ (FREE, SM, 1, "session free")                                             \
  33   _ (IO_EVT_COUNTS, COUNTS_EVT_DBG, 1, "io evt counts")                       \
  34   _ (COUNTS, COUNTS_EVT_DBG, 1, "ctrl evt counts")
  35
  36 typedef enum _session_evt_dbg
  37 {
  38 #define _(sym, grp, lvl, str) SESSION_EVT_##sym,
  39   foreach_session_dbg_evt
  40 #undef _
  41 } session_evt_dbg_e;
  42
  43 typedef enum session_evt_lvl_
  44 {
  45 #define _(sym, grp, lvl, str) SESSION_EVT_##sym##_LVL = lvl,
  46   foreach_session_dbg_evt
  47 #undef _
  48 } session_evt_lvl_e;
  49
  50 #define foreach_session_evt_grp                                               \
  51   _ (DEQ_EVTS, "dequeue/enqueue events")                                      \
  52   _ (DISPATCH_DBG, "dispatch")                                                \
  53   _ (EVT_POLL_DBG, "event poll")                                              \
  54   _ (SM, "state machine")                                                     \
  55   _ (CLOCKS_EVT_DBG, "clocks events")                                         \
  56   _ (COUNTS_EVT_DBG, "counts events")
  57
  58 typedef enum session_evt_grp_
  59 {
  60 #define _(sym, str) SESSION_EVT_GRP_##sym,
  61   foreach_session_evt_grp
  62 #undef _
  63     SESSION_EVT_N_GRP
  64 } session_evt_grp_e;
  65
  66 typedef enum session_evt_to_grp_
  67 {
  68 #define _(sym, grp, lvl, str) SESSION_EVT_##sym##_GRP = SESSION_EVT_GRP_##grp,
  69   foreach_session_dbg_evt
  70 #undef _
  71 } session_evt_to_grp_e;
  72
  73 #define foreach_session_events                                                \
  74   _ (CLK_UPDATE_TIME, 1, 1, "Time Update Time")                               \
  75   _ (CLK_MQ_DEQ, 1, 1, "Time MQ Dequeue")                                     \
  76   _ (CLK_CTRL_EVTS, 1, 1, "Time Ctrl Events")                                 \
  77   _ (CLK_NEW_IO_EVTS, 1, 1, "Time New IO Events")                             \
  78   _ (CLK_OLD_IO_EVTS, 1, 1, "Time Old IO Events")                             \
  79   _ (CLK_TOTAL, 1, 1, "Time Total in Node")                                   \
  80   _ (CLK_START, 1, 1, "Time Since Last Reset")                                \
  81                                                                               \
  82   _ (CNT_MQ_EVTS, 1, 0, "# of MQ Events Processed")                           \
  83   _ (CNT_CTRL_EVTS, 1, 0, "# of Ctrl Events Processed")                       \
  84   _ (CNT_NEW_EVTS, 1, 0, "# of New Events Processed")                         \
  85   _ (CNT_OLD_EVTS, 1, 0, "# of Old Events Processed")                         \
  86   _ (CNT_IO_EVTS, 1, 0, "# of Events Processed")                              \
  87   _ (CNT_NODE_CALL, 1, 0, "# of Node Calls")                                  \
  88                                                                               \
  89   _ (BASE_OFFSET_IO_EVTS, 0, 0, "NULL")                                       \
  90   _ (SESSION_IO_EVT_RX, 1, 0, "# of IO Event RX")                             \
  91   _ (SESSION_IO_EVT_TX, 1, 0, "# of IO Event TX")                             \
  92   _ (SESSION_IO_EVT_TX_FLUSH, 1, 0, "# of IO Event TX Flush")                 \
  93   _ (SESSION_IO_EVT_BUILTIN_RX, 1, 0, "# of IO Event BuiltIn RX")             \
  94   _ (SESSION_IO_EVT_TX_MAIN, 1, 0, "# of IO Event TX Main")
  95
  96 typedef enum
  97 {
  98 #define _(sym, disp, type, str) SESS_Q_##sym,
  99   foreach_session_events
 100 #undef _
 101   SESS_Q_MAX_EVT_TYPES
 102 } sess_q_node_events_types_t;
 103
 104 typedef struct session_dbg_counter_
 105 {
 106   union
 107   {
 108     f64 f64;
 109     u64 u64;
 110   };
 111 } session_dbg_counter_t;
 112
 113 typedef struct session_dbg_evts_t
 114 {
 115   CLIB_CACHE_LINE_ALIGN_MARK (cacheline0);
 116   f64 last_time;
 117   f64 start_time;
 118   u64 prev_io;
 119   session_dbg_counter_t counters[SESS_Q_MAX_EVT_TYPES];
 120 } session_dbg_evts_t;
 121
 122 typedef struct session_dbg_main_
 123 {
 124   session_dbg_evts_t *wrk;
 125   u8 grp_dbg_lvl[SESSION_EVT_N_GRP];
 126 } session_dbg_main_t;
 127
 128 extern session_dbg_main_t session_dbg_main;
 129
 130 #if defined VPP_SESSION_DEBUG && (TRANSPORT_DEBUG > 0)
 131 #define SESSION_DEBUG          (1)
 132 #define SESSION_DEQ_EVTS       (1)
 133 #define SESSION_DISPATCH_DBG   (1)
 134 #define SESSION_EVT_POLL_DBG   (1)
 135 #define SESSION_SM             (1)
 136 #define SESSION_CLOCKS_EVT_DBG (1)
 137 #define SESSION_COUNTS_EVT_DBG (1)
 138 #else
 139 #define SESSION_DEBUG          (0)
 140 #define SESSION_DEQ_EVTS       (0)
 141 #define SESSION_DISPATCH_DBG   (0)
 142 #define SESSION_EVT_POLL_DBG   (0)
 143 #define SESSION_SM             (0)
 144 #define SESSION_CLOCKS_EVT_DBG (0)
 145 #define SESSION_COUNTS_EVT_DBG (0)
 146 #endif
 147
 148 #if SESSION_DEBUG
 149
 150 #define SESSION_DBG(_fmt, _args...) clib_warning (_fmt, ##_args)
 151
 152 #define DEC_SESSION_ETD(_s, _e, _size)                                  \
 153   struct                                                                \
 154   {                                                                     \
 155     u32 data[_size];                                                    \
 156   } * ed;                                                               \
 157   transport_connection_t *_tc = session_get_transport (_s);             \
 158   ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main,                    \
 159                         _e, _tc->elog_track)
 160
 161 #define DEC_SESSION_ED(_e, _size)                                       \
 162   struct                                                                \
 163   {                                                                     \
 164     u32 data[_size];                                                    \
 165   } * ed;                                                               \
 166   ed = ELOG_DATA (&vlib_global_main.elog_main, _e)
 167
 168 #if SESSION_SM
 169 #define SESSION_EVT_STATE_CHANGE_HANDLER(_s)                                  \
 170   {                                                                           \
 171     ELOG_TYPE_DECLARE (_e) = {                                                \
 172       .format = "%s: idx %u",                                                 \
 173       .format_args = "t4i4",                                                  \
 174       .n_enum_strings = 12,                                                   \
 175       .enum_strings = {                                                       \
 176                        "created",                                             \
 177                        "listening",                                           \
 178                        "connecting",                                          \
 179                        "accepting",                                           \
 180                        "ready",                                               \
 181                        "opened",                                              \
 182                        "transport closing",                                   \
 183                        "closing",                                             \
 184                        "app closed",                                          \
 185                        "transport closed",                                    \
 186                        "closed",                                              \
 187                        "transport deleted",                                   \
 188                        },                                                     \
 189     };                                   \
 190     DEC_SESSION_ETD (_s, _e, 2);                                              \
 191     ed->data[0] = _s->session_state;                                          \
 192     ed->data[1] = _s->session_index;                                          \
 193   }
 194
 195 #define SESSION_EVT_FREE_HANDLER(_s)                                          \
 196   {                                                                           \
 197     ELOG_TYPE_DECLARE (_e) = {                                                \
 198       .format = "free: idx %u",                                               \
 199       .format_args = "i4",                                                    \
 200     };                                                                        \
 201     DEC_SESSION_ED (_e, 1);                                                   \
 202     ed->data[0] = _s->session_index;                                          \
 203   }
 204 #else
 205 #define SESSION_EVT_STATE_CHANGE_HANDLER(_s)
 206 #define SESSION_EVT_FREE_HANDLER(_s)
 207 #endif
 208
 209 #if SESSION_DEQ_EVTS
 210 #define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)          \
 211 {                                                                       \
 212   ELOG_TYPE_DECLARE (_e) =                                              \
 213   {                                                                     \
 214     .format = "deq: now %u max %d evt %u ts %d",                        \
 215     .format_args = "i4i4i4i4",                                          \
 216   };                                                                    \
 217   DEC_SESSION_ETD(_s, _e, 4);                                           \
 218   ed->data[0] = _now;                                                   \
 219   ed->data[1] = _max;                                                   \
 220   ed->data[2] = _has_evt;                                               \
 221   ed->data[3] = _ts * 1000000.0;                                        \
 222 }
 223
 224 #define SESSION_EVT_ENQ_HANDLER(_s, _len)                               \
 225 {                                                                       \
 226   ELOG_TYPE_DECLARE (_e) =                                              \
 227   {                                                                     \
 228     .format = "enq: length %d",                                         \
 229     .format_args = "i4",                                                \
 230   };                                                                    \
 231   DEC_SESSION_ETD(_s, _e, 1);                                           \
 232   ed->data[0] = _len;                                                   \
 233 }
 234 #else
 235 #define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)
 236 #define SESSION_EVT_ENQ_HANDLER(_s, _body)
 237 #endif /* SESSION_DEQ_NODE_EVTS */
 238
 239 #if SESSION_DISPATCH_DBG
 240 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)             \
 241 {                                                                       \
 242   ELOG_TYPE_DECLARE (_e) =                                              \
 243   {                                                                     \
 244     .format = "dispatch: %s pkts %u re-entry: %u dispatch %u",          \
 245     .format_args = "t4i4i4i4",                                          \
 246     .n_enum_strings = 2,                                                \
 247     .enum_strings = {                                                   \
 248       "start",                                                          \
 249       "end",                                                            \
 250     },                                                                  \
 251   };                                                                    \
 252   DEC_SESSION_ED(_e, 4);                                                \
 253   ed->data[0] = _node_evt;                                              \
 254   ed->data[1] = _ntx;                                                   \
 255   ed->data[2] = (_wrk->last_vlib_time - _wrk->last_event_poll)          \
 256                 * 1000000.0;                                            \
 257   ed->data[3] = (vlib_time_now (_wrk->vm) - _wrk->last_vlib_time)       \
 258                 * 1000000.0;                                            \
 259 }
 260 #else
 261 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)
 262 #endif /* SESSION_DISPATCH_DBG */
 263
 264 #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
 265 #define SESSION_EVT_POLL_GAP(_wrk)                                      \
 266 {                                                                       \
 267   ELOG_TYPE_DECLARE (_e) =                                              \
 268   {                                                                     \
 269     .format = "nixon-gap: %d us",                                       \
 270     .format_args = "i4",                                                \
 271   };                                                                    \
 272   DEC_SESSION_ED(_e, 1);                                                \
 273   ed->data[0] = (u32) ((_wrk->last_vlib_time - _wrk->last_event_poll)   \
 274                         *1000000.0);                                    \
 275 }
 276 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk)                        \
 277 {                                                                       \
 278   if (PREDICT_TRUE (_wrk->last_event_poll != 0.0))                      \
 279     if (_wrk->last_vlib_time > _wrk->last_event_poll + 500e-6)          \
 280       SESSION_EVT_POLL_GAP(_wrk);                                       \
 281   _wrk->last_event_poll = _wrk->last_vlib_time;                         \
 282 }
 283
 284 #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk)                    \
 285 {                                                                       \
 286   f64 diff = vlib_time_now (vlib_get_main ()) - _wrk->last_event_poll;  \
 287   if (diff > 5e-2)                                                      \
 288     {                                                                   \
 289       ELOG_TYPE_DECLARE (_e) =                                          \
 290       {                                                                 \
 291         .format = "dispatch time: %d us",                               \
 292         .format_args = "i4",                                            \
 293       };                                                                \
 294       DEC_SESSION_ED(_e, 1);                                            \
 295       ed->data[0] = diff *1000000.0;                                    \
 296     }                                                                   \
 297 }
 298
 299 #else
 300 #define SESSION_EVT_POLL_GAP(_wrk)
 301 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk)
 302 #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk)
 303 #define SESSION_EVT_POLL_CLOCKS_TIME_HANDLER(_wrk)
 304
 305 #endif /* SESSION_EVT_POLL_DBG */
 306
 307 #if SESSION_CLOCKS_EVT_DBG
 308
 309 #define SESSION_EVT_DSP_CNTRS_UPDATE_TIME_HANDLER(_wrk, _diff, _args...)      \
 310   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];    \
 311   sde->counters[SESS_Q_CLK_UPDATE_TIME].f64 += _diff;
 312
 313 #define SESSION_EVT_DSP_CNTRS_MQ_DEQ_HANDLER(_wrk, _diff, _cnt, _args...)     \
 314   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];    \
 315   sde->counters[SESS_Q_CNT_MQ_EVTS].u64 += _cnt;                              \
 316   sde->counters[SESS_Q_CLK_MQ_DEQ].f64 += _diff;
 317
 318 #define SESSION_EVT_DSP_CNTRS_CTRL_EVTS_HANDLER(_wrk, _diff, _args...)          \
 319   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 320   sde->counters[SESS_Q_CLK_CTRL_EVTS].f64 += _diff;                             \
 321   sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64;                         \
 322
 323 #define SESSION_EVT_DSP_CNTRS_NEW_IO_EVTS_HANDLER(_wrk, _diff, _args...)        \
 324   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 325   sde->counters[SESS_Q_CLK_NEW_IO_EVTS].f64 += _diff;                           \
 326   sde->counters[SESS_Q_CNT_NEW_EVTS].u64 +=                                     \
 327     sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io;                       \
 328   sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64;                         \
 329
 330 #define SESSION_EVT_DSP_CNTRS_OLD_IO_EVTS_HANDLER(_wrk, _diff, _args...)        \
 331   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 332   sde->counters[SESS_Q_CLK_OLD_IO_EVTS].f64 += _diff;                           \
 333   sde->counters[SESS_Q_CNT_OLD_EVTS].u64 +=                                     \
 334     sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io;                       \
 335
 336 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)                \
 337 {                                                                               \
 338   f64 time_now = vlib_time_now (_wrk->vm), diff;                                \
 339   diff = time_now - session_dbg_main.wrk[_wrk->vm->thread_index].last_time;     \
 340   session_dbg_main.wrk[_wrk->vm->thread_index].last_time = time_now;            \
 341   CC(CC(SESSION_EVT_DSP_CNTRS_,_disp_evt),_HANDLER)(wrk, diff, _args);          \
 342 }
 343 #else
 344 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)
 345 #endif /*SESSION_CLOCKS_EVT_DBG */
 346
 347 #if SESSION_COUNTS_EVT_DBG
 348 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)       \
 349 {                                                               \
 350   session_dbg_main.wrk[_wrk->vm->thread_index].                 \
 351         counters[SESS_Q_##_node_evt].u64 += _cnt;               \
 352 }
 353
 354 #define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)              \
 355   {                                                                           \
 356     u8 type = SESS_Q_BASE_OFFSET_IO_EVTS + _node_evt + 1;                     \
 357     session_dbg_evts_t *sde;                                                  \
 358     sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                      \
 359     sde->counters[type].u64 += _cnt;                                          \
 360     sde->counters[SESS_Q_CNT_IO_EVTS].u64 += _cnt;                            \
 361   }
 362 #else
 363 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
 364 #define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
 365 #endif /*SESSION_COUNTS_EVT_DBG */
 366
 367
 368 #define SESSION_EVT_DISPATCH_START_HANDLER(_wrk)                        \
 369 {                                                                       \
 370   session_dbg_evts_t *sde;                                              \
 371   sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                  \
 372   if (SESSION_DEQ_EVTS > 1)                                             \
 373     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0);                          \
 374   SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk);                             \
 375   sde->counters[SESS_Q_##CNT_NODE_CALL].u64 +=1;                        \
 376   sde->last_time = vlib_time_now (_wrk->vm);                            \
 377 }
 378
 379 #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx)                    \
 380 {                                                                       \
 381   f64 now = vlib_time_now (_wrk->vm);                                   \
 382   session_dbg_evts_t *sde;                                              \
 383   sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                  \
 384   if (_ntx)                                                             \
 385     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx);                       \
 386   SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk);                         \
 387   _wrk->last_event_poll = now;                                          \
 388   sde->counters[SESS_Q_CLK_TOTAL].f64 += now - _wrk->last_vlib_time;    \
 389   sde->counters[SESS_Q_CLK_START].f64 = now - sde->start_time;          \
 390 }
 391
 392 #define CONCAT_HELPER(_a, _b) _a##_b
 393 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
 394 #define session_evt_lvl(_evt) CC (_evt, _LVL)
 395 #define session_evt_grp(_evt) CC (_evt, _GRP)
 396 #define session_evt_grp_dbg_lvl(_evt)                                         \
 397   session_dbg_main.grp_dbg_lvl[session_evt_grp (_evt)]
 398 #define SESSION_EVT(_evt, _args...)                                           \
 399   do                                                                          \
 400     {                                                                         \
 401       if (PREDICT_FALSE (session_evt_grp_dbg_lvl (_evt) >=                    \
 402                          session_evt_lvl (_evt)))                             \
 403         CC (_evt, _HANDLER) (_args);                                          \
 404     }                                                                         \
 405   while (0)
 406 #else
 407 #define SESSION_EVT(_evt, _args...)
 408 #define SESSION_DBG(_fmt, _args...)
 409 #endif /* SESSION_DEBUG */
 410
 411 void session_debug_init (void);
 412
 413 #endif /* SRC_VNET_SESSION_SESSION_DEBUG_H_ */
 414 /*
 415  * fd.io coding-style-patch-verification: ON
 416  *
 417  * Local Variables:
 418  * eval: (c-set-style "gnu")
 419  * End:
 420  */