Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1759212AbdLRPRk convert rfc822-to-8bit (ORCPT <rfc822;w@1wt.eu>);
        Mon, 18 Dec 2017 10:17:40 -0500
Received: from mout.gmx.net ([212.227.15.15]:63915 "EHLO mout.gmx.net"
        rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
        id S1758386AbdLRPRU (ORCPT <rfc822;linux-kernel@vger.kernel.org>);
        Mon, 18 Dec 2017 10:17:20 -0500
Message-ID: <1513610231.7998.13.camel@gmx.de>
Subject: NFS: 82ms wakeup latency 4.14-rc4
From: Mike Galbraith <efault@gmx.de>
To: lkml <linux-kernel@vger.kernel.org>
Cc: "J. Bruce Fields" <bfields@fieldses.org>,
        Jeff Layton <jlayton@kernel.org>, linux-nfs@vger.kernel.org
Date: Mon, 18 Dec 2017 16:17:11 +0100
Content-Type: text/plain; charset="ISO-8859-15"
X-Mailer: Evolution 3.20.5 
Mime-Version: 1.0
Content-Transfer-Encoding: 8BIT
X-Provags-ID: V03:K0:1dW16AmqxdB+/C2Afbf+5HKlUFxjKaBI9VhvDRQPddWGhpLaNSW
 yxa4u6x5j0Zws+l53CVSiTeX+cK7VwQOcs3GwnBMr5eaRvdFZyUu6U1o51uZuiIV6K8eX3S
 h8hhBNn+dz6ju5gzlMC+bGQNrOJKoPJaKWFIgXC56SqtkB3WqU+LccVhSQwWhx/Hc9AJM+F
 w504UmKNHsZlwxM/igtpA==
X-UI-Out-Filterresults: notjunk:1;V01:K0:Nxlcn06KIL0=:rxGYv2GSwLovGGtAZ80TYf
 xfuNEo53v58RMO+ie8yalPKT7U0hWQ2iHZmNKrdHGOiiAJGoszvbIhCJD0sOsJPmp1hXruMg+
 NDx5fXnvdDgY7BBuVU35cdVPKQJeXafquiBO8V2f4tO6sTwvyEfceXhW6EpQZHaKJS/knVycC
 EF0CSqsIf7t63m7KBxL9rEPPsiz7nyXm0XJBxNmO/ZyZgEjAnH8HC0rlMEP02GLQRD1daCQYy
 PNMApQ5kjYQWIY1dPjG6e0n0VGhtxedZG8GxHsyJDsjzS7FSHPSQDVjot4Wu64ylSLPI2C23P
 UgLEmpfBu/ftsmzZ4RmScimiZDlZ31JYtBoJwSP/SbmPovZx6cbYCG81xZHkwi2/NtvTgHiYY
 7P84FAfd5fqthvjaoAWcCUOC38wkY7HvsxebCmZnykDpYb9gpZQT6x6rajqB9GFRT88CkHmvI
 jbeQ4xbq60Cx53P/ZDTTFdRpq6sYdIA2nmAEdJ/ADzWf7Yz+O8LtXJJB3+IG6KQyTLKottzqo
 LYji5H7D4sRVHdxikOHUb6L3qNQyMFTAygLsQwkYMC4O9tmLEPxbNptKQ6qbzdbBBIARAnhHr
 nXZuls3CWsB64iAI1wHpd/XgXjBVR2CHrr6cghiE7guEJvzWQ6TWQEhbr0meahpUf/ZNRITh8
 Wt4vk7OLK1ExHJ73hs8i6sONPI5S4YvWOUnXl9c+yF7lEBWBF5z5S6AbZaIZ2e/8DCSFUUuAE
 T+wahnOM3qXJwgh5Y6l0AuOLeexsfHPKIfqFjuRACm+K2Ygd+fwlFb20BEViBmnPlS5UbO5u7
 H15s7LWEu+b7la+lA4JuoshJt0hSsnWU1CQanlyP+I5zhdpN4s=
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org
Content-Length: 2318
Lines: 36

Greetings,

While doing some generic scheduler latency testing, I stumbled onto
$subject. ?To reproduce this, I simply nfs mount my box, cd to one of
it's spinning rust buckets, and do bonnie -s <ramsize>. ?With nothing
else going on in the box, I've hit > 100ms wakeup latencies.

(nouveau apparently also thinks this is uncool, and whimpers)?

....
kworker/-7421    0.N.. 82893us : nfs_release_request <-nfs_commit_release_pages
kworker/-7421    0.N.. 82893us : nfs_unlock_and_release_request <-nfs_commit_release_pages
kworker/-7421    0.N.. 82893us : nfs_unlock_request <-nfs_unlock_and_release_request
kworker/-7421    0.N.. 82893us : nfs_page_group_destroy <-nfs_commit_release_pages
kworker/-7421    0.N.. 82893us : nfs_page_group_sync_on_bit <-nfs_page_group_destroy
kworker/-7421    0.N.. 82893us : nfs_page_group_lock <-nfs_page_group_sync_on_bit
kworker/-7421    0.N.. 82893us : nfs_page_group_unlock <-nfs_page_group_sync_on_bit
kworker/-7421    0.N.. 82893us : nfs_free_request <-nfs_page_group_destroy
kworker/-7421    0.N.. 82893us : nfs_put_lock_context <-nfs_free_request
kworker/-7421    0.N.. 82893us : put_nfs_open_context <-nfs_free_request
kworker/-7421    0.N.. 82893us : __put_nfs_open_context <-nfs_free_request
kworker/-7421    0.N.. 82894us : kmem_cache_free <-nfs_page_group_destroy
kworker/-7421    0.N.. 82894us : __slab_free <-kmem_cache_free
kworker/-7421    0.N.. 82894us : clear_wb_congested <-nfs_commit_release_pages
kworker/-7421    0.N.. 82894us : nfs_init_cinfo <-nfs_commit_release_pages
kworker/-7421    0.N.. 82894us : nfs_init_cinfo_from_inode <-nfs_commit_release_pages
kworker/-7421    0.N.. 82894us : nfs_commit_end <-nfs_commit_release_pages
kworker/-7421    0.N.. 82894us : nfs_commitdata_release <-rpc_free_task
kworker/-7421    0.N.. 82894us : put_nfs_open_context <-nfs_commitdata_release
kworker/-7421    0.N.. 82894us : __put_nfs_open_context <-nfs_commitdata_release
kworker/-7421    0.N.. 82895us : mempool_free <-rpc_free_task
kworker/-7421    0.N.. 82895us : mempool_free_slab <-rpc_free_task
kworker/-7421    0.N.. 82895us : kmem_cache_free <-rpc_free_task
kworker/-7421    0.N.. 82895us : ___might_sleep <-process_one_work
kworker/-7421    0.N.. 82895us : _cond_resched <-process_one_work
kworker/-7421    0dN.1 82895us : rcu_note_context_switch <-__schedule