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 Session Update Timers")  \
  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 \
  48 _(CNT_MQ_EVTS, 1, 0, "# of MQ Events Processed" )           \
  49 _(CNT_CTRL_EVTS, 1, 0, "# of Cntrl Events Processed" )      \
  50 _(CNT_NEW_EVTS, 1, 0, "# of New Events Processed" )         \
  51 _(CNT_OLD_EVTS, 1, 0, "# of Old Events Processed" )         \
  52 _(CNT_IO_EVTS, 1, 0, "# of Events Processed" )          \
  53 _(NODE_CALL_CNT, 1, 0, "Node call count")                  \
  54 _(NEW_IO_EVTS, 1, 0, "New IO Events")                      \
  55 _(OLD_IO_EVTS, 1, 0, "Old IO Events")                      \
  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
  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   u64 prev_io;
  87   session_dbg_counter_t sess_dbg_evt_type[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(_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 *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 242   sdm->sess_dbg_evt_type[SESS_Q_CLK_UPDATE_TIME].f64 += _diff;                  \
 243
 244 #define SESSION_EVT_DSP_CNTRS_MQ_DEQ_HANDLER(_wrk, _diff, _cnt, _args...)       \
 245   session_dbg_evts_t *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 246   sdm->sess_dbg_evt_type[SESS_Q_CNT_MQ_EVTS].u64 += _cnt;                       \
 247   sdm->sess_dbg_evt_type[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 *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 251   sdm->sess_dbg_evt_type[SESS_Q_CLK_CTRL_EVTS].f64 += _diff;                    \
 252   sdm->prev_io = sdm->sess_dbg_evt_type[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 *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 256   sdm->sess_dbg_evt_type[SESS_Q_CLK_NEW_IO_EVTS].f64 += _diff;                  \
 257   sdm->sess_dbg_evt_type[SESS_Q_CNT_NEW_EVTS].u64 +=                            \
 258     sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 - sdm->prev_io;              \
 259   sdm->prev_io = sdm->sess_dbg_evt_type[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 *sdm = &session_dbg_main.wrk[_wrk->vm->thread_index];      \
 263   sdm->sess_dbg_evt_type[SESS_Q_CLK_OLD_IO_EVTS].f64 += _diff;                  \
 264   sdm->sess_dbg_evt_type[SESS_Q_CNT_OLD_EVTS].u64 +=                            \
 265     sdm->sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 - sdm->prev_io;              \
 266
 267 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)                \
 268 {                                                                               \
 269   f64 time_now = vlib_time_now (_wrk->vm);                                      \
 270   f64 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_CLOCKS_HANDLER(_node_evt, _wrk)
 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         sess_dbg_evt_type[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_main.wrk[_wrk->vm->thread_index].                  \
 289         sess_dbg_evt_type[type].u64 += _cnt ;                    \
 290   session_dbg_main.wrk[_wrk->vm->thread_index].                  \
 291         sess_dbg_evt_type[SESS_Q_CNT_IO_EVTS].u64 += _cnt ;     \
 292 }
 293 #else
 294 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _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   if (SESSION_DEQ_EVTS > 1)                                             \
 302     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0);                          \
 303   SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk);                             \
 304   session_dbg_main.wrk[_wrk->vm->thread_index].                         \
 305         sess_dbg_evt_type[SESS_Q_##NODE_CALL_CNT].u64 +=1;              \
 306 }
 307
 308 #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx)                    \
 309 {                                                                       \
 310   if (_ntx)                                                             \
 311     SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx);                       \
 312   SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk);                         \
 313   _wrk->last_event_poll = vlib_time_now (_wrk->vm);                     \
 314 }
 315
 316 #define CONCAT_HELPER(_a, _b) _a##_b
 317 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
 318 #define SESSION_EVT(_evt, _args...) CC(_evt, _HANDLER)(_args)
 319
 320 #else
 321 #define SESSION_EVT(_evt, _args...)
 322 #define SESSION_DBG(_fmt, _args...)
 323 #endif /* SESSION_DEBUG */
 324
 325 #endif /* SRC_VNET_SESSION_SESSION_DEBUG_H_ */
 326 /*
 327  * fd.io coding-style-patch-verification: ON
 328  *
 329  * Local Variables:
 330  * eval: (c-set-style "gnu")
 331  * End:
 332  */