FD.io VPP  v19.01.3-6-g70449b9b9
Vector Packet Processing
tcp_debug.h
Go to the documentation of this file.
1 /*
2  * Copyright (c) 2017 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: %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: irs %u", \
205  .format_args = "i4", \
206  }; \
207  DECLARE_ETD(_tc, _e, 1); \
208  ed->data[0] = _tc->irs; \
209  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
210 }
211 
212 #define TCP_EVT_UNBIND_HANDLER(_tc, ...) \
213 { \
214  TCP_EVT_DEALLOC_HANDLER(_tc); \
215  ELOG_TYPE_DECLARE (_e) = \
216  { \
217  .format = "unbind: listener %d", \
218  }; \
219  DECLARE_ETD(_tc, _e, 1); \
220  ed->data[0] = _tc->c_c_index; \
221  TCP_EVT_DEALLOC_HANDLER(_tc); \
222 }
223 
224 #define TCP_EVT_DELETE_HANDLER(_tc, ...) \
225 { \
226  ELOG_TYPE_DECLARE (_e) = \
227  { \
228  .format = "delete: %d", \
229  .format_args = "i4", \
230  }; \
231  DECLARE_ETD(_tc, _e, 1); \
232  ed->data[0] = _tc->c_c_index; \
233  TCP_EVT_DEALLOC_HANDLER(_tc); \
234 }
235 
236 #define CONCAT_HELPER(_a, _b) _a##_b
237 #define CC(_a, _b) CONCAT_HELPER(_a, _b)
238 #define TCP_EVT_DBG(_evt, _args...) CC(_evt, _HANDLER)(_args)
239 #else
240 #define TCP_EVT_DBG(_evt, _args...)
241 #define TCP_DBG(_fmt, _args...)
242 #endif
243 
244 /*
245  * State machine
246  */
247 #if TCP_DEBUG_SM
248 
249 #define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...) \
250 { \
251  ELOG_TYPE_DECLARE (_e) = \
252  { \
253  .format = "state: %s", \
254  .format_args = "t4", \
255  .n_enum_strings = 11, \
256  .enum_strings = { \
257  "closed", \
258  "listen", \
259  "syn-sent", \
260  "syn-rcvd", \
261  "established", \
262  "close_wait", \
263  "fin-wait-1", \
264  "last-ack", \
265  "closing", \
266  "fin-wait-2", \
267  "time-wait", \
268  }, \
269  }; \
270  DECLARE_ETD(_tc, _e, 1); \
271  ed->data[0] = _tc->state; \
272 }
273 
274 #define TCP_EVT_SYN_SENT_HANDLER(_tc, ...) \
275 { \
276  ELOG_TYPE_DECLARE (_e) = \
277  { \
278  .format = "syn-tx: iss %u snd_una %u snd_una_max %u snd_nxt %u", \
279  .format_args = "i4i4i4i4", \
280  }; \
281  DECLARE_ETD(_tc, _e, 4); \
282  ed->data[0] = _tc->iss; \
283  ed->data[1] = _tc->snd_una - _tc->iss; \
284  ed->data[2] = _tc->snd_una_max - _tc->iss; \
285  ed->data[3] = _tc->snd_nxt - _tc->iss; \
286  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
287 }
288 
289 #define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...) \
290 { \
291  ELOG_TYPE_DECLARE (_e) = \
292  { \
293  .format = "synack-tx: iss %u irs %u snd_una %u snd_nxt %u rcv_nxt %u",\
294  .format_args = "i4i4i4i4i4", \
295  }; \
296  DECLARE_ETD(_tc, _e, 5); \
297  ed->data[0] = _tc->iss; \
298  ed->data[1] = _tc->irs; \
299  ed->data[2] = _tc->snd_una - _tc->iss; \
300  ed->data[3] = _tc->snd_nxt - _tc->iss; \
301  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
302 }
303 
304 #define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...) \
305 { \
306  ELOG_TYPE_DECLARE (_e) = \
307  { \
308  .format = "synack-rx: iss %u irs %u snd_una %u snd_nxt %u rcv_nxt %u",\
309  .format_args = "i4i4i4i4i4", \
310  }; \
311  DECLARE_ETD(_tc, _e, 5); \
312  ed->data[0] = _tc->iss; \
313  ed->data[1] = _tc->irs; \
314  ed->data[2] = _tc->snd_una - _tc->iss; \
315  ed->data[3] = _tc->snd_nxt - _tc->iss; \
316  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
317  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
318 }
319 
320 #define TCP_EVT_FIN_SENT_HANDLER(_tc, ...) \
321 { \
322  ELOG_TYPE_DECLARE (_e) = \
323  { \
324  .format = "fin-tx: snd_nxt %d rcv_nxt %d", \
325  .format_args = "i4i4", \
326  }; \
327  DECLARE_ETD(_tc, _e, 2); \
328  ed->data[0] = _tc->snd_nxt - _tc->iss; \
329  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
330 }
331 
332 #define TCP_EVT_RST_SENT_HANDLER(_tc, ...) \
333 { \
334 if (_tc) \
335  { \
336  ELOG_TYPE_DECLARE (_e) = \
337  { \
338  .format = "rst-tx: snd_nxt %d rcv_nxt %d", \
339  .format_args = "i4i4", \
340  }; \
341  DECLARE_ETD(_tc, _e, 2); \
342  ed->data[0] = _tc->snd_nxt - _tc->iss; \
343  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
344  TCP_EVT_STATE_CHANGE_HANDLER(_tc); \
345  } \
346 }
347 
348 #define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...) \
349 { \
350  ELOG_TYPE_DECLARE (_e) = \
351  { \
352  .format = "fin-rx: snd_nxt %d rcv_nxt %d", \
353  .format_args = "i4i4", \
354  }; \
355  DECLARE_ETD(_tc, _e, 2); \
356  ed->data[0] = _tc->snd_nxt - _tc->iss; \
357  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
358 }
359 
360 #define TCP_EVT_RST_RCVD_HANDLER(_tc, ...) \
361 { \
362  ELOG_TYPE_DECLARE (_e) = \
363  { \
364  .format = "rst-rx: snd_nxt %d rcv_nxt %d", \
365  .format_args = "i4i4", \
366  }; \
367  DECLARE_ETD(_tc, _e, 2); \
368  ed->data[0] = _tc->snd_nxt - _tc->iss; \
369  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
370 }
371 
372 #define TCP_EVT_SYN_RXT_HANDLER(_tc, _type, ...) \
373 { \
374  ELOG_TYPE_DECLARE (_e) = \
375  { \
376  .format = "%s-rxt: iss %u irs %u snd_nxt %u rcv_nxt %u", \
377  .format_args = "t4i4i4i4i4", \
378  .n_enum_strings = 2, \
379  .enum_strings = { \
380  "syn", \
381  "syn-ack", \
382  }, \
383  }; \
384  DECLARE_ETD(_tc, _e, 5); \
385  ed->data[0] = _type; \
386  ed->data[1] = _tc->iss; \
387  ed->data[2] = _tc->irs; \
388  ed->data[3] = _tc->snd_nxt - _tc->iss; \
389  ed->data[4] = _tc->rcv_nxt - _tc->irs; \
390 }
391 
392 #define TCP_EVT_TIMER_POP_HANDLER(_tc_index, _timer_id, ...) \
393 { \
394  tcp_connection_t *_tc; \
395  if (_timer_id == TCP_TIMER_RETRANSMIT_SYN \
396  || _timer_id == TCP_TIMER_ESTABLISH_AO) \
397  { \
398  _tc = tcp_half_open_connection_get (_tc_index); \
399  } \
400  else \
401  { \
402  u32 _thread_index = vlib_get_thread_index (); \
403  _tc = tcp_connection_get (_tc_index, _thread_index); \
404  } \
405  ELOG_TYPE_DECLARE (_e) = \
406  { \
407  .format = "timer-pop: %s (%d)", \
408  .format_args = "t4i4", \
409  .n_enum_strings = 8, \
410  .enum_strings = { \
411  "retransmit", \
412  "delack", \
413  "persist", \
414  "keep", \
415  "waitclose", \
416  "retransmit syn", \
417  "establish", \
418  "establish-ao", \
419  }, \
420  }; \
421  if (_tc) \
422  { \
423  DECLARE_ETD(_tc, _e, 2); \
424  ed->data[0] = _timer_id; \
425  ed->data[1] = _timer_id; \
426  } \
427  else \
428  { \
429  clib_warning ("pop %d for unexisting connection %d", _timer_id, \
430  _tc_index); \
431  } \
432 }
433 
434 #else
435 #define TCP_EVT_SYN_SENT_HANDLER(_tc, ...)
436 #define TCP_EVT_SYNACK_SENT_HANDLER(_tc, ...)
437 #define TCP_EVT_SYNACK_RCVD_HANDLER(_tc, ...)
438 #define TCP_EVT_SYN_RXT_HANDLER(_tc, ...)
439 #define TCP_EVT_FIN_SENT_HANDLER(_tc, ...)
440 #define TCP_EVT_RST_SENT_HANDLER(_tc, ...)
441 #define TCP_EVT_FIN_RCVD_HANDLER(_tc, ...)
442 #define TCP_EVT_RST_RCVD_HANDLER(_tc, ...)
443 #define TCP_EVT_STATE_CHANGE_HANDLER(_tc, ...)
444 #define TCP_EVT_TIMER_POP_HANDLER(_tc_index, _timer_id, ...)
445 #endif
446 
447 #if TCP_DEBUG_SM > 1
448 #define TCP_EVT_SEG_INVALID_HANDLER(_tc, _btcp, ...) \
449 { \
450  ELOG_TYPE_DECLARE (_e) = \
451  { \
452  .format = "seg-inv: seq %u end %u rcv_las %u rcv_nxt %u rcv_wnd %u",\
453  .format_args = "i4i4i4i4i4", \
454  }; \
455  DECLARE_ETD(_tc, _e, 5); \
456  ed->data[0] = _btcp.seq_number - _tc->irs; \
457  ed->data[1] = _btcp.seq_end - _tc->irs; \
458  ed->data[2] = _tc->rcv_las - _tc->irs; \
459  ed->data[3] = _tc->rcv_nxt - _tc->irs; \
460  ed->data[4] = _tc->rcv_wnd; \
461 }
462 
463 #define TCP_EVT_PAWS_FAIL_HANDLER(_tc, _seq, _end, ...) \
464 { \
465  ELOG_TYPE_DECLARE (_e) = \
466  { \
467  .format = "paws-err: seq %u end %u tsval %u tsval_recent %u", \
468  .format_args = "i4i4i4i4", \
469  }; \
470  DECLARE_ETD(_tc, _e, 4); \
471  ed->data[0] = _seq - _tc->irs; \
472  ed->data[1] = _end - _tc->irs; \
473  ed->data[2] = _tc->rcv_opts.tsval; \
474  ed->data[3] = _tc->tsval_recent; \
475 }
476 
477 #define TCP_EVT_ACK_RCV_ERR_HANDLER(_tc, _type, _ack, ...) \
478 { \
479  ELOG_TYPE_DECLARE (_e) = \
480  { \
481  .format = "ack-err: %s ack %u snd_una %u snd_nxt %u una_max %u", \
482  .format_args = "t4i4i4i4i4", \
483  .n_enum_strings = 3, \
484  .enum_strings = { \
485  "invalid", \
486  "old", \
487  "future", \
488  }, \
489  }; \
490  DECLARE_ETD(_tc, _e, 5); \
491  ed->data[0] = _type; \
492  ed->data[1] = _ack - _tc->iss; \
493  ed->data[2] = _tc->snd_una - _tc->iss; \
494  ed->data[3] = _tc->snd_nxt - _tc->iss; \
495  ed->data[4] = _tc->snd_una_max - _tc->iss; \
496 }
497 
498 #define TCP_EVT_RCV_WND_SHRUNK_HANDLER(_tc, _obs, _av, ...) \
499 { \
500 if (_av > 0) \
501 { \
502  ELOG_TYPE_DECLARE (_e) = \
503  { \
504  .format = "huh?: rcv_wnd %u obsd %u av %u rcv_nxt %u rcv_las %u", \
505  .format_args = "i4i4i4i4i4", \
506  }; \
507  DECLARE_ETD(_tc, _e, 5); \
508  ed->data[0] = _tc->rcv_wnd; \
509  ed->data[1] = _obs; \
510  ed->data[2] = _av; \
511  ed->data[3] = _tc->rcv_nxt - _tc->irs; \
512  ed->data[4] = _tc->rcv_las - _tc->irs; \
513 } \
514 }
515 #else
516 #define TCP_EVT_SEG_INVALID_HANDLER(_tc, _btcp, ...)
517 #define TCP_EVT_PAWS_FAIL_HANDLER(_tc, _seq, _end, ...)
518 #define TCP_EVT_ACK_RCV_ERR_HANDLER(_tc, _type, _ack, ...)
519 #define TCP_EVT_RCV_WND_SHRUNK_HANDLER(_tc, _obs, _av, ...)
520 #endif
521 
522 #if TCP_DEBUG_SM > 2
523 
524 #define TCP_EVT_ACK_SENT_HANDLER(_tc, ...) \
525 { \
526  ELOG_TYPE_DECLARE (_e) = \
527  { \
528  .format = "ack-tx: acked %u rcv_nxt %u rcv_wnd %u snd_nxt %u snd_wnd %u",\
529  .format_args = "i4i4i4i4i4", \
530  }; \
531  DECLARE_ETD(_tc, _e, 5); \
532  ed->data[0] = _tc->rcv_nxt - _tc->rcv_las; \
533  ed->data[1] = _tc->rcv_nxt - _tc->irs; \
534  ed->data[2] = _tc->rcv_wnd; \
535  ed->data[3] = _tc->snd_nxt - _tc->iss; \
536  ed->data[4] = _tc->snd_wnd; \
537 }
538 
539 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...) \
540 { \
541  ELOG_TYPE_DECLARE (_e) = \
542  { \
543  .format = "ack-rx: %u snd_una %u snd_wnd %u cwnd %u inflight %u", \
544  .format_args = "i4i4i4i4i4", \
545  }; \
546  DECLARE_ETD(_tc, _e, 5); \
547  ed->data[0] = _tc->bytes_acked; \
548  ed->data[1] = _tc->snd_una - _tc->iss; \
549  ed->data[2] = _tc->snd_wnd; \
550  ed->data[3] = _tc->cwnd; \
551  ed->data[4] = tcp_flight_size(_tc); \
552 }
553 
554 #define TCP_EVT_PKTIZE_HANDLER(_tc, ...) \
555 { \
556  ELOG_TYPE_DECLARE (_e) = \
557  { \
558  .format = "tx: una %u snd_nxt %u space %u flight %u rcv_wnd %u",\
559  .format_args = "i4i4i4i4i4", \
560  }; \
561  DECLARE_ETD(_tc, _e, 5); \
562  ed->data[0] = _tc->snd_una - _tc->iss; \
563  ed->data[1] = _tc->snd_nxt - _tc->iss; \
564  ed->data[2] = tcp_available_output_snd_space (_tc); \
565  ed->data[3] = tcp_flight_size (_tc); \
566  ed->data[4] = _tc->rcv_wnd; \
567 }
568 
569 #define TCP_EVT_INPUT_HANDLER(_tc, _type, _len, _written, ...) \
570 { \
571  ELOG_TYPE_DECLARE (_e) = \
572  { \
573  .format = "in: %s len %u written %d rcv_nxt %u rcv_wnd(o) %d", \
574  .format_args = "t4i4i4i4i4", \
575  .n_enum_strings = 2, \
576  .enum_strings = { \
577  "order", \
578  "ooo", \
579  }, \
580  }; \
581  DECLARE_ETD(_tc, _e, 5); \
582  ed->data[0] = _type; \
583  ed->data[1] = _len; \
584  ed->data[2] = _written; \
585  ed->data[3] = (_tc->rcv_nxt - _tc->irs) + _written; \
586  ed->data[4] = _tc->rcv_wnd - (_tc->rcv_nxt - _tc->rcv_las); \
587 }
588 
589 #else
590 #define TCP_EVT_ACK_SENT_HANDLER(_tc, ...)
591 #define TCP_EVT_ACK_RCVD_HANDLER(_tc, ...)
592 #define TCP_EVT_PKTIZE_HANDLER(_tc, ...)
593 #define TCP_EVT_INPUT_HANDLER(_tc, _type, _len, _written, ...)
594 #endif
595 
596 /*
597  * State machine verbose
598  */
599 #if TCP_DEBUG_SM > 3
600 #define TCP_EVT_SND_WND_HANDLER(_tc, ...) \
601 { \
602  ELOG_TYPE_DECLARE (_e) = \
603  { \
604  .format = "snd-wnd update: %u ", \
605  .format_args = "i4", \
606  }; \
607  DECLARE_ETD(_tc, _e, 1); \
608  ed->data[0] = _tc->snd_wnd; \
609 }
610 
611 #define TCP_EVT_OUTPUT_HANDLER(_tc, flags, n_bytes,...) \
612 { \
613  ELOG_TYPE_DECLARE (_e) = \
614  { \
615  .format = "out: flags %x, bytes %u", \
616  .format_args = "i4i4", \
617  }; \
618  DECLARE_ETD(_tc, _e, 2); \
619  ed->data[0] = flags; \
620  ed->data[1] = n_bytes; \
621 }
622 #else
623 #define TCP_EVT_SND_WND_HANDLER(_tc, ...)
624 #define TCP_EVT_OUTPUT_HANDLER(_tc, flags, n_bytes,...)
625 #endif
626 
627 /*
628  * Congestion Control
629  */
630 
631 #if TCP_DEBUG_CC
632 
633 #define TCP_EVT_CC_EVT_PRINT(_tc, _sub_evt) \
634 { \
635  ELOG_TYPE_DECLARE (_e) = \
636  { \
637  .format = "cc: %s snd_space %u snd_una %u out %u flight %u", \
638  .format_args = "t4i4i4i4i4", \
639  .n_enum_strings = 7, \
640  .enum_strings = { \
641  "fast-rxt", \
642  "first-rxt", \
643  "rxt-timeout", \
644  "recovered", \
645  "congestion", \
646  "undo", \
647  "recovery", \
648  }, \
649  }; \
650  DECLARE_ETD(_tc, _e, 5); \
651  ed->data[0] = _sub_evt; \
652  ed->data[1] = tcp_available_cc_snd_space (_tc); \
653  ed->data[2] = _tc->snd_una - _tc->iss; \
654  ed->data[3] = tcp_bytes_out(_tc); \
655  ed->data[4] = tcp_flight_size (_tc); \
656 }
657 
658 #define TCP_EVT_CC_EVT_HANDLER(_tc, _sub_evt, ...) \
659 { \
660  if (_tc->snd_una != _tc->iss) \
661  TCP_EVT_CC_STAT_PRINT (_tc); \
662  if ((_sub_evt <= 1 && TCP_DEBUG_CC > 1) \
663  || (_sub_evt > 1 && TCP_DEBUG_CC > 0)) \
664  TCP_EVT_CC_EVT_PRINT (_tc, _sub_evt); \
665 }
666 #else
667 #define TCP_EVT_CC_EVT_HANDLER(_tc, _sub_evt, ...) \
668 
669 #endif
670 
671 #if TCP_DEBUG_CC > 1
672 #define TCP_EVT_CC_RTX_HANDLER(_tc, offset, n_bytes, ...) \
673 { \
674  ELOG_TYPE_DECLARE (_e) = \
675  { \
676  .format = "rxt: snd_nxt %u offset %u snd %u rxt %u", \
677  .format_args = "i4i4i4i4", \
678  }; \
679  DECLARE_ETD(_tc, _e, 4); \
680  ed->data[0] = _tc->snd_nxt - _tc->iss; \
681  ed->data[1] = offset; \
682  ed->data[2] = n_bytes; \
683  ed->data[3] = _tc->snd_rxt_bytes; \
684 }
685 
686 #define TCP_EVT_DUPACK_SENT_HANDLER(_tc, _btcp, ...) \
687 { \
688  ELOG_TYPE_DECLARE (_e) = \
689  { \
690  .format = "dack-tx: rcv_nxt %u seq %u rcv_wnd %u snd_nxt %u av_wnd %u",\
691  .format_args = "i4i4i4i4i4", \
692  }; \
693  DECLARE_ETD(_tc, _e, 5); \
694  ed->data[0] = _tc->rcv_nxt - _tc->irs; \
695  ed->data[1] = _btcp.seq_number - _tc->irs; \
696  ed->data[2] = _tc->rcv_wnd; \
697  ed->data[3] = _tc->snd_nxt - _tc->iss; \
698  ed->data[4] = tcp_available_snd_wnd(_tc); \
699 }
700 
701 #define TCP_EVT_DUPACK_RCVD_HANDLER(_tc, ...) \
702 { \
703  ELOG_TYPE_DECLARE (_e) = \
704  { \
705  .format = "dack-rx: snd_una %u cwnd %u snd_wnd %u flight %u rcv_wnd %u",\
706  .format_args = "i4i4i4i4i4", \
707  }; \
708  DECLARE_ETD(_tc, _e, 5); \
709  ed->data[0] = _tc->snd_una - _tc->iss; \
710  ed->data[1] = _tc->cwnd; \
711  ed->data[2] = _tc->snd_wnd; \
712  ed->data[3] = tcp_flight_size(_tc); \
713  ed->data[4] = _tc->rcv_wnd; \
714 }
715 
716 #define TCP_EVT_CC_PACK_HANDLER(_tc, ...) \
717 { \
718  ELOG_TYPE_DECLARE (_e) = \
719  { \
720  .format = "pack: snd_una %u snd_una_max %u", \
721  .format_args = "i4i4", \
722  }; \
723  DECLARE_ETD(_tc, _e, 2); \
724  ed->data[0] = _tc->snd_una - _tc->iss; \
725  ed->data[1] = _tc->snd_una_max - _tc->iss; \
726 }
727 #define TCP_EVT_CC_SCOREBOARD_HANDLER(_tc, ...) \
728 { \
729 if (TCP_DEBUG_CC > 1 && _tc->sack_sb.last_sacked_bytes) \
730  { \
731  ELOG_TYPE_DECLARE (_e) = \
732  { \
733  .format = "sb1: holes %u lost %u sacked %u high %u highrxt %u", \
734  .format_args = "i4i4i4i4i4", \
735  }; \
736  DECLARE_ETD(_tc, _e, 5); \
737  ed->data[0] = pool_elts(_tc->sack_sb.holes); \
738  ed->data[1] = _tc->sack_sb.lost_bytes; \
739  ed->data[2] = _tc->sack_sb.sacked_bytes; \
740  ed->data[3] = _tc->sack_sb.high_sacked - _tc->iss; \
741  ed->data[4] = _tc->sack_sb.high_rxt - _tc->iss; \
742  } \
743 if (TCP_DEBUG_CC > 1 && _tc->sack_sb.last_sacked_bytes) \
744  { \
745  sack_scoreboard_hole_t *hole; \
746  hole = scoreboard_first_hole (&_tc->sack_sb); \
747  ELOG_TYPE_DECLARE (_e) = \
748  { \
749  .format = "sb2: first start: %u end %u last start %u end %u", \
750  .format_args = "i4i4i4i4", \
751  }; \
752  DECLARE_ETD(_tc, _e, 4); \
753  ed->data[0] = hole ? hole->start - _tc->iss : 0; \
754  ed->data[1] = hole ? hole->end - _tc->iss : 0; \
755  hole = scoreboard_last_hole (&_tc->sack_sb); \
756  ed->data[2] = hole ? hole->start - _tc->iss : 0; \
757  ed->data[3] = hole ? hole->end - _tc->iss : 0; \
758  } \
759 }
760 #define TCP_EVT_CC_SACKS_HANDLER(_tc, ...) \
761 { \
762 if (TCP_DEBUG_CC > 1) \
763  { \
764  ELOG_TYPE_DECLARE (_e) = \
765  { \
766  .format = "sacks: blocks %u bytes %u", \
767  .format_args = "i4i4", \
768  }; \
769  DECLARE_ETD(_tc, _e, 2); \
770  ed->data[0] = vec_len (_tc->snd_sacks); \
771  ed->data[1] = tcp_sack_list_bytes (_tc); \
772  } \
773 }
774 #define TCP_EVT_CC_INPUT_HANDLER(_tc, _len, _written, ...) \
775 { \
776  ELOG_TYPE_DECLARE (_e) = \
777  { \
778  .format = "cc input: len %u written %d rcv_nxt %u rcv_wnd(o) %d", \
779  .format_args = "i4i4i4i4", \
780  }; \
781  DECLARE_ETD(_tc, _e, 4); \
782  ed->data[0] = _len; \
783  ed->data[1] = _written; \
784  ed->data[2] = _tc->rcv_nxt - _tc->irs; \
785  ed->data[3] = _tc->rcv_wnd - (_tc->rcv_nxt - _tc->rcv_las); \
786 }
787 #else
788 #define TCP_EVT_CC_RTX_HANDLER(_tc, offset, n_bytes, ...)
789 #define TCP_EVT_DUPACK_SENT_HANDLER(_tc, _btcp, ...)
790 #define TCP_EVT_DUPACK_RCVD_HANDLER(_tc, ...)
791 #define TCP_EVT_CC_PACK_HANDLER(_tc, ...)
792 #define TCP_EVT_CC_SCOREBOARD_HANDLER(_tc, ...)
793 #define TCP_EVT_CC_SACKS_HANDLER(_tc, ...)
794 #define TCP_EVT_CC_INPUT_HANDLER(_tc, _len, _written, ...)
795 #endif
796 
797 /*
798  * Congestion control stats
799  */
800 #if TCP_DEBUG_CC_STAT
801 
802 #define STATS_INTERVAL 1
803 
804 #define tcp_cc_time_to_print_stats(_tc) \
805  _tc->c_cc_stat_tstamp + STATS_INTERVAL < tcp_time_now() \
806  || tcp_in_fastrecovery (_tc) \
807 
808 #define TCP_EVT_CC_RTO_STAT_PRINT(_tc) \
809 { \
810  ELOG_TYPE_DECLARE (_e) = \
811  { \
812  .format = "rcv_stat: rto %u srtt %u mrtt-us %u rttvar %u", \
813  .format_args = "i4i4i4i4", \
814  }; \
815  DECLARE_ETD(_tc, _e, 4); \
816  ed->data[0] = _tc->rto; \
817  ed->data[1] = _tc->srtt; \
818  ed->data[2] = (u32) (_tc->mrtt_us * 1e6); \
819  ed->data[3] = _tc->rttvar; \
820 }
821 
822 #define TCP_EVT_CC_RTO_STAT_HANDLER(_tc, ...) \
823 { \
824 if (tcp_cc_time_to_print_stats (_tc)) \
825 { \
826  TCP_EVT_CC_RTO_STAT_PRINT (_tc); \
827  _tc->c_cc_stat_tstamp = tcp_time_now (); \
828 } \
829 }
830 
831 #define TCP_EVT_CC_SND_STAT_PRINT(_tc) \
832 { \
833  ELOG_TYPE_DECLARE (_e) = \
834  { \
835  .format = "snd_stat: cc_space %u sacked %u lost %u out %u rxt %u", \
836  .format_args = "i4i4i4i4i4", \
837  }; \
838  DECLARE_ETD(_tc, _e, 5); \
839  ed->data[0] = tcp_available_cc_snd_space (_tc); \
840  ed->data[1] = _tc->sack_sb.sacked_bytes; \
841  ed->data[2] = _tc->sack_sb.lost_bytes; \
842  ed->data[3] = tcp_bytes_out (_tc); \
843  ed->data[3] = _tc->snd_rxt_bytes; \
844 }
845 
846 #define TCP_EVT_CC_SND_STAT_HANDLER(_tc, ...) \
847 { \
848 if (tcp_cc_time_to_print_stats (_tc)) \
849 { \
850  TCP_EVT_CC_SND_STAT_PRINT(_tc); \
851  _tc->c_cc_stat_tstamp = tcp_time_now (); \
852 } \
853 }
854 
855 #define TCP_EVT_CC_STAT_PRINT(_tc) \
856 { \
857  ELOG_TYPE_DECLARE (_e) = \
858  { \
859  .format = "cc_stat: cwnd %u flight %u space %u ssthresh %u snd_wnd %u",\
860  .format_args = "i4i4i4i4i4", \
861  }; \
862  DECLARE_ETD(_tc, _e, 5); \
863  ed->data[0] = _tc->cwnd; \
864  ed->data[1] = tcp_flight_size (_tc); \
865  ed->data[2] = tcp_snd_space (_tc); \
866  ed->data[3] = _tc->ssthresh; \
867  ed->data[4] = _tc->snd_wnd; \
868  TCP_EVT_CC_RTO_STAT_PRINT (_tc); \
869  TCP_EVT_CC_SND_STAT_PRINT (_tc); \
870 }
871 
872 #define TCP_EVT_CC_STAT_HANDLER(_tc, ...) \
873 { \
874 if (tcp_cc_time_to_print_stats (_tc)) \
875 { \
876  TCP_EVT_CC_STAT_PRINT (_tc); \
877  _tc->c_cc_stat_tstamp = tcp_time_now(); \
878 } \
879 }
880 #else
881 #define TCP_EVT_CC_STAT_HANDLER(_tc, ...)
882 #define TCP_EVT_CC_STAT_PRINT(_tc)
883 #endif
884 
885 /*
886  * Buffer allocation
887  */
888 #if TCP_DEBUG_BUFFER_ALLOCATION
889 
890 #define TCP_DBG_BUFFER_ALLOC_MAYBE_FAIL(thread_index) \
891 { \
892  static u32 *buffer_fail_counters; \
893  if (PREDICT_FALSE (buffer_fail_counters == 0)) \
894  { \
895  u32 num_threads; \
896  vlib_thread_main_t *vtm = vlib_get_thread_main (); \
897  num_threads = 1 /* main thread */ + vtm->n_threads; \
898  vec_validate (buffer_fail_counters, num_threads - 1); \
899  } \
900  if (PREDICT_FALSE (tcp_main.buffer_fail_fraction != 0.0)) \
901  { \
902  if (PREDICT_TRUE (buffer_fail_counters[thread_index] > 0)) \
903  { \
904  if ((1.0 / (f32) (buffer_fail_counters[thread_index])) \
905  < tcp_main.buffer_fail_fraction) \
906  { \
907  buffer_fail_counters[thread_index] = 0.0000001; \
908  return -1; \
909  } \
910  } \
911  buffer_fail_counters[thread_index] ++; \
912  } \
913 }
914 #else
915 #define TCP_DBG_BUFFER_ALLOC_MAYBE_FAIL(thread_index)
916 #endif
917 
918 #endif /* SRC_VNET_TCP_TCP_DEBUG_H_ */
919 /*
920  * fd.io coding-style-patch-verification: ON
921  *
922  * Local Variables:
923  * eval: (c-set-style "gnu")
924  * End:
925  */
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