System hangs when adding ZIL

[aufalien]

Hi all,

Having not to swell of a time thus far with FreeNAS 9.1.

Hoping to get over this mis-step but when I add a ZIL, the system hangs. My console goes crazy with messages but I cannot tell whats going on. After a cold boot, looking at /var/log/messages doesn't yield much.

What in terms of info can I get to see what exaclty is going on?

I've tried 2 diff models of SSDs from 40Gb to 240GB.

Any one seen this before?

Thanks in advance.

 

[dlavigne]

Can you post a screenshot of the messages?

 

[aufalien]

Thanks for looking into this.

So I was tailing /var/log/messages during ZIL creation and caught this, the system quickly hangs while repeating the CAM errors in a console as I've a monitor directly attached to it.

I've tried creating the ZIL via CLI and get the same results.

Aug 13 11:10:04 freenas kernel: GEOM_ELI: Detached da2p1.eli on last close.
Aug 13 11:10:05 freenas kernel: GEOM_ELI: Detached da3p1.eli on last close.
Aug 13 11:10:05 freenas kernel: GEOM_ELI: Detached da6p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da7p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da8p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da9p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da10p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da11p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da12p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da13p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da14p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da15p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da16p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da17p1.eli on last close.
Aug 13 11:10:06 freenas kernel: GEOM_ELI: Detached da18p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da19p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da20p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da26p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da27p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da28p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da29p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da30p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da31p1.eli on last close.
Aug 13 11:10:07 freenas kernel: GEOM_ELI: Detached da32p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da33p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da34p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da35p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da36p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da37p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da38p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da39p1.eli on last close.
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da40p1.eli on last close.
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da2p1.eli as swap device
Aug 13 11:10:08 freenas kernel: GEOM_ELI: Detached da41p1.eli on last close.
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da3p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da6p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da7p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da8p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da9p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da10p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da11p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da12p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da13p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da14p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da15p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da16p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da17p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da18p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da19p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da20p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da26p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da27p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da28p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da29p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da30p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da31p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da32p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da33p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da34p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da35p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da36p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da37p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da38p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da39p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da40p1.eli as swap device
Aug 13 11:10:08 freenas notifier: swapoff: removing /dev/da41p1.eli as swap device
Aug 13 11:10:08 freenas notifier: 1+0 records in
Aug 13 11:10:08 freenas notifier: 1+0 records out
Aug 13 11:10:08 freenas notifier: 1048576 bytes transferred in 0.022101 secs (47444891 bytes/sec)
Aug 13 11:10:09 freenas notifier: dd: /dev/da0: short write on character device
Aug 13 11:10:09 freenas notifier: dd: /dev/da0: end of device
Aug 13 11:10:09 freenas notifier: 5+0 records in
Aug 13 11:10:09 freenas notifier: 4+1 records out
Aug 13 11:10:09 freenas notifier: 4907008 bytes transferred in 0.106332 secs (46147962 bytes/sec)
Aug 13 11:10:09 freenas notifier: 1+0 records in
Aug 13 11:10:09 freenas notifier: 1+0 records out
Aug 13 11:10:09 freenas notifier: 1048576 bytes transferred in 0.022553 secs (46493927 bytes/sec)
Aug 13 11:10:10 freenas notifier: dd: /dev/da1: short write on character device
Aug 13 11:10:10 freenas notifier: dd: /dev/da1: end of device
Aug 13 11:10:10 freenas notifier: 5+0 records in
Aug 13 11:10:10 freenas notifier: 4+1 records out
Aug 13 11:10:10 freenas notifier: 4907008 bytes transferred in 0.376849 secs (13021146 bytes/sec)
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): ATA COMMAND PASS THROUGH(16). CDB: 85 0d 06 00 01 00 01 00 00 00 00 00 00 40 06 00
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): CAM status: CCB request completed with an error
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): Retrying command
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): ATA COMMAND PASS THROUGH(16). CDB: 85 0d 06 00 01 00 01 00 00 00 00 00 00 40 06 00
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): CAM status: CCB request completed with an error
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): Retrying command
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): ATA COMMAND PASS THROUGH(16). CDB: 85 0d 06 00 01 00 01 00 00 00 00 00 00 40 06 00
Aug 13 11:10:11 freenas kernel: (da0:isci0:0:0:0): CAM status: CCB request completed with an error

 

[aufalien]

Something hilarious just happened.

But first, let me explain this motherboard I have;

http://ark.intel.com/products/65399/Intel-Server-System-R2312SC2SHGR

The unit itself is a 2 U with 12 hot plug drive bays.

They seem to be split in an odd fashion were that last 4 ports are controlled via the motherboard BIOS and the first 8 are controlled by Intels RAID BIOS.

