Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756014AbbFOWZN (ORCPT ); Mon, 15 Jun 2015 18:25:13 -0400 Received: from mail-pa0-f52.google.com ([209.85.220.52]:34640 "EHLO mail-pa0-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754250AbbFOWYc (ORCPT ); Mon, 15 Jun 2015 18:24:32 -0400 Message-ID: <557F509D.2000509@plumgrid.com> Date: Mon, 15 Jun 2015 15:24:29 -0700 From: Alexei Starovoitov User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:31.0) Gecko/20100101 Thunderbird/31.7.0 MIME-Version: 1.0 To: paulmck@linux.vnet.ibm.com, Daniel Wagner , LKML Subject: call_rcu from trace_preempt Content-Type: multipart/mixed; boundary="------------070602050402010606070004" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 7713 Lines: 157 This is a multi-part message in MIME format. --------------070602050402010606070004 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Hi Paul, I've been debugging the issue reported by Daniel: http://thread.gmane.org/gmane.linux.kernel/1974304/focus=1974304 and it seems I narrowed it down to recursive call_rcu. From trace_preempt_on() I'm doing: e = kmalloc(sizeof(struct elem), GFP_ATOMIC) kfree_rcu(e, rcu) which causing all sorts of corruptions like: [ 2.074175] WARNING: CPU: 0 PID: 3 at ../lib/debugobjects.c:263 debug_print_object+0x8c/0xb0() [ 2.075567] ODEBUG: active_state not available (active state 0) object type: rcu_head hint: (null) [ 2.102141] WARNING: CPU: 0 PID: 3 at ../lib/debugobjects.c:263 debug_print_object+0x8c/0xb0() [ 2.103547] ODEBUG: deactivate not available (active state 0) object type: rcu_head hint: (null) [ 2.253995] WARNING: CPU: 0 PID: 7 at ../kernel/rcu/tree.c:2976 __call_rcu.constprop.67+0x1e5/0x350() [ 2.255510] __call_rcu(): Leaked duplicate callback Sometimes stack looks like: [ 2.145163] WARNING: CPU: 0 PID: 102 at ../lib/debugobjects.c:263 debug_print_object+0x8c/0xb0() [ 2.147465] ODEBUG: active_state not available (active state 0) object type: rcu_head hint: (null) [ 2.148022] Modules linked in: [ 2.148022] CPU: 0 PID: 102 Comm: systemd-udevd Not tainted 4.1.0-rc7+ #653 [ 2.148022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-rc1-0-gb1d4dc9-20140515_140003-nilsson.home.kraxel.org 04/01/2014 [ 2.148022] ffffffff81a34f77 ffff88000fc03d18 ffffffff81781ed4 0000000000000105 [ 2.148022] ffff88000fc03d68 ffff88000fc03d58 ffffffff81064e57 0000000000000000 [ 2.148022] ffff88000fc03e20 ffffffff81c50f00 ffffffff81a34fdf 0000000000000286 [ 2.148022] Call Trace: [ 2.148022] [] dump_stack+0x4f/0x7b [ 2.148022] [] warn_slowpath_common+0x97/0xe0 [ 2.148022] [] warn_slowpath_fmt+0x46/0x50 [ 2.148022] [] debug_print_object+0x8c/0xb0 [ 2.148022] [] ? debug_object_active_state+0x66/0x160 [ 2.148022] [] debug_object_active_state+0xf1/0x160 [ 2.148022] [] rcu_process_callbacks+0x301/0xae0 [ 2.148022] [] ? rcu_process_callbacks+0x2e7/0xae0 [ 2.148022] [] ? run_timer_softirq+0x218/0x4c0 [ 2.148022] [] __do_softirq+0x14f/0x670 [ 2.148022] [] irq_exit+0xa5/0xb0 [ 2.148022] [] smp_apic_timer_interrupt+0x4a/0x60 [ 2.148022] [] apic_timer_interrupt+0x70/0x80 [ 2.148022] [] ? debug_object_activate+0x9c/0x1e0 [ 2.148022] [] ? _raw_spin_unlock_irqrestore+0x67/0x80 [ 2.148022] [] debug_object_activate+0x156/0x1e0 [ 2.148022] [] rcuhead_fixup_activate+0x37/0x40 [ 2.148022] [] debug_object_activate+0x101/0x1e0 [ 2.148022] [] ? _raw_spin_unlock_irqrestore+0x4b/0x80 [ 2.148022] [] __call_rcu.constprop.67+0x46/0x350 [ 2.148022] [] ? __debug_object_init+0x3f4/0x430 [ 2.148022] [] ? _raw_spin_unlock_irqrestore+0x4b/0x80 [ 2.148022] [] kfree_call_rcu+0x1a/0x20 [ 2.148022] [] trace_preempt_on+0x180/0x290 [ 2.148022] [] ? trace_preempt_on+0xce/0x290 [ 2.148022] [] preempt_count_sub+0x73/0xf0 [ 2.148022] [] _raw_spin_unlock_irqrestore+0x4b/0x80 [ 2.148022] [] __debug_object_init+0x3f4/0x430 [ 2.148022] [] ? trace_preempt_on+0x18c/0x290 [ 2.148022] [] debug_object_init+0x1b/0x20 [ 2.148022] [] rcuhead_fixup_activate+0x28/0x40 [ 2.148022] [] debug_object_activate+0x101/0x1e0 [ 2.148022] [] ? get_max_files+0x20/0x20 [ 2.148022] [] __call_rcu.constprop.67+0x46/0x350 [ 2.148022] [] call_rcu+0x17/0x20 [ 2.148022] [] __fput+0x183/0x200 [ 2.148022] [] ____fput+0xe/0x10 [ 2.148022] [] task_work_run+0xb5/0xe0 [ 2.148022] [] do_notify_resume+0x64/0x80 [ 2.148022] [] int_signal+0x12/0x17 My reading of the code is debug_object_*() bits are reporting real problem. In the above trace the call debug_rcu_head_unqueue(list); from rcu_do_batch() is not finding 'list' in tracked objects. I know that doing call_rcu() from trace_preempt is ill advised, but I still want to understand why call_rcu corrupts the memory. Attaching a patch that I'm using for debugging. It's doing recursion preemption check, so number of nested call_rcu is no more than 2. Also if I replace kfree_rcu is this patch with a regular kfree, all works fine. I'm seeing this crashes in VM with _single_ cpu. Kernel is built with CONFIG_PREEMPT, CONFIG_PREEMPT_TRACER and CONFIG_DEBUG_OBJECTS_RCU_HEAD. Also interesting that size of struct elem { u64 pad[32]; struct rcu_head rcu; }; that I'm using in kmalloc/kfree_rcu changes the crash. If padding is zero, kernel just locksup, if pad[1] I see one type of odebug warnings, if pad[32] - another. Any advise on where to look is greatly appreciated. Thanks! --------------070602050402010606070004 Content-Type: text/plain; charset=UTF-8; name="trace.patch" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="trace.patch" ZGlmZiAtLWdpdCBhL2tlcm5lbC90cmFjZS90cmFjZV9pcnFzb2ZmLmMgYi9rZXJuZWwvdHJh Y2UvdHJhY2VfaXJxc29mZi5jCmluZGV4IDg1MjNlYTM0NWYyYi4uODk0MzNhODNkZDJkIDEw MDY0NAotLS0gYS9rZXJuZWwvdHJhY2UvdHJhY2VfaXJxc29mZi5jCisrKyBiL2tlcm5lbC90 cmFjZS90cmFjZV9pcnFzb2ZmLmMKQEAgLTEzLDYgKzEzLDcgQEAKICNpbmNsdWRlIDxsaW51 eC91YWNjZXNzLmg+CiAjaW5jbHVkZSA8bGludXgvbW9kdWxlLmg+CiAjaW5jbHVkZSA8bGlu dXgvZnRyYWNlLmg+CisjaW5jbHVkZSA8bGludXgvc2xhYi5oPgogCiAjaW5jbHVkZSAidHJh Y2UuaCIKIApAQCAtNTEwLDggKzUxMSw0MiBAQCBFWFBPUlRfU1lNQk9MKHRyYWNlX2hhcmRp cnFzX29mZl9jYWxsZXIpOwogI2VuZGlmIC8qICBDT05GSUdfSVJRU09GRl9UUkFDRVIgKi8K IAogI2lmZGVmIENPTkZJR19QUkVFTVBUX1RSQUNFUgorc3RydWN0IGVsZW0geworCXU2NCBw YWRbMzJdOworCXN0cnVjdCByY3VfaGVhZCByY3U7Cit9OworCitzdGF0aWMgREVGSU5FX1BF Ul9DUFUoaW50LCBwcm9nX2FjdGl2ZSk7CitzdGF0aWMgdm9pZCAqIHRlc3RfYWxsb2Modm9p ZCkKK3sKKwlzdHJ1Y3QgZWxlbSAqZSA9IE5VTEw7CisKKwlpZiAoaW5fbm1pKCkpCisJCXJl dHVybiBlOworCisJcHJlZW1wdF9kaXNhYmxlX25vdHJhY2UoKTsKKwlpZiAodW5saWtlbHko X190aGlzX2NwdV9pbmNfcmV0dXJuKHByb2dfYWN0aXZlKSAhPSAxKSkKKwkJZ290byBvdXQ7 CisKKwlyY3VfcmVhZF9sb2NrKCk7CisJZSA9IGttYWxsb2Moc2l6ZW9mKHN0cnVjdCBlbGVt KSwgR0ZQX0FUT01JQyk7CisJcmN1X3JlYWRfdW5sb2NrKCk7CisJaWYgKCFlKQorCQlnb3Rv IG91dDsKKworCWtmcmVlX3JjdShlLCByY3UpOworb3V0OgorCV9fdGhpc19jcHVfZGVjKHBy b2dfYWN0aXZlKTsKKwlwcmVlbXB0X2VuYWJsZV9ub19yZXNjaGVkX25vdHJhY2UoKTsKKwly ZXR1cm4gZTsKK30KKwogdm9pZCB0cmFjZV9wcmVlbXB0X29uKHVuc2lnbmVkIGxvbmcgYTAs IHVuc2lnbmVkIGxvbmcgYTEpCiB7CisJdm9pZCAqIGJ1ZiA9IDA7CisJc3RhdGljIGludCBj bnQgPSAwOworCWlmIChjbnQrKyA+IDMwMDAwMDApCisJCWJ1ZiA9IHRlc3RfYWxsb2MoKTsK IAlpZiAocHJlZW1wdF90cmFjZSgpICYmICFpcnFfdHJhY2UoKSkKIAkJc3RvcF9jcml0aWNh bF90aW1pbmcoYTAsIGExKTsKIH0K --------------070602050402010606070004-- -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/