From patchwork Sun Mar 19 15:10:36 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Paul Blakey X-Patchwork-Id: 740698 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from mail.linuxfoundation.org (mail.linuxfoundation.org [140.211.169.12]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3vmMwC5XFnz9rxw for ; Mon, 20 Mar 2017 02:10:51 +1100 (AEDT) Authentication-Results: ozlabs.org; dkim=fail reason="signature verification failed" (1024-bit key; unprotected) header.d=Mellanox.com header.i=@Mellanox.com header.b="seenTWB/"; dkim-atps=neutral Received: from mail.linux-foundation.org (localhost [127.0.0.1]) by mail.linuxfoundation.org (Postfix) with ESMTP id 57FF4899; Sun, 19 Mar 2017 15:10:48 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@mail.linuxfoundation.org Received: from smtp1.linuxfoundation.org (smtp1.linux-foundation.org [172.17.192.35]) by mail.linuxfoundation.org (Postfix) with ESMTPS id 8A8E37A4 for ; Sun, 19 Mar 2017 15:10:47 +0000 (UTC) X-Greylist: whitelisted by SQLgrey-1.7.6 Received: from EUR01-HE1-obe.outbound.protection.outlook.com (mail-he1eur01on0078.outbound.protection.outlook.com [104.47.0.78]) by smtp1.linuxfoundation.org (Postfix) with ESMTPS id CCB5F13D for ; Sun, 19 Mar 2017 15:10:45 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=Mellanox.com; s=selector1; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version; bh=kMoHjd292mxkok/fJ6h8zm+STemd/jlnLAe1VPG1yE8=; b=seenTWB/6skYT+pAHaCQT0elh1/xVvC3L8+BuFpVdt67I7BFtStu+b8EXo6acsHuEYtp75eyaGiMzfBKhFU7QgiTgI+i52STprr+sJKIRWMrrAVpkcHw/Yl7ooMIxm+wSOheSg56MrUT/zWhcXn8x8MZQMozquAJB8ss6JUArHQ= Authentication-Results: ovn.org; dkim=none (message not signed) header.d=none; ovn.org; dmarc=none action=none header.from=mellanox.com; Received: from [10.223.3.152] (193.47.165.251) by HE1PR0501MB2489.eurprd05.prod.outlook.com (10.168.126.21) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384_P384) id 15.1.977.11; Sun, 19 Mar 2017 15:10:41 +0000 To: References: From: Paul Blakey Message-ID: <40322c88-ed71-8d1c-9a21-8702ce837c71@mellanox.com> Date: Sun, 19 Mar 2017 17:10:36 +0200 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Thunderbird/45.7.1 MIME-Version: 1.0 In-Reply-To: X-Originating-IP: [193.47.165.251] X-ClientProxiedBy: VI1PR0501CA0010.eurprd05.prod.outlook.com (10.172.9.148) To HE1PR0501MB2489.eurprd05.prod.outlook.com (10.168.126.21) X-MS-Office365-Filtering-Correlation-Id: 4e32f77c-7baa-43ae-0a79-08d46eda1c48 X-MS-Office365-Filtering-HT: Tenant X-Microsoft-Antispam: UriScan:; BCL:0; PCL:0; RULEID:(22001)(48565401081); SRVR:HE1PR0501MB2489; X-Microsoft-Exchange-Diagnostics: 1; HE1PR0501MB2489; 3:UqYQyci1WFd9lS+xCTmY6f2ohYc/8EUQCSEyso+aYywottYutemQlI8cNNz2hBn8Db0DF/1FBDoQ5C94FwNhl87nrHeZDrorVebb8W83wPzQymg5B9ACvdf2SM0iEzhrOaIOzAZB4fmOl2H7CMjdVBIcE09z10Su36DBuE7nMPpWsaTWfcKTKa3BlokQdkyxwFcSFquKZAlmgpnIPTuMAde+NVey2WtJjxnem/VDOe1PB73lvHzh66FKI/m6plhQ9AxXHJCfup7C9WiJV+sS4LUVyP1PylLJQj1+0cPzg08=; 25:DnhiwJ2CqFh0D/lvbne5Jcd2oh8ARctFP5BiSNNWN93kVre4PzKU7dAgXsf7ME6FDjivo5aNBKAQeUkueeEV/Wj5Csce8baPf1XbmtE241/qwxvIxPhd8Cmq1ehUtoh2zjxLyTtBUTm/Kv0jGG9LdsTy5FXdt34B6KdlreRAcLatrc/ZMNrIG4a//LEfatAVqav2TtpZFObVYeb5YmTAW7l9fJYR3Aqk16bDQffRJncTHDnWHe3QUV2tMCkhlKaYN+5ASxLXtYccUyP+RRCUg8OWSdGvLkg4IrWa0vnIF2ZqVQ7FARqxh5pnfhUag0YDlH71icAp9nNJkcpVAm2LEMLpgFzzGtBXbiILEc3ZqU6FQgFjYFdtX+lsrAf/79A6hCtHpVTpHh8e+dZsWO6GRfr99/VoNNPcb6Z9wmq032rpd8O0e5Bnjj1QsWRahdjWNmH7Mw95Ps/lIpnmPlHtjA== X-Microsoft-Exchange-Diagnostics: 1; HE1PR0501MB2489; 31:dGc3CHP8p35SfR+/XUniCpCOkTCkgXfjWJ3wogsciMW3F32mKI3xyFIarQjjspzklcnb2S/Rx4bZBduqPY2FurQBPiI6btCE9YHTim+4+yHP+FaFyJJekk6OWNrYx+k7LYlt45eYOtePDNbr5DcNIma32srP3xr5tlF7cs10QPTnR7TFu9K6NxHp88X187hkumyC70D3E9UB4e0gtuLyT8vWSotJUdN2xPhOCgpo9ao=; 20:g5orqKivnvF6tQgce2tvEMsbL+/Afl3B/tXTpbnug8CNhKBuCViRPG6jd2PHK2WHWDybTh+N0NS8UzwhKRza/5JzTteHOj31GaoFqH8aJOlB59Mv36PfMXkDDrjjXq9L13IdwqERMne3i/icBZBhWbUmtnVdO9yBU4Rh1F2q+s1cTwglunFue/JDA97IQImR5TiKVRPseaVHhRP6briiIMYsEnNdpUUl4SZ0n8bUbotVS1JIv7mWRWSZADWkTqmQzhr/20CxK9VaRHC24eSQnKeHYWjr1d6A0iGoFwj4nmw4Ttda1/3UV9B18TxONwR32+IWO2kiL3tKo6SabrSevzc4vjSDuQ53ABrg8uD5E+AakPdYmWfPLg4Z4pe5c6+6dCj8qKRZmxxGRMvOFud/VMBuIRGjdszjbddOXBGGs4qRVQrEUkEjjPB0QAXa8uTJ8xcb0weBYGuhF/itPSu7DXtVnlh3tmkIdPFz6/ea3TQI3n5bnguYAS5Bs6ewNp9/ X-Microsoft-Antispam-PRVS: X-Exchange-Antispam-Report-Test: UriScan:; X-Exchange-Antispam-Report-CFA-Test: BCL:0; PCL:0; RULEID:(6040375)(601004)(2401047)(8121501046)(5005006)(3002001)(10201501046)(6055026)(6041248)(20161123558025)(20161123564025)(20161123562025)(20161123555025)(20161123560025)(6072148); SRVR:HE1PR0501MB2489; BCL:0; PCL:0; RULEID:; SRVR:HE1PR0501MB2489; X-Microsoft-Exchange-Diagnostics: 1; HE1PR0501MB2489; 4:85QLkGTI9Rk/nepVjbVE1tF753N7j8AyNaM/CxR9mUbag+9avLCzKKC4FzCVpltheip5iJElsI45FUTi0Hk5PumU4/TRfD4HyjkgR+TlxKdxvsNzaaTzfktvOeDn0PqlnBgis0KjGcZShBrh2u4mgdyqmOu1K4uT7UqI5NDfaJ4s3hLk7VHqbqRGg6gG40WCKogzuud2mDQqxhP/zFTeNn1WsoiipOs+cK5gy1QNknFkMubQrjR5TcOO8CMsAaQfShSLraY2Zh+FeqcMLb5B13h4lp+b6c1iX9JC8hyAVn7CncvhlaSrZVsFsVsrUt8NdkB6rOGJptO8VQbqra0fmkZqn4NYPQRhGMwEKOD8EoFn9kydXM/WT7xnQvBP4CEvHKR3D7N2GZ8zDfo0STQeRnZV3lYiCbuHnTT3G3+GfDxdS4OW7EKEHOx5nw65ZPYHnuBm0R8a6+iUVhPKDeP567ZblPG4nQxGuC6JZH+cOQoFWe97CMo4OW8vNJfs3t+i/yGF4kz2e0YGyo3eHG4etVDGwo4JRNq5H80ceOmXrUGovmce4U0xtcHinaolUY5fHtzvP+BJU84IYi5/wLPxRzEf6qRJl5K5AeitUou/yXD/pi4ngorJgCDmeXQqVQU0 X-Forefront-PRVS: 025100C802 X-Forefront-Antispam-Report: SFV:NSPM; SFS:(10009020)(4630300001)(6049001)(6009001)(39860400002)(39840400002)(39850400002)(39450400003)(39410400002)(24454002)(55674003)(53754006)(305945005)(50466002)(65826007)(7736002)(83506001)(64126003)(2351001)(54906002)(77096006)(65956001)(33646002)(230700001)(6486002)(66066001)(6116002)(5660300001)(3846002)(90366009)(8676002)(229853002)(81166006)(25786008)(47776003)(4001350100001)(53936002)(31686004)(4326008)(42186005)(2950100002)(6916009)(189998001)(2906002)(53546008)(6246003)(31696002)(110136004)(86362001)(38730400002)(6666003)(54356999)(36756003)(50986999)(76176999); DIR:OUT; SFP:1101; SCL:1; SRVR:HE1PR0501MB2489; H:[10.223.3.152]; FPR:; SPF:None; MLV:sfv; LANG:en; X-Microsoft-Exchange-Diagnostics: =?windows-1255?Q?1; HE1PR0501MB2489; 23:7Q7VmJkA+BWnAJIPbEKIW7cliR3PASI6e/C?= =?windows-1255?Q?Lv4XG9UDVvekkqFRj7y6l7awVVoJ5Y9BYzGhlbv/dwnsC7Xw9pmxczAz?= =?windows-1255?Q?N49sxZdAKvQygYFrEY2hYAohDk0Ef/pfqKqJw1bBozxFGHesEhERZUzf?= =?windows-1255?Q?dXanJ8EccxGxaXKuelplNUCPygplOQP0dmJ/dcEmHN04wwk9D83csSCS?= =?windows-1255?Q?f2Tf8wQM2+PiSR/9wkiwzOYqYXc8i6PwRO8cx2M8d/n6AzVvhWs27s8F?= =?windows-1255?Q?LZOl/GKncQ8hQ1nggsWZoGyOBxyZzTQb2+LuYJU71CczC3Zngpr+scOK?= =?windows-1255?Q?pV2jd1+AlLW++zDkarhnotXUE5fcBi3O+AXpI99RcenJ62COVQkPhMV6?= =?windows-1255?Q?J3vw2ad73KZcc7n+MAVlPNaEOPI8YU2LiPT3yCu/YNbdImf+yjm/hQJw?= =?windows-1255?Q?I162yEFxO/blTtM/34eTivgcqzwQpJ2kKQX2s2rBNoMdciOc8kvqCt0s?= =?windows-1255?Q?S+YFSbluofvtqr6CcEbz0CnmOS+6ghTKMA/nzXRt/cs04iOOiFl7u6BE?= =?windows-1255?Q?ia8PgMfmHHBxndLOZBK07PLybHw4XyL3cLxIt0S9ldNiqCXRdqrzw+8o?= =?windows-1255?Q?yu/ONbWzT56L3WUPJkMVwdyF9i6ht5XQe0OUSgWHrb5Cb/gCG0Wg18sP?= =?windows-1255?Q?mXI8OabuzgkdILDoFF4PTOzWZrBUh7Jf2yWBh7W5JJlJM9yAEhrj6Adr?= =?windows-1255?Q?5yr4MjywdCpc2guCd7r7dZzd8j4k4/IMhUFvugc6L0LRDoZgi6bFQT6Z?= =?windows-1255?Q?dK9Sf/axWtgwZN03lz9H0iN6SSKzS1tEoDfQLvvCJCLAkKwBiOWXOhQ8?= =?windows-1255?Q?mV67zX9XoIo/ejUuJVwCp4yd7Wo7m5Z7RABof4GPp8kZvFN0Erroz2S5?= =?windows-1255?Q?zzjehZWl94bMlONjm9IIZS507/g9hcGBfd4RUEWv0ZaR4XHjszMFgLR9?= =?windows-1255?Q?839rAkNgAxb76edWJzNBIjXsMyBgJxjL1Jhni9TgVqXlDB9SBDIe9Aq6?= =?windows-1255?Q?Xm3YLpWIh2W4O7FX36XapzTTbOzV2skgGZicbasFL4oxxrDHu//GzJvK?= =?windows-1255?Q?msbD3kX0F1Ylo5xf0caNo2cY/LCVAFyDIbrPbvsSp7XOxP1rsHwHg7Rv?= =?windows-1255?Q?YWUpFZk5mbGOspGu0XfMq1PNyhgrYCx02XELspFNs2h9Xs11EP3QcMVy?= =?windows-1255?Q?0TJgNiZO8MZ+pG0dCP554DOOU8z4aT0WzRIUv3uFiV+dDcRTBpZHSg94?= =?windows-1255?Q?wDS8hyva/eK/Y9jZPXar0y7dvttmGsr1i9tsBiODAOIqcZG0mYK4UIQw?= =?windows-1255?Q?YHhPiAqwK7aG14rySlhr4EDkOAWCRmrpcVg5IuK0nUxf+/Ne7wV3E1Bg?= =?windows-1255?Q?=3D?= X-Microsoft-Exchange-Diagnostics: 1; HE1PR0501MB2489; 6:V2BhSidXBU7MLPA4gWYETg+Avn1tvkA7EXNcdmTPUfI/7MxatOG/gM7Fhp2viZrx90ffhtqu5yqSbtxOLP3fPqNoRozyx4rfFPd9kLIUJvbCvlcf0RNkFskxbssLsof/ikAZN0ClczDwrwAKwexl7Zn/7/3Unqc4KQk1TNRTT+E+xPCchVOE6Byjnyljlhc1m7SH/ZtQe1/q0584+cFrHgEXNFfcPeRWZKJulgKZ0pz9ANwkEwf5aEiO8li4dsRZw6zDS/4LBPQhdrQcy/Y4p7nbUhCGBEyygJcFzzBuxAhM5DCx4zwdoVwlZrIDFvbmCu2GSoj32UtWjasM57gfREN8+or1XWY0IWpUYeLfo7pykUJ+/9RW42bj5KdRmxs2gr3+fr1vIvJKz46q8csHL55Cejc+BR2cyVEr2cA6sl0=; 5:aaj8zYdnWNGS7HkQMKkvadGj7WKVx48ArxZyyTBA4cdL8nD/spuWpCGCtG+mUgvCYdOm3CsbfL2yxPz/SZxl9JNXODoJXYW9l++259dF7CfBIe+3raTwFgFQ/mVsh2WRm4XOrLEwwiQeKqMLkLB2dA==; 24:Yl1/MXfSKRVlIlztmeaXvfBZoT/JyFOIRafJa1EYNTRNXX/OvjIVrmtus7yhau9htRJttmnO6cj2JGYk7ZeP/E5nwae7hsuKGdrzM5QCPys= SpamDiagnosticOutput: 1:99 SpamDiagnosticMetadata: NSPM X-Microsoft-Exchange-Diagnostics: 1; HE1PR0501MB2489; 7:/q6gdGm6pYKNql9RTk1WD6v/g0FvyN55f13ZOfnDh4rXCx+hKW9HD921xunehAwKWdr2qz2g6sRLZjEANtqsZhujMx0DqtBuDTtnVu1dBAV2Sv9Y+p+N5BNkPD2y47dH9SUD7XBqhopwEhQvsRhxpEvQW7cqaWX3LwQUDFXPQbjmgKDr4kOoVPN+ewc32Bhvp+U6gngJJj55M9cHCtpaOBgHY0vASYtfZMcHxuJgihu27YN3VsXEv0682+l7Q6VNCrhjJLKrz0b1l7FGP+e2XJXpANm5rUngpw4LtGvK7GNtCERHUama8+c/NQZlAbGAUtyrwRFJU5VNdbaXz/wZVw== X-OriginatorOrg: Mellanox.com X-MS-Exchange-CrossTenant-OriginalArrivalTime: 19 Mar 2017 15:10:41.5686 (UTC) X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted X-MS-Exchange-Transport-CrossTenantHeadersStamped: HE1PR0501MB2489 X-Spam-Status: No, score=-2.0 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, RCVD_IN_DNSWL_NONE autolearn=ham version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on smtp1.linux-foundation.org Subject: Re: [ovs-dev] About a race condition between handle_upcalls and revalidate X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: ovs-dev-bounces@openvswitch.org Errors-To: ovs-dev-bounces@openvswitch.org On 19/03/2017 16:28, Paul Blakey wrote: > Hi all, > > While using out patches for HW offload we've noticed we get a ovs > assertion at transition ukey, which tries to > transition the ukey state from EVICTED back to OPERATIONAL. > With furthur investigation it seem that this can happen without our HW > offload patches as there might be a race between handle_upcalls and > revalidate. > > The procedure is as such: > > handle_upcalls receives a new upcall and creates a new ukey, its state > is VISIBLE, it then it installs a flow (FLOW_PUT) to the datapat and > upon success wants to set the ukey state to OPERATIONAL (line 1408). for > that the handler running handle_upcalls wants to reaquirce the ukey > lock, but in the meantime revalidators dump (line 2261) the already > inserted flow and want to delete this flow (line 2328, say because of > openflow db changes, or aging). The revalidator deletes the flow and > moves the ukey from > VISIBLE -> OPERATIONAL (line 2320) -> EVICTING (line 2220) -> EVICTED > (line 2134) > > finally handler succesfuly acquires the flow and now set the state to > OPERERTIONAL which will cause the assert in transition_ukey. > > Line numbers in question are from ofproto/ofproto-dpif-upcall.c > > I can provide a test the could show this happening, basicly adding a > sleep before (writing it now). > > Thanks, > Paul Blakey. > > > Here's a test: 1) Install the below patch 2) Set max-idle to 500ms, n-handlers to 1, revalidators to 10 3) Create a simple setup (like veth pair in OVS_TRAFFIC_VSWITCHD_START traffic testsuite) 4) Ping one of the machines/veths slowly and wait till you get to sleeping part and stop (put: 24 print) Here is my log: ....... 2017-03-19T14:48:18.609Z|00121|ofproto_dpif_upcall(handler12)|INFO|ukey_install__ 1696 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 transition from 0 to VISIBLE 2017-03-19T14:48:18.609Z|00122|ofproto_dpif_upcall(handler12)|INFO|state transition for ukey ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1: 0 -> 1 2017-03-19T14:48:18.609Z|00123|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 1/20 sec 1 2017-03-19T14:48:18.832Z|00001|ofproto_dpif_upcall(revalidator15)|INFO|revalidate 2376 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 transition from 1 to OPERATIONAL 2017-03-19T14:48:18.832Z|00002|ofproto_dpif_upcall(revalidator15)|INFO|state transition for ukey ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1: 1 -> 2 2017-03-19T14:48:18.832Z|00003|ofproto_dpif_upcall(revalidator15)|INFO|reval_op_init 2272 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 transition from 2 to EVICITING 2017-03-19T14:48:18.832Z|00004|ofproto_dpif_upcall(revalidator15)|INFO|state transition for ukey ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1: 2 -> 3 2017-03-19T14:48:18.832Z|00005|ofproto_dpif_upcall(revalidator15)|INFO|push_dp_ops 2182 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 transition from 3 to EVICTED 2017-03-19T14:48:18.832Z|00006|ofproto_dpif_upcall(revalidator15)|INFO|state transition for ukey ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1: 3 -> 4 2017-03-19T14:48:19.609Z|00124|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 2/20 sec 4 2017-03-19T14:48:20.610Z|00125|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 3/20 sec 4 2017-03-19T14:48:21.610Z|00126|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 4/20 sec 4 2017-03-19T14:48:22.610Z|00127|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 5/20 sec 4 2017-03-19T14:48:23.610Z|00128|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 6/20 sec 4 2017-03-19T14:48:24.610Z|00129|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 7/20 sec 4 2017-03-19T14:48:25.611Z|00130|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 8/20 sec 4 2017-03-19T14:48:26.611Z|00131|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 9/20 sec 4 2017-03-19T14:48:27.611Z|00132|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 10/20 sec 4 2017-03-19T14:48:28.611Z|00133|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 11/20 sec 4 2017-03-19T14:48:29.611Z|00134|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 12/20 sec 4 2017-03-19T14:48:30.611Z|00135|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 13/20 sec 4 2017-03-19T14:48:31.611Z|00136|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 14/20 sec 4 2017-03-19T14:48:32.612Z|00137|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 15/20 sec 4 2017-03-19T14:48:33.612Z|00138|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 16/20 sec 4 2017-03-19T14:48:34.612Z|00139|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 17/20 sec 4 2017-03-19T14:48:35.612Z|00140|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 18/20 sec 4 2017-03-19T14:48:36.612Z|00141|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 19/20 sec 4 2017-03-19T14:48:37.612Z|00142|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1423 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 sleeping 20/20 sec 4 2017-03-19T14:48:38.613Z|00143|ofproto_dpif_upcall(handler12)|INFO|put: 25 2017-03-19T14:48:38.613Z|00144|ofproto_dpif_upcall(handler12)|INFO|handle_upcalls 1434 ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1 transition from 4 to OPERATIONAL 2017-03-19T14:48:38.613Z|00145|ofproto_dpif_upcall(handler12)|INFO|state transition for ukey ufid:60dc4fe2-5166-4817-99e9-e62d79d6a7e1: 4 -> 2 2017-03-19T14:48:38.613Z|00146|util(handler12)|EMER|ofproto/ofproto-dpif-upcall.c:1716: assertion dst >= ukey->state failed in transition_ukey() commit 4755254db3053bcf7ceac88fedce60fd228c8640 (HEAD) Author: Paul Blakey Date: Sun Mar 19 17:00:30 2017 +0200 test add prints and forcefully slow down some actions (EVICTED->DELETED, and VISIBLE -> OPERATIONAL) + ds_destroy(&ds); } } } @@ -1659,6 +1680,10 @@ ukey_install__(struct udpif *udpif, struct udpif_key *new_ukey) } else { ovs_mutex_lock(&new_ukey->mutex); cmap_insert(&umap->cmap, &new_ukey->cmap_node, new_ukey->hash); + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&new_ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to VISIBLE", __func__, __LINE__, ds_cstr(&ds), new_ukey->state); + ds_destroy(&ds); transition_ukey(new_ukey, UKEY_VISIBLE); locked = true; } @@ -1671,6 +1696,12 @@ static void transition_ukey(struct udpif_key *ukey, enum ukey_state dst) OVS_REQUIRES(ukey->mutex) { + struct ds ds = DS_EMPTY_INITIALIZER; + + odp_format_ufid(&ukey->ufid, &ds); + VLOG_INFO("state transition for ukey %s: %d -> %d", ds_cstr(&ds), ukey->state, dst); + ds_destroy(&ds); + ovs_assert(dst >= ukey->state); if (ukey->state == dst && dst == UKEY_OPERATIONAL) { return; @@ -1699,12 +1730,12 @@ transition_ukey(struct udpif_key *ukey, enum ukey_state dst) dst < UKEY_DELETED)) { ukey->state = dst; } else { - struct ds ds = DS_EMPTY_INITIALIZER; + struct ds ds2 = DS_EMPTY_INITIALIZER; - odp_format_ufid(&ukey->ufid, &ds); + odp_format_ufid(&ukey->ufid, &ds2); VLOG_WARN_RL(&rl, "Invalid state transition for ukey %s: %d -> %d", - ds_cstr(&ds), ukey->state, dst); - ds_destroy(&ds); + ds_cstr(&ds2), ukey->state, dst); + ds_destroy(&ds2); } } @@ -1797,6 +1828,10 @@ ukey_delete(struct umap *umap, struct udpif_key *ukey) if (ukey->state < UKEY_DELETED) { cmap_remove(&umap->cmap, &ukey->cmap_node, ukey->hash); ovsrcu_postpone(ukey_delete__, ukey); + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to DELETED", __func__, __LINE__, ds_cstr(&ds), ukey->state); + ds_destroy(&ds); transition_ukey(ukey, UKEY_DELETED); } ovs_mutex_unlock(&ukey->mutex); @@ -2131,6 +2166,10 @@ push_dp_ops(struct udpif *udpif, struct ukey_op *ops, size_t n_ops) if (op->ukey) { ovs_mutex_lock(&op->ukey->mutex); + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&op->ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to EVICTED", __func__, __LINE__, ds_cstr(&ds), op->ukey->state); + ds_destroy(&ds); transition_ukey(op->ukey, UKEY_EVICTED); push->used = MAX(stats->used, op->ukey->stats.used); push->tcp_flags = stats->tcp_flags | op->ukey->stats.tcp_flags; @@ -2217,6 +2256,10 @@ reval_op_init(struct ukey_op *op, enum reval_result result, { if (result == UKEY_DELETE) { delete_op_init(udpif, op, ukey); + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to EVICITING", __func__, __LINE__, ds_cstr(&ds), ukey->state); + ds_destroy(&ds); transition_ukey(ukey, UKEY_EVICTING); } else if (result == UKEY_MODIFY) { /* Store the new recircs. */ @@ -2317,6 +2360,10 @@ revalidate(struct revalidator *revalidator) } /* The flow is now confirmed to be in the datapath. */ + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to OPERATIONAL", __func__, __LINE__, ds_cstr(&ds), ukey->state); + ds_destroy(&ds); transition_ukey(ukey, UKEY_OPERATIONAL); if (!used) { @@ -2417,6 +2464,11 @@ revalidator_sweep__(struct revalidator *revalidator, bool purge) ovs_mutex_unlock(&ukey->mutex); if (ukey_state == UKEY_EVICTED) { + + while (global_temp) { + xsleep(1); + } + /* The common flow deletion case involves deletion of the flow * during the dump phase and ukey deletion here. */ ovs_mutex_lock(&umap->mutex); @@ -2471,6 +2523,10 @@ dp_purge_cb(void *aux, unsigned pmd_id) CMAP_FOR_EACH(ukey, cmap_node, &umap->cmap) { if (ukey->pmd_id == pmd_id) { delete_op_init(udpif, &ops[n_ops++], ukey); + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&ukey->ufid, &ds); + VLOG_INFO("%s %d %s transition from %d to EVICITING", __func__, __LINE__, ds_cstr(&ds), ukey->state); + ds_destroy(&ds); transition_ukey(ukey, UKEY_EVICTING); if (n_ops == REVALIDATE_MAX_BATCH) { diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c index 660383f..0dfffdb 100644 --- a/ofproto/ofproto-dpif-upcall.c +++ b/ofproto/ofproto-dpif-upcall.c @@ -45,6 +45,8 @@ #define UPCALL_MAX_BATCH 64 #define REVALIDATE_MAX_BATCH 50 +int global_temp = 0; + VLOG_DEFINE_THIS_MODULE(ofproto_dpif_upcall); COVERAGE_DEFINE(dumped_duplicate_flow); @@ -1399,15 +1401,34 @@ handle_upcalls(struct udpif *udpif, struct upcall *upcalls, dpif_operate(udpif->dpif, opsp, n_opsp); for (i = 0; i < n_ops; i++) { struct udpif_key *ukey = ops[i].ukey; + static int i = 0; if (ukey) { + struct ds ds = DS_EMPTY_INITIALIZER; + odp_format_ufid(&ukey->ufid, &ds); + + if (i++%25 == 25-1) { + global_temp = 1; + for (int z = 0; z < 20; z++) { + VLOG_INFO("%s %d %s sleeping %d/%d sec %d", __func__, __LINE__, ds_cstr(&ds), z+1, 20, ukey->state); + xsleep(1); + } + } + VLOG_INFO("put: %d", i); + ovs_mutex_lock(&ukey->mutex); if (ops[i].dop.error) { + VLOG_INFO("%s %d %s transition from %d to EVICTED", __func__, __LINE__, ds_cstr(&ds), ukey->state); transition_ukey(ukey, UKEY_EVICTED); } else { + VLOG_INFO("%s %d %s transition from %d to OPERATIONAL", __func__, __LINE__, ds_cstr(&ds), ukey->state); transition_ukey(ukey, UKEY_OPERATIONAL); } ovs_mutex_unlock(&ukey->mutex); + + global_temp = 0; +