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