From owner-freebsd-stable@freebsd.org Mon Jul 24 17:25:58 2017 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id C73B7CFF18C for ; Mon, 24 Jul 2017 17:25:58 +0000 (UTC) (envelope-from mavbsd@gmail.com) Received: from mail-lf0-x231.google.com (mail-lf0-x231.google.com [IPv6:2a00:1450:4010:c07::231]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 47730705F8; Mon, 24 Jul 2017 17:25:58 +0000 (UTC) (envelope-from mavbsd@gmail.com) Received: by mail-lf0-x231.google.com with SMTP id y15so46968639lfd.5; Mon, 24 Jul 2017 10:25:58 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=sender:subject:to:cc:references:from:message-id:date:user-agent :mime-version:in-reply-to:content-language:content-transfer-encoding; bh=Yx32P5h5AzUiFDz14W/wA8ZCb9hDg+/HWIEfGwqQ/k4=; b=iRmo5H+ej2dwf5EhLEXDmzXZ/Iys9SNZildlUcgCQpNrDE7ouOiXJ7DNjJAKUvh+4D eQaL4rcMGNYOx/jHbm//41OB8xFqrtRPVmJyaB0eHkIQvgMFMarfhdhyCFtyWHkL4M2G ArDJpZDbQQusf1eT29QYiUVjbAoUnncLXg2KOa72peMi7JmQVUai+yMGnWzQ6FH6loqG pSQ+JnQ6yEQoGKxw8Xu4NC+k6OpUWI+WLXYgnutvTIMonghkjIr3t+q8vhEBzn6dFW5x q0fLudio1T05X8D4kKjqrfWyh7OGJ00k/gkcA8KXfttMc5Z9zK3v8dp7DQWd9EoGlD5A 0MEw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:sender:subject:to:cc:references:from:message-id :date:user-agent:mime-version:in-reply-to:content-language :content-transfer-encoding; bh=Yx32P5h5AzUiFDz14W/wA8ZCb9hDg+/HWIEfGwqQ/k4=; b=eTxRJbymZilOAdYtPanSaEPUzJ11jTaM8L3o+ZGLw8sh+maaH3rVO54omXD15nKqEr /aHRkVqD3DcqI5UfYj0/Zl/5Wirde7oQYg6SK4AFerpr4jSJ+KxQE6wt5/STcy8oQ3e0 AJAXvFJotaE7ZRhRPkzu/TweuXe3atogz5FOWmwhhQCY+8WtjwSt/Eb9X73UUPdOctnS XP5Szuxu1MBc1V/RBh262b+QW9+VyEv2+DIh/jm3SzEidg9XgYfPNqezHy7xpdfEN0jw 6qONpVmL4Ex8Z1jnCpnwDIeKohBz+XkKoziOABYBgGFJWEzVVDil2cBLHSTFZUEr1wxJ 8wDQ== X-Gm-Message-State: AIVw112x9y4LapohDOQQyksRTdsomSjPcKprsFWNP+q0bKyZyFDKauAY aoO3go3FDY9fbMQXAQw= X-Received: by 10.25.218.26 with SMTP id r26mr5728457lfg.149.1500917155167; Mon, 24 Jul 2017 10:25:55 -0700 (PDT) Received: from spectre.mavhome.dp.ua ([134.249.139.101]) by smtp.gmail.com with ESMTPSA id 70sm2457971ljj.80.2017.07.24.10.25.53 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Mon, 24 Jul 2017 10:25:54 -0700 (PDT) Sender: Alexander Motin Subject: Re: stable/11 debugging kernel unable to produce crashdump again To: Eugene Grosbein , Mark Johnston Cc: FreeBSD Stable References: <587928B3.2050607@grosbein.net> <20170113193726.GC77535@wkstn-mjohnston.west.isilon.com> <587A0E12.7070205@grosbein.net> <59746BD5.5010301@grosbein.net> <20170724014445.GA20872@raichu> <59762849.5090208@grosbein.net> From: Alexander Motin Message-ID: Date: Mon, 24 Jul 2017 20:25:52 +0300 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:52.0) Gecko/20100101 Thunderbird/52.2.1 MIME-Version: 1.0 In-Reply-To: <59762849.5090208@grosbein.net> Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 24 Jul 2017 17:25:58 -0000 I guess that problem of g_raid_shutdown_post_sync in case of panic can be explained by the fact it tries to write clean metadata in regular (not dumping) way while system is already in panic mode and there is no proper scheduling. May be it could be just bypassed in case of dumping (should be trivial and probably OK), or use g_raid_subdisk_kerneldump() in that case instead of normal GEOM I/O. On 24.07.2017 20:03, Eugene Grosbein wrote: > CCing mav@ as graid expert. > > On 24.07.2017 08:44, Mark Johnston wrote: > >>> Sadly, this time 11.1-STABLE r321371 SMP hangs instead of doing crashdump: >>> >>> - "call doadump" from DDB prompt works just fine; >>> - "shutdown -r now" reboots the system without problems; >>> - "sysctl debug.kdb.panic=1" triggers a panic just fine but system hangs just afer showing uptime >>> instead of continuing with crashdump generation; same if "real" panic occurs. >>> >>> Same for debug.minidump set to 1 or 0. How do I debug this? >> >> I'm not able to reproduce the problem in bhyve using r321401. Looking >> at the code, the culprits might be cngrab(), or one of the >> shutdown_post_sync eventhandlers. Since you're apparently able to see >> the console output at the time of the panic, I guess it's probably the >> latter. Could you try your test with the patch below applied? It'll >> print a bunch of "entering post_sync"/"leaving post_sync" messages with >> addresses that can be resolved using kgdb. That'll help determine where >> we're getting stuck. >> >> Index: sys/sys/eventhandler.h >> =================================================================== >> --- sys/sys/eventhandler.h (revision 321401) >> +++ sys/sys/eventhandler.h (working copy) >> @@ -85,7 +85,11 @@ >> _t = (struct eventhandler_entry_ ## name *)_ep; \ >> CTR1(KTR_EVH, "eventhandler_invoke: executing %p", \ >> (void *)_t->eh_func); \ >> + if (strcmp(__STRING(name), "shutdown_post_sync") == 0) \ >> + printf("entering post_sync %p\n", (void *)_t->eh_func); \ >> _t->eh_func(_ep->ee_arg , ## __VA_ARGS__); \ >> + if (strcmp(__STRING(name), "shutdown_post_sync") == 0) \ >> + printf("leaving post_sync %p\n", (void *)_t->eh_func); \ >> EHL_LOCK((list)); \ >> } \ >> } \ >> > > Thanks, this helped: > > $ addr2line -f -e kernel.debug 0xffffffff80919c00 > g_raid_shutdown_post_sync > /home/src/sys/geom/raid/g_raid.c:2458 > > That is GEOM_RAID's g_raid_shutdown_post_sync() that hangs if called just before > crashdump generation but works just fine during normal system shutdown. > > I should note my graid's RAID1 is running in degraded state currently > due to dead SSD module that does not respond. Here is part of boot log: > > ahcich5: AHCI reset: device not ready after 31000ms (tfd = 00000080) > ahcich5: Poll timeout on slot 2 port 0 > ahcich5: is 00000000 cs 00000004 ss 00000000 rs 00000004 tfd 80 serr 00000000 cmd 0000c217 > (aprobe2:ahcich5:0:0:0): NOP FLUSHQUEUE. ACB: 00 00 00 00 00 00 00 00 00 00 00 00 > (aprobe2:ahcich5:0:0:0): CAM status: Command timeout > (aprobe2:ahcich5:0:0:0): Error 5, Retries exhausted > run_interrupt_driven_hooks: still waiting after 60 seconds for xpt_config > ahcich5: Poll timeout on slot 3 port 0 > ahcich5: is 00000000 cs 00000008 ss 00000000 rs 00000008 tfd 80 serr 00000000 cmd 0000c317 > (aprobe2:ahcich5:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00 > (aprobe2:ahcich5:0:0:0): CAM status: Command timeout > (aprobe2:ahcich5:0:0:0): Error 5, Retries exhausted > [skip] > Trying to mount root from ufs:/dev/raid/r0s4a [rw,noatime]... > Root mount waiting for: GRAID-Intel > Root mount waiting for: GRAID-Intel > Root mount waiting for: GRAID-Intel > Root mount waiting for: GRAID-Intel > Root mount waiting for: GRAID-Intel > GEOM_RAID: Intel-c291fe96: Force array start due to timeout. > GEOM_RAID: Intel-c291fe96: Disk ada0 state changed from NONE to ACTIVE. > GEOM_RAID: Intel-c291fe96: Subdisk r0:0-ada0 state changed from NONE to STALE. > GEOM_RAID: Intel-c291fe96: Array started. > GEOM_RAID: Intel-c291fe96: Subdisk r0:0-ada0 state changed from STALE to ACTIVE. > GEOM_RAID: Intel-c291fe96: Volume r0 state changed from STARTING to DEGRADED. > GEOM_RAID: Intel-c291fe96: Provider raid/r0 for volume r0 created. > > > -- Alexander Motin