Now I do have Intels RAID disabled which is a fake RAID anyways and everything set to AHCI.

But it appears that anything in the first 8 slots will yield the CAM errors if attempting to add as a ZIL I haven't tried to add as storage yet but will do so shortly.

But I am now finally able to add as ZIL providing I use the last 4 slots for such devices.

Perhaps this sheds some insight?

Why would this be so?

- aurf

 

[aufalien]

UPDATE, it appears that if I use any device in the first 8 slots for either data, ZIL or L2ARC for my ZFS volume, the system hangs with those ATA CAM errors.

It appears to be a driver issue, so I will try using FreeBSD 9.2RC1 to see what happens and report back. Intel does not have any FreeBSD drivers per se for my motherboard.

Hope this helps or HTH as they say.

 

[aufalien]

UPDATE 2, so it appears that FreeBSD 9.2RC1 works w/o issue.

If you need a system to debug on, I am more then willing to help. Can provide SSH. etc access to it.

Or, simply give me things to run on either FreeNAS 9.1, FreeBSD9.1/92.RC1, etc...

In the mean time, here are the logs on FreeBSD 9.2RC1 from the ports exhibiting ATA CAM errors in FreeNAS when plugging a drive in;

Aug 13 21:03:51 prometheus kernel: da1 at isci0 bus 1 scbus1 target 3 lun 0
Aug 13 21:03:51 prometheus kernel: da1: <ATA ST33000650NS 0004> Fixed Direct Access SCSI-5 device
Aug 13 21:03:51 prometheus kernel: da1: 300.000MB/s transfers
Aug 13 21:03:51 prometheus kernel: da1: Command Queueing enabled
Aug 13 21:03:51 prometheus kernel: da1: 2861588MB (5860533168 512 byte sectors: 255H 63S/T 364801C)


And here are the logs on FreeBSD 9.2RC1 from the ports not exhibiting errors in FreeNAS when plugging drives in;

Aug 13 21:05:05 prometheus kernel: ada1 at ahcich5 bus 0 scbus9 target 0 lun 0
Aug 13 21:05:05 prometheus kernel: ada1: <ST33000650NS 0004> ATA-8 SATA 3.x device
Aug 13 21:05:05 prometheus kernel: ada1: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
Aug 13 21:05:05 prometheus kernel: ada1: Command Queueing enabled
Aug 13 21:05:05 prometheus kernel: ada1: 2861588MB (5860533168 512 byte sectors: 16H 63S/T 16383C)


Shortly I'll post what FreeNAS 9.1 shows in its log.

- aurf

 

[aufalien]

Well, it appears the messages are pretty much the same from FreeNAS 9.1.

Ports that had the ATA CAM errors;

Aug 13 16:21:15 freenas kernel: da1 at isci0 bus 0 scbus0 target 0 lun 0
Aug 13 16:21:15 freenas kernel: da1: <ATA INTEL SSDSA2M040 02M3> Fixed Direct Access SCSI-5 device
Aug 13 16:21:15 freenas kernel: da1: 300.000MB/s transfers
Aug 13 16:21:15 freenas kernel: da1: Command Queueing enabled
Aug 13 16:21:15 freenas kernel: da1: 38166MB (78165360 512 byte sectors: 255H 63S/T 4865C)


Ports that had no errors;

Aug 13 16:21:43 freenas kernel: ada0 at ahcich5 bus 0 scbus9 target 0 lun 0
Aug 13 16:21:43 freenas kernel: ada0: <ST33000650NS 0004> ATA-8 SATA 3.x device
Aug 13 16:21:43 freenas kernel: ada0: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
Aug 13 16:21:43 freenas kernel: ada0: Command Queueing enabled

 

[paleoN]

You appear to be looking for support.freenas.org to report bugs.

 

[aufalien]

Well, how do I really know its a bug unless some one gets back to me?

I'd like to avoid submitting a ticket unless its confirmed. I'm sure the FreeNAS peeps get a lot of bogus bug reports.

 

[paleoN]

Well, how do I really know its a bug unless some one gets back to me?

In which case you have the wrong forum, Bug Reporting. William, has stated that he wishes they would do away with that entire forum and only have support.freenas.org. From what I've seen he touches the majority of the tickets.

I'd like to avoid submitting a ticket unless its confirmed.

Use your best judgement. It seems to be a driver issue or a hardware problem. Do a search for "FreeBSD 9" and your motherboard/chipset/driver/HBA beforehand.

In the future use [code][/code] tags for CLI output.

 

[aufalien]

Thanks for replying.

I'll open another support ticket as after reading your reply, I'm sure its a bug :)

Thanks again.