Date: Tue, 25 Jul 2017 00:03:05 +0700 From: Eugene Grosbein <eugen@grosbein.net> To: Mark Johnston <markj@FreeBSD.org> Cc: FreeBSD Stable <freebsd-stable@FreeBSD.org>, Alexander Motin <mav@freebsd.org> Subject: Re: stable/11 debugging kernel unable to produce crashdump again Message-ID: <59762849.5090208@grosbein.net> In-Reply-To: <20170724014445.GA20872@raichu> References: <587928B3.2050607@grosbein.net> <20170113193726.GC77535@wkstn-mjohnston.west.isilon.com> <587A0E12.7070205@grosbein.net> <59746BD5.5010301@grosbein.net> <20170724014445.GA20872@raichu>
next in thread | previous in thread | raw e-mail | index | archive | help
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.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?59762849.5090208>