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