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   _ (FREE, SM, 1, "session free")                                             \
  32   _ (IO_EVT_COUNTS, COUNTS_EVT_DBG, 1, "io evt counts")                       \
  33   _ (COUNTS, COUNTS_EVT_DBG, 1, "ctrl evt counts")
  34
  35 typedef enum _session_evt_dbg
  36 {
  37 #define _(sym, grp, lvl, str) SESSION_EVT_##sym,
  38   foreach_session_dbg_evt
  39 #undef _
  40 } session_evt_dbg_e;
  41
  42 typedef enum session_evt_lvl_
  43 {
  44 #define _(sym, grp, lvl, str) SESSION_EVT_##sym##_LVL = lvl,
  45   foreach_session_dbg_evt
  46 #undef _
  47 } session_evt_lvl_e;
  48
  49 #define foreach_session_evt_grp                                               \
  50   _ (DEQ_EVTS, "dequeue/enqueue events")                                      \
  51   _ (DISPATCH_DBG, "dispatch")                                                \
  52   _ (EVT_POLL_DBG, "event poll")                                              \
  53   _ (SM, "state machine")                                                     \
  54   _ (CLOCKS_EVT_DBG, "clocks events")                                         \
  55   _ (COUNTS_EVT_DBG, "counts events")
  56
  57 typedef enum session_evt_grp_
  58 {
  59 #define _(sym, str) SESSION_EVT_GRP_##sym,
  60   foreach_session_evt_grp
  61 #undef _
  62     SESSION_EVT_N_GRP
  63 } session_evt_grp_e;
  64
  65 typedef enum session_evt_to_grp_
  66 {
  67 #define _(sym, grp, lvl, str) SESSION_EVT_##sym##_GRP = SESSION_EVT_GRP_##grp,
  68   foreach_session_dbg_evt
  69 #undef _
  70 } session_evt_to_grp_e;
  71
  72 #define foreach_session_events                                  \
  73 _(CLK_UPDATE_TIME, 1, 1, "Time Update Time")                    \
  74 _(CLK_MQ_DEQ, 1, 1, "Time MQ Dequeue")                          \
  75 _(CLK_CTRL_EVTS, 1, 1, "Time Ctrl Events")                      \
  76 _(CLK_NEW_IO_EVTS, 1, 1, "Time New IO Events")                  \
  77 _(CLK_OLD_IO_EVTS, 1, 1, "Time Old IO Events")                  \
  78 _(CLK_TOTAL, 1, 1, "Time Total in Node")                        \
  79 _(CLK_START, 1, 1, "Time Since Last Reset")                     \
  80                                                                 \
  81 _(CNT_MQ_EVTS, 1, 0, "# of MQ Events Processed" )               \
  82 _(CNT_CTRL_EVTS, 1, 0, "# of Ctrl Events Processed" )           \
  83 _(CNT_NEW_EVTS, 1, 0, "# of New Events Processed" )             \
  84 _(CNT_OLD_EVTS, 1, 0, "# of Old Events Processed" )             \
  85 _(CNT_IO_EVTS, 1, 0, "# of Events Processed" )                  \
  86 _(CNT_NODE_CALL, 1, 0, "# of Node Calls")                       \
  87                                                                 \
  88 _(BASE_OFFSET_IO_EVTS, 0, 0, "NULL")                            \
  89 _(SESSION_IO_EVT_RX, 1, 0, "# of IO Event RX")                  \
  90 _(SESSION_IO_EVT_TX,  1, 0, "# of IO Event TX")                 \
  91 _(SESSION_IO_EVT_TX_FLUSH, 1, 0, "# of IO Event TX Flush")      \
  92 _(SESSION_IO_EVT_BUILTIN_RX, 1, 0, "# of IO Event BuiltIn RX")  \
  93 _(SESSION_IO_EVT_BUILTIN_TX, 1, 0, "# of IO Event BuiltIn TX")  \
  94
  95 typedef enum
  96 {
  97 #define _(sym, disp, type, str) SESS_Q_##sym,
  98   foreach_session_events
  99 #undef _
 100   SESS_Q_MAX_EVT_TYPES
 101 } sess_q_node_events_types_t;
 102
 103 typedef struct session_dbg_counter_
 104 {
 105   union
 106   {
 107     f64 f64;
 108     u64 u64;
 109   };
 110 } session_dbg_counter_t;
 111
 112 typedef struct session_dbg_evts_t
 113 {
 114   CLIB_CACHE_LINE_ALIGN_MARK (cacheline0);
 115   f64 last_time;
 116   f64 start_time;
 117   u64 prev_io;
 118   session_dbg_counter_t counters[SESS_Q_MAX_EVT_TYPES];
 119 } session_dbg_evts_t;
 120
 121 typedef struct session_dbg_main_
 122 {
 123   session_dbg_evts_t *wrk;
 124   u8 grp_dbg_lvl[SESSION_EVT_N_GRP];
 125 } session_dbg_main_t;
 126
 127 extern session_dbg_main_t session_dbg_main;
 128
 129 #if defined VPP_SESSION_DEBUG && (TRANSPORT_DEBUG > 0)
 130 #define SESSION_DEBUG          (1)
 131 #define SESSION_DEQ_EVTS       (1)
 132 #define SESSION_DISPATCH_DBG   (1)
 133 #define SESSION_EVT_POLL_DBG   (1)
 134 #define SESSION_SM             (1)
 135 #define SESSION_CLOCKS_EVT_DBG (1)
 136 #define SESSION_COUNTS_EVT_DBG (1)
 137 #else
 138 #define SESSION_DEBUG          (0)
 139 #define SESSION_DEQ_EVTS       (0)
 140 #define SESSION_DISPATCH_DBG   (0)
 141 #define SESSION_EVT_POLL_DBG   (0)
 142 #define SESSION_SM             (0)
 143 #define SESSION_CLOCKS_EVT_DBG (0)
 144 #define SESSION_COUNTS_EVT_DBG (0)
 145 #endif
 146
 147 #if SESSION_DEBUG
 148
 149 #define SESSION_DBG(_fmt, _args...) clib_warning (_fmt, ##_args)
 150
 151 #define DEC_SESSION_ETD(_s, _e, _size)                                  \
 152   struct                                                                \
 153   {                                                                     \
 154     u32 data[_size];                                                    \
 155   } * ed;                                                               \
 156   transport_connection_t *_tc = session_get_transport (_s);             \
 157   ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main,                    \
 158                         _e, _tc->elog_track)
 159
 160 #define DEC_SESSION_ED(_e, _size)                                       \
 161   struct                                                                \
 162   {                                                                     \
 163     u32 data[_size];                                                    \
 164   } * ed;                                                               \
 165   ed = ELOG_DATA (&vlib_global_main.elog_main, _e)
 166
 167 #if SESSION_SM
 168 #define SESSION_EVT_FREE_HANDLER(_s)                                          \
 169   {                                                                           \
 170     ELOG_TYPE_DECLARE (_e) = {                                                \
 171       .format = "free: idx %u",                                               \
 172       .format_args = "i4",                                                    \
 173     };                                                                        \
 174     DEC_SESSION_ED (_e, 1);                                                   \
 175     ed->data[0] = _s->session_index;                                          \
 176   }
 177 #else
 178 #define SESSION_EVT_FREE_HANDLER(_s)
 179 #endif
 180
 181 #if SESSION_DEQ_EVTS
 182 #define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)          \
 183 {                                                                       \
 184   ELOG_TYPE_DECLARE (_e) =                                              \
 185   {                                                                     \
 186     .format = "deq: now %u max %d evt %u ts %d",                        \
 187     .format_args = "i4i4i4i4",                                          \
 188   };                                                                    \
 189   DEC_SESSION_ETD(_s, _e, 4);                                           \
 190   ed->data[0] = _now;                                                   \
 191   ed->data[1] = _max;                                                   \
 192   ed->data[2] = _has_evt;                                               \
 193   ed->data[3] = _ts * 1000000.0;                                        \
 194 }
 195
 196 #define SESSION_EVT_ENQ_HANDLER(_s, _len)                               \
 197 {                                                                       \
 198   ELOG_TYPE_DECLARE (_e) =                                              \
 199   {                                                                     \
 200     .format = "enq: length %d",                                         \
 201     .format_args = "i4",                                                \
 202   };                                                                    \
 203   DEC_SESSION_ETD(_s, _e, 1);                                           \
 204   ed->data[0] = _len;                                                   \
 205 }
 206 #else
 207 #define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)
 208 #define SESSION_EVT_ENQ_HANDLER(_s, _body)
 209 #endif /* SESSION_DEQ_NODE_EVTS */
 210
 211 #if SESSION_DISPATCH_DBG
 212 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)             \
 213 {                                                                       \
 214   ELOG_TYPE_DECLARE (_e) =                                              \
 215   {                                                                     \
 216     .format = "dispatch: %s pkts %u re-entry: %u dispatch %u",          \
 217     .format_args = "t4i4i4i4",                                          \
 218     .n_enum_strings = 2,                                                \
 219     .enum_strings = {                                                   \
 220       "start",                                                          \
 221       "end",                                                            \
 222     },                                                                  \
 223   };                                                                    \
 224   DEC_SESSION_ED(_e, 4);                                                \
 225   ed->data[0] = _node_evt;                                              \
 226   ed->data[1] = _ntx;                                                   \
 227   ed->data[2] = (_wrk->last_vlib_time - _wrk->last_event_poll)          \
 228                 * 1000000.0;                                            \
 229   ed->data[3] = (vlib_time_now (_wrk->vm) - _wrk->last_vlib_time)       \
 230                 * 1000000.0;                                            \
 231 }
 232 #else
 233 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)
 234 #endif /* SESSION_DISPATCH_DBG */
 235
 236 #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
 237 #define SESSION_EVT_POLL_GAP(_wrk)                                      \
 238 {                                                                       \
 239   ELOG_TYPE_DECLARE (_e) =                                              \
 240   {                                                                     \
 241     .format = "nixon-gap: %d us",                                       \
 242     .format_args = "i4",                                                \
 243   };                                                                    \
 244   DEC_SESSION_ED(_e, 1);                                                \
 245   ed->data[0] = (u32) ((_wrk->last_vlib_time - _wrk->last_event_poll)   \
 246                         *1000000.0);                                    \
 247 }
 248 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk)                        \
 249 {                                                                       \
 250   if (PREDICT_TRUE (_wrk->last_event_poll != 0.0))                      \
 251     if (_wrk->last_vlib_time > _wrk->last_event_poll + 500e-6)          \
 252       SESSION_EVT_POLL_GAP(_wrk);                                       \
 253   _wrk->last_event_poll = _wrk->last_vlib_time;                         \
 254 }
 255
 256 #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk)                    \
 257 {                                                                       \
 258   f64 diff = vlib_time_now (vlib_get_main ()) - _wrk->last_event_poll;  \
 259   if (diff > 5e-2)                                                      \
 260     {                                                                   \
 261       ELOG_TYPE_DECLARE (_e) =                                          \
 262       {                                                                 \
 263         .format = "dispatch time: %d us",                               \
 264         .format_args = "i4",                                            \
 265       };                                                                \
 266       DEC_SESSION_ED(_e, 1);                                            \
 267       ed->data[0] = diff *1000000.0;                                    \
 268     }                                                                   \
 269 }
 270
 271 #else
 272 #define SESSION_EVT_POLL_GAP(_wrk)
 273 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk)
 274 #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk)
 275 #define SESSION_EVT_POLL_CLOCKS_TIME_HANDLER(_wrk)
 276
 277 #endif /* SESSION_EVT_POLL_DBG */
 278
 279 #if SESSION_CLOCKS_EVT_DBG
 280
 281 #define SESSION_EVT_DSP_CNTRS_UPDATE_TIME_HANDLER(_wrk, _diff, _args...)      \
 282   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];    \
 283   sde->counters[SESS_Q_CLK_UPDATE_TIME].f64 += _diff;
 284
 285 #define SESSION_EVT_DSP_CNTRS_MQ_DEQ_HANDLER(_wrk, _diff, _cnt, _args...)     \
 286   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];    \
 287   sde->counters[SESS_Q_CNT_MQ_EVTS].u64 += _cnt;                              \
 288   sde->counters[SESS_Q_CLK_MQ_DEQ].f64 += _diff;
 289
 290 #define SESSION_EVT_DSP_CNTRS_CTRL_EVTS_HANDLER(_wrk, _diff, _args...)          \
 291   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 292   sde->counters[SESS_Q_CLK_CTRL_EVTS].f64 += _diff;                             \
 293   sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64;                         \
 294
 295 #define SESSION_EVT_DSP_CNTRS_NEW_IO_EVTS_HANDLER(_wrk, _diff, _args...)        \
 296   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 297   sde->counters[SESS_Q_CLK_NEW_IO_EVTS].f64 += _diff;                           \
 298   sde->counters[SESS_Q_CNT_NEW_EVTS].u64 +=                                     \
 299     sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io;                       \
 300   sde->prev_io = sde->counters[SESS_Q_CNT_IO_EVTS].u64;                         \
 301
 302 #define SESSION_EVT_DSP_CNTRS_OLD_IO_EVTS_HANDLER(_wrk, _diff, _args...)        \
 303   session_dbg_evts_t *sde = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 304   sde->counters[SESS_Q_CLK_OLD_IO_EVTS].f64 += _diff;                           \
 305   sde->counters[SESS_Q_CNT_OLD_EVTS].u64 +=                                     \
 306     sde->counters[SESS_Q_CNT_IO_EVTS].u64 - sde->prev_io;                       \
 307
 308 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)                \
 309 {                                                                               \
 310   f64 time_now = vlib_time_now (_wrk->vm), diff;                                \
 311   diff = time_now - session_dbg_main.wrk[_wrk->vm->thread_index].last_time;     \
 312   session_dbg_main.wrk[_wrk->vm->thread_index].last_time = time_now;            \
 313   CC(CC(SESSION_EVT_DSP_CNTRS_,_disp_evt),_HANDLER)(wrk, diff, _args);          \
 314 }
 315 #else
 316 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)
 317 #endif /*SESSION_CLOCKS_EVT_DBG */
 318
 319 #if SESSION_COUNTS_EVT_DBG
 320 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)       \
 321 {                                                               \
 322   session_dbg_main.wrk[_wrk->vm->thread_index].                 \
 323         counters[SESS_Q_##_node_evt].u64 += _cnt;               \
 324 }
 325
 326 #define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)              \
 327   {                                                                           \
 328     u8 type = SESS_Q_BASE_OFFSET_IO_EVTS + _node_evt + 1;                     \
 329     session_dbg_evts_t *sde;                                                  \
 330     sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                      \
 331     sde->counters[type].u64 += _cnt;                                          \
 332     sde->counters[SESS_Q_CNT_IO_EVTS].u64 += _cnt;                            \
 333   }
 334 #else
 335 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
 336 #define SESSION_EVT_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk)
 337 #endif /*SESSION_COUNTS_EVT_DBG */
 338
 339
 340 #define SESSION_EVT_DISPATCH_START_HANDLER(_wrk)                        \
 341 {                                                                       \
 342   session_dbg_evts_t *sde;                                              \
 343   sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                  \
 344   if (SESSION_DEQ_EVTS > 1)                                             \
 345     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0);                          \
 346   SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk);                             \
 347   sde->counters[SESS_Q_##CNT_NODE_CALL].u64 +=1;                        \
 348   sde->last_time = vlib_time_now (_wrk->vm);                            \
 349 }
 350
 351 #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx)                    \
 352 {                                                                       \
 353   f64 now = vlib_time_now (_wrk->vm);                                   \
 354   session_dbg_evts_t *sde;                                              \
 355   sde = &session_dbg_main.wrk[_wrk->vm->thread_index];                  \
 356   if (_ntx)                                                             \
 357     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx);                       \
 358   SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk);                         \
 359   _wrk->last_event_poll = now;                                          \
 360   sde->counters[SESS_Q_CLK_TOTAL].f64 += now - _wrk->last_vlib_time;    \
 361   sde->counters[SESS_Q_CLK_START].f64 = now - sde->start_time;          \
 362 }
 363
 364 #define CONCAT_HELPER(_a, _b) _a##_b
 365 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
 366 #define session_evt_lvl(_evt) CC (_evt, _LVL)
 367 #define session_evt_grp(_evt) CC (_evt, _GRP)
 368 #define session_evt_grp_dbg_lvl(_evt)                                         \
 369   session_dbg_main.grp_dbg_lvl[session_evt_grp (_evt)]
 370 #define SESSION_EVT(_evt, _args...)                                           \
 371   if (PREDICT_FALSE (session_evt_grp_dbg_lvl (_evt) >=                        \
 372                      session_evt_lvl (_evt)))                                 \
 373   CC (_evt, _HANDLER) (_args)
 374 #else
 375 #define SESSION_EVT(_evt, _args...)
 376 #define SESSION_DBG(_fmt, _args...)
 377 #endif /* SESSION_DEBUG */
 378
 379 void session_debug_init (void);
 380
 381 #endif /* SRC_VNET_SESSION_SESSION_DEBUG_H_ */
 382 /*
 383  * fd.io coding-style-patch-verification: ON
 384  *
 385  * Local Variables:
 386  * eval: (c-set-style "gnu")
 387  * End:
 388  */