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;
Date:   Sun, 7 May 2023 16:05:10 +0800
From:   Yujie Liu <yujie.liu@intel.com>
To:     Thomas Gleixner <tglx@linutronix.de>
CC:     Shanker Donthineni <sdonthineni@nvidia.com>,
        <oe-lkp@lists.linux.dev>, <lkp@intel.com>,
        <linux-kernel@vger.kernel.org>, Marc Zyngier <maz@kernel.org>,
        Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
        "Michael Walle" <michael@walle.cc>,
        Vikram Sethi <vsethi@nvidia.com>
Subject: Re: [PATCH v3 3/3] genirq: Use the maple tree for IRQ descriptors
 management
Message-ID: <ZFdbtipfTsIF0u6z@yujie-X299>
References: <202304251035.19367560-yujie.liu@intel.com>
 <87a5yuzvzd.ffs@tglx>
 <ZEsiYbi8dorXTI5t@yujie-X299>
 <877ctw5mdp.ffs@tglx>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
In-Reply-To: <877ctw5mdp.ffs@tglx>
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?gHfxpow9HFifAsuyWOwcSF1CfQ+MLv2sht/HaXYEZSUMjgX8nwDwixobDr/r?=
 =?us-ascii?Q?hN2Mxhxe4g1kNM4GyyhSzAWkA7QAbSSZIkcdHRArG5/TtBopTkLy/uc2z09E?=
 =?us-ascii?Q?5FAM0JxLexgK/6A3826oBLgg/x8+CphHoktb1+gf99WY6rRKPQT2jitSPDGS?=
 =?us-ascii?Q?DOfcIcM/17d7Q0ksa2qQR2qN4MU6GJACqa6uxNE5CSgIAVUSLZ1WM87nFSHg?=
 =?us-ascii?Q?EO5cocy4/sHtHPHTtrUHbwJrRZ0rXNEIvGYcLxyS4Rp0eJ9NR2zWkkLAft5M?=
 =?us-ascii?Q?x3PuMINoDqx6D8gVpndumLe5IpN777ZFzdBaX8qAPUfum/4CvD50eXuZB1/h?=
 =?us-ascii?Q?160mS439raRAjuWTQMFJDYr8D/PNv79ddCsgkUnBeH5pjY6JnQfr20cZZj5/?=
 =?us-ascii?Q?gx4EYcKcZ9EEnHMQGY+OK1hQDlRL75EqVb2JHHPLXsKcS3PnDplBti71lKbF?=
 =?us-ascii?Q?0S3FqRjcCEyHbXdM1WS4+SqP+Euojnf9b2tXDcj6EcsPNCAGlSIFPtLSVACw?=
 =?us-ascii?Q?NU6eKOQWxLCHupSJvBzEKwv81VzcBWqhFfAKcQS0lQMu0i7LG+CcbzIUkJaF?=
 =?us-ascii?Q?ruBB8x5EQd77wynD1PabDkubfd9r1A7rICvscMZPK8vnLdSvx9/iY6ry/2r8?=
 =?us-ascii?Q?ii/Ro5aoBrbZtU3ZLBodbxc6Wv/tgD8qc4bzwKSCWUKdMi692YUUgz1fdT5E?=
 =?us-ascii?Q?30CdqBbiERcGjN+WCX8Gm0YiYjgqbNfuYwcfTBvLaFE0zC0l2QMFv3lpvm7h?=
 =?us-ascii?Q?AYR049nLf61eZIy9ulpXN1YqoTYkLLj51hxnETyZgsHw30immg2zkeM1Nxmq?=
 =?us-ascii?Q?gvI0ix07Cl0pDLo6BlpZcuKaADaknYDiifEZUuLjzGZLETbBP3Ha9qsRIfME?=
 =?us-ascii?Q?nNYykipYAfzm0jzfbndpHC2x+E9/CtOpvBYtQOcdN8bcVBbrBP6t1UHfxXPL?=
 =?us-ascii?Q?1SU4TmoU7vWkefr2C7LpU2fsG8739TLZq8ViqDXZ80G/vPZAfrJ2Gtdt9QAE?=
 =?us-ascii?Q?z9YMhY2ZCPr4S24zt+ogJrQvi/lVlaXZlU5Z07/VuIsjuX1JVD0AYCX9wnZz?=
 =?us-ascii?Q?VafLVUN4t8WevWXItqpWCHllGUo/SQr6hfAmXjylf/YPuIocOY5wlKS7rvIm?=
 =?us-ascii?Q?ZlFos0U82Wpjj7OVGAKaT19CKn8P5KC4s89Tvp5vRJtaldz9akufRDS8B4ll?=
 =?us-ascii?Q?Z1+bRJl/SqM3fKJicKBCGr26IvAVUUFLO6rgc2vGJ0tSn963vTCILzoAm8ap?=
 =?us-ascii?Q?vLhrNRNqX7lQ2Ic4NMfA+pKE4wyigt1Mq/N86ll9pZiGohTlt7mZ94S78DRd?=
 =?us-ascii?Q?iYvLMW7S7Ybaa3DtVOpZDYM5RNcZUx/oVsWTHFidD6GNT3qxC9kxf7xwJNPj?=
 =?us-ascii?Q?4uqeiqsZxjGZ/5t7Bsc2hvddxY8RARR7cHv/R9dsdNRFLU5mJXcKQnOoFg41?=
 =?us-ascii?Q?iyZDWdrzH8iP5Rt2qDjGvpHFyEYhWwHxXvcsz3f7jLvzCQs8zF5J9Vdaf9nY?=
 =?us-ascii?Q?v3bME1d4BSnVbEscChhvPmUroSjSWA2qEyc/L64ifnRNKX60d82oR+k7AiWc?=
 =?us-ascii?Q?N/7p5lb18sxzjQaviXIMDuxaPXyHAE2taZBqWRh0?=
