From patchwork Mon Oct 22 20:26:11 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chris Perl X-Patchwork-Id: 1627811 Return-Path: X-Original-To: patchwork-linux-nfs@patchwork.kernel.org Delivered-To: patchwork-process-083081@patchwork2.kernel.org Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by patchwork2.kernel.org (Postfix) with ESMTP id 46603DFB7A for ; Mon, 22 Oct 2012 20:26:36 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756176Ab2JVU0a (ORCPT ); Mon, 22 Oct 2012 16:26:30 -0400 Received: from mail-vc0-f174.google.com ([209.85.220.174]:51746 "EHLO mail-vc0-f174.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756155Ab2JVU02 (ORCPT ); Mon, 22 Oct 2012 16:26:28 -0400 Received: by mail-vc0-f174.google.com with SMTP id fk26so3432215vcb.19 for ; Mon, 22 Oct 2012 13:26:27 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=date:from:to:cc:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; bh=bQtvP7/JFab3vQHemsOOmRPLkqwft0Q5uZXC4bxVwmM=; b=YXFTZyVILSKsoqVxPfqnuJVWAhgMHDrdcKa9RjS4NYTz35TGfXNnthVIOzXeiO9XUX psoSFzu7nP+XI8RQGsqfF2uT/6UGLnR6wBTcCXm3xRriBOjs8Wt1lAc7wn2hqLdYfpvJ E3rvvmPqEx+hRnxNlnS0ekhZsuB2ObFeDe//vmbYp6fXXfxHNoFPZbqKZJOTEDqJ/0N0 YcR6S16TAnpd2UyZdfOBZjg40SKMYz3/dS4APWyNlDU+hxCbTyb0/L+lf1iNN1YLnwb/ bg5nYPfq6ZbmyCWTkl1cdRvrDXgDQaeLOLGn/Mo7mTBmYP56xn8DTVavWJYC17WH91pn uAIg== Received: by 10.52.23.71 with SMTP id k7mr13989441vdf.26.1350937587669; Mon, 22 Oct 2012 13:26:27 -0700 (PDT) Received: from nyc-qws-132.nyc.delacy.com ([38.105.200.252]) by mx.google.com with ESMTPS id t12sm11048522vdi.18.2012.10.22.13.26.26 (version=TLSv1/SSLv3 cipher=OTHER); Mon, 22 Oct 2012 13:26:27 -0700 (PDT) Date: Mon, 22 Oct 2012 16:26:11 -0400 From: Chris Perl To: "Myklebust, Trond" Cc: "linux-nfs@vger.kernel.org" Subject: Re: RPC Race Condition Message-ID: <20121022202611.GA27191@nyc-qws-132.nyc.delacy.com> References: <20121022180339.GC24763@nyc-qws-132.nyc.delacy.com> <4FA345DA4F4AE44899BD2B03EEEC2FA909289403@SACEXCMBX04-PRD.hq.netapp.com> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <4FA345DA4F4AE44899BD2B03EEEC2FA909289403@SACEXCMBX04-PRD.hq.netapp.com> User-Agent: Mutt/1.5.20 (2009-12-10) Sender: linux-nfs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org On Mon, Oct 22, 2012 at 06:28:02PM +0000, Myklebust, Trond wrote: > Hi Chris, > > Thanks for helping to debug this, and for providing such a thorough > analysis! This is great work! > > Does adding a check in xs_error_report() for xprt_connecting(xprt) so > that we skip the call to xprt_wake_pending_tasks() if true, help to > resolve the race? This is what I changed: Unfortunately it does not resolve it. It appears that does stop the wakeup from happening where I detailed it before, but we still wake up too early. The following is the call stack from SystemTap catching the call to `rpc_make_runnable': 0xffffffffa0434840 : rpc_make_runnable+0x0/0x80 [sunrpc] 0xffffffffa0434b5e : rpc_wake_up_task_queue_locked+0x18e/0x270 [sunrpc] 0xffffffffa0434c8e : rpc_wake_up_status+0x4e/0x80 [sunrpc] 0xffffffffa042d8ec : xprt_wake_pending_tasks+0x2c/0x30 [sunrpc] 0xffffffffa042da56 : xprt_disconnect_done+0x46/0x70 [sunrpc] 0xffffffffa04305b0 : xs_tcp_setup_socket+0x330/0x4c0 [sunrpc] 0xffffffff8108c760 : worker_thread+0x170/0x2a0 [kernel] 0xffffffff81091d66 : kthread+0x96/0xa0 [kernel] 0xffffffff8100c14a : child_rip+0xa/0x20 [kernel] However, its mildly confusing to me since I cannot follow that exact call stack in the code. The nearest I can find to that is the following: rpc_make_runnable rpc_wake_up_task_queue_locked rpc_wake_up_status xprt_wake_pending_tasks xprt_disconnect_done xs_sock_mark_closed xs_abort_connection xs_tcp_reuse_connection xs_tcp_setup_socket As far as I can tell, we get here because the call to `kernel_connect' from within `xs_abort_connection' by rpciod is returning 0 sometimes (and EINPROGRESS others). When it returns 0, we enter this block: if (!result) xs_sock_mark_closed(&transport->xprt); else dprintk("RPC: AF_UNSPEC connect return code %d\n", result); and that eventually gets us woken up via the call stack above. The end result is the same, we wake up and move on to `call_transmit' before rpciod is done connecting the socket. I'll do some more tracing and see what else I can come up with. Chris --- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html --- a/net/sunrpc/xprtsock.c 2012-08-14 08:47:16.000000000 -0400 +++ b/net/sunrpc/xprtsock.c 2012-10-22 14:50:09.237725498 -0400 @@ -1571,7 +1571,8 @@ dprintk("RPC: %s client %p...\n" "RPC: error %d\n", __func__, xprt, sk->sk_err); - xprt_wake_pending_tasks(xprt, -EAGAIN); + if (!xprt_connecting(xprt)) + xprt_wake_pending_tasks(xprt, -EAGAIN); out: read_unlock_bh(&sk->sk_callback_lock); }