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:
7 * http://www.apache.org/licenses/LICENSE-2.0
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.
15 #ifndef SRC_VNET_SESSION_SESSION_DEBUG_H_
16 #define SRC_VNET_SESSION_SESSION_DEBUG_H_
18 #include <vnet/session/transport.h>
19 #include <vlib/vlib.h>
20 #include <vpp/vnet/config.h>
22 #define foreach_session_dbg_evt \
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") \
35 typedef enum _session_evt_dbg
37 #define _(sym, str) SESSION_EVT_##sym,
38 foreach_session_dbg_evt
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") \
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") \
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") \
67 #define _(sym, disp, type, str) SESS_Q_##sym,
68 foreach_session_events
71 } sess_q_node_events_types_t;
73 typedef struct session_dbg_counter_
80 } session_dbg_counter_t;
82 typedef struct session_dbg_evts_t
84 CLIB_CACHE_LINE_ALIGN_MARK (cacheline0);
88 session_dbg_counter_t counters[SESS_Q_MAX_EVT_TYPES];
91 typedef struct session_dbg_main_
93 session_dbg_evts_t *wrk;
96 extern session_dbg_main_t session_dbg_main;
98 #ifdef VPP_SESSION_DEBUG
99 #define SESSION_DEBUG 1 * (TRANSPORT_DEBUG > 0)
101 #define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0)
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)
113 #define SESSION_DBG(_fmt, _args...) clib_warning (_fmt, ##_args)
115 #define DEC_SESSION_ETD(_s, _e, _size) \
120 transport_connection_t *_tc = session_get_transport (_s); \
121 ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, \
124 #define DEC_SESSION_ED(_e, _size) \
129 ed = ELOG_DATA (&vlib_global_main.elog_main, _e)
132 #define SESSION_EVT_FREE_HANDLER(_s) \
134 ELOG_TYPE_DECLARE (_e) = \
136 .format = "free: idx %u", \
137 .format_args = "i4", \
139 DEC_SESSION_ETD(_s, _e, 1); \
140 ed->data[0] = _s->session_index; \
143 #define SESSION_EVT_FREE_HANDLER(_s)
147 #define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts) \
149 ELOG_TYPE_DECLARE (_e) = \
151 .format = "deq: now %u max %d evt %u ts %d", \
152 .format_args = "i4i4i4i4", \
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; \
161 #define SESSION_EVT_ENQ_HANDLER(_s, _len) \
163 ELOG_TYPE_DECLARE (_e) = \
165 .format = "enq: length %d", \
166 .format_args = "i4", \
168 DEC_SESSION_ETD(_s, _e, 1); \
169 ed->data[0] = _len; \
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 */
176 #if SESSION_DISPATCH_DBG
177 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx) \
179 ELOG_TYPE_DECLARE (_e) = \
181 .format = "dispatch: %s pkts %u re-entry: %u dispatch %u", \
182 .format_args = "t4i4i4i4", \
183 .n_enum_strings = 2, \
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) \
194 ed->data[3] = (vlib_time_now (_wrk->vm) - _wrk->last_vlib_time) \
198 #define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx)
199 #endif /* SESSION_DISPATCH_DBG */
201 #if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
202 #define SESSION_EVT_POLL_GAP(_wrk) \
204 ELOG_TYPE_DECLARE (_e) = \
206 .format = "nixon-gap: %d us", \
207 .format_args = "i4", \
209 DEC_SESSION_ED(_e, 1); \
210 ed->data[0] = (u32) ((_wrk->last_vlib_time - _wrk->last_event_poll) \
213 #define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk) \
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; \
221 #define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk) \
223 f64 diff = vlib_time_now (vlib_get_main ()) - _wrk->last_event_poll; \
226 ELOG_TYPE_DECLARE (_e) = \
228 .format = "dispatch time: %d us", \
229 .format_args = "i4", \
231 DEC_SESSION_ED(_e, 1); \
232 ed->data[0] = diff *1000000.0; \
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)
242 #endif /* SESSION_EVT_POLL_DBG */
244 #if SESSION_CLOCKS_EVT_DBG
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;
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;
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; \
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; \
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; \
273 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...) \
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); \
281 #define SESSION_EVT_DSP_CNTRS_HANDLER(_disp_evt, _wrk, _args...)
282 #endif /*SESSION_CLOCKS_EVT_DBG */
284 #if SESSION_COUNTS_EVT_DBG
285 #define SESSION_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) \
287 session_dbg_main.wrk[_wrk->vm->thread_index]. \
288 counters[SESS_Q_##_node_evt].u64 += _cnt; \
291 #define SESSION_IO_EVT_COUNTS_HANDLER(_node_evt, _cnt, _wrk) \
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 ; \
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 */
305 #define SESSION_EVT_DISPATCH_START_HANDLER(_wrk) \
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); \
316 #define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx) \
318 f64 now = vlib_time_now (_wrk->vm); \
319 session_dbg_evts_t *sde; \
320 sde = &session_dbg_main.wrk[_wrk->vm->thread_index]; \
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; \
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)
334 #define SESSION_EVT(_evt, _args...)
335 #define SESSION_DBG(_fmt, _args...)
336 #endif /* SESSION_DEBUG */
338 void session_debug_init (void);
340 #endif /* SRC_VNET_SESSION_SESSION_DEBUG_H_ */
342 * fd.io coding-style-patch-verification: ON
345 * eval: (c-set-style "gnu")