From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-0.8 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,SPF_PASS autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 010ABC43381 for ; Thu, 21 Mar 2019 04:49:39 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id B0933218A5 for ; Thu, 21 Mar 2019 04:49:39 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="P7sANXmS" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1725947AbfCUEti (ORCPT ); Thu, 21 Mar 2019 00:49:38 -0400 Received: from mail-wm1-f67.google.com ([209.85.128.67]:32994 "EHLO mail-wm1-f67.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1725877AbfCUEti (ORCPT ); Thu, 21 Mar 2019 00:49:38 -0400 Received: by mail-wm1-f67.google.com with SMTP id z6so1218766wmi.0 for ; Wed, 20 Mar 2019 21:49:36 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:cc:references:from:message-id:date:user-agent :mime-version:in-reply-to:content-language:content-transfer-encoding; bh=xZot1E+m6T8astuH7LhwLwpEpWwa3ryoeYbe1nK+PLU=; b=P7sANXmSzB+Be0xWeHW5JWTrVWqqdt1DDZlr9gTsmkAMhku/iaS1D2fMbVUs7Khauw sO1VBUotQmER9X7kSR8qOQNyGM1ynaHQOqhCZX8O66xs8FuKt9yJCV3WUfmXUwL5xQrR znZB1bgX9w/NUgVdB8mFrxvod4HgjiUgPDxl7rm0N+I3sebHlLUY7MScdPCZnEYObk3i uOfJD0C0DKkjs27Rqjd23jwdoH4GdWslFDNDPRO+BUioOBcd8Z3Fvs0FnbVPCnndagTs bmGaYmCwd5bmunzp+i2Qm98LcqcDCWQEnS7E00QFmKGAe4lvkeni8wrl4z4h98WebupM d1lQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:cc:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language :content-transfer-encoding; bh=xZot1E+m6T8astuH7LhwLwpEpWwa3ryoeYbe1nK+PLU=; b=cB1mE10/OiqTh2ndiwtUjkxLedvzQhEVC3N+JQlo7bjEgyLtS5ZgjWxXumYEeSwgWn /Z6rO0ri7ABs3k1W08i8sND8/mydlCwLG1YGq7XzxNNOm4npFlZDGJ3fASUW+rkegjMd TApsQsMqvEl5tjJlznGdtkuV1oejPji7NSm1PksAr0iT1mxQ7AnR+dUD+hBIQb0kDtWo QDUIP3OQO2t6ynWV+oXdeh0nne5gOnOBQEkbII3B68Sn/HddybpiDT6SiWCgQIi6iPop x7AuKHC4UcrWeONEDbQvh1Fr+uC3N3UB40q2Xax2dG8YWwsKP4L3MX4eDivaFyd4pGzd dHgw== X-Gm-Message-State: APjAAAWiKZAeUOsigepmhmctLNkXZ4LAiyzQ0uuxkmiU3Ls2USMUcuws WGy5eL/0i2qbLwJhnIIqDhE= X-Google-Smtp-Source: APXvYqw+scGRcFC8R7wIOIfqjwN6N1b2tkTIivdG0364+lkdAHpRn/jD1ka7zuCUxyfRb5iINo3ldw== X-Received: by 2002:a1c:480a:: with SMTP id v10mr943842wma.57.1553143775884; Wed, 20 Mar 2019 21:49:35 -0700 (PDT) Received: from [172.31.96.190] ([195.39.71.253]) by smtp.gmail.com with ESMTPSA id i11sm5249298wrp.40.2019.03.20.21.49.34 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 20 Mar 2019 21:49:35 -0700 (PDT) Subject: Re: [BUG] BPF splat on latest kernels To: Alexei Starovoitov Cc: Daniel Borkmann , Alexei Starovoitov , Networking , Eric Dumazet References: From: Eric Dumazet Message-ID: <855d58ca-c458-9749-2086-eea7d38d4dea@gmail.com> Date: Wed, 20 Mar 2019 21:49:34 -0700 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Thunderbird/52.9.1 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit Sender: netdev-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: netdev@vger.kernel.org On 03/08/2019 04:29 PM, Alexei Starovoitov wrote: > On Fri, Mar 8, 2019 at 12:33 PM Eric Dumazet wrote: >> >> Running test_progs on a LOCKDEP enabled kernel (latest David Miller net tree) >> >> I got the following splat. >> >> It is not immediately obvious to me. Any idea ? > > I think I saw something similar running test_maps, > but I had other changes in the tree. And later I was > never able to reproduce it, so figured it must have > been my local change. Looks like it was for real. > Do you have a reproducer? > I'll take a look on monday. Hi Alexei Has this problem been root caused ? Thanks ! > >> [ 4169.908826] ====================================================== >> [ 4169.914996] WARNING: possible circular locking dependency detected >> [ 4169.921172] 5.0.0-dbg-DEV #597 Not tainted >> [ 4169.925294] ------------------------------------------------------ >> [ 4169.931482] swapper/29/0 is trying to acquire lock: >> [ 4169.936379] 00000000541e3f72 (&htab->buckets[i].lock){....}, at: htab_map_update_elem+0x1b6/0x3a0 >> [ 4169.945262] >> but task is already holding lock: >> [ 4169.951084] 00000000e213eabd (&rq->lock){-.-.}, at: __schedule+0xd6/0xb80 >> [ 4169.957904] >> which lock already depends on the new lock. >> >> [ 4169.966101] >> the existing dependency chain (in reverse order) is: >> [ 4169.973605] >> -> #4 (&rq->lock){-.-.}: >> [ 4169.978651] _raw_spin_lock+0x2f/0x40 >> [ 4169.982866] task_fork_fair+0x37/0x160 >> [ 4169.987150] sched_fork+0x206/0x310 >> [ 4169.991167] copy_process.part.41+0x7eb/0x2370 >> [ 4169.996128] _do_fork+0xda/0x6a0 >> [ 4169.999872] kernel_thread+0x29/0x30 >> [ 4170.003962] rest_init+0x22/0x260 >> [ 4170.007820] arch_call_rest_init+0xe/0x10 >> [ 4170.012382] start_kernel+0x4d8/0x4f9 >> [ 4170.016557] x86_64_start_reservations+0x24/0x26 >> [ 4170.021697] x86_64_start_kernel+0x6f/0x72 >> [ 4170.026312] secondary_startup_64+0xa4/0xb0 >> [ 4170.031039] >> -> #3 (&p->pi_lock){-.-.}: >> [ 4170.036265] _raw_spin_lock_irqsave+0x3a/0x50 >> [ 4170.041172] try_to_wake_up+0x41/0x610 >> [ 4170.045466] wake_up_process+0x15/0x20 >> [ 4170.049745] create_worker+0x16b/0x1e0 >> [ 4170.054039] workqueue_init+0x1ff/0x31d >> [ 4170.058397] kernel_init_freeable+0x116/0x2a5 >> [ 4170.063291] kernel_init+0xf/0x180 >> [ 4170.067212] ret_from_fork+0x24/0x30 >> [ 4170.071307] >> -> #2 (&(&pool->lock)->rlock){-.-.}: >> [ 4170.077425] _raw_spin_lock+0x2f/0x40 >> [ 4170.081602] __queue_work+0xb2/0x540 >> [ 4170.085709] queue_work_on+0x38/0x80 >> [ 4170.089827] free_percpu+0x231/0x270 >> [ 4170.093933] array_map_free+0x47/0x80 >> [ 4170.098131] bpf_map_free_deferred+0x3c/0x50 >> [ 4170.102926] process_one_work+0x1f4/0x590 >> [ 4170.107466] worker_thread+0x6f/0x430 >> [ 4170.111654] kthread+0x132/0x170 >> [ 4170.115431] ret_from_fork+0x24/0x30 >> [ 4170.119520] >> -> #1 (pcpu_lock){..-.}: >> [ 4170.124562] _raw_spin_lock_irqsave+0x3a/0x50 >> [ 4170.129448] pcpu_alloc+0xfa/0x790 >> [ 4170.133383] __alloc_percpu_gfp+0x12/0x20 >> [ 4170.137905] alloc_htab_elem+0x182/0x2b0 >> [ 4170.142351] __htab_percpu_map_update_elem+0x270/0x2c0 >> [ 4170.148036] bpf_percpu_hash_update+0x7c/0x130 >> [ 4170.153035] __do_sys_bpf+0x194a/0x1c10 >> [ 4170.157385] __x64_sys_bpf+0x1a/0x20 >> [ 4170.161485] do_syscall_64+0x5a/0x460 >> [ 4170.165674] entry_SYSCALL_64_after_hwframe+0x49/0xbe >> [ 4170.171255] >> -> #0 (&htab->buckets[i].lock){....}: >> [ 4170.177433] lock_acquire+0xa7/0x190 >> [ 4170.181549] _raw_spin_lock_irqsave+0x3a/0x50 >> [ 4170.186448] htab_map_update_elem+0x1b6/0x3a0 >> [ 4170.191347] >> other info that might help us debug this: >> >> [ 4170.199345] Chain exists of: >> &htab->buckets[i].lock --> &p->pi_lock --> &rq->lock >> >> [ 4170.209867] Possible unsafe locking scenario: >> >> [ 4170.215776] CPU0 CPU1 >> [ 4170.220301] ---- ---- >> [ 4170.224823] lock(&rq->lock); >> [ 4170.227882] lock(&p->pi_lock); >> [ 4170.233646] lock(&rq->lock); >> [ 4170.239208] lock(&htab->buckets[i].lock); >> [ 4170.243384] >> *** DEADLOCK *** >> >> [ 4170.249297] 2 locks held by swapper/29/0: >> [ 4170.253307] #0: 00000000e213eabd (&rq->lock){-.-.}, at: __schedule+0xd6/0xb80 >> [ 4170.260558] #1: 000000006891c367 (rcu_read_lock){....}, at: trace_call_bpf+0x40/0x260 >> [ 4170.268476] >> stack backtrace: >> [ 4170.272838] CPU: 29 PID: 0 Comm: swapper/29 Not tainted 5.0.0-dbg-DEV #597 >> [ 4170.279708] Hardware name: Intel RML,PCH/Iota_QC_19, BIOS 2.54.0 06/07/2018 >> [ 4170.286658] Call Trace: >> [ 4170.289108] dump_stack+0x67/0x95 >> [ 4170.292424] print_circular_bug.isra.36+0x1fd/0x20b >> [ 4170.297302] __lock_acquire+0x15b3/0x1850 >> [ 4170.301308] ? __pcpu_freelist_pop+0x87/0xb0 >> [ 4170.305579] lock_acquire+0xa7/0x190 >> [ 4170.309157] ? lock_acquire+0xa7/0x190 >> [ 4170.312900] ? htab_map_update_elem+0x1b6/0x3a0 >> [ 4170.317434] _raw_spin_lock_irqsave+0x3a/0x50 >> [ 4170.321791] ? htab_map_update_elem+0x1b6/0x3a0 >> [ 4170.326324] htab_map_update_elem+0x1b6/0x3a0 >> [ 4170.330684] ? trace_call_bpf+0x100/0x260 >> [ 4170.334695] ? perf_trace_run_bpf_submit+0x42/0xb0 >> [ 4170.339487] ? perf_trace_sched_switch+0x129/0x1a0 >> [ 4170.344279] ? __schedule+0x44d/0xb80 >> [ 4170.347943] ? lockdep_hardirqs_on+0x14d/0x1d0 >> [ 4170.352388] ? trace_hardirqs_on+0x3f/0xf0 >> [ 4170.356487] ? schedule_idle+0x2c/0x40 >> [ 4170.360237] ? do_idle+0x184/0x280 >> [ 4170.363634] ? cpu_startup_entry+0x1d/0x20 >> [ 4170.367735] ? start_secondary+0x184/0x1d0 >> [ 4170.371830] ? secondary_startup_64+0xa4/0xb0 >>