Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
From:   David Wysochanski <dwysocha@redhat.com>
Date:   Tue, 24 Nov 2020 16:56:37 -0500
Message-ID: <CALF+zOntimx8nyiAUyN5Y58T9_-PztLpUU2vpYgOzQkcK7C09w@mail.gmail.com>
Subject: NFS failure with generic/074 when lockdep is enabled - BUG: Invalid
 wait context
To:     linux-nfs <linux-nfs@vger.kernel.org>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

I've started seeing this failure since testing 5.10-rc4 - this does
not happen on 5.9


f31-node1 login: [  124.055768] FS-Cache: Netfs 'nfs' registered for caching
[  125.046104] Key type dns_resolver registered
[  125.770354] NFS: Registering the id_resolver key type
[  125.780599] Key type id_resolver registered
[  125.782440] Key type id_legacy registered
[  126.563717] run fstests generic/074 at 2020-11-24 11:23:49
[  178.736479]
[  178.751380] =============================
[  178.753249] [ BUG: Invalid wait context ]
[  178.754886] 5.10.0-rc4 #127 Not tainted
[  178.756423] -----------------------------
[  178.758055] kworker/1:2/848 is trying to lock:
[  178.759866] ffff8947fffd33d8 (&zone->lock){..-.}-{3:3}, at:
get_page_from_freelist+0x897/0x2190
[  178.763333] other info that might help us debug this:
[  178.765354] context-{5:5}
[  178.766437] 3 locks held by kworker/1:2/848:
[  178.768158]  #0: ffff8946ce825538
((wq_completion)nfsiod){+.+.}-{0:0}, at: process_one_work+0x1be/0x540
[  178.771871]  #1: ffff9e6b408f7e58
((work_completion)(&task->u.tk_work)#2){+.+.}-{0:0}, at:
process_one_work+0x1be/0x540
[  178.776562]  #2: ffff8947f7c5b2b0 (krc.lock){..-.}-{2:2}, at:
kvfree_call_rcu+0x69/0x230
[  178.779803] stack backtrace:
[  178.780996] CPU: 1 PID: 848 Comm: kworker/1:2 Kdump: loaded Not
tainted 5.10.0-rc4 #127
[  178.784374] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[  178.787071] Workqueue: nfsiod rpc_async_release [sunrpc]
[  178.789308] Call Trace:
[  178.790386]  dump_stack+0x8d/0xb5
[  178.791816]  __lock_acquire.cold+0x20b/0x2c8
[  178.793605]  lock_acquire+0xca/0x380
[  178.795113]  ? get_page_from_freelist+0x897/0x2190
[  178.797116]  _raw_spin_lock+0x2c/0x40
[  178.798638]  ? get_page_from_freelist+0x897/0x2190
[  178.800620]  get_page_from_freelist+0x897/0x2190
[  178.802537]  __alloc_pages_nodemask+0x1b4/0x460
[  178.804416]  __get_free_pages+0xd/0x30
[  178.805987]  kvfree_call_rcu+0x168/0x230
[  178.807687]  nfs_free_request+0xab/0x180 [nfs]
[  178.809547]  nfs_page_group_destroy+0x41/0x80 [nfs]
[  178.811588]  nfs_read_completion+0x129/0x1f0 [nfs]
[  178.813633]  rpc_free_task+0x39/0x60 [sunrpc]
[  178.815481]  rpc_async_release+0x29/0x40 [sunrpc]
[  178.817451]  process_one_work+0x23e/0x540
[  178.819136]  worker_thread+0x50/0x3a0
[  178.820657]  ? process_one_work+0x540/0x540
[  178.822427]  kthread+0x10f/0x150
[  178.823805]  ? kthread_park+0x90/0x90
[  178.825339]  ret_from_fork+0x22/0x30


# eu-addr2line -e ./fs/nfs/nfs.ko nfs_free_request+0xab
fs/nfs/pagelist.c:559:24

    541 static void nfs_clear_request(struct nfs_page *req)
    542 {
    543         struct page *page = req->wb_page;
    544         struct nfs_lock_context *l_ctx = req->wb_lock_context;
    545         struct nfs_open_context *ctx;
    546
    547         if (page != NULL) {
    548                 put_page(page);
    549                 req->wb_page = NULL;
    550         }
    551         if (l_ctx != NULL) {
    552                 if (atomic_dec_and_test(&l_ctx->io_count)) {
    553                         wake_up_var(&l_ctx->io_count);
    554                         ctx = l_ctx->open_context;
    555                         if (test_bit(NFS_CONTEXT_UNLOCK, &ctx->flags))
    556
rpc_wake_up(&NFS_SERVER(d_inode(ctx->dentry))->uoc_rpcwaitq);
    557                 }
    558                 nfs_put_lock_context(l_ctx);
    559                 req->wb_lock_context = NULL;
    560         }
    561 }

    924 void nfs_put_lock_context(struct nfs_lock_context *l_ctx)
    925 {
    926         struct nfs_open_context *ctx = l_ctx->open_context;
    927         struct inode *inode = d_inode(ctx->dentry);
    928
    929         if (!refcount_dec_and_lock(&l_ctx->count, &inode->i_lock))
    930                 return;
    931         list_del_rcu(&l_ctx->list);
    932         spin_unlock(&inode->i_lock);
    933         put_nfs_open_context(ctx);
    934         kfree_rcu(l_ctx, rcu_head);
    935 }
    936 EXPORT_SYMBOL_GPL(nfs_put_lock_context);


# eu-addr2line -e ./vmlinux get_page_from_freelist+0x897
mm/page_alloc.c:2887:2

   2875 /*
   2876  * Obtain a specified number of elements from the buddy
allocator, all under
   2877  * a single hold of the lock, for efficiency.  Add them to the
supplied list.
   2878  * Returns the number of new pages which were placed at *list.
   2879  */
   2880 static int rmqueue_bulk(struct zone *zone, unsigned int order,
   2881                         unsigned long count, struct list_head *list,
   2882                         int migratetype, unsigned int alloc_flags)
   2883 {
   2884         int i, alloced = 0;
   2885
   2886         spin_lock(&zone->lock);
   2887         for (i = 0; i < count; ++i) {
   2888                 struct page *page = __rmqueue(zone, order, migratetype,
   2889
 alloc_flags);


# eu-addr2line -e ./vmlinux kvfree_call_rcu+0x168
kernel/rcu/tree.c:3391:6

   3362         /* Check if a new block is required. */
   3363         if (!krcp->bkvhead[idx] ||
   3364                         krcp->bkvhead[idx]->nr_records ==
KVFREE_BULK_MAX_ENTR) {
   3365                 bnode = get_cached_bnode(krcp);
   3366                 if (!bnode) {
   3367                         /*
   3368                          * To keep this path working on raw
non-preemptible
   3369                          * sections, prevent the optional entry into the
   3370                          * allocator as it uses sleeping
locks. In fact, even
   3371                          * if the caller of kfree_rcu() is
preemptible, this
   3372                          * path still is not, as krcp->lock is
a raw spinlock.
   3373                          * With additional page pre-allocation
in the works,
   3374                          * hitting this return is going to be
much less likely.
   3375                          */
   3376                         if (IS_ENABLED(CONFIG_PREEMPT_RT))
   3377                                 return false;
   3378
   3379                         /*
   3380                          * NOTE: For one argument of kvfree_rcu() we can
   3381                          * drop the lock and get the page in sleepable
   3382                          * context. That would allow to
maintain an array
   3383                          * for the CONFIG_PREEMPT_RT as well
if no cached
   3384                          * pages are available.
   3385                          */
   3386                         bnode = (struct kvfree_rcu_bulk_data *)
   3387                                 __get_free_page(GFP_NOWAIT |
__GFP_NOWARN);
   3388                 }
   3389
   3390                 /* Switch to emergency path. */
   3391                 if (unlikely(!bnode))
   3392                         return false;