summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorFlorin Coras <fcoras@cisco.com>2019-10-30 17:11:53 -0700
committerAndrew Yourtchenko <ayourtch@gmail.com>2019-11-05 10:42:46 +0000
commite04a58d27bac8f97bda85a7684b7bb68682341cc (patch)
treebf6167a00311abff1d3a3ac6b07001c30fcb9510
parent6de46b40d2d2429e8f4f06272536fb5535c73908 (diff)
session: fix dispatch event logging
Type: fix Change-Id: Icf3c73cd7eb7565ed6e1b0371da172b5408a9d36 Signed-off-by: Florin Coras <fcoras@cisco.com> (cherry picked from commit ba13c3b3695cb4758848d856174b725afcc7cdb8)
-rw-r--r--src/vnet/session/session_debug.h43
1 files changed, 27 insertions, 16 deletions
diff --git a/src/vnet/session/session_debug.h b/src/vnet/session/session_debug.h
index 228c1b36ac6..a57b02d228e 100644
--- a/src/vnet/session/session_debug.h
+++ b/src/vnet/session/session_debug.h
@@ -37,6 +37,7 @@ typedef enum _session_evt_dbg
#define SESSION_DEBUG 0 * (TRANSPORT_DEBUG > 0)
#define SESSION_DEQ_EVTS (0)
+#define SESSION_DISPATCH_DBG (0)
#define SESSION_EVT_POLL_DBG (0)
#define SESSION_SM (0)
@@ -100,27 +101,35 @@ typedef enum _session_evt_dbg
DEC_SESSION_ETD(_s, _e, 1); \
ed->data[0] = _len; \
}
+#else
+#define SESSION_EVT_DEQ_HANDLER(_s, _now, _max, _has_evt, _ts)
+#define SESSION_EVT_ENQ_HANDLER(_s, _body)
+#endif /* SESSION_DEQ_NODE_EVTS */
-#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt) \
+#if SESSION_DISPATCH_DBG
+#define SESSION_EVT_DEQ_NODE_HANDLER(_wrk, _node_evt, _ntx) \
{ \
ELOG_TYPE_DECLARE (_e) = \
{ \
- .format = "deq-node: %s", \
- .format_args = "t4", \
+ .format = "dispatch: %s pkts %u re-entry: %u dispatch %u", \
+ .format_args = "t4i4i4i4", \
.n_enum_strings = 2, \
.enum_strings = { \
"start", \
"end", \
}, \
}; \
- DEC_SESSION_ED(_e, 1); \
+ DEC_SESSION_ED(_e, 4); \
ed->data[0] = _node_evt; \
+ ed->data[1] = _ntx; \
+ ed->data[2] = (_wrk->last_vlib_time - _wrk->last_event_poll) \
+ * 1000000.0; \
+ ed->data[3] = (vlib_time_now (_wrk->vm) - _wrk->last_vlib_time) \
+ * 1000000.0; \
}
#else
-#define SESSION_EVT_DEQ_HANDLER(_s, _body)
-#define SESSION_EVT_ENQ_HANDLER(_s, _body)
-#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt)
-#endif /* SESSION_DEQ_NODE_EVTS */
+#define SESSION_EVT_DEQ_NODE_HANDLER(_node_evt, _ntx)
+#endif /* SESSION_DISPATCH_DBG */
#if SESSION_EVT_POLL_DBG && SESSION_DEBUG > 1
#define SESSION_EVT_POLL_GAP(_wrk) \
@@ -131,14 +140,15 @@ typedef enum _session_evt_dbg
.format_args = "i4", \
}; \
DEC_SESSION_ED(_e, 1); \
- ed->data[0] = (u32) ((now - _wrk->last_event_poll)*1000000.0); \
+ ed->data[0] = (u32) ((_wrk->last_vlib_time - _wrk->last_event_poll) \
+ *1000000.0); \
}
#define SESSION_EVT_POLL_GAP_TRACK_HANDLER(_wrk) \
{ \
- if (PREDICT_TRUE (smm->last_event_poll != 0.0)) \
- if (now > smm->last_event_poll + 500e-6) \
- SESSION_EVT_POLL_GAP(smm, _ti); \
- _wrk->last_event_poll = now; \
+ if (PREDICT_TRUE (_wrk->last_event_poll != 0.0)) \
+ if (_wrk->last_vlib_time > _wrk->last_event_poll + 500e-6) \
+ SESSION_EVT_POLL_GAP(_wrk); \
+ _wrk->last_event_poll = _wrk->last_vlib_time; \
}
#define SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk) \
@@ -165,15 +175,16 @@ typedef enum _session_evt_dbg
#define SESSION_EVT_DISPATCH_START_HANDLER(_wrk) \
{ \
if (SESSION_DEQ_EVTS > 1) \
- SESSION_EVT_DEQ_NODE_HANDLER (0); \
+ SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 0, 0); \
SESSION_EVT_POLL_GAP_TRACK_HANDLER (wrk); \
}
#define SESSION_EVT_DISPATCH_END_HANDLER(_wrk, _ntx) \
{ \
- if (SESSION_DEQ_EVTS > 1 || _ntx) \
- SESSION_EVT_DEQ_NODE_HANDLER (1); \
+ if (_ntx) \
+ SESSION_EVT_DEQ_NODE_HANDLER (_wrk, 1, _ntx); \
SESSION_EVT_POLL_DISPATCH_TIME_HANDLER(_wrk); \
+ _wrk->last_event_poll = vlib_time_now (_wrk->vm); \
}
#define CONCAT_HELPER(_a, _b) _a##_b