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