Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
MIME-Version: 1.0
Date:   Thu, 20 Apr 2023 02:17:21 +0000
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
From:   "Yajun Deng" <yajun.deng@linux.dev>
Message-ID: <acb95e0283e0720979f67f8321c3cdbe@linux.dev>
Subject: Re: [PATCH] net: sched: print jiffies when transmit queue time
 out
To:     "Jakub Kicinski" <kuba@kernel.org>
Cc:     jhs@mojatatu.com, xiyou.wangcong@gmail.com, jiri@resnulli.us,
        davem@davemloft.net, edumazet@google.com, pabeni@redhat.com,
        netdev@vger.kernel.org, linux-kernel@vger.kernel.org
In-Reply-To: <20230419182713.2cd1f81b@kernel.org>
References: <20230419182713.2cd1f81b@kernel.org>
 <20230419115632.738730-1-yajun.deng@linux.dev>
Precedence: bulk

April 20, 2023 9:27 AM, "Jakub Kicinski" <kuba@kernel.org> wrote:=0A=0A> =
On Wed, 19 Apr 2023 19:56:32 +0800 Yajun Deng wrote:=0A> =0A>> Although t=
here is watchdog_timeo to let users know when the transmit queue=0A>> beg=
in stall, but dev_watchdog() is called with an interval. The jiffies=0A>>=
 will always be greater than watchdog_timeo.=0A>> =0A>> To let users know=
 the exact time the stall started, print jiffies when=0A>> the transmit q=
ueue time out.=0A> =0A> Please add an explanation of how this information=
 is useful in practice.=0A=0AWe found some cases with several warnings. W=
e want to confirm which happened first. =0A=0AFirst warning:=0A16:37:57 k=
ernel: [ 7100.097547] ------------[ cut here ]------------=0A16:37:57 ker=
nel: [ 7100.097550] NETDEV WATCHDOG: eno2 (i40e): transmit queue 8 timed =
out=0A16:37:57 kernel: [ 7100.097571] WARNING: CPU: 8 PID: 0 at net/sched=
/sch_generic.c:467 dev_watchdog+0x260/0x270=0A...=0A=0ASecond warning:=0A=
16:38:44 kernel: [ 7147.756952] rcu: INFO: rcu_preempt self-detected stal=
l on CPU=0A16:38:44 kernel: [ 7147.756958] rcu:   24-....: (59999 ticks t=
his GP) idle=3D546/1/0x4000000000000000 softirq=3D367      3137/3673146 f=
qs=3D13844=0A16:38:44 kernel: [ 7147.756960]        (t=3D60001 jiffies g=
=3D4322709 q=3D133381)=0A16:38:44 kernel: [ 7147.756962] NMI backtrace fo=
r cpu 24=0A...=0A=0AAs we can see, the transmit queue start stall should =
be before 16:37:52, the rcu start stall is 16:37:44.=0AThese two times ar=
e closer, we want to confirm which happened first.