FD.io VPP  v21.01.1
Vector Packet Processing
session_debug.h
Go to the documentation of this file.
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  */
SESS_Q_MAX_EVT_TYPES
Definition: session_debug.h:69
CLIB_CACHE_LINE_ALIGN_MARK
#define CLIB_CACHE_LINE_ALIGN_MARK(mark)
Definition: cache.h:60
session_debug_init
void session_debug_init(void)
Definition: session_debug.c:115
u64
unsigned long u64
Definition: types.h:89
session_dbg_main_t
struct session_dbg_main_ session_dbg_main_t
session_dbg_main
session_dbg_main_t session_dbg_main
foreach_session_dbg_evt
#define foreach_session_dbg_evt
Definition: session_debug.h:21
f64
double f64
Definition: types.h:142
session_dbg_evts_t
struct session_dbg_evts_t session_dbg_evts_t
sess_q_node_events_types_t
sess_q_node_events_types_t
Definition: session_debug.h:64
session_dbg_main_
Definition: session_debug.h:90
session_evt_dbg_e
enum _session_evt_dbg session_evt_dbg_e
session_dbg_counter_
Definition: session_debug.h:72
session_dbg_main_::wrk
session_dbg_evts_t * wrk
Definition: session_debug.h:92
foreach_session_events
#define foreach_session_events
Definition: session_debug.h:41
session_dbg_counter_::f64
f64 f64
Definition: session_debug.h:76
session_dbg_counter_::u64
u64 u64
Definition: session_debug.h:77
session_dbg_evts_t::start_time
f64 start_time
Definition: session_debug.h:85
session_dbg_evts_t::last_time
f64 last_time
Definition: session_debug.h:84
session_dbg_counter_t
struct session_dbg_counter_ session_dbg_counter_t
session_dbg_evts_t
Definition: session_debug.h:81
session_dbg_evts_t::prev_io
u64 prev_io
Definition: session_debug.h:86