Root Mount waiting for CAM

[veldthui]

I had Freenas 11.2 running on my Dell R730 fine with no issues with reboots and had been running for some time. It was running under BIOS rather the UEFI.
I decided to upgrade it to TrueNas U2 and changed the boot mode to UEFI. When it boots now most times it will hang displaying "Root Mount waiting for CAM". Sometimes it will start but most often wont.
Not sure what this CAM is so unsure of where to start. Could it be an issue with the UEFI? Would changing back to BIOS fix it?

Thanks.

 

[veldthui]

So I changed it back to BIOS mode boot and the issue has gone away. Not sure what it is as I have another Dell R720XD that does not have the issue.

 

[Samuel Tai]

Do you happen to have an HBA in your R730? Because this "waiting for CAM" message means the HBA didn't initialize under UEFI. The other system may have its HBA flashed with both a BIOS and a UEFI image, whereas this one may only be flashed with a BIOS image. Occasionally, it will initialize under UEFI using the CSM BIOS compatibility module.

 

[veldthui]

Do you happen to have an HBA in your R730? Because this "waiting for CAM" message means the HBA didn't initialize under UEFI. The other system may have its HBA flashed with both a BIOS and a UEFI image, whereas this one may only be flashed with a BIOS image. Occasionally, it will initialize under UEFI using the CSM BIOS compatibility module.

No, Just the standard Dell PERC730P Mini controller. The drives are set for non-raid so are available to the OS. The R720 has a Dell Perc 310 mini which has been flashed to allow the drives to be presented to the OS. I will leave it running under BIOS mode for now but at least I know where to start looking.

 

[Gcon]

I am having the same issue with Dell R730 UEFI mode and Dell PERC730P mini in HBA mode. Everything is the latest firmware from for BIOS, iDRAC, Lifecycle controller, onboard HBA, nics, Dell disks and power supplies. There is nothing that isn't firmware upgraded. The PERC730P from what I've read is based on the LSI SAS3108.

I am running TrueNAS Core 12.0-5 fresh install and get the issue. Happens on cold boot and reboot.

