Eugene Grosbein
2017-Jul-24 17:03 UTC
stable/11 debugging kernel unable to produce crashdump again
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.
Mark Johnston
2017-Jul-24 17:22 UTC
stable/11 debugging kernel unable to produce crashdump again
On Tue, Jul 25, 2017 at 12:03:05AM +0700, Eugene Grosbein wrote:> 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 think graid probably needs a treatment similar to r301173/r316032. g_raid_shutdown_post_sync() appears to be quite similar to the corresponding gmirror handler. In particular, it just attempts to mark the individual components as clean and destroy the GEOM, which is not really safe after a panic. diff --git a/sys/geom/raid/g_raid.c b/sys/geom/raid/g_raid.c index 7a1fd8c5ce2e..aa2529d5466a 100644 --- a/sys/geom/raid/g_raid.c +++ b/sys/geom/raid/g_raid.c @@ -2461,6 +2461,9 @@ g_raid_shutdown_post_sync(void *arg, int howto) struct g_raid_softc *sc; struct g_raid_volume *vol; + if (panicstr != NULL) + return; + mp = arg; g_topology_lock(); g_raid_shutdown = 1;
Alexander Motin
2017-Jul-24 17:25 UTC
stable/11 debugging kernel unable to produce crashdump again
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