X-MS-Exchange-CrossTenant-Network-Message-Id: 3fd6a4ed-4696-44a9-2fc2-08db4ed23fac
X-MS-Exchange-CrossTenant-AuthSource: DS0PR11MB6397.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 07 May 2023 08:08:32.7233
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 46c98d88-e344-4ed4-8496-4ed7712e255d
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: SXjUOpCQC5sTga6/xUcNTUc7KQRAYC/eM/uABzuLNSVRJW5DbhBFH7OWm/c+Z2glV0YsP9x0QY46/rKK/eOfdg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BL1PR11MB5511
X-OriginatorOrg: intel.com
X-Spam-Status: No, score=-4.6 required=5.0 tests=BAYES_00,DKIMWL_WL_HIGH,
        DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_MED,
        SPF_HELO_NONE,SPF_NONE,T_SCC_BODY_TEXT_LINE,URIBL_BLOCKED
        autolearn=ham autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hi Thomas,

Sorry for late reply as we were on public holiday earlier this week.

On Fri, Apr 28, 2023 at 12:31:14PM +0200, Thomas Gleixner wrote:
> On Fri, Apr 28 2023 at 09:33, Yujie Liu wrote:
> > On Wed, Apr 26, 2023 at 02:08:54PM +0200, Thomas Gleixner wrote:
> >> Can you please retest this on v6.3 and report back when the problem
> >> persists?
> >
> > Thanks for your help looking into this problem.
> >
> > The problem persists when tested on v6.3, but not 100% reproducible.
> > We ran the test on v6.3 and v6.3+patch each for 20 runs. There are 9
> > failed runs on v6.3+patch, while v6.3 is all clean. Full dmesg is
> > attached.
>=20
> Under the assumption that the code is correct, then the effect of this
> patch is that it changes the timing. Sigh.
>=20
>   1) Does this happen with a 64-bit kernel too?

It doesn't happen on a 64-bit kernel:

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
commit/compiler/disk/kconfig/rootfs/tbox_group/test/testcase:
  32c58fc685e5cd6b5947a5f8e9a3c318a63fcf0a/gcc-11/1SSD/i386-debian-10.3-fun=
c/debian-11.1-i386-20220923.cgz/lkp-skl-d06/block-group-00/blktests

commit/compiler/disk/kconfig/rootfs/tbox_group/test/testcase:
  32c58fc685e5cd6b5947a5f8e9a3c318a63fcf0a/gcc-11/1SSD/x86_64-rhel-8.3-func=
/debian-11.1-x86_64-20220510.cgz/lkp-skl-d06/block-group-00/blktests

kconfig:
  i386-debian-10.3-func
  x86_64-rhel-8.3-func

i386-debian-10.3        x86_64-rhel-8.3-func
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
         16:48         -33%            :7     dmesg.EIP:default_send_IPI_ma=
sk_logical
         16:48         -33%            :7     dmesg.WARNING:at_arch/x86/ker=
nel/apic/ipi.c:#default_send_IPI_mask_logical

>   2) Can you enable the irq_vector:vector_*.* tracepoints and provide
>      the trace?

I'm a beginner of kernel and not sure if I'm doing this correctly. Here
are my test steps:

# enable irq_vector events
# cat /sys/kernel/debug/tracing/set_event
irq_vectors:vector_free_moved
irq_vectors:vector_setup
irq_vectors:vector_teardown
irq_vectors:vector_deactivate
irq_vectors:vector_activate
irq_vectors:vector_alloc_managed
irq_vectors:vector_alloc
irq_vectors:vector_reserve
irq_vectors:vector_reserve_managed
irq_vectors:vector_clear
irq_vectors:vector_update
irq_vectors:vector_config

# turn on the tracer
# cat /sys/kernel/debug/tracing/tracing_on
1

# run the testcase
# ./check block/008
block/008 =3D> sdb2 (do IO while hotplugging CPUs)
    read iops  0       ...
    runtime    0.576s  ...

block/008 =3D> sdb2 (do IO while hotplugging CPUs)             [failed]
    read iops  0       ...  0d06 at May  7 07:33:46 ...
    runtime    0.576s  ...  0.580sommon_interrupt: 2.34 No irq handler for =
vector
    --- tests/block/008.out     2023-04-18 17:36:53.000000000 +0000
    +++ /lkp/benchmarks/blktests/results/sdb2/block/008.out.bad 2023-05-07 =
07:33:47.336596084 +0000
    @@ -1,2 +1,8 @@
     Running block/008
    +fio: io_u error on file /dev/sdb2: Input/output error: read offset=3D2=
73571840, buflen=3D4096
    +fio: io_u error on file /dev/sdb2: Input/output error: read offset=3D6=
4757760, buflen=3D4096
    +fio: io_u error on file /dev/sdb2: Input/output error: read offset=3D7=
00571648, buflen=3D4096
    +fio: io_u error on file /dev/sdb2: Input/output error: read offset=3D1=
05357312, buflen=3D4096
    +fio exited with status 0
    +4;fio-3.25;reads;0;5;0;0;0;0;0;0;0.000000;0.000000;0;0;0.000000;0.0000=