Code:

Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM usbus0 usbus1
Aug 16 18:01:29 gtnas01 uhub0: 2 ports with 2 removable, self powered
Aug 16 18:01:29 gtnas01 uhub1: 2 ports with 2 removable, self powered
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM usbus0 usbus1
Aug 16 18:01:29 gtnas01 ugen1.2: <vendor 0x8087 product 0x8002> at usbus1
Aug 16 18:01:29 gtnas01 uhub2 numa-domain 0 on uhub0
Aug 16 18:01:29 gtnas01 uhub2: <vendor 0x8087 product 0x8002, class 9/0, rev 2.00/0.05, addr 2> on usbus1
Aug 16 18:01:29 gtnas01 ugen0.2: <vendor 0x8087 product 0x800a> at usbus0
Aug 16 18:01:29 gtnas01 uhub3 numa-domain 0 on uhub1
Aug 16 18:01:29 gtnas01 uhub3: <vendor 0x8087 product 0x800a, class 9/0, rev 2.00/0.05, addr 2> on usbus0
Aug 16 18:01:29 gtnas01 uhub3: 6 ports with 6 removable, self powered
Aug 16 18:01:29 gtnas01 uhub2: 8 ports with 8 removable, self powered
Aug 16 18:01:29 gtnas01 ugen0.3: <no manufacturer Gadget USB HUB> at usbus0
Aug 16 18:01:29 gtnas01 uhub4 numa-domain 0 on uhub3
Aug 16 18:01:29 gtnas01 uhub4: <no manufacturer Gadget USB HUB, class 9/0, rev 2.00/0.00, addr 3> on usbus0
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM usbus0
Aug 16 18:01:29 gtnas01 uhub4: 6 ports with 6 removable, self powered
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM usbus0
Aug 16 18:01:29 gtnas01 ugen0.4: <Avocent Keyboard/Mouse Function> at usbus0
Aug 16 18:01:29 gtnas01 ukbd0 numa-domain 0 on uhub4
Aug 16 18:01:29 gtnas01 ukbd0: <Keyboard> on usbus0
Aug 16 18:01:29 gtnas01 kbd1 at ukbd0
Aug 16 18:01:29 gtnas01 ums0 numa-domain 0 on uhub4
Aug 16 18:01:29 gtnas01 ums0: <Mouse> on usbus0
Aug 16 18:01:29 gtnas01 ums0: 3 buttons and [Z] coordinates ID=0
Aug 16 18:01:29 gtnas01 ums1 numa-domain 0 on uhub4
Aug 16 18:01:29 gtnas01 ums1: <Mouse REL> on usbus0
Aug 16 18:01:29 gtnas01 ums1: 3 buttons and [XYZ] coordinates ID=0
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM
Aug 16 18:01:29 gtnas01 Root[3084]: Last message 'mount waiting for: C' repeated 161 times, suppressed by syslog-ng on <<SANITISED>>
Aug 16 18:01:29 gtnas01 mrsas0: Initiating Target RESET because of SCSI IO timeout!
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM
Aug 16 18:01:29 gtnas01 Root[3084]: Last message 'mount waiting for: C' repeated 4 times, suppressed by syslog-ng on <<SANITISED>>
Aug 16 18:01:29 gtnas01 mrsas0: Task management NOT SUPPORTED for CAM target:0
Aug 16 18:01:29 gtnas01 mrsas0: target reset FAIL!!
Aug 16 18:01:29 gtnas01 mrsas0: Initiaiting OCR because of TM FAILURE!
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM
Aug 16 18:01:29 gtnas01 mrsas0: [ 0]waiting for 9 commands to complete
Aug 16 18:01:29 gtnas01 Root mount waiting for: CAM
Aug 16 18:01:29 gtnas01 mrsas0: Reset Exit with 0.
Aug 16 18:01:29 gtnas01 ses0 at mrsas0 bus 1 scbus1 target 32 lun 0
Aug 16 18:01:29 gtnas01 ses0: <DP BP13G+ 2.25> Fixed Enclosure Services SPC-3 SCSI device
Aug 16 18:01:29 gtnas01 ses0: 150.000MB/s transfers
Aug 16 18:01:29 gtnas01 ses0: SES Device
Aug 16 18:01:29 gtnas01 ses1 at ahciem0 bus 0 scbus6 target 0 lun 0
Aug 16 18:01:29 gtnas01 ses1: <AHCI SGPIO Enclosure 2.00 0001> SEMB S-E-S 2.00 device
Aug 16 18:01:29 gtnas01 ses1: SEMB SES Device
Aug 16 18:01:29 gtnas01 ses2 at ahciem1 bus 0 scbus13 target 0 lun 0
Aug 16 18:01:29 gtnas01 ses2: <AHCI SGPIO Enclosure 2.00 0001> SEMB S-E-S 2.00 device
Aug 16 18:01:29 gtnas01 ses2: SEMB SES Device
Aug 16 18:01:29 gtnas01 ada0 at ahcich8 bus 0 scbus11 target 0 lun 0
Aug 16 18:01:29 gtnas01 ada0: <INTEL SSDSCKKB240G8 XC311132> ACS-3 ATA SATA 3.x device
Aug 16 18:01:29 gtnas01 ada0: Serial Number <<SANITISED>>
Aug 16 18:01:29 gtnas01 ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 512bytes)
Aug 16 18:01:29 gtnas01 ada0: Command Queueing enabled
Aug 16 18:01:29 gtnas01 ada0: 228936MB (468862128 512 byte sectors)
Aug 16 18:01:29 gtnas01 ada1 at ahcich9 bus 0 scbus12 target 0 lun 0
Aug 16 18:01:29 gtnas01 ada1: <INTEL SSDSCKKB240G8 XC311132> ACS-3 ATA SATA 3.x device
Aug 16 18:01:29 gtnas01 ada1: Serial Number <<SANITISED>>
Aug 16 18:01:29 gtnas01 ada1: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 512bytes)
Aug 16 18:01:29 gtnas01 ada1: Command Queueing enabled
Aug 16 18:01:29 gtnas01 ada1: 228936MB (468862128 512 byte sectors)
Aug 16 18:01:29 gtnas01 ses2: ada0 in 'Slot 04', SATA Slot: scbus11 target 0
Aug 16 18:01:29 gtnas01 ses2: ada1 in 'Slot 05', SATA Slot: scbus12 target 0
Aug 16 18:01:29 gtnas01 da0 at mrsas0 bus 1 scbus1 target 0 lun 0
Aug 16 18:01:29 gtnas01 da0: <HGST HUS726060AL5214 KK45> Fixed Direct Access SPC-4 SCSI device
Aug 16 18:01:29 gtnas01 da0: Serial Number <<SANITISED>>
Aug 16 18:01:29 gtnas01 da0: 150.000MB/s transfers
Aug 16 18:01:29 gtnas01 da0: 5723166MB (11721045168 512 byte sectors, DIF type 2)
Aug 16 18:01:29 gtnas01 da1 at mrsas0 bus 1 scbus1 target 1 lun 0
Aug 16 18:01:29 gtnas01 da1: <HGST HUS726060AL5214 KK45> Fixed Direct Access SPC-4 SCSI device
Aug 16 18:01:29 gtnas01 da1: Serial Number <<SANITISED>>
Aug 16 18:01:29 gtnas01 da1: 150.000MB/s transfers
Aug 16 18:01:29 gtnas01 da1: 5723166MB (11721045168 512 byte sectors, DIF type 2)

