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:   Wed, 6 Jul 2022 22:21:36 +0800
From:   Oliver Sang <oliver.sang@intel.com>
To:     Mel Gorman <mgorman@techsingularity.net>
Cc:     Andrew Morton <akpm@linux-foundation.org>,
        0day robot <lkp@intel.com>,
        LKML <linux-kernel@vger.kernel.org>, linux-mm@kvack.org,
        lkp@lists.01.org, Nicolas Saenz Julienne <nsaenzju@redhat.com>,
        Marcelo Tosatti <mtosatti@redhat.com>,
        Vlastimil Babka <vbabka@suse.cz>,
        Michal Hocko <mhocko@kernel.org>,
        Hugh Dickins <hughd@google.com>
Subject: Re: [mm/page_alloc]  2bd8eec68f:
 BUG:sleeping_function_called_from_invalid_context_at_mm/gup.c
Message-ID: <YsWacP1k8wMgGfXx@xsang-OptiPlex-9020>
References: <20220613125622.18628-8-mgorman@techsingularity.net>
 <YsFk/qU+QtWun04h@xsang-OptiPlex-9020>
 <20220703132209.875b823d1cb7169a8d51d56d@linux-foundation.org>
 <YsRB3fZHAfik0M/q@xsang-OptiPlex-9020>
 <20220706095535.GD27531@techsingularity.net>
 <20220706115328.GE27531@techsingularity.net>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20220706115328.GE27531@techsingularity.net>
Precedence: bulk

hi, Mel Gorman,

On Wed, Jul 06, 2022 at 12:53:29PM +0100, Mel Gorman wrote:
> On Wed, Jul 06, 2022 at 10:55:35AM +0100, Mel Gorman wrote:
> > On Tue, Jul 05, 2022 at 09:51:25PM +0800, Oliver Sang wrote:
> > > Hi Andrew Morton,
> > > 
> > > On Sun, Jul 03, 2022 at 01:22:09PM -0700, Andrew Morton wrote:
> > > > On Sun, 3 Jul 2022 17:44:30 +0800 kernel test robot <oliver.sang@intel.com> wrote:
> > > > 
> > > > > FYI, we noticed the following commit (built with gcc-11):
> > > > > 
> > > > > commit: 2bd8eec68f740608db5ea58ecff06965228764cb ("[PATCH 7/7] mm/page_alloc: Replace local_lock with normal spinlock")
> > > > > url: https://github.com/intel-lab-lkp/linux/commits/Mel-Gorman/Drain-remote-per-cpu-directly/20220613-230139
> > > > > base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git b13baccc3850ca8b8cccbf8ed9912dbaa0fdf7f3
> > > > > patch link: https://lore.kernel.org/lkml/20220613125622.18628-8-mgorman@techsingularity.net
> > > > > 
> > > > 
> > > > Did this test include the followup patch
> > > > mm-page_alloc-replace-local_lock-with-normal-spinlock-fix.patch?
> > > 
> > > no, we just fetched original patch set and test upon it.
> > > 
> > > now we applied the patch you pointed to us upon 2bd8eec68f and found the issue
> > > still exist.
> > > (attached dmesg FYI)
> > > 
> > 
> > Thanks Oliver.
> > 
> > The trace is odd in that it hits in GUP when the page allocator is no
> > longer active and the context is a syscall. First, is this definitely
> > the first patch the problem occurs?
> > 
> 
> I tried reproducing this on a 2-socket machine with Xeon
> Gold Gold 5218R CPUs. It was necessary to set timeouts in both
> vm/settings and kselftest/runner.sh to avoid timeouts. Testing with
> a standard config on my original 5.19-rc3 baseline and the baseline
> b13baccc3850ca8b8cccbf8ed9912dbaa0fdf7f3 both passed. I tried your kernel
> config with i915 disabled (would not build) and necessary storage drivers
> and network drivers enabled (for boot and access). The kernel log shows
> a bunch of warnings related to USBAN during boot and during some of the
> tests but otherwise compaction_test completed successfully as well as
> the other VM tests.
> 
> Is this always reproducible?

