Date: Tue, 23 Feb 2021 22:40:20 +0000 From: "Scheffenegger, Richard" <Richard.Scheffenegger@netapp.com> To: "avg@FreeBSD.org" <avg@FreeBSD.org> Cc: "tuexen@freebsd.org" <tuexen@freebsd.org>, "net@FreeBSD.org" <net@freebsd.org> Subject: AW: panic: sackhint bytes rtx >= 0 Message-ID: <SN4PR0601MB37288873BB2967AC78B26C8986809@SN4PR0601MB3728.namprd06.prod.outlook.com> In-Reply-To: <8BB910F9-B828-49A2-8941-4F6C6419D8EA@freebsd.org> References: <960081ac-2839-a226-3142-5a4666eb54ad@FreeBSD.org> <8BB910F9-B828-49A2-8941-4F6C6419D8EA@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
Hi Andriy,
I guess I am currently the person who has the most recent knowledge about t=
hat 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 poin=
t that this may cause issues, potentially)?
Or was something done with the ipfw that may have temporarily impacted a tc=
p session?
The accounting with sack_bytes_rexmit is rather old, and not touched recent=
ly (but the sackhint struct was changed recently, and other/additional scor=
eboard accounting was added).
(kgdb) p *cur
$1 =3D {start =3D 3846347980, end =3D 3846352300, rxmit =3D 3846352300, scb=
link =3D
{tqe_next =3D 0xfffff8013da5a220, tqe_prev =3D 0xfffff80754818930}}
This indicates, that the current hole in the SACK scoreboard (3 segments of=
size 1440 bytes) were retransmitted (rxmit =3D=3D end), before the curren=
t acknowledgement came back.
Thus the expectation is, that sackhint.sack_bytes_rexmit also has a value o=
f 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@entry->sackhint.sack_bytes_rexmit<mailto:tp@entry-%3esackhint.s=
ack_bytes_rexmit>
$3 =3D -1440
Indicating negative one packet had been retransmitted before (thus subtract=
ing the hole, which was previously retransmitted violates the invariant). A=
nd the only piece of code decrementing it appears to be in tcp_output() dur=
ing 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 s=
egments) the client knows about segments 2..34 and 35..47.
The first hole has shrunk from the right (unusual; possible when two retran=
smissions 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@netapp.com<mailto:Richard.Scheffenegger@netapp.com>
https://ts.la/richard49892
Von: tuexen@freebsd.org <tuexen@freebsd.org>
Gesendet: Dienstag, 23. Februar 2021 22:21
An: Richard Scheffenegger <rscheff@freebsd.org>
Betreff: Fwd: panic: sackhint bytes rtx >=3D 0
NetApp Security WARNING: This is an external email. Do not click links or o=
pen attachments unless you recognize the sender and know the content is saf=
e.
FYI
Begin forwarded message:
From: Andriy Gapon <avg@FreeBSD.org<mailto:avg@FreeBSD.org>>
Subject: panic: sackhint bytes rtx >=3D 0
Date: 23. February 2021 at 22:02:20 CET
To: FreeBSD Current <current@FreeBSD.org<mailto:current@FreeBSD.org>>, net@=
FreeBSD.org<mailto:net@FreeBSD.org>
Got this panic on 13.0-STABLE 4b2a20dfde9c using a custom kernel with INVAR=
IANTS
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=3Dtextdump@entry=3D1)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:399
#1 0xffffffff808396b2 in kern_reboot (howto=3D260)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:486
#2 0xffffffff80839d07 in vpanic (
fmt=3D0xffffffff80cbd551 "sackhint bytes rtx >=3D 0", ap=3D0xfffffe0120b=
9e6d0)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:919
#3 0xffffffff808398b3 in panic (fmt=3D<unavailable>)
at /usr/devel/git/trant/sys/kern/kern_shutdown.c:843
#4 0xffffffff8098a82c in tcp_sack_doack (tp=3D<optimized out>,
tp@entry=3D0xfffff807548187f0, to=3D<optimized out>,
to@entry=3D0xfffffe0120b9e780, th_ack=3D<optimized out>)
at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691
#5 0xffffffff80983699 in tcp_do_segment (m=3D0xfffff8029868ca00,
m@entry=3D<error reading variable: value is not available>,
th=3D<optimized out>,
th@entry=3D<error reading variable: value is not available>,
so=3D0xfffff804e7359b10,
so@entry=3D<error reading variable: value is not available>,
tp=3D0xfffff807548187f0,
tp@entry=3D<error reading variable: value is not available>,
drop_hdrlen=3D60,
drop_hdrlen@entry=3D<error reading variable: value is not available>,
tlen=3D<optimized out>,
tlen@entry=3D<error reading variable: value is not available>,
iptos=3D72 'H',
iptos@entry=3D<error reading variable: value is not available>)
at /usr/devel/git/trant/sys/netinet/tcp_input.c:2497
#6 0xffffffff80980d97 in tcp_input (mp=3D<optimized out>,
mp@entry=3D<error reading variable: value is not available>,
offp=3D<optimized out>,
offp@entry=3D<error reading variable: value is not available>,
proto=3D<optimized out>)
at /usr/devel/git/trant/sys/netinet/tcp_input.c:1381
#7 0xffffffff80976eb7 in ip_input (m=3D0x0)
at /usr/devel/git/trant/sys/netinet/ip_input.c:833
#8 0xffffffff8094c78f in netisr_dispatch_src (proto=3D1,
source=3Dsource@entry=3D0, m=3D0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1143
#9 0xffffffff8094cb0e in netisr_dispatch (proto=3D<unavailable>,
m=3D<unavailable>) at /usr/devel/git/trant/sys/net/netisr.c:1234
#10 0xffffffff80943345 in ether_demux (ifp=3Difp@entry=3D0xfffff80008c75000=
,
m=3D<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:923
#11 0xffffffff809446c1 in ether_input_internal (ifp=3D0xfffff80008c75000,
m=3D<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:709
#12 0xffffffff809443d0 in ether_nh_input (m=3D<unavailable>)
at /usr/devel/git/trant/sys/net/if_ethersubr.c:739
#13 0xffffffff8094c78f in netisr_dispatch_src (proto=3Dproto@entry=3D5,
source=3Dsource@entry=3D0, m=3Dm@entry=3D0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1143
#14 0xffffffff8094cb0e in netisr_dispatch (proto=3D<unavailable>,
proto@entry=3D5, m=3D<unavailable>, m@entry=3D0xfffff8029868ca00)
at /usr/devel/git/trant/sys/net/netisr.c:1234
#15 0xffffffff8094383d in ether_input (ifp=3D0xfffff80008c75000,
ifp@entry=3D<error reading variable: value is not available>,
m=3D0xfffff8029868ca00,
m@entry=3D<error reading variable: value is not available>)
at /usr/devel/git/trant/sys/net/if_ethersubr.c:830
#16 0xffffffff8066da13 in re_rxeof (sc=3Dsc@entry=3D0xfffffe00391a5000,
rx_npktsp=3D0x0) at /usr/devel/git/trant/sys/dev/re/if_re.c:2388
#17 0xffffffff8066b3ab in re_intr_msi (xsc=3D0xfffffe00391a5000)
at /usr/devel/git/trant/sys/dev/re/if_re.c:2684
#18 0xffffffff80801bcf in intr_event_execute_handlers (
p=3Dp@entry=3D0xfffff80006a94a50, ie=3Die@entry=3D0xfffff80008c57800)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1168
#19 0xffffffff80801942 in ithread_execute_handlers (
p=3Dp@entry=3D0xfffff80006a94a50, ie=3Die@entry=3D0xfffff80008c57800)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1181
#20 0xffffffff80801758 in ithread_loop (arg=3Darg@entry=3D0xfffff80008c20c4=
0)
at /usr/devel/git/trant/sys/kern/kern_intr.c:1269
#21 0xffffffff807fe0a9 in fork_exit (
callout=3D0xffffffff808016c0 <ithread_loop>, arg=3D0xfffff80008c20c40,
frame=3D0xfffffe0120b9ed40)
at /usr/devel/git/trant/sys/kern/kern_fork.c:1069
(kgdb) fr 4
#4 0xffffffff8098a82c in tcp_sack_doack (tp=3D<optimized out>,
tp@entry=3D0xfffff807548187f0, to=3D<optimized out>, to@entry=3D0xfffffe012=
0b9e780,
th_ack=3D<optimized out>) at /usr/devel/git/trant/sys/netinet/tcp_sack.c:69=
1
691 KASSERT(tp->sackhint.sack_bytes_rexmit >=3D 0,
(kgdb) i loc
sack_blocks =3D {{start =3D 3846350860, end =3D 3846396940}, {start =3D 384=
6398380, end
=3D 3846415660}, {start =3D 0, end =3D 0}, {start =3D 1417775088, end =3D 4=
294965255},
{start =3D 549054304, end =3D 4294966785}}
left_edge_delta =3D <optimized out>
delivered_data =3D 0
sack_changed =3D <optimized out>
num_sack_blks =3D <optimized out>
i =3D <optimized out>
j =3D <optimized out>
sack =3D {start =3D <optimized out>, end =3D <optimized out>}
sblkp =3D 0xfffffe0120b9e700
temp =3D <optimized out>
cur =3D 0xfffff8013da5a320
(kgdb) p *cur
$1 =3D {start =3D 3846347980, end =3D 3846352300, rxmit =3D 3846352300, scb=
link =3D
{tqe_next =3D 0xfffff8013da5a220, tqe_prev =3D 0xfffff80754818930}}
(kgdb) p 3846352300 - 3846347980
$2 =3D 4320
(kgdb) p tp->sackhint.sack_bytes_rexmit
value has been optimized out
(kgdb) p tp@entry->sackhint.sack_bytes_rexmit<mailto:tp@entry-%3esackhint.s=
ack_bytes_rexmit>
$3 =3D -1440
(kgdb) p 4320 - 1440
$4 =3D 2880
(kgdb) p *sblkp
$5 =3D {start =3D 3846350860, end =3D 3846396940}
(kgdb) p *tp@entry
$7 =3D {t_inpcb =3D 0xfffff80640ca65b8, t_fb =3D 0xffffffff80ef4700 <tcp_de=
f_funcblk>,
t_fb_ptr =3D 0x0, t_maxseg =3D 1440, t_logstate =3D 0, t_port =3D 0, t_stat=
e =3D 4,
t_idle_reduce =3D 0, t_delayed_ack =3D 0, t_fin_is_rst =3D 0,
t_log_state_set =3D 0, bits_spare =3D 0, t_flags =3D 1613759072, snd_una =
=3D
3846347980, snd_max =3D 3846417100, snd_nxt =3D 3846417100, snd_up =3D 3846=
347980,
snd_wnd =3D 237568, snd_cwnd =3D 4320, t_peakrate_thr =3D 0, ts_offset =3D =
71449215,
rfbuf_ts =3D 162235772, rcv_numsacks =3D 0, t_tsomax =3D 0, t_tsomaxsegcou=
nt =3D 0,
t_tsomaxsegsize =3D 0, rcv_nxt =3D 2281639092, rcv_adv =3D 2281705332, rcv_=
wnd =3D
66240, t_flags2 =3D 1030, t_srtt =3D 876, t_rttvar =3D 33, ts_recent =3D 0,
snd_scale =3D 8 '\b', rcv_scale =3D 6 '\006', snd_limited =3D 2 '\002',
request_r_scale =3D 6 '\006', last_ack_sent =3D 2281639092, t_rcvtime =3D 2=
309118641,
rcv_up =3D 2281639092, t_segqlen =3D 0, t_segqmbuflen =3D 0, t_segq =3D {
tqh_first =3D 0x0, tqh_last =3D 0xfffff80754818880}, t_in_pkt =3D 0x0, t=
_tail_pkt
=3D 0x0, t_timers =3D 0xfffff80754818a78, t_vnet =3D 0x0, snd_ssthresh =3D =
31680,
snd_wl1 =3D 2281639092, snd_wl2 =3D 3846347980, irs =3D 2281631223,
iss =3D 3840447913, t_acktime =3D 0, t_sndtime =3D 2309118613, ts_recent_a=
ge =3D 0,
snd_recover =3D 3846415660, cl4_spare =3D 0, t_oobflags =3D 0 '\000', t_iob=
c =3D 0
'\000', t_rxtcur =3D 270, t_rxtshift =3D 1, t_rtttime =3D 2309118613,
t_rtseq =3D 3846415660, t_starttime =3D 2309086941, t_fbyte_in =3D 2309087=
188,
t_fbyte_out =3D 2309087159, t_pmtud_saved_maxseg =3D 0, t_blackhole_enter =
=3D 0,
t_blackhole_exit =3D 0, t_rttmin =3D 30, t_rttbest =3D 845, t_softerror =3D=
0,
max_sndwnd =3D 237568, snd_cwnd_prev =3D 64800, snd_ssthresh_prev =3D 8640=
,
snd_recover_prev =3D 3846347980, t_sndzerowin =3D 0, t_rttupdated =3D 368,
snd_numholes =3D 2, t_badrxtwin =3D 0, snd_holes =3D {tqh_first =3D 0xfffff=
8013da5a320,
tqh_last =3D 0xfffff8013da5a230}, snd_fack =3D 3846415660, sackblks =3D =
{{start =3D
2281632180, end =3D 2281632690}, {start =3D 0, end =3D 0}, {start =3D 0, en=
d =3D 0},
{start =3D 0, end =3D 0}, {start =3D 0, end =3D 0}, {start =3D 0, end =3D 0=
}},
sackhint =3D {nexthole =3D 0xfffff8013da5a220, sack_bytes_rexmit =3D -1440=
,
last_sack_ack =3D 3846415660, delivered_data =3D 1440, sacked_bytes =3D 619=
20,
recover_fs =3D 67680, prr_delivered =3D 1440, _pad =3D {0}}, t_rttlow =3D 2=
5,
rfbuf_cnt =3D 0, tod =3D 0x0, t_sndrexmitpack =3D 520, t_rcvoopack =3D 0, =
t_toe =3D 0x0,
cc_algo =3D 0xffffffff80ef2530 <newreno_cc_algo>, ccv =3D 0xfffff80754818bc=
0, osd =3D
0x0, t_bytes_acked =3D 11520, t_maxunacktime =3D 0, t_keepinit =3D 0,
t_keepidle =3D 0, t_keepintvl =3D 0, t_keepcnt =3D 0, t_dupacks =3D 4, t_l=
ognum =3D 0,
t_loglimit =3D 0, t_pacing_rate =3D -1, t_logs =3D {stqh_first =3D 0x0, stq=
h_last =3D
0x0}, t_lin =3D 0x0, t_lib =3D 0x0, t_output_caller =3D 0x0, t_stats =3D 0x=
0,
t_logsn =3D 0, gput_ts =3D 0, gput_seq =3D 0, gput_ack =3D 0, t_stats_gput=
_prev =3D 0,
t_tfo_client_cookie_len =3D 0 '\000', t_end_info_status =3D 0, t_tfo_pendin=
g =3D 0x0,
t_tfo_cookie =3D {client =3D '\000' <repeats 15 times>, server =3D 0}, {
t_end_info_bytes =3D "\000\000\000\000\000\000\000", t_end_info =3D 0}}
(kgdb) p *tp@entry->sackhint.nexthole<mailto:*tp@entry-%3esackhint.nexthole=
>
$8 =3D {start =3D 3846396940, end =3D 3846398380, rxmit =3D 3846398380, scb=
link =3D
{tqe_next =3D 0x0, tqe_prev =3D 0xfffff8013da5a330}}
--
Andriy Gapon
_______________________________________________
freebsd-current@freebsd.org<mailto:freebsd-current@freebsd.org> mailing lis=
t
https://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to "freebsd-current-unsubscribe@freebsd.org<m=
ailto:freebsd-current-unsubscribe@freebsd.org>"
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?SN4PR0601MB37288873BB2967AC78B26C8986809>