FD.io VPP  v19.08.3-2-gbabecb413
Vector Packet Processing
tcp_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 
16 #ifndef SRC_VNET_TCP_TCP_DEBUG_H_
17 #define SRC_VNET_TCP_TCP_DEBUG_H_
18 
19 #include <vlib/vlib.h>
20 
21 /**
22  * Build debugging infra unconditionally. Debug components controlled via
23  * debug configuration. Comes with some overhead so it's not recommended for
24  * production/performance scenarios. Takes priority over TCP_DEBUG_ENABLE.
25  */
26 #define TCP_DEBUG_ALWAYS (0)
27 /**
28  * Build debugging infra only if enabled. Debug components controlled via
29  * macros that follow.
30  */
31 #define TCP_DEBUG_ENABLE (0)
32 
33 #define TCP_DEBUG_SM (0)
34 #define TCP_DEBUG_CC (0)
35 #define TCP_DEBUG_CS (0)
36 #define TCP_DEBUG_LC (0 || TCP_DEBUG_SM || TCP_DEBUG_CC || TCP_DEBUG_CS)
37 
38 #define TCP_DEBUG (TCP_DEBUG_ALWAYS || TCP_DEBUG_ENABLE)
39 #define TCP_DEBUG_BUF_ALLOC (0)
40 
41 #if TCP_DEBUG > 0
42 #define TRANSPORT_DEBUG (1)
43 #endif
44 
45 #define TCP_CONCAT_HELPER(_a, _b) _a##_b
46 #define TCP_CC(_a, _b) TCP_CONCAT_HELPER(_a, _b)
47 
48 #define tcp_evt_lvl(_evt) TCP_CC(_evt, _LVL)
49 #define tcp_evt_grp(_evt) TCP_CC(_evt, _GRP)
50 #define tcp_evt_handler(_evt, _args...) TCP_CC(_evt, _HANDLER) (_args)
51 #define tcp_evt_grp_dbg_lvl(_evt) tcp_dbg_main.grp_dbg_lvl[tcp_evt_grp (_evt)]
52 
53 #define foreach_tcp_evt_grp \
54  _(LC, "life cycle") \
55  _(SM, "state machine") \
56  _(CC, "congestion control") \
57  _(CS, "cc stats") \
58 
59 typedef enum tcp_evt_grp_
60 {
61 #define _(sym, str) TCP_EVT_GRP_ ## sym,
62  foreach_tcp_evt_grp
63 #undef _
64  TCP_EVT_N_GRP
65 } tcp_evt_grp_e;
66 
67 typedef struct tcp_dbg_main_
68 {
69  u8 grp_dbg_lvl[TCP_EVT_N_GRP];
70  u32 *free_track_indices;
71 } tcp_dbg_main_t;
72 
73 extern tcp_dbg_main_t tcp_dbg_main;
74 
75 #define foreach_tcp_dbg_evt \
76  _(INIT, LC, 1, "init") \
77  _(DEALLOC, LC, 1, "dealloc") \
78  _(OPEN, LC, 1, "open") \
79  _(CLOSE, LC, 1, "close") \
80  _(BIND, LC, 1, "bind") \
81  _(UNBIND, LC, 1, "unbind") \
82  _(DELETE, LC, 1, "delete") \
83  _(SYN_RCVD, LC, 1, "SYN rcvd") \
84  _(STATE_CHANGE, LC, 1, "state change") \
85  _(SYN_SENT, SM, 1, "SYN sent") \
86  _(SYN_RXT, SM, 1, "SYN retransmit") \
87  _(SYNACK_SENT, SM, 1, "SYNACK sent") \
88  _(SYNACK_RCVD, SM, 1, "SYNACK rcvd") \
89  _(FIN_SENT, SM, 1, "FIN sent") \
90  _(FIN_RCVD, SM, 1, "FIN rcvd") \
91  _(RST_SENT, SM, 1, "RST sent") \
92  _(RST_RCVD, SM, 1, "RST rcvd") \
93  _(TIMER_POP, SM, 1, "timer pop") \
94  _(SEG_INVALID, SM, 2, "invalid segment") \
95  _(PAWS_FAIL, SM, 2, "failed paws check") \
96  _(ACK_RCV_ERR, SM, 2, "invalid ack") \
97  _(RCV_WND_SHRUNK, SM, 2, "shrunk rcv_wnd") \
98  _(ACK_SENT, SM, 3, "ACK sent") \
99  _(ACK_RCVD, SM, 3, "ACK rcvd") \
100  _(PKTIZE, SM, 3, "packetize") \
101  _(INPUT, SM, 3, "in") \
102  _(OUTPUT, SM, 4, "output") \
103  _(SND_WND, SM, 4, "snd_wnd update") \
104  _(CC_EVT, CC, 1, "cc event") \
105  _(CC_RTX, CC, 2, "retransmit") \
106  _(CC_PACK, CC, 2, "cc partial ack") \
107  _(DUPACK_SENT, CC, 2, "DUPACK sent") \
108  _(DUPACK_RCVD, CC, 2, "DUPACK rcvd") \
109  _(CC_SCOREBOARD, CC, 2, "scoreboard stats") \
110  _(CC_SACKS, CC, 2, "snd sacks stats") \
111  _(CC_INPUT, CC, 2, "ooo data delivered") \
112  _(CC_STAT, CS, 1, "cc stats") \
113  _(CC_RTO_STAT, CS, 1, "cc rto stats") \
114 
115 typedef enum tcp_evt_types_
116 {
117 #define _(sym, grp, lvl, str) TCP_EVT_##sym,
118  foreach_tcp_dbg_evt
119 #undef _
120 } tcp_evt_types_e;
121 
122 typedef enum tcp_evt_lvl_
123 {
124 #define _(sym, grp, lvl, str) TCP_EVT_## sym ## _LVL = lvl,
125  foreach_tcp_dbg_evt
126 #undef _
127 } tcp_evt_lvl_e;
128 
129 typedef enum tcp_evt_to_grp_
130 {
131 #define _(sym, grp, lvl, str) TCP_EVT_ ## sym ## _GRP = TCP_EVT_GRP_ ## grp,
132  foreach_tcp_dbg_evt
133 #undef _
134 } tcp_evt_to_grp_e;
135 
136 #if TCP_DEBUG_ALWAYS > 0
137 #define TCP_EVT(_evt, _args...) \
138  if (PREDICT_FALSE (tcp_evt_grp_dbg_lvl (_evt) >= tcp_evt_lvl (_evt))) \
139  tcp_evt_handler (_evt, _args)
140 #define TCP_DBG(_fmt, _args...) clib_warning (_fmt, ##_args)
141 #elif TCP_DEBUG_ENABLE > 0
142 #define TCP_EVT(_evt, _args...) tcp_evt_handler(_evt, _args)
143 #define TCP_DBG(_fmt, _args...) clib_warning (_fmt, ##_args)
144 #else
145 #define TCP_EVT(_evt, _args...)
146 #define TCP_DBG(_fmt, _args...)
147 #endif
148 
149 void tcp_evt_track_register (elog_track_t * et);
150 void tcp_debug_init (void);
151 
152 #define TCP_DECLARE_ETD(_tc, _e, _size) \
153 struct \
154 { \
155  u32 data[_size]; \
156 } * ed; \
157 ed = ELOG_TRACK_DATA (&vlib_global_main.elog_main, _e, \
158  _tc->c_elog_track) \
159 
160 /*
161  * Event handlers definitions
162  */
163 
164 #if TCP_DEBUG_LC || TCP_DEBUG_ALWAYS
165 
166 /*
167  * Infra and evt track setup
168  */
169 
170 #define TCP_DBG_IP_TAG_LCL(_tc) \
171 { \
172  if (_tc->c_is_ip4) \
173  { \
174  ELOG_TYPE_DECLARE (_e) = \
175  { \
176  .format = "lcl: %d.%d.%d.%d:%d", \
177  .format_args = "i4i4i4i4i4", \
178  }; \
179  TCP_DECLARE_ETD(_tc, _e, 5); \
180  ed->data[0] = _tc->c_lcl_ip.ip4.as_u8[0]; \
181  ed->data[1] = _tc->c_lcl_ip.ip4.as_u8[1]; \
182  ed->data[2] = _tc->c_lcl_ip.ip4.as_u8[2]; \
183  ed->data[3] = _tc->c_lcl_ip.ip4.as_u8[3]; \
184  ed->data[4] = clib_net_to_host_u16(_tc->c_lcl_port); \
185  } \
186 }
187 
188 #define TCP_DBG_IP_TAG_RMT(_tc) \
189 { \
190  if (_tc->c_is_ip4) \
191  { \
192  ELOG_TYPE_DECLARE (_e) = \
193  { \
194  .format = "rmt: %d.%d.%d.%d:%d", \
195  .format_args = "i4i4i4i4i4", \
196  }; \
197  TCP_DECLARE_ETD(_tc, _e, 5); \
198  ed->data[0] = _tc->c_rmt_ip.ip4.as_u8[0]; \
199  ed->data[1] = _tc->c_rmt_ip.ip4.as_u8[1]; \
200  ed->data[2] = _tc->c_rmt_ip.ip4.as_u8[2]; \
201  ed->data[3] = _tc->c_rmt_ip.ip4.as_u8[3]; \
202  ed->data[4] = clib_net_to_host_u16(_tc->c_rmt_port); \
203  } \
204 }
205 
206 #define TCP_EVT_INIT_HANDLER(_tc, _is_l, ...) \
207 { \
208  char *_fmt = _is_l ? "l[%d].%d:%d%c" : "[%d].%d:%d->.%d:%d%c"; \
209  if (_tc->c_is_ip4) \
210  { \
211  _tc->c_elog_track.name = \
212  (char *) format (0, _fmt, _tc->c_thread_index, \
213  _tc->c_lcl_ip.ip4.as_u8[3], \
214  clib_net_to_host_u16(_tc->c_lcl_port), \
215  _tc->c_rmt_ip.ip4.as_u8[3], \
216  clib_net_to_host_u16(_tc->c_rmt_port), 0); \
217  } \
218  else \
219  _tc->c_elog_track.name = \
220  (char *) format (0, _fmt, _tc->c_thread_index, \
221  _tc->c_lcl_ip.ip6.as_u8[15], \
222  clib_net_to_host_u16(_tc->c_lcl_port), \
223  _tc->c_rmt_ip.ip6.as_u8[15], \
224  clib_net_to_host_u16(_tc->c_rmt_port), 0); \
225  tcp_evt_track_register (&_tc->c_elog_track); \
226  TCP_DBG_IP_TAG_LCL(_tc); \
227  TCP_DBG_IP_TAG_RMT(_tc); \
228 }
229 
230 #define TCP_EVT_DEALLOC_HANDLER(_tc, ...) \
231 { \
232  vec_free (_tc->c_elog_track.name); \
233  vec_add1 (tcp_dbg_main.free_track_indices, \
234  _tc->c_elog_track.track_index_plus_one - 1); \
235 }
236 
237 #define TCP_EVT_OPEN_HANDLER(_tc, ...) \
238 { \
239  TCP_EVT_INIT_HANDLER(_tc, 0); \
240  ELOG_TYPE_DECLARE (_e) = \
241  { \
242  .format = "open: index %d", \
243  .format_args = "i4", \
244  }; \
245  TCP_DECLARE_ETD(_tc, _e, 1); \
246  ed->data[0] = _tc->c_c_index; \
247 }
248 
249 #define TCP_EVT_CLOSE_HANDLER(_tc, ...) \
250 { \
251  ELOG_TYPE_DECLARE (_e) = \
252  { \
253  .format = "close: cidx %d", \
254  .format_args = "i4", \
255  }; \
256  TCP_DECLARE_ETD(_tc, _e, 1); \
257  ed->data[0] = _tc->c_c_index; \
258 }
259 
260 #define TCP_EVT_BIND_HANDLER(_tc, ...) \
261 { \
262  TCP_EVT_INIT_HANDLER(_tc, 1); \
263  ELOG_TYPE_DECLARE (_e) = \
264  { \
265  .format = "bind: listener %d", \
266  }; \
267  TCP_DECLARE_ETD(_tc, _e, 1); \
268  ed->data[0] = _tc->c_c_index; \
269 }
270 
271 #define TCP_EVT_SYN_RCVD_HANDLER(_tc,_init, ...) \
272 { \
273  if (_init) \
274  TCP_EVT_INIT_HANDLER(_tc, 0); \
275  ELOG_TYPE_DECLARE (_e) = \
276  { \
277  .format = "syn-rx: cidx %u sidx %u irs %u", \
278  .format_args = "i4i4i4", \
279  }; \
280  TCP_DECLARE_ETD(_tc, _e, 3); \
281  ed->data[0] = _tc->c_c_index; \
282  ed->data[1] = _tc->c_s_index; \
283  ed->data[2] = _tc->irs; \
284  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
285 }
286 
287 #define TCP_EVT_UNBIND_HANDLER(_tc, ...) \
288 { \
289  TCP_EVT_DEALLOC_HANDLER(_tc); \
290  ELOG_TYPE_DECLARE (_e) = \
291  { \
292  .format = "unbind: listener %d", \
293  }; \
294  TCP_DECLARE_ETD(_tc, _e, 1); \
295  ed->data[0] = _tc->c_c_index; \
296  TCP_EVT_DEALLOC_HANDLER(_tc); \
297 }
298 
299 #define TCP_EVT_DELETE_HANDLER(_tc, ...) \
300 { \
301  ELOG_TYPE_DECLARE (_e) = \
302  { \
303  .format = "delete: cidx %d sidx %d", \
304  .format_args = "i4i4", \
305  }; \
306  TCP_DECLARE_ETD(_tc, _e, 2); \
307  ed->data[0] = _tc->c_c_index; \
308  ed->data[1] = _tc->c_s_index; \
309  TCP_EVT_DEALLOC_HANDLER(_tc); \
310 }
311 
312 #endif
313 
314 /*
315  * State machine
316  */
317 #if TCP_DEBUG_SM > 0 || TCP_DEBUG_ALWAYS
318 
319 #define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...) \
320 { \
321  ELOG_TYPE_DECLARE (_e) = \
322  { \
323  .format = "state: %s", \
324  .format_args = "t4", \
325  .n_enum_strings = 11, \
326  .enum_strings = { \
327  "closed", \
328  "listen", \
329  "syn-sent", \
330  "syn-rcvd", \
331  "established", \
332  "close_wait", \
333  "fin-wait-1", \
334  "last-ack", \
335  "closing", \
336  "fin-wait-2", \
337  "time-wait", \
338  }, \
339  }; \
340  TCP_DECLARE_ETD(_tc, _e, 1); \
341  ed->data[0] = _tc->state; \
342 }
343 
344 #define TCP_EVT_SYN_SENT_HANDLER(_tc, ...) \
345 { \
346  ELOG_TYPE_DECLARE (_e) = \
347  { \
348  .format = "syn-tx: iss %u snd_una %u snd_una_max %u snd_nxt %u", \
349  .format_args = "i4i4i4i4", \
350  }; \
351  TCP_DECLARE_ETD(_tc, _e, 4); \
352  ed->data[0] = _tc->iss; \
353  ed->data[1] = _tc->snd_una - _tc->iss; \
354  ed->data[2] = _tc->snd_una_max - _tc->iss; \
355  ed->data[3] = _tc->snd_nxt - _tc->iss; \
356  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
357 }
358 
359 #define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...) \
360 { \
361  ELOG_TYPE_DECLARE (_e) = \
362  { \
363  .format = "synack-tx: iss %u irs %u snd_una %u snd_nxt %u rcv_nxt %u",\
364  .format_args = "i4i4i4i4i4", \
365  }; \
366  TCP_DECLARE_ETD(_tc, _e, 5); \
367  ed->data[0] = _tc->iss; \
368  ed->data[1] = _tc->irs; \
369  ed->data[2] = _tc->snd_una - _tc->iss; \
370  ed->data[3] = _tc->snd_nxt - _tc->iss; \
371  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
372 }
373 
374 #define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...) \
375 { \
376  ELOG_TYPE_DECLARE (_e) = \
377  { \
378  .format = "synack-rx: iss %u irs %u snd_una %u snd_nxt %u rcv_nxt %u",\
379  .format_args = "i4i4i4i4i4", \
380  }; \
381  TCP_DECLARE_ETD(_tc, _e, 5); \
382  ed->data[0] = _tc->iss; \
383  ed->data[1] = _tc->irs; \
384  ed->data[2] = _tc->snd_una - _tc->iss; \
385  ed->data[3] = _tc->snd_nxt - _tc->iss; \
386  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
387  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
388 }
389 
390 #define TCP_EVT_FIN_SENT_HANDLER(_tc, ...) \
391 { \
392  ELOG_TYPE_DECLARE (_e) = \
393  { \
394  .format = "fin-tx: snd_nxt %d rcv_nxt %d", \
395  .format_args = "i4i4", \
396  }; \
397  TCP_DECLARE_ETD(_tc, _e, 2); \
398  ed->data[0] = _tc->snd_nxt - _tc->iss; \
399  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
400 }
401 
402 #define TCP_EVT_RST_SENT_HANDLER(_tc, ...) \
403 { \
404 if (_tc) \
405  { \
406  ELOG_TYPE_DECLARE (_e) = \
407  { \
408  .format = "rst-tx: snd_nxt %d rcv_nxt %d", \
409  .format_args = "i4i4", \
410  }; \
411  TCP_DECLARE_ETD(_tc, _e, 2); \
412  ed->data[0] = _tc->snd_nxt - _tc->iss; \
413  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
414  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
415  } \
416 }
417 
418 #define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...) \
419 { \
420  ELOG_TYPE_DECLARE (_e) = \
421  { \
422  .format = "fin-rx: snd_nxt %d rcv_nxt %d", \
423  .format_args = "i4i4", \
424  }; \
425  TCP_DECLARE_ETD(_tc, _e, 2); \
426  ed->data[0] = _tc->snd_nxt - _tc->iss; \
427  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
428 }
429 
430 #define TCP_EVT_RST_RCVD_HANDLER(_tc, ...) \
431 { \
432  ELOG_TYPE_DECLARE (_e) = \
433  { \
434  .format = "rst-rx: snd_nxt %d rcv_nxt %d", \
435  .format_args = "i4i4", \
436  }; \
437  TCP_DECLARE_ETD(_tc, _e, 2); \
438  ed->data[0] = _tc->snd_nxt - _tc->iss; \
439  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
440 }
441 
442 #define TCP_EVT_SYN_RXT_HANDLER(_tc, _type, ...) \
443 { \
444  ELOG_TYPE_DECLARE (_e) = \
445  { \
446  .format = "%s-rxt: iss %u irs %u snd_nxt %u rcv_nxt %u", \
447  .format_args = "t4i4i4i4i4", \
448  .n_enum_strings = 2, \
449  .enum_strings = { \
450  "syn", \
451  "synack", \
452  }, \
453  }; \
454  TCP_DECLARE_ETD(_tc, _e, 5); \
455  ed->data[0] = _type; \
456  ed->data[1] = _tc->iss; \
457  ed->data[2] = _tc->irs; \
458  ed->data[3] = _tc->snd_nxt - _tc->iss; \
459  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
460 }
461 
462 #define TCP_EVT_TIMER_POP_HANDLER(_tc_index, _timer_id, ...) \
463 { \
464  tcp_connection_t *_tc; \
465  if (_timer_id == TCP_TIMER_RETRANSMIT_SYN) \
466  { \
467  _tc = tcp_half_open_connection_get (_tc_index); \
468  } \
469  else \
470  { \
471  u32 _thread_index = vlib_get_thread_index (); \
472  _tc = tcp_connection_get (_tc_index, _thread_index); \
473  } \
474  ELOG_TYPE_DECLARE (_e) = \
475  { \
476  .format = "timer-pop: %s cidx %u sidx %u", \
477  .format_args = "t4i4i4", \
478  .n_enum_strings = 8, \
479  .enum_strings = { \
480  "retransmit", \
481  "delack", \
482  "persist", \
483  "keep", \
484  "waitclose", \
485  "retransmit syn", \
486  "establish", \
487  "establish-ao", \
488  }, \
489  }; \
490  if (_tc) \
491  { \
492  TCP_DECLARE_ETD(_tc, _e, 3); \
493  ed->data[0] = _timer_id; \
494  ed->data[1] = _tc->c_c_index; \
495  ed->data[2] = _tc->c_s_index; \
496  } \
497  else \
498  { \
499  clib_warning ("pop %d for unexisting connection %d", _timer_id, \
500  _tc_index); \
501  } \
502 }
503 
504 #else
505 #define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)
506 #define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...)
507 #define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...)
508 #define TCP_EVT_SYN_RXT_HANDLER(_tc, ...)
509 #define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)
510 #define TCP_EVT_RST_SENT_HANDLER(_tc, ...)
511 #define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)
512 #define TCP_EVT_RST_RCVD_HANDLER(_tc, ...)
513 #define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...)
514 #define TCP_EVT_TIMER_POP_HANDLER(_tc_index, _timer_id, ...)
515 #endif
516 
517 #if TCP_DEBUG_SM > 1 || TCP_DEBUG_ALWAYS
518 #define TCP_EVT_SEG_INVALID_HANDLER(_tc, _btcp, ...) \
519 { \
520  ELOG_TYPE_DECLARE (_e) = \
521  { \
522  .format = "seg-inv: seq %u end %u rcv_las %u rcv_nxt %u rcv_wnd %u",\
523  .format_args = "i4i4i4i4i4", \
524  }; \
525  TCP_DECLARE_ETD(_tc, _e, 5); \
526  ed->data[0] = _btcp.seq_number - _tc->irs; \
527  ed->data[1] = _btcp.seq_end - _tc->irs; \
528  ed->data[2] = _tc->rcv_las - _tc->irs; \
529  ed->data[3] = _tc->rcv_nxt - _tc->irs; \
530  ed->data[4] = _tc->rcv_wnd; \
531 }
532 
533 #define TCP_EVT_PAWS_FAIL_HANDLER(_tc, _seq, _end, ...) \
534 { \
535  ELOG_TYPE_DECLARE (_e) = \
536  { \
537  .format = "paws-err: seq %u end %u tsval %u tsval_recent %u", \
538  .format_args = "i4i4i4i4", \
539  }; \
540  TCP_DECLARE_ETD(_tc, _e, 4); \
541  ed->data[0] = _seq - _tc->irs; \
542  ed->data[1] = _end - _tc->irs; \
543  ed->data[2] = _tc->rcv_opts.tsval; \
544  ed->data[3] = _tc->tsval_recent; \
545 }
546 
547 #define TCP_EVT_ACK_RCV_ERR_HANDLER(_tc, _type, _ack, ...) \
548 { \
549  ELOG_TYPE_DECLARE (_e) = \
550  { \
551  .format = "ack-err: %s ack %u snd_una %u snd_nxt %u una_max %u", \
552  .format_args = "t4i4i4i4i4", \
553  .n_enum_strings = 3, \
554  .enum_strings = { \
555  "invalid", \
556  "old", \
557  "future", \
558  }, \
559  }; \
560  TCP_DECLARE_ETD(_tc, _e, 5); \
561  ed->data[0] = _type; \
562  ed->data[1] = _ack - _tc->iss; \
563  ed->data[2] = _tc->snd_una - _tc->iss; \
564  ed->data[3] = _tc->snd_nxt - _tc->iss; \
565  ed->data[4] = _tc->snd_una_max - _tc->iss; \
566 }
567 
568 #define TCP_EVT_RCV_WND_SHRUNK_HANDLER(_tc, _obs, _av, ...) \
569 { \
570 if (_av > 0) \
571 { \
572  ELOG_TYPE_DECLARE (_e) = \
573  { \
574  .format = "huh?: rcv_wnd %u obsd %u av %u rcv_nxt %u rcv_las %u", \
575  .format_args = "i4i4i4i4i4", \
576  }; \
577  TCP_DECLARE_ETD(_tc, _e, 5); \
578  ed->data[0] = _tc->rcv_wnd; \
579  ed->data[1] = _obs; \
580  ed->data[2] = _av; \
581  ed->data[3] = _tc->rcv_nxt - _tc->irs; \
582  ed->data[4] = _tc->rcv_las - _tc->irs; \
583 } \
584 }
585 #else
586 #define TCP_EVT_SEG_INVALID_HANDLER(_tc, _btcp, ...)
587 #define TCP_EVT_PAWS_FAIL_HANDLER(_tc, _seq, _end, ...)
588 #define TCP_EVT_ACK_RCV_ERR_HANDLER(_tc, _type, _ack, ...)
589 #define TCP_EVT_RCV_WND_SHRUNK_HANDLER(_tc, _obs, _av, ...)
590 #endif
591 
592 #if TCP_DEBUG_SM > 2 || TCP_DEBUG_ALWAYS
593 
594 #define TCP_EVT_ACK_SENT_HANDLER(_tc, ...) \
595 { \
596  ELOG_TYPE_DECLARE (_e) = \
597  { \
598  .format = "ack-tx: acked %u rcv_nxt %u rcv_wnd %u snd_nxt %u snd_wnd %u",\
599  .format_args = "i4i4i4i4i4", \
600  }; \
601  TCP_DECLARE_ETD(_tc, _e, 5); \
602  ed->data[0] = _tc->rcv_nxt - _tc->rcv_las; \
603  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
604  ed->data[2] = _tc->rcv_wnd; \
605  ed->data[3] = _tc->snd_nxt - _tc->iss; \
606  ed->data[4] = _tc->snd_wnd; \
607 }
608 
609 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...) \
610 { \
611  ELOG_TYPE_DECLARE (_e) = \
612  { \
613  .format = "ack-rx: %u snd_una %u snd_wnd %u cwnd %u inflight %u", \
614  .format_args = "i4i4i4i4i4", \
615  }; \
616  TCP_DECLARE_ETD(_tc, _e, 5); \
617  ed->data[0] = _tc->bytes_acked; \
618  ed->data[1] = _tc->snd_una - _tc->iss; \
619  ed->data[2] = _tc->snd_wnd; \
620  ed->data[3] = _tc->cwnd; \
621  ed->data[4] = tcp_flight_size(_tc); \
622 }
623 
624 #define TCP_EVT_PKTIZE_HANDLER(_tc, ...) \
625 { \
626  ELOG_TYPE_DECLARE (_e) = \
627  { \
628  .format = "tx: una %u snd_nxt %u space %u flight %u rcv_wnd %u",\
629  .format_args = "i4i4i4i4i4", \
630  }; \
631  TCP_DECLARE_ETD(_tc, _e, 5); \
632  ed->data[0] = _tc->snd_una - _tc->iss; \
633  ed->data[1] = _tc->snd_nxt - _tc->iss; \
634  ed->data[2] = tcp_available_output_snd_space (_tc); \
635  ed->data[3] = tcp_flight_size (_tc); \
636  ed->data[4] = _tc->rcv_wnd; \
637 }
638 
639 #define TCP_EVT_INPUT_HANDLER(_tc, _type, _len, _written, ...) \
640 { \
641  ELOG_TYPE_DECLARE (_e) = \
642  { \
643  .format = "in: %s len %u written %d rcv_nxt %u rcv_wnd(o) %d", \
644  .format_args = "t4i4i4i4i4", \
645  .n_enum_strings = 2, \
646  .enum_strings = { \
647  "order", \
648  "ooo", \
649  }, \
650  }; \
651  TCP_DECLARE_ETD(_tc, _e, 5); \
652  ed->data[0] = _type; \
653  ed->data[1] = _len; \
654  ed->data[2] = _written; \
655  ed->data[3] = (_tc->rcv_nxt - _tc->irs) + _written; \
656  ed->data[4] = _tc->rcv_wnd - (_tc->rcv_nxt - _tc->rcv_las); \
657 }
658 
659 #else
660 #define TCP_EVT_ACK_SENT_HANDLER(_tc, ...)
661 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...)
662 #define TCP_EVT_PKTIZE_HANDLER(_tc, ...)
663 #define TCP_EVT_INPUT_HANDLER(_tc, _type, _len, _written, ...)
664 #endif
665 
666 /*
667  * State machine verbose
668  */
669 #if TCP_DEBUG_SM > 3 || TCP_DEBUG_ALWAYS
670 #define TCP_EVT_SND_WND_HANDLER(_tc, ...) \
671 { \
672  ELOG_TYPE_DECLARE (_e) = \
673  { \
674  .format = "snd-wnd update: %u ", \
675  .format_args = "i4", \
676  }; \
677  TCP_DECLARE_ETD(_tc, _e, 1); \
678  ed->data[0] = _tc->snd_wnd; \
679 }
680 
681 #define TCP_EVT_OUTPUT_HANDLER(_tc, flags, n_bytes,...) \
682 { \
683  ELOG_TYPE_DECLARE (_e) = \
684  { \
685  .format = "out: flags %x, bytes %u", \
686  .format_args = "i4i4", \
687  }; \
688  TCP_DECLARE_ETD(_tc, _e, 2); \
689  ed->data[0] = flags; \
690  ed->data[1] = n_bytes; \
691 }
692 #else
693 #define TCP_EVT_SND_WND_HANDLER(_tc, ...)
694 #define TCP_EVT_OUTPUT_HANDLER(_tc, flags, n_bytes,...)
695 #endif
696 
697 /*
698  * Congestion Control
699  */
700 
701 #if TCP_DEBUG_CC || TCP_DEBUG_ALWAYS
702 
703 #define TCP_EVT_CC_EVT_PRINT(_tc, _sub_evt) \
704 { \
705  ELOG_TYPE_DECLARE (_e) = \
706  { \
707  .format = "cc: %s snd_space %u snd_una %u out %u flight %u", \
708  .format_args = "t4i4i4i4i4", \
709  .n_enum_strings = 7, \
710  .enum_strings = { \
711  "fast-rxt", \
712  "first-rxt", \
713  "rxt-timeout", \
714  "recovered", \
715  "congestion", \
716  "undo", \
717  "recovery", \
718  }, \
719  }; \
720  TCP_DECLARE_ETD(_tc, _e, 5); \
721  ed->data[0] = _sub_evt; \
722  ed->data[1] = tcp_available_cc_snd_space (_tc); \
723  ed->data[2] = _tc->snd_una - _tc->iss; \
724  ed->data[3] = tcp_bytes_out(_tc); \
725  ed->data[4] = tcp_flight_size (_tc); \
726 }
727 
728 #define TCP_EVT_CC_EVT_HANDLER(_tc, _sub_evt, ...) \
729 { \
730  if (_tc->snd_una != _tc->iss) \
731  TCP_EVT_CC_STAT_PRINT (_tc); \
732  if ((_sub_evt <= 1 && TCP_DEBUG_CC > 1) \
733  || (_sub_evt > 1 && TCP_DEBUG_CC > 0)) \
734  TCP_EVT_CC_EVT_PRINT (_tc, _sub_evt); \
735 }
736 #else
737 #define TCP_EVT_CC_EVT_HANDLER(_tc, _sub_evt, ...) \
738 
739 #endif
740 
741 #if TCP_DEBUG_CC > 1 || TCP_DEBUG_ALWAYS
742 #define TCP_EVT_CC_RTX_HANDLER(_tc, offset, n_bytes, ...) \
743 { \
744  ELOG_TYPE_DECLARE (_e) = \
745  { \
746  .format = "rxt: snd_nxt %u offset %u snd %u rxt %u", \
747  .format_args = "i4i4i4i4", \
748  }; \
749  TCP_DECLARE_ETD(_tc, _e, 4); \
750  ed->data[0] = _tc->snd_nxt - _tc->iss; \
751  ed->data[1] = offset; \
752  ed->data[2] = n_bytes; \
753  ed->data[3] = _tc->snd_rxt_bytes; \
754 }
755 
756 #define TCP_EVT_DUPACK_SENT_HANDLER(_tc, _btcp, ...) \
757 { \
758  ELOG_TYPE_DECLARE (_e) = \
759  { \
760  .format = "dack-tx: rcv_nxt %u seq %u rcv_wnd %u snd_nxt %u av_wnd %u",\
761  .format_args = "i4i4i4i4i4", \
762  }; \
763  TCP_DECLARE_ETD(_tc, _e, 5); \
764  ed->data[0] = _tc->rcv_nxt - _tc->irs; \
765  ed->data[1] = _btcp.seq_number - _tc->irs; \
766  ed->data[2] = _tc->rcv_wnd; \
767  ed->data[3] = _tc->snd_nxt - _tc->iss; \
768  ed->data[4] = tcp_available_snd_wnd(_tc); \
769 }
770 
771 #define TCP_EVT_DUPACK_RCVD_HANDLER(_tc, ...) \
772 { \
773  ELOG_TYPE_DECLARE (_e) = \
774  { \
775  .format = "dack-rx: snd_una %u cwnd %u snd_wnd %u flight %u rcv_wnd %u",\
776  .format_args = "i4i4i4i4i4", \
777  }; \
778  TCP_DECLARE_ETD(_tc, _e, 5); \
779  ed->data[0] = _tc->snd_una - _tc->iss; \
780  ed->data[1] = _tc->cwnd; \
781  ed->data[2] = _tc->snd_wnd; \
782  ed->data[3] = tcp_flight_size(_tc); \
783  ed->data[4] = _tc->rcv_wnd; \
784 }
785 
786 #define TCP_EVT_CC_PACK_HANDLER(_tc, ...) \
787 { \
788  ELOG_TYPE_DECLARE (_e) = \
789  { \
790  .format = "pack: snd_una %u snd_una_max %u", \
791  .format_args = "i4i4", \
792  }; \
793  TCP_DECLARE_ETD(_tc, _e, 2); \
794  ed->data[0] = _tc->snd_una - _tc->iss; \
795  ed->data[1] = _tc->snd_una_max - _tc->iss; \
796 }
797 #define TCP_EVT_CC_SCOREBOARD_HANDLER(_tc, ...) \
798 { \
799 if (TCP_DEBUG_CC > 1 && _tc->sack_sb.last_sacked_bytes) \
800  { \
801  ELOG_TYPE_DECLARE (_e) = \
802  { \
803  .format = "sb1: holes %u lost %u sacked %u high %u highrxt %u", \
804  .format_args = "i4i4i4i4i4", \
805  }; \
806  TCP_DECLARE_ETD(_tc, _e, 5); \
807  ed->data[0] = pool_elts(_tc->sack_sb.holes); \
808  ed->data[1] = _tc->sack_sb.lost_bytes; \
809  ed->data[2] = _tc->sack_sb.sacked_bytes; \
810  ed->data[3] = _tc->sack_sb.high_sacked - _tc->iss; \
811  ed->data[4] = _tc->sack_sb.high_rxt - _tc->iss; \
812  } \
813 if (TCP_DEBUG_CC > 1 && _tc->sack_sb.last_sacked_bytes) \
814  { \
815  sack_scoreboard_hole_t *hole; \
816  hole = scoreboard_first_hole (&_tc->sack_sb); \
817  ELOG_TYPE_DECLARE (_e) = \
818  { \
819  .format = "sb2: first start: %u end %u last start %u end %u", \
820  .format_args = "i4i4i4i4", \
821  }; \
822  TCP_DECLARE_ETD(_tc, _e, 4); \
823  ed->data[0] = hole ? hole->start - _tc->iss : 0; \
824  ed->data[1] = hole ? hole->end - _tc->iss : 0; \
825  hole = scoreboard_last_hole (&_tc->sack_sb); \
826  ed->data[2] = hole ? hole->start - _tc->iss : 0; \
827  ed->data[3] = hole ? hole->end - _tc->iss : 0; \
828  } \
829 }
830 #define TCP_EVT_CC_SACKS_HANDLER(_tc, ...) \
831 { \
832 if (TCP_DEBUG_CC > 1) \
833  { \
834  ELOG_TYPE_DECLARE (_e) = \
835  { \
836  .format = "sacks: blocks %u bytes %u", \
837  .format_args = "i4i4", \
838  }; \
839  TCP_DECLARE_ETD(_tc, _e, 2); \
840  ed->data[0] = vec_len (_tc->snd_sacks); \
841  ed->data[1] = tcp_sack_list_bytes (_tc); \
842  } \
843 }
844 #define TCP_EVT_CC_INPUT_HANDLER(_tc, _len, _written, ...) \
845 { \
846  ELOG_TYPE_DECLARE (_e) = \
847  { \
848  .format = "cc input: len %u written %d rcv_nxt %u rcv_wnd(o) %d", \
849  .format_args = "i4i4i4i4", \
850  }; \
851  TCP_DECLARE_ETD(_tc, _e, 4); \
852  ed->data[0] = _len; \
853  ed->data[1] = _written; \
854  ed->data[2] = _tc->rcv_nxt - _tc->irs; \
855  ed->data[3] = _tc->rcv_wnd - (_tc->rcv_nxt - _tc->rcv_las); \
856 }
857 #else
858 #define TCP_EVT_CC_RTX_HANDLER(_tc, offset, n_bytes, ...)
859 #define TCP_EVT_DUPACK_SENT_HANDLER(_tc, _btcp, ...)
860 #define TCP_EVT_DUPACK_RCVD_HANDLER(_tc, ...)
861 #define TCP_EVT_CC_PACK_HANDLER(_tc, ...)
862 #define TCP_EVT_CC_SCOREBOARD_HANDLER(_tc, ...)
863 #define TCP_EVT_CC_SACKS_HANDLER(_tc, ...)
864 #define TCP_EVT_CC_INPUT_HANDLER(_tc, _len, _written, ...)
865 #endif
866 
867 /*
868  * Congestion control stats
869  */
870 #if TCP_DEBUG_CS || TCP_DEBUG_ALWAYS
871 
872 #define STATS_INTERVAL 1
873 
874 #define tcp_cc_time_to_print_stats(_tc) \
875  _tc->c_cc_stat_tstamp + STATS_INTERVAL < tcp_time_now() \
876  || tcp_in_fastrecovery (_tc) \
877 
878 #define TCP_EVT_CC_RTO_STAT_PRINT(_tc) \
879 { \
880  ELOG_TYPE_DECLARE (_e) = \
881  { \
882  .format = "rcv_stat: rto %u srtt %u mrtt-us %u rttvar %u", \
883  .format_args = "i4i4i4i4", \
884  }; \
885  TCP_DECLARE_ETD(_tc, _e, 4); \
886  ed->data[0] = _tc->rto; \
887  ed->data[1] = _tc->srtt; \
888  ed->data[2] = (u32) (_tc->mrtt_us * 1e6); \
889  ed->data[3] = _tc->rttvar; \
890 }
891 
892 #define TCP_EVT_CC_RTO_STAT_HANDLER(_tc, ...) \
893 { \
894 if (tcp_cc_time_to_print_stats (_tc)) \
895 { \
896  TCP_EVT_CC_RTO_STAT_PRINT (_tc); \
897  _tc->c_cc_stat_tstamp = tcp_time_now (); \
898 } \
899 }
900 
901 #define TCP_EVT_CC_SND_STAT_PRINT(_tc) \
902 { \
903  ELOG_TYPE_DECLARE (_e) = \
904  { \
905  .format = "snd_stat: cc_space %u sacked %u lost %u out %u rxt %u", \
906  .format_args = "i4i4i4i4i4", \
907  }; \
908  TCP_DECLARE_ETD(_tc, _e, 5); \
909  ed->data[0] = tcp_available_cc_snd_space (_tc); \
910  ed->data[1] = _tc->sack_sb.sacked_bytes; \
911  ed->data[2] = _tc->sack_sb.lost_bytes; \
912  ed->data[3] = tcp_bytes_out (_tc); \
913  ed->data[3] = _tc->snd_rxt_bytes; \
914 }
915 
916 #define TCP_EVT_CC_SND_STAT_HANDLER(_tc, ...) \
917 { \
918 if (tcp_cc_time_to_print_stats (_tc)) \
919 { \
920  TCP_EVT_CC_SND_STAT_PRINT(_tc); \
921  _tc->c_cc_stat_tstamp = tcp_time_now (); \
922 } \
923 }
924 
925 #define TCP_EVT_CC_STAT_PRINT(_tc) \
926 { \
927  ELOG_TYPE_DECLARE (_e) = \
928  { \
929  .format = "cc_stat: cwnd %u flight %u space %u ssthresh %u snd_wnd %u",\
930  .format_args = "i4i4i4i4i4", \
931  }; \
932  TCP_DECLARE_ETD(_tc, _e, 5); \
933  ed->data[0] = _tc->cwnd; \
934  ed->data[1] = tcp_flight_size (_tc); \
935  ed->data[2] = tcp_snd_space (_tc); \
936  ed->data[3] = _tc->ssthresh; \
937  ed->data[4] = _tc->snd_wnd; \
938  TCP_EVT_CC_RTO_STAT_PRINT (_tc); \
939  TCP_EVT_CC_SND_STAT_PRINT (_tc); \
940 }
941 
942 #define TCP_EVT_CC_STAT_HANDLER(_tc, ...) \
943 { \
944 if (tcp_cc_time_to_print_stats (_tc)) \
945 { \
946  TCP_EVT_CC_STAT_PRINT (_tc); \
947  _tc->c_cc_stat_tstamp = tcp_time_now(); \
948 } \
949 }
950 #else
951 #define TCP_EVT_CC_STAT_HANDLER(_tc, ...)
952 #define TCP_EVT_CC_STAT_PRINT(_tc)
953 #endif
954 
955 /*
956  * Buffer allocation
957  */
958 #if TCP_DEBUG_BUF_ALLOC
959 
960 #define TCP_DBG_BUFFER_ALLOC_MAYBE_FAIL(thread_index) \
961 { \
962  static u32 *buffer_fail_counters; \
963  if (PREDICT_FALSE (buffer_fail_counters == 0)) \
964  { \
965  u32 num_threads; \
966  vlib_thread_main_t *vtm = vlib_get_thread_main (); \
967  num_threads = 1 /* main thread */ + vtm->n_threads; \
968  vec_validate (buffer_fail_counters, num_threads - 1); \
969  } \
970  if (PREDICT_FALSE (tcp_cfg.buffer_fail_fraction != 0.0)) \
971  { \
972  if (PREDICT_TRUE (buffer_fail_counters[thread_index] > 0)) \
973  { \
974  if ((1.0 / (f32) (buffer_fail_counters[thread_index])) \
975  < tcp_cfg.buffer_fail_fraction) \
976  { \
977  buffer_fail_counters[thread_index] = 0.0000001; \
978  return -1; \
979  } \
980  } \
981  buffer_fail_counters[thread_index] ++; \
982  } \
983 }
984 #else
985 #define TCP_DBG_BUFFER_ALLOC_MAYBE_FAIL(thread_index)
986 #endif
987 
988 #endif /* SRC_VNET_TCP_TCP_DEBUG_H_ */
989 /*
990  * fd.io coding-style-patch-verification: ON
991  *
992  * Local Variables:
993  * eval: (c-set-style "gnu")
994  * End:
995  */
tcp_dbg_main_
Definition: tcp_debug.h:67
TCP_EVT_N_GRP
Definition: tcp_debug.h:64
tcp_evt_lvl_e
enum tcp_evt_lvl_ tcp_evt_lvl_e
tcp_evt_types_
tcp_evt_types_
Definition: tcp_debug.h:115
tcp_dbg_main_::free_track_indices
u32 * free_track_indices
Definition: tcp_debug.h:70
u8
unsigned char u8
Definition: types.h:56
foreach_tcp_evt_grp
#define foreach_tcp_evt_grp
Definition: tcp_debug.h:53
u32
unsigned int u32
Definition: types.h:88
tcp_dbg_main_::grp_dbg_lvl
u8 grp_dbg_lvl[TCP_EVT_N_GRP]
Definition: tcp_debug.h:69
tcp_evt_to_grp_
tcp_evt_to_grp_
Definition: tcp_debug.h:129
tcp_evt_track_register
void tcp_evt_track_register(elog_track_t *et)
Definition: tcp_debug.c:20
tcp_dbg_main
tcp_dbg_main_t tcp_dbg_main
Definition: tcp_debug.c:17
tcp_evt_grp_
tcp_evt_grp_
Definition: tcp_debug.h:59
elog_track_t
Definition: elog.h:113
tcp_evt_to_grp_e
enum tcp_evt_to_grp_ tcp_evt_to_grp_e
tcp_evt_lvl_
tcp_evt_lvl_
Definition: tcp_debug.h:122
tcp_debug_init
void tcp_debug_init(void)
tcp_dbg_main_t
struct tcp_dbg_main_ tcp_dbg_main_t
tcp_evt_types_e
enum tcp_evt_types_ tcp_evt_types_e
foreach_tcp_dbg_evt
#define foreach_tcp_dbg_evt
Definition: tcp_debug.h:75
tcp_evt_grp_e
enum tcp_evt_grp_ tcp_evt_grp_e