AW: panic: sackhint bytes rtx >= 0
Scheffenegger, Richard
Richard.Scheffenegger at netapp.com
Tue Feb 23 22:40:24 UTC 2021
Hi Andriy,
I guess I am currently the person who has the most recent knowledge about that part of the base stack...
Do you happen to have more (preceding) information about this, or a way to reproduce this?
Are you running any special stack (RACK, BBR) which may have switched back to the base stack in the middle of a loss recovery (I suspected at one point that this may cause issues, potentially)?
Or was something done with the ipfw that may have temporarily impacted a tcp session?
The accounting with sack_bytes_rexmit is rather old, and not touched recently (but the sackhint struct was changed recently, and other/additional scoreboard accounting was added).
(kgdb) p *cur
$1 = {start = 3846347980, end = 3846352300, rxmit = 3846352300, scblink =
{tqe_next = 0xfffff8013da5a220, tqe_prev = 0xfffff80754818930}}
This indicates, that the current hole in the SACK scoreboard (3 segments of size 1440 bytes) were retransmitted (rxmit == end), before the current acknowledgement came back.
Thus the expectation is, that sackhint.sack_bytes_rexmit also has a value of at least that number of bytes (4320). It is increased in tcp_output() for each packet leaving while performing a retransmission.
But this is the peculiar part:
(kgdb) p tp at entry->sackhint.sack_bytes_rexmit<mailto:tp at entry-%3esackhint.sack_bytes_rexmit>
$3 = -1440
Indicating negative one packet had been retransmitted before (thus subtracting the hole, which was previously retransmitted violates the invariant). And the only piece of code decrementing it appears to be in tcp_output() during non-permanent error handling...
All updates to sackhint should be protected by the INPLOCK, so even if the rx and tx paths are running on different core, the sack_bytes_rexmit should never become negative.
The sack blocks returned indicate that (with snd.una as zero baseline, in segments) the client knows about segments 2..34 and 35..47.
The first hole has shrunk from the right (unusual; possible when two retransmissions were lost again, or the 3 segment originally sent, delayed by ~50 segments (unlikely).
Sorry to not being able to spot something obvious right away...
Richard Scheffenegger
Consulting Solution Architect
NAS & Networking
NetApp
+43 1 3676 811 3157 Direct Phone
+43 664 8866 1857 Mobile Phone
Richard.Scheffenegger at netapp.com<mailto:Richard.Scheffenegger at netapp.com>
https://ts.la/richard49892
Von: tuexen at freebsd.org <tuexen at freebsd.org>
Gesendet: Dienstag, 23. Februar 2021 22:21
An: Richard Scheffenegger <rscheff at freebsd.org>
Betreff: Fwd: panic: sackhint bytes rtx >= 0
NetApp Security WARNING: This is an external email. Do not click links or open attachments unless you recognize the sender and know the content is safe.
FYI
Begin forwarded message:
From: Andriy Gapon <avg at FreeBSD.org<mailto:avg at FreeBSD.org>>
Subject: panic: sackhint bytes rtx >= 0
Date: 23. February 2021 at 22:02:20 CET
To: FreeBSD Current <current at FreeBSD.org<mailto:current at FreeBSD.org>>, net at FreeBSD.org<mailto:net at FreeBSD.org>
Got this panic on 13.0-STABLE 4b2a20dfde9c using a custom kernel with INVARIANTS
enabled.
Below is some information from the crash dump.
If anyone has any clues, suggestions, etc, please help.
I will try to help you to help me the best I can.
#0 doadump (textdump=textdump at entry=1)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:399
#1 0xffffffff808396b2 in kern_reboot (howto=260)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:486
#2 0xffffffff80839d07 in vpanic (
fmt=0xffffffff80cbd551 "sackhint bytes rtx >= 0", ap=0xfffffe0120b9e6d0)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:919
#3 0xffffffff808398b3 in panic (fmt=<unavailable>)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:843
#4 0xffffffff8098a82c in tcp_sack_doack (tp=<optimized out>,
tp at entry=0xfffff807548187f0, to=<optimized out>,
to at entry=0xfffffe0120b9e780, th_ack=<optimized out>)
at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691
#5 0xffffffff80983699 in tcp_do_segment (m=0xfffff8029868ca00,
m at entry=<error reading variable: value is not available>,
th=<optimized out>,
th at entry=<error reading variable: value is not available>,
so=0xfffff804e7359b10,
so at entry=<error reading variable: value is not available>,
tp=0xfffff807548187f0,
tp at entry=<error reading variable: value is not available>,
drop_hdrlen=60,
drop_hdrlen at entry=<error reading variable: value is not available>,
tlen=<optimized out>,
tlen at entry=<error reading variable: value is not available>,
iptos=72 'H',
iptos at entry=<error reading variable: value is not available>)
at /usr/devel/git/trant/sys/netinet/tcp_input.c:2497
#6 0xffffffff80980d97 in tcp_input (mp=<optimized out>,
mp at entry=<error reading variable: value is not available>,
offp=<optimized out>,
offp at entry=<error reading variable: value is not available>,
proto=<optimized out>)
at /usr/devel/git/trant/sys/netinet/tcp_input.c:1381
#7 0xffffffff80976eb7 in ip_input (m=0x0)
at /usr/devel/git/trant/sys/netinet/ip_input.c:833
#8 0xffffffff8094c78f in netisr_dispatch_src (proto=1,
source=source at entry=0, m=0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1143
#9 0xffffffff8094cb0e in netisr_dispatch (proto=<unavailable>,
m=<unavailable>) at /usr/devel/git/trant/sys/net/netisr.c:1234
#10 0xffffffff80943345 in ether_demux (ifp=ifp at entry=0xfffff80008c75000,
m=<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:923
#11 0xffffffff809446c1 in ether_input_internal (ifp=0xfffff80008c75000,
m=<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:709
#12 0xffffffff809443d0 in ether_nh_input (m=<unavailable>)
at /usr/devel/git/trant/sys/net/if_ethersubr.c:739
#13 0xffffffff8094c78f in netisr_dispatch_src (proto=proto at entry=5,
source=source at entry=0, m=m at entry=0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1143
#14 0xffffffff8094cb0e in netisr_dispatch (proto=<unavailable>,
proto at entry=5, m=<unavailable>, m at entry=0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1234
#15 0xffffffff8094383d in ether_input (ifp=0xfffff80008c75000,
ifp at entry=<error reading variable: value is not available>,
m=0xfffff8029868ca00,
m at entry=<error reading variable: value is not available>)
at /usr/devel/git/trant/sys/net/if_ethersubr.c:830
#16 0xffffffff8066da13 in re_rxeof (sc=sc at entry=0xfffffe00391a5000,
rx_npktsp=0x0) at /usr/devel/git/trant/sys/dev/re/if_re.c:2388
#17 0xffffffff8066b3ab in re_intr_msi (xsc=0xfffffe00391a5000)
at /usr/devel/git/trant/sys/dev/re/if_re.c:2684
#18 0xffffffff80801bcf in intr_event_execute_handlers (
p=p at entry=0xfffff80006a94a50, ie=ie at entry=0xfffff80008c57800)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1168
#19 0xffffffff80801942 in ithread_execute_handlers (
p=p at entry=0xfffff80006a94a50, ie=ie at entry=0xfffff80008c57800)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1181
#20 0xffffffff80801758 in ithread_loop (arg=arg at entry=0xfffff80008c20c40)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1269
#21 0xffffffff807fe0a9 in fork_exit (
callout=0xffffffff808016c0 <ithread_loop>, arg=0xfffff80008c20c40,
frame=0xfffffe0120b9ed40)
at /usr/devel/git/trant/sys/kern/kern_fork.c:1069
(kgdb) fr 4
#4 0xffffffff8098a82c in tcp_sack_doack (tp=<optimized out>,
tp at entry=0xfffff807548187f0, to=<optimized out>, to at entry=0xfffffe0120b9e780,
th_ack=<optimized out>) at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691
691 KASSERT(tp->sackhint.sack_bytes_rexmit >= 0,
(kgdb) i loc
sack_blocks = {{start = 3846350860, end = 3846396940}, {start = 3846398380, end
= 3846415660}, {start = 0, end = 0}, {start = 1417775088, end = 4294965255},
{start = 549054304, end = 4294966785}}
left_edge_delta = <optimized out>
delivered_data = 0
sack_changed = <optimized out>
num_sack_blks = <optimized out>
i = <optimized out>
j = <optimized out>
sack = {start = <optimized out>, end = <optimized out>}
sblkp = 0xfffffe0120b9e700
temp = <optimized out>
cur = 0xfffff8013da5a320
(kgdb) p *cur
$1 = {start = 3846347980, end = 3846352300, rxmit = 3846352300, scblink =
{tqe_next = 0xfffff8013da5a220, tqe_prev = 0xfffff80754818930}}
(kgdb) p 3846352300 - 3846347980
$2 = 4320
(kgdb) p tp->sackhint.sack_bytes_rexmit
value has been optimized out
(kgdb) p tp at entry->sackhint.sack_bytes_rexmit<mailto:tp at entry-%3esackhint.sack_bytes_rexmit>
$3 = -1440
(kgdb) p 4320 - 1440
$4 = 2880
(kgdb) p *sblkp
$5 = {start = 3846350860, end = 3846396940}
(kgdb) p *tp at entry
$7 = {t_inpcb = 0xfffff80640ca65b8, t_fb = 0xffffffff80ef4700 <tcp_def_funcblk>,
t_fb_ptr = 0x0, t_maxseg = 1440, t_logstate = 0, t_port = 0, t_state = 4,
t_idle_reduce = 0, t_delayed_ack = 0, t_fin_is_rst = 0,
t_log_state_set = 0, bits_spare = 0, t_flags = 1613759072, snd_una =
3846347980, snd_max = 3846417100, snd_nxt = 3846417100, snd_up = 3846347980,
snd_wnd = 237568, snd_cwnd = 4320, t_peakrate_thr = 0, ts_offset = 71449215,
rfbuf_ts = 162235772, rcv_numsacks = 0, t_tsomax = 0, t_tsomaxsegcount = 0,
t_tsomaxsegsize = 0, rcv_nxt = 2281639092, rcv_adv = 2281705332, rcv_wnd =
66240, t_flags2 = 1030, t_srtt = 876, t_rttvar = 33, ts_recent = 0,
snd_scale = 8 '\b', rcv_scale = 6 '\006', snd_limited = 2 '\002',
request_r_scale = 6 '\006', last_ack_sent = 2281639092, t_rcvtime = 2309118641,
rcv_up = 2281639092, t_segqlen = 0, t_segqmbuflen = 0, t_segq = {
tqh_first = 0x0, tqh_last = 0xfffff80754818880}, t_in_pkt = 0x0, t_tail_pkt
= 0x0, t_timers = 0xfffff80754818a78, t_vnet = 0x0, snd_ssthresh = 31680,
snd_wl1 = 2281639092, snd_wl2 = 3846347980, irs = 2281631223,
iss = 3840447913, t_acktime = 0, t_sndtime = 2309118613, ts_recent_age = 0,
snd_recover = 3846415660, cl4_spare = 0, t_oobflags = 0 '\000', t_iobc = 0
'\000', t_rxtcur = 270, t_rxtshift = 1, t_rtttime = 2309118613,
t_rtseq = 3846415660, t_starttime = 2309086941, t_fbyte_in = 2309087188,
t_fbyte_out = 2309087159, t_pmtud_saved_maxseg = 0, t_blackhole_enter = 0,
t_blackhole_exit = 0, t_rttmin = 30, t_rttbest = 845, t_softerror = 0,
max_sndwnd = 237568, snd_cwnd_prev = 64800, snd_ssthresh_prev = 8640,
snd_recover_prev = 3846347980, t_sndzerowin = 0, t_rttupdated = 368,
snd_numholes = 2, t_badrxtwin = 0, snd_holes = {tqh_first = 0xfffff8013da5a320,
tqh_last = 0xfffff8013da5a230}, snd_fack = 3846415660, sackblks = {{start =
2281632180, end = 2281632690}, {start = 0, end = 0}, {start = 0, end = 0},
{start = 0, end = 0}, {start = 0, end = 0}, {start = 0, end = 0}},
sackhint = {nexthole = 0xfffff8013da5a220, sack_bytes_rexmit = -1440,
last_sack_ack = 3846415660, delivered_data = 1440, sacked_bytes = 61920,
recover_fs = 67680, prr_delivered = 1440, _pad = {0}}, t_rttlow = 25,
rfbuf_cnt = 0, tod = 0x0, t_sndrexmitpack = 520, t_rcvoopack = 0, t_toe = 0x0,
cc_algo = 0xffffffff80ef2530 <newreno_cc_algo>, ccv = 0xfffff80754818bc0, osd =
0x0, t_bytes_acked = 11520, t_maxunacktime = 0, t_keepinit = 0,
t_keepidle = 0, t_keepintvl = 0, t_keepcnt = 0, t_dupacks = 4, t_lognum = 0,
t_loglimit = 0, t_pacing_rate = -1, t_logs = {stqh_first = 0x0, stqh_last =
0x0}, t_lin = 0x0, t_lib = 0x0, t_output_caller = 0x0, t_stats = 0x0,
t_logsn = 0, gput_ts = 0, gput_seq = 0, gput_ack = 0, t_stats_gput_prev = 0,
t_tfo_client_cookie_len = 0 '\000', t_end_info_status = 0, t_tfo_pending = 0x0,
t_tfo_cookie = {client = '\000' <repeats 15 times>, server = 0}, {
t_end_info_bytes = "\000\000\000\000\000\000\000", t_end_info = 0}}
(kgdb) p *tp at entry->sackhint.nexthole<mailto:*tp at entry-%3esackhint.nexthole>
$8 = {start = 3846396940, end = 3846398380, rxmit = 3846398380, scblink =
{tqe_next = 0x0, tqe_prev = 0xfffff8013da5a330}}
--
Andriy Gapon
_______________________________________________
freebsd-current at freebsd.org<mailto:freebsd-current at freebsd.org> mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to "freebsd-current-unsubscribe at freebsd.org<mailto:freebsd-current-unsubscribe at freebsd.org>"
More information about the freebsd-net
mailing list