i386/103435: Kernel appears somewhat deadlocked during heavy ATA I/O (post-August 4th)

[Jeremy Chadwick]

Follow-up:

The PR I referenced has indeed now happened to me.  This ultimately
resulted in a hard system lock -- then the kernel panic'd in some
UFS2 code.

When I came home from work, I was able to play around a bit on
the console of the box.  Naturally I did "panic" to make a memory
dump -- but it couldn't.  It tried to write 1MB of the 1014MB (or
so), and simply sat there doing nothing; disk LED wasn't even
lit.

When I brought the machine back up, I saw the following:

Sep 20 14:48:19 icarus kernel: Trying to mount root from ufs:/dev/ad12s1a
Sep 20 14:48:19 icarus kernel: WARNING: / was not properly dismounted
Sep 20 14:48:19 icarus kernel: WARNING: /var was not properly dismounted
Sep 20 14:48:19 icarus kernel: /var: mount pending error: blocks 4 files 1
Sep 20 14:48:19 icarus kernel: WARNING: /tmp was not properly dismounted
Sep 20 14:48:19 icarus kernel: WARNING: /usr was not properly dismounted
Sep 20 14:48:19 icarus kernel: WARNING: /home was not properly dismounted
Sep 20 14:48:19 icarus kernel: /home: mount pending error: blocks 4 files 1
Sep 20 14:48:19 icarus kernel: WARNING: /storage/ad14 was not properly dismounted
Sep 20 14:48:19 icarus savecore: no dumps found

I was able to go through /var/log/messages to find all of this --
none of which bodes well for 6.2-RELEASE, if you ask me.  Has anyone
contacted Soren and/or Kris about this?

Sep 20 14:48:19 icarus syslogd: kernel boot file is /boot/kernel/kernel
Sep 20 14:48:19 icarus kernel: anged to UP
Sep 20 14:48:19 icarus kernel: g_vfs_done():ad12s1g[WRITE(offset=56459116544, length=16384)]error = 5
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (1 retry left) LBA=287
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (1 retry left) LBA=524639
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (0 retries left) LBA=287
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (0 retries left) LBA=524639
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: FAILURE - WRITE_DMA timed out LBA=287
Sep 20 14:48:19 icarus kernel: g_vfs_done():ad12s1a[WRITE(offset=114688, length=16384)]error = 5
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: FAILURE - WRITE_DMA timed out LBA=524639
Sep 20 14:48:19 icarus kernel: g_vfs_done():ad12s1a[WRITE(offset=268582912, length=16384)]error = 5
{...and so on...}
Sep 20 14:48:19 icarus kernel: em0: watchdog timeout -- resetting
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (1 retry left) LBA=30998367
Sep 20 14:48:19 icarus kernel: em0: 2 link states coalesced
Sep 20 14:48:19 icarus kernel: em0: link state changed to UP
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (0 retries left) LBA=17837855
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: em0: watchdog timeout -- resetting
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: TIMEOUT - WRITE_DMA retrying (0 retries left) LBA=30998367
Sep 20 14:48:19 icarus kernel: em0: link state changed to DOWN
Sep 20 14:48:19 icarus kernel: em0: link state changed to UP
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: FAILURE - WRITE_DMA timed out LBA=17837855
Sep 20 14:48:19 icarus kernel: g_vfs_done():ad12s1d[WRITE(offset=6144000, length=2048)]error = 5
Sep 20 14:48:19 icarus kernel: em0: watchdog timeout -- resetting
{...lots more...}
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES SET TRANSFER MODE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE RCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SETFEATURES ENABLE WCACHE taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: WARNING - SET_MULTI taskqueue timeout - completing request directly
Sep 20 14:48:19 icarus kernel: ad12: FAILURE - WRITE_DMA timed out LBA=41160159
Sep 20 14:48:19 icarus kernel: g_vfs_done():ad12s1d[WRITE(offset=11947163648, length=16384)]error = 5
Sep 20 14:48:19 icarus kernel: panic: initiate_write_inodeblock_ufs2: already started
Sep 20 14:48:19 icarus kernel: KDB: enter: panic
Sep 20 14:48:19 icarus kernel: panic: from debugger
Sep 20 14:48:19 icarus kernel: Uptime: 2d5h35m17s
Sep 20 14:48:19 icarus kernel: Dumping 1014 MB (2 chunks)
Sep 20 14:48:19 icarus kernel: chunk 0: 1MB (159 pages) (CTRL-C to abort)  (CTRL-C to abort)  (CTRL-C to abort)  (CTRL-C to abort)  (CTRL-C to abort)
Sep 20 14:48:19 icarus kernel: Dump aborted
Sep 20 14:48:19 icarus kernel: Automatic reboot in 15 seconds - press a key on the console to abort
Sep 20 14:48:19 icarus kernel: --> Press a key on the console to reboot,
Sep 20 14:48:19 icarus kernel: --> or switch off the system now.
Sep 20 14:48:19 icarus kernel: Rebooting...

-- 
| Jeremy Chadwick                                 jdc at parodius.com |
| Parodius Networking                        http://www.parodius.com/ |
| UNIX Systems Administrator                   Mountain View, CA, USA |
| Making life hard for others since 1977.               PGP: 4BD6C0CB |