I included above and below the issues for context. You can clearly see "mrsas0" having all sorts of issues. I believe it's a driver issue with this driver as there's nothing wrong with my hardware.

Code:

root@gtnas01[/var/log]# camcontrol devlist
<HGST HUS726060AL5214 KK45>        at scbus1 target 0 lun 0 (pass0,da0)
<HGST HUS726060AL5214 KK45>        at scbus1 target 1 lun 0 (pass1,da1)
<HGST HUS726060AL5214 KK45>        at scbus1 target 2 lun 0 (pass2,da2)
<HGST HUS726060AL5214 KK45>        at scbus1 target 3 lun 0 (pass3,da3)
<HGST HUS726060AL5214 KK45>        at scbus1 target 4 lun 0 (pass4,da4)
<HGST HUS726060AL5214 KK45>        at scbus1 target 5 lun 0 (pass5,da5)
<HGST HUS726060AL5214 KK45>        at scbus1 target 6 lun 0 (pass6,da6)
<HGST HUS726060AL5214 KK45>        at scbus1 target 7 lun 0 (pass7,da7)
<DP BP13G+ 2.25>                   at scbus1 target 32 lun 0 (pass8,ses0)
<AHCI SGPIO Enclosure 2.00 0001>   at scbus6 target 0 lun 0 (pass9,ses1)
<INTEL SSDSCKKB240G8 XC311132>     at scbus11 target 0 lun 0 (pass10,ada0)
<INTEL SSDSCKKB240G8 XC311132>     at scbus12 target 0 lun 0 (pass11,ada1)
<AHCI SGPIO Enclosure 2.00 0001>   at scbus13 target 0 lun 0 (pass12,ses2)

Everything works fine after booting up. Either the CAM delays weren't there straight after the initial install, or I didn't noticie them. It's a bit too late to sweep the issue under the carpet and switch back to BIOS mode as I've already put this box into production. I'll just have to suffer through the couple of minutes of added boot delays until the box eventually boots, which it always seems to eventually (please don't jinx it!).

