| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <874j8fjhv7.fsf@kurt.kurt.home>
Date: Wed, 24 Jul 2024 10:48:12 +0200
From: Kurt Kanzenbach <kurt.kanzenbach@...utronix.de>
To: Rodrigo Cataldo via B4 Relay
<devnull+rodrigo.cadore.l-acoustics.com@...nel.org>, Jesse Brandeburg
<jesse.brandeburg@...el.com>, Tony Nguyen <anthony.l.nguyen@...el.com>,
"David S. Miller" <davem@...emloft.net>, Eric Dumazet
<edumazet@...gle.com>, Jakub Kicinski <kuba@...nel.org>, Paolo Abeni
<pabeni@...hat.com>, Richard Cochran <richardcochran@...il.com>, Vinicius
Costa Gomes <vinicius.gomes@...el.com>, "Christopher S. Hall"
<christopher.s.hall@...el.com>
Cc: intel-wired-lan@...ts.osuosl.org, netdev@...r.kernel.org,
linux-kernel@...r.kernel.org, Rodrigo Cataldo
<rodrigo.cadore@...coustics.com>
Subject: Re: [PATCH iwl-net] igc: Ensure PTM request is completed before
timeout has started
On Mon Jul 08 2024, Rodrigo Cataldo via B4 Relay wrote:
> From: Rodrigo Cataldo <rodrigo.cadore@...coustics.com>
>
> When a PTM is requested via wr32(IGC_PTM_STAT), the operation may only
> be completed by the next read operation (flush). Unfortunately, the next
> read operation in the PTM request loop happens after we have already
> started evaluating the response timeout.
>
> Thus, the following behavior has been observed::
>
> phc2sys-1655 [010] 103.233752: funcgraph_entry: | igc_ptp_getcrosststamp() {
> phc2sys-1655 [010] 103.233754: funcgraph_entry: | igc_phc_get_syncdevice_time() {
> phc2sys-1655 [010] 103.233755: funcgraph_entry: | igc_rd32() {
> phc2sys-1655 [010] 103.233931: preempt_disable: caller=irq_enter_rcu+0x14 parent=irq_enter_rcu+0x14
> phc2sys-1655 [010] 103.233932: local_timer_entry: vector=236
> phc2sys-1655 [010] 103.233932: hrtimer_cancel: hrtimer=0xffff8edeef526118
> phc2sys-1655 [010] 103.233933: hrtimer_expire_entry: hrtimer=0xffff8edeef526118 now=103200127876 function=tick_nohz_handler/0x0
>
> ... tick handler ...
>
> phc2sys-1655 [010] 103.233971: funcgraph_exit: ! 215.559 us | }
> phc2sys-1655 [010] 103.233972: funcgraph_entry: | igc_rd32() {
> phc2sys-1655 [010] 103.234135: funcgraph_exit: ! 164.370 us | }
> phc2sys-1655 [010] 103.234136: funcgraph_entry: 1.942 us | igc_rd32();
> phc2sys-1655 [010] 103.234147: console: igc 0000:03:00.0 enp3s0: Timeout reading IGC_PTM_STAT register
>
> Based on the (simplified) code::
>
> ctrl = rd32(IGC_PTM_CTRL);
> /* simplified: multiple writes here */
> wr32(IGC_PTM_STAT, IGC_PTM_STAT_VALID);
>
> err = readx_poll_timeout(rd32, IGC_PTM_STAT, stat,
> stat, IGC_PTM_STAT_SLEEP,
> IGC_PTM_STAT_TIMEOUT);
> if (err < 0) {
> netdev_err(adapter->netdev, "Timeout reading IGC_PTM_STAT register\n");
> return err;
> }
>
> Where readx_poll_timeout() starts the timeout evaluation before calling
> the rd32() parameter (rd32() is a macro for igc_rd32()).
>
> In the trace shown, the read operation of readx_poll_timeout() (second
> igc_rd32()) took so long that the timeout (IGC_PTM_STAT_VALID) has expired
> and no sleep has been performed.
>
> With this patch, a write flush is added (which is an additional
> igc_rd32() in practice) that can wait for the write before the timeout
> is evaluated::
>
> phc2sys-1615 [010] 74.517954: funcgraph_entry: | igc_ptp_getcrosststamp() {
> phc2sys-1615 [010] 74.517956: funcgraph_entry: | igc_phc_get_syncdevicetime() {
> phc2sys-1615 [010] 74.517957: funcgraph_entry: | igc_rd32() {
> phc2sys-1615 [010] 74.518127: preempt_disable: caller=irq_enter_rcu+0x14 parent=irq_enter_rcu+0x14
> phc2sys-1615 [010] 74.518128: local_timer_entry: vector=236
> phc2sys-1615 [010] 74.518128: hrtimer_cancel: hrtimer=0xffff96466f526118
> phc2sys-1615 [010] 74.518128: hrtimer_expire_entry: hrtimer=0xffff96466f526118 now=74484007229 function=tick_nohz_handler/0x0
>
> ... tick handler ...
>
> phc2sys-1615 [010] 74.518180: funcgraph_exit: ! 222.282 us | }
> phc2sys-1615 [010] 74.518181: funcgraph_entry: | igc_rd32() {
> phc2sys-1615 [010] 74.518349: funcgraph_exit: ! 168.160 us | }
> phc2sys-1615 [010] 74.518349: funcgraph_entry: 1.970 us | igc_rd32();
> phc2sys-1615 [010] 74.518352: hrtimer_init: hrtimer=0xffffa6f9413a3940 clockid=CLOCK_MONOTONIC mode=0x0
> phc2sys-1615 [010] 74.518352: preempt_disable: caller=_raw_spin_lock_irqsave+0x28 parent=hrtimer_start_range_ns+0x56
> phc2sys-1615 [010] 74.518353: hrtimer_start: hrtimer=0xffffa6f9413a3940 function=hrtimer_wakeup/0x0 expires=74484232878 softexpires=74484231878
>
> .. hrtimer setup and return ...
>
> kworker/10:1-242 [010] 74.518382: sched_switch: kworker/10:1:242 [120] W ==> phc2sys:1615 [120]
> phc2sys-1615 [010] 74.518383: preempt_enable: caller=schedule+0x36 parent=schedule+0x36
> phc2sys-1615 [010] 74.518384: funcgraph_entry: ! 100.088 us | igc_rd32();
> phc2sys-1615 [010] 74.518484: funcgraph_entry: 1.958 us | igc_rd32();
> phc2sys-1615 [010] 74.518488: funcgraph_entry: 2.019 us | igc_rd32();
> phc2sys-1615 [010] 74.518490: funcgraph_entry: 1.956 us | igc_rd32();
> phc2sys-1615 [010] 74.518492: funcgraph_entry: 1.980 us | igc_rd32();
> phc2sys-1615 [010] 74.518494: funcgraph_exit: ! 539.386 us | }
>
> Now the sleep is called as expected, and the operation succeeds.
> Therefore, regardless of how long it will take for the write to be
> completed, we will poll+sleep at least for the time specified in
> IGC_PTM_STAT_TIMEOUT.
>
> Fixes: a90ec8483732 ("igc: Add support for PTP getcrosststamp()")
> Signed-off-by: Rodrigo Cataldo <rodrigo.cadore@...coustics.com>
Thanks for sending this upstream.
Reviewed-by: Kurt Kanzenbach <kurt@...utronix.de>
Download attachment "signature.asc" of type "application/pgp-signature" (874 bytes)
Powered by blists - more mailing lists