00;1.000000%=3D0;5.000000%=3D0;10.000000%=3D0;20.000000%=3D0;30.000000%=3D0=
;40.000000%=3D0;50.000000%=3D0;60.000000%=3D0;70.000000%=3D0;80.000000%=3D0=
;90.000000%=3D0;95.000000%=3D0;99.000000%=3D0;99.500000%=3D0;99.900000%=3D0=
;99.950000%=3D0;99.990000%=3D0;0%=3D0;0%=3D0;0%=3D0;0;0;0.000000;0.000000;0=
;0;0.000000%;0.000000;0.000000;0;0;0;0;0;0;0.000000;0.000000;0;0;0.000000;0=
.000000;1.000000%=3D0;5.000000%=3D0;10.000000%=3D0;20.000000%=3D0;30.000000=
%=3D0;40.000000%=3D0;50.000000%=3D0;60.000000%=3D0;70.000000%=3D0;80.000000=
%=3D0;90.000000%=3D0;95.000000%=3D0;99.000000%=3D0;99.500000%=3D0;99.900000=
%=3D0;99.950000%=3D0;99.990000%=3D0;0%=3D0;0%=3D0;0%=3D0;0;0;0.000000;0.000=
000;0;0;0.000000%;0.000000;0.000000;0;0;0;0;0;0;0.000000;0.000000;0;0;0.000=
000;0.000000;1.000000%=3D0;5.000000%=3D0;10.000000%=3D0;20.000000%=3D0;30.0=
00000%=3D0;40.000000%=3D0;50.000000%=3D0;60.000000%=3D0;70.000000%=3D0;80.0=
00000%=3D0;90.000000%=3D0;95.000000%=3D0;99.000000%=3D0;99.500000%=3D0;99.9=
00000%=3D0;99.950000%=3D0;99.990000%=3D0;0%=3D0;0%=3D0;0%=3D0;0;0;0.000000;=
0.000000;0;0;0.000000%;0.000000;0.000000;0.000000%;0.000000%;12;0;163;100.0=
%;0.0%;0.0%;0.0%;0.0%;0.0%;0.0%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0=
.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00%;0.00=
%;0.00%;0.00%;sdb;0;0;0;0;0;0;0;0.00%
    ...
    (Run 'diff -u tests/block/008.out /lkp/benchmarks/blktests/results/sdb2=
/block/008.out.bad' to see the entire diff)

# check the trace
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                                _-----=3D> irqs-off/BH-disabled
#                               / _----=3D> need-resched
#                              | / _---=3D> hardirq/softirq
#                              || / _--=3D> preempt-depth
#                              ||| / _-=3D> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |

Nothing was written to trace buffer, seems like no irq_vector events
were captured during this test.

> And please provide /proc/interrupts from that machine.

Before running the test:

# cat /proc/interrupts
            CPU0       CPU1       CPU2       CPU3
   0:         34          0          0          0   IO-APIC    2-edge      =
timer
   1:          4          0          0          0   IO-APIC    1-edge      =
i8042
   4:          0          0        635          0   IO-APIC    4-edge      =
ttyS0
   8:          0          0          0          0   IO-APIC    8-edge      =
rtc0
   9:          0          0          0          0   IO-APIC    9-fasteoi   =
acpi
  12:          0          0          0          6   IO-APIC   12-edge      =
i8042
  16:          0          0          0          4   IO-APIC   16-fasteoi   =
i801_smbus
  19:         12          0          0          0   IO-APIC   19-fasteoi
 120:       3608          0        617          0  PCI-MSI-0000:00:1f.6    =
0-edge      eth0
 121:         50          0          0          0  PCI-MSI-0000:00:16.0    =
0-edge      mei_me
 122:          0          0          0          0  PCI-MSI-0000:00:14.0    =
0-edge      xhci_hcd
 123:          0          0    2109981          0  PCI-MSI-0000:00:17.0    =
0-edge      ahci[0000:00:17.0]
 124:          0          0          0        206  PCI-MSI-0000:00:02.0    =
0-edge      i915
 NMI:          0          0          0          0   Non-maskable interrupts
 LOC:     221252     228764     471985     229286   Local timer interrupts
 SPU:          0          0          0          0   Spurious interrupts
 PMI:          0          0          0          0   Performance monitoring =
interrupts
 IWI:         16          0          0          8   IRQ work interrupts
 RTR:        108         25         15         11   APIC ICR read retries
 RES:       5016       5486        697      10440   Rescheduling interrupts
 CAL:       4618       4578       2775       5754   Function call interrupt=
s
 TLB:         12         15         14         18   TLB shootdowns
 TRM:          0          0          0          0   Thermal event interrupt=
s
 THR:          0          0          0          0   Threshold APIC interrup=
ts
 MCE:          0          0          0          0   Machine check exception=
s
 MCP:          4        108        109        107   Machine check polls
 ERR:          0
 MIS:          0
 PIN:          0          0          0          0   Posted-interrupt notifi=
cation event
 NPI:          0          0          0          0   Nested posted-interrupt=
 event
 PIW:          0          0          0          0   Posted-interrupt wakeup=
 event

After running the test:

# cat /proc/interrupts
            CPU0       CPU1       CPU2       CPU3
   0:         34          0          0          0   IO-APIC    2-edge      =
timer
   1:          4          0          0          0   IO-APIC    1-edge      =
i8042
   4:          0          0        635          0   IO-APIC    4-edge      =
ttyS0
   8:          0          0          0          0   IO-APIC    8-edge      =
rtc0
   9:          0          0          0          0   IO-APIC    9-fasteoi   =
acpi
  12:          0          0          0          6   IO-APIC   12-edge      =
i8042
  16:          0          0          0          4   IO-APIC   16-fasteoi   =
i801_smbus
  19:         12          0          0          0   IO-APIC   19-fasteoi
 120:       3807          0        617          0  PCI-MSI-0000:00:1f.6    =
0-edge      eth0
 121:         50          0          0          0  PCI-MSI-0000:00:16.0    =
0-edge      mei_me
 122:          0          0          0          0  PCI-MSI-0000:00:14.0    =
0-edge      xhci_hcd
 123:          0          0    2109981          0  PCI-MSI-0000:00:17.0    =
0-edge      ahci[0000:00:17.0]
 124:          0          0          0        206  PCI-MSI-0000:00:02.0    =
0-edge      i915
 NMI:          0          0          0          0   Non-maskable interrupts
 LOC:     221568     228973     472239     229475   Local timer interrupts
 SPU:          0          0          0          0   Spurious interrupts
 PMI:          0          0          0          0   Performance monitoring =
interrupts
 IWI:         16          0          0          8   IRQ work interrupts
 RTR:        108         25         16         11   APIC ICR read retries
 RES:       5017       5488        698      10440   Rescheduling interrupts
 CAL:       4622       4584       2783       5757   Function call interrupt=
s
 TLB:         12         15         15         19   TLB shootdowns
 TRM:          0          0          0          0   Thermal event interrupt=
s
 THR:          0          0          0          0   Threshold APIC interrup=
ts
 MCE:          0          0          0          0   Machine check exception=
s
 MCP:          4        108        109        109   Machine check polls
 ERR:          0
 MIS:          0
 PIN:          0          0          0          0   Posted-interrupt notifi=
cation event
 NPI:          0          0          0          0   Nested posted-interrupt=
 event
 PIW:          0          0          0          0   Posted-interrupt wakeup=
 event


Thanks again for taking the time to look into this.

--
Best Regards,
Yujie