This thread is very interesting
https://forums.freebsd.org/threads/mrsas-and-the-mystery-of-lost-speed.79585/

The May 12th 2021 post shows the same kind of timeouts. Other(s) in the thread indicate that maybe the "mpr" driver should be used instead of "mrsas".

 

[Gcon]

Here is a link to the FreeBSD mrsas driver info.

Here's my H730P Mini card which that driver suppports.

Code:

root@gtnas01[/var/log]# lspci -vq -s 02:00.0
02:00.0 RAID bus controller: Broadcom / LSI MegaRAID SAS-3 3108 [Invader] (rev 02)
        Subsystem: Dell PERC H730 Mini
        Flags: bus master, fast devsel, latency 0, IRQ 255
        I/O ports at 2000
        Memory at 92300000 (64-bit, non-prefetchable)
        Memory at 92200000 (64-bit, non-prefetchable)
        Expansion ROM at fff00000 [disabled]
        Capabilities: [50] Power Management version 3
        Capabilities: [68] Express Endpoint, MSI 00
        Capabilities: [a8] MSI: Enable- Count=1/1 Maskable+ 64bit+
        Capabilities: [c0] MSI-X: Enable+ Count=97 Masked-
        Capabilities: [100] Advanced Error Reporting
        Capabilities: [1e0] Secondary PCI Express
        Capabilities: [1c0] Power Budgeting <?>
        Capabilities: [148] Alternative Routing-ID Interpretation (ARI)

root@gtnas01[/var/log]# lspci -vn -s 02:00.0
02:00.0 0104: 1000:005d (rev 02)
        Subsystem: 1028:1f49
        Flags: bus master, fast devsel, latency 0, IRQ 255
        I/O ports at 2000
        Memory at 92300000 (64-bit, non-prefetchable)
        Memory at 92200000 (64-bit, non-prefetchable)
        Expansion ROM at fff00000 [disabled]
        Capabilities: [50] Power Management version 3
        Capabilities: [68] Express Endpoint, MSI 00
        Capabilities: [a8] MSI: Enable- Count=1/1 Maskable+ 64bit+
        Capabilities: [c0] MSI-X: Enable+ Count=97 Masked-
        Capabilities: [100] Advanced Error Reporting
        Capabilities: [1e0] Secondary PCI Express
        Capabilities: [1c0] Power Budgeting <?>
        Capabilities: [148] Alternative Routing-ID Interpretation (ARI)

You can see it is an "Invader" card, as the Device ID is x005d.

I don't have any performance problems. Speed is great when all is booted up. All my links are showing 12.0gb/s which is what I want for my SAS3 backplane and drives:

Code:

root@gtnas01[/var/log]# MegaCli -PDList -aALL | grep Speed
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
Device Speed: 12.0Gb/s
Link Speed: 12.0Gb/s
root@gtnas01[/var/log]# 

https://github.com/freebsd/freebsd-src/tree/releng/12.2/sys/dev/mrsas - not too much activity there in 12.2 release eng.
https://github.com/freebsd/freebsd-src/tree/releng/13.0/sys/dev/mrsas - more dev happening in 13.

Hopefully this will be fixed somehow, but maybe this will have to wait until a TrueNAS CORE 13.x. Not sure. For now I just plan to expect a long boot up time, and only reboot when necessary.

 

[mikecindi]

Still not fixed. This started after I enabled JBOD on my second LSI 9285-8e today. I added the card a while back but did not add the drives until yesterday. There were no boot issues with the drives unallocated (a couple of reboots for other reasons). The other LSI 9285-8e had JBOD enabled when I loaded TrueNAS core 13.0, I updated to U2 recently so that may be another possibility for causing the issue.

 

[mikecindi]

Correction: the "other 9285" is actually a LSI 9200-8e with HBA firmware so perhaps there's something extra needed for the 9285 to get the drives "ready". It adds several minutes to the boot process but that doesn't happen often.