not always but high rate.
we actually also observed other dmesgs stats for both 2bd8eec68f74 and its
parent, but those dmesg.BUG:sleeping_function_called_from_invalid_context_at*
seem only happen on 2bd8eec68f74 as well as the '-fix' commit.

=========================================================================================
compiler/group/kconfig/rootfs/sc_nr_hugepages/tbox_group/testcase/ucode:
  gcc-11/vm/x86_64-rhel-8.3-kselftests/debian-11.1-x86_64-20220510.cgz/2/lkp-csl-2sp9/kernel-selftests/0x500320a

commit:
  eec0ff5df294 ("mm/page_alloc: Remotely drain per-cpu lists")
  2bd8eec68f74 ("mm/page_alloc: Replace local_lock with normal spinlock")
  292baeb4c714 ("mm/page_alloc: replace local_lock with normal spinlock -fix")

eec0ff5df2945d19 2bd8eec68f740608db5ea58ecff 292baeb4c7149ac2cb844137481
---------------- --------------------------- ---------------------------
       fail:runs  %reproduction    fail:runs  %reproduction    fail:runs
           |             |             |             |             |
           :20          75%          15:20          70%          14:21    dmesg.BUG:scheduling_while_atomic
           :20           5%           1:20           0%            :21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_fs/binfmt_elf.c
           :20           5%           1:20          10%           2:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_fs/dcache.c
           :20           5%           1:20           5%           1:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_include/linux/freezer.h
           :20          10%           2:20          25%           5:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_include/linux/mmu_notifier.h
           :20           5%           1:20           0%            :21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_include/linux/percpu-rwsem.h
           :20          40%           8:20          40%           8:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_include/linux/sched/mm.h
           :20          10%           2:20           0%            :21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c
           :20          10%           2:20          10%           2:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_lib/strncpy_from_user.c
           :20          55%          11:20          65%          13:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/gup.c
           :20          15%           3:20           5%           1:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/memory.c
           :20          60%          12:20          55%          11:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/migrate.c
           :20           5%           1:20           5%           1:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c
           :20           0%            :20           5%           1:21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/rmap.c
           :20          15%           3:20           0%            :21    dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/vmalloc.c
           :20          45%           9:20          45%           9:21    dmesg.BUG:workqueue_leaked_lock_or_atomic
           :20          25%           5:20          15%           3:21    dmesg.Kernel_panic-not_syncing:Attempted_to_kill_init!exitcode=
           :20           5%           1:20           0%            :21    dmesg.RIP:__clear_user
         20:20           0%          20:20           5%          21:21    dmesg.RIP:rcu_eqs_exit
         20:20           0%          20:20           5%          21:21    dmesg.RIP:sched_clock_tick
           :20           5%           1:20           0%            :21    dmesg.RIP:smp_call_function_many_cond
         20:20           0%          20:20           5%          21:21    dmesg.WARNING:at_kernel/rcu/tree.c:#rcu_eqs_exit
         20:20           0%          20:20           5%          21:21    dmesg.WARNING:at_kernel/sched/clock.c:#sched_clock_tick
           :20           5%           1:20           0%            :21    dmesg.WARNING:at_kernel/smp.c:#smp_call_function_many_cond
         20:20           0%          20:20           5%          21:21    dmesg.WARNING:suspicious_RCU_usage
         20:20           0%          20:20           5%          21:21    dmesg.boot_failures
          9:20         -15%           6:20          -5%           8:21    dmesg.include/linux/rcupdate.h:#rcu_read_lock()used_illegally_while_idle
          9:20         -15%           6:20          -5%           8:21    dmesg.include/linux/rcupdate.h:#rcu_read_unlock()used_illegally_while_idle
         20:20           0%          20:20           5%          21:21    dmesg.include/trace/events/error_report.h:#suspicious_rcu_dereference_check()usage
         20:20           0%          20:20           5%          21:21    dmesg.include/trace/events/lock.h:#suspicious_rcu_dereference_check()usage


> 
> -- 
> Mel Gorman
> SUSE Labs