AHCI controller reports success but reads no data

[mariuszp]

My AHCI driver works correctly in VirtualBox, I'm able to read and write sectors and perform a full installation of my OS. On my physical machine, I'm getting some strange behaviour. It successfully initializes the port, sends an IDENTIFY command, and receives the correct disk size and name, and PRDC is set to 0x200 after this operation - the correct size. Here is the code for ataInit(), where the IDENTIFY command is sent:

Code: Select all

void ataInit(AHCIController *ctrl, int portno)
{
	ATADevice *dev = NEW(ATADevice);
	ctrl->ataDevices[ctrl->numAtaDevices++] = dev;
	mutexInit(&dev->lock);
	
	dev->ctrl = ctrl;
	dev->port = &ctrl->regs->ports[portno];
	dev->sd = NULL;
	
	// create the operations area
	if (dmaCreateBuffer(&dev->dmabuf, sizeof(AHCIOpArea), 0) != 0)
	{
		// it didn't work
		kprintf("sdahci: failed to allocate operations area\n");
		kfree(dev);
		ctrl->numAtaDevices--;
		return;
	};
	
	// set up the operations area
	AHCIOpArea *opArea = (AHCIOpArea*) dmaGetPtr(&dev->dmabuf);
	memset(opArea, 0, sizeof(AHCIOpArea));
	
	// set the command list and FIS area
	dev->port->clb = dmaGetPhys(&dev->dmabuf) + __builtin_offsetof(AHCIOpArea, cmdlist);
	dev->port->fb = dmaGetPhys(&dev->dmabuf) + __builtin_offsetof(AHCIOpArea, fisArea);
	
	// we only use the first command header, so initialize it to point to the table
	opArea->cmdlist[0].ctba = dmaGetPhys(&dev->dmabuf) + __builtin_offsetof(AHCIOpArea, cmdtab);
	
	// start the command engine
	ahciStartCmd(dev->port);
	dev->port->serr = dev->port->serr;
	dev->port->is = dev->port->is;
	
	// send the IDENTIFY command.
	opArea->cmdlist[0].cfl = sizeof(FIS_REG_H2D)/4;		// FIS length in dwords
	opArea->cmdlist[0].w = 0;				// read data
	opArea->cmdlist[0].prdtl = 1;				// only one PRDT entry
	opArea->cmdlist[0].p = 1;
	
	opArea->cmdtab.prdt[0].dba = dmaGetPhys(&dev->dmabuf) + __builtin_offsetof(AHCIOpArea, id);
	opArea->cmdtab.prdt[0].dbc = 511;			// length-1
	opArea->cmdtab.prdt[0].i = 0;				// do not interrupt
	
	// set up command FIS
	FIS_REG_H2D *cmdfis = (FIS_REG_H2D*) opArea->cmdtab.cfis;
	cmdfis->fis_type = FIS_TYPE_REG_H2D;
	cmdfis->c = 1;
	cmdfis->command = ATA_CMD_IDENTIFY;
	
	// issue the command and await completion
	__sync_synchronize();
	if (ahciIssueCmd(dev->port) != 0)
	{
		kprintf("sdahci: error during identification\n");
		return;
	};

	kprintf("IDENTIFY PRDC: 0x%08x\n", opArea->cmdlist[0].prdbc);
	sleep(8000);
	
	uint32_t *cmdsetptr = (uint32_t*) &opArea->id[ATA_IDENT_COMMANDSETS];
	
	uint32_t cmdset = *cmdsetptr;
	uint64_t size;
	if (cmdset & (1 << 26))
	{
		uint64_t *szptr = (uint64_t*) &opArea->id[ATA_IDENT_MAX_LBA_EXT];
		size = (*szptr) & 0xFFFFFFFFFFFF;
	}
	else
	{
		uint32_t *szptr = (uint32_t*) &opArea->id[ATA_IDENT_MAX_LBA];
		size = (uint64_t) (*szptr);
	};

	char model[41];
	int k;
	for (k=0; k<40; k+=2)
	{
		model[k] = opArea->id[ATA_IDENT_MODEL + k + 1];
		model[k+1] = opArea->id[ATA_IDENT_MODEL + k];
	};
	model[40] = 0;
	char *check = &model[39];
	while (*check == ' ')
	{
		if (check == model) break;
		*check-- = 0;
	};

	kprintf("sdahci: size in MB: %lu, model: %s\n", size / 1024 / 2, model);
	
	SDParams sdpars;
	sdpars.flags = 0;
	sdpars.blockSize = 512;
	sdpars.totalSize = size * 512;

	// do a cache flush
	opArea->cmdlist[0].w = 0;
	opArea->cmdlist[0].p = 0;
	opArea->cmdlist[0].c = 1;
	opArea->cmdlist[0].prdtl = 0;

	cmdfis->fis_type = FIS_TYPE_REG_H2D;
	cmdfis->c = 1;
	cmdfis->command = ATA_CMD_CACHE_FLUSH_EXT;
	
	cmdfis->lba0 = 0;
	cmdfis->lba1 = 0;
	cmdfis->lba2 = 0;
	cmdfis->device = 1<<6;	// LBA mode
 
	cmdfis->lba3 = 0;
	cmdfis->lba4 = 0;
	cmdfis->lba5 = 0;
	
	cmdfis->countl = 0;
	cmdfis->counth = 0;
	
	// issue the flush command
	int status = ahciIssueCmd(dev->port);
	kprintf("sdahci: cache flush status: %d\n", status);
	
	dev->sd = sdCreate(&sdpars, model, &ataOps, dev);
	if (dev->sd == NULL)
	{
		kprintf("sdahci: SD creation failed\n");
		// NOTE: do not free anything; this is done upon removing the driver
	};
};

It prints "IDENTIFY PRDC: 0x200" on real hardware. ahciIssueCmd() is defined as:

Code: Select all

int ahciIssueCmd(volatile AHCIPort *port)
{
	uint64_t startTime = getNanotime();
	
	port->is = port->is;
	port->ci = 1;
	
	while (1)
	{
		if (getNanotime()-startTime > 8*NANO_PER_SEC)
		{
			// taking longer than 8 seconds
			kprintf("sdahci: timeout; aborting command. IS=0x%08X, SERR=0x%08X, TFD=0x%08X\n", port->is, port->serr, port->tfd);
			ahciStopCmd(port);
			ahciStartCmd(port);
			port->serr = port->serr;
			return EIO;
		};
		
		if (port->is & IS_ERR_FATAL)
		{
			// a fatal error occured
			kprintf("sdahci: fatal error. IS=0x%08X, SERR=0x%08X\n", port->is, port->serr);
			
			ahciStopCmd(port);
			ahciStartCmd(port);
			port->serr = port->serr;
			return EIO;
		};
		
		if ((port->ci & 1) == 0)
		{
			break;
		};
	};
	
	int busy = STS_BSY | STS_DRQ;
	while (port->tfd & busy)
	{
		if (getNanotime()-startTime > 8*NANO_PER_SEC)
		{
			kprintf("sdahci: timeout; aborting command. IS=0x%08X, SERR=0x%08X, TFD=0x%08X\n", port->is, port->serr, port->tfd);
			ahciStopCmd(port);
			ahciStartCmd(port);
			port->serr = port->serr;
			return EIO;
		};
	};
	
	if (port->tfd & STS_ERR)
	{
		return EIO;
	};
	
	return 0;
};

And here is how I implement reading, along with some deubgging:

Code: Select all

int ataTransferBlocks(ATADevice *dev, size_t startBlock, size_t numBlocks, void *buffer, int dir)
{
	mutexLock(&dev->lock);
	
	AHCIOpArea *opArea = (AHCIOpArea*) dmaGetPtr(&dev->dmabuf);
	opArea->cmdlist[0].cfl = sizeof(FIS_REG_H2D) / 4;
	opArea->cmdlist[0].c = 1;				// clear BSY when done
	
	if (dir == ATA_READ)
	{
		opArea->cmdlist[0].w = 0;
		opArea->cmdlist[0].p = 1;
	}
	else
	{
		opArea->cmdlist[0].w = 1;
		opArea->cmdlist[0].p = 0;
	};

	uint16_t prdtl = 0;
	
	DMARegion reg;
	for (dmaFirstRegion(&reg, buffer, 512*numBlocks, 0); reg.physAddr!=0; dmaNextRegion(&reg))
	{
		if (prdtl == 9) panic("unexpected input");

		if (dir == ATA_READ && startBlock == 0)
		{
			kprintf("ATA_READ 0: Region: physAddr=0x%016lX, physSize=0x%04lX\n", reg.physAddr, reg.physSize);
		};
		
		opArea->cmdtab.prdt[prdtl].dba = reg.physAddr;
		opArea->cmdtab.prdt[prdtl].dbc = reg.physSize - 1;
		opArea->cmdtab.prdt[prdtl].i = 0;
		
		prdtl++;
	};
	
	opArea->cmdlist[0].prdtl = prdtl;

	FIS_REG_H2D *cmdfis = (FIS_REG_H2D*)(&opArea->cmdtab.cfis);
	cmdfis->fis_type = FIS_TYPE_REG_H2D;
	cmdfis->c = 1;
	if (dir == ATA_READ)
	{
		cmdfis->command = ATA_CMD_READ_DMA_EXT;
	}
	else
	{
		cmdfis->command = ATA_CMD_WRITE_DMA_EXT;
	};
	
	cmdfis->lba0 = (uint8_t)startBlock;
	cmdfis->lba1 = (uint8_t)(startBlock>>8);
	cmdfis->lba2 = (uint8_t)(startBlock>>16);
	cmdfis->lba3 = (uint8_t)(startBlock>>24);
	cmdfis->lba4 = (uint8_t)(startBlock>>32);
	cmdfis->lba5 = (uint8_t)(startBlock>>40);
	cmdfis->device = 1<<6;	// LBA mode
	
	cmdfis->countl = numBlocks & 0xFF;
	cmdfis->counth = (numBlocks >> 8) & 0xFF;
	
	// issue the command
	int status = ahciIssueCmd(dev->port);
	if (status != 0)
	{
		mutexUnlock(&dev->lock);
		return status;
	};

	kprintf("PRDC: 0x%08x, IS=0x%08x, SERR=0x%08x\n", opArea->cmdlist[0].prdbc, dev->port->is, dev->port->serr);
	
	// do a cache flush
	opArea->cmdlist[0].w = 0;
	opArea->cmdlist[0].p = 0;
	opArea->cmdlist[0].c = 1;
	opArea->cmdlist[0].prdtl = 0;

	cmdfis->fis_type = FIS_TYPE_REG_H2D;
	cmdfis->c = 1;
	cmdfis->command = ATA_CMD_CACHE_FLUSH_EXT;
	
	cmdfis->lba0 = 0;
	cmdfis->lba1 = 0;
	cmdfis->lba2 = 0;
	cmdfis->device = 1<<6;	// LBA mode
 
	cmdfis->lba3 = 0;
	cmdfis->lba4 = 0;
	cmdfis->lba5 = 0;
	
	cmdfis->countl = 0;
	cmdfis->counth = 0;
	
	// issue the flush command
	status = ahciIssueCmd(dev->port);
	mutexUnlock(&dev->lock);
	return status;
};

int ataReadBlocks(void *drvdata, size_t startBlock, size_t numBlocks, void *buffer)
{
	// DEBUG
	memset(buffer, 0, 512 * numBlocks);

	ATADevice *dev = (ATADevice*) drvdata;
	int result = ataTransferBlocks(dev, startBlock, numBlocks, buffer, ATA_READ);

	if (startBlock == 0)
	{
		kprintf("Dumping first sector of ATA drive:");

		uint8_t *buf = (uint8_t*) buffer;
		for (size_t i=0; i<512; i++)
		{
			if ((i % 32) == 0)
			{
				kprintf("\n");
			};

			kprintf("%02hhx ", buf[i]);
		};

		kprintf("\nEND OF DUMP\n");
	};

	return result;
};

In VirtualBox, the read operation works too. It reports no errors (PxSERR = 0), and PRDC=0x8000, the requested size. The debugging code prints the regions it iterates over when building the PRDT, there are a few regions all of which are page-aligned and page-sized (That is, each one is a single page). It prints the correct hex dump of the first sector, where I can clearly see the boot signature.

But on physical hardware, the IDENTIFY command succeeds as I mentioned, but something strange happens with the read: ahciIssueCmd() succeeds, returning 0, but PRDC is set to 0, and indeed no data is transferred (The buffer is filled with zeroes, but there by the memset()). PxSERR is set to 0 at this point and PxIS is set to 0x1. This is identical to VirtualBox, except that in VirtualBox, PRDC is 0x8000 but on physical hardware it's 0.

I checked:

* The alignment for all structures is correct.
* The regions are page-aligned, and page-sized (i.e. each is a single page).
* PxSERR is zero.

I don't understand what I'm doing differently between the 2 commands that causes the reads to fail. Can anyone see what I'm doing wrong? I'll continue debugging in the meantime.

[linuxyne]

perhaps cache-mgmt, if the various buffers used to communicate with the device are cached in the CPU caches?
Or is something optimized away that emulators have a sane default for, but that an actual hw might need?

[mariuszp]

As far as i can tell, the CPU is cache-coherent with the PCI bus master on x86_64. Are there any steps your driver takes to manage the cache?

EDIT: I keep forgetting, but i think i also checked this: although for the IDENTIFY command my memory is uncached, there is also another different; after IDENTIFY, PRDC is 0x200, but after the read it is zero; indicating the AHCI controller read zero bytes (despite reporting success), not just that the CPU is reading the wrong data. PRDC itself is uncached.

[linuxyne]

As far as i can tell, the CPU is cache-coherent with the PCI bus master on x86_64. Are there any steps your driver takes to manage the cache?

Apologies. You are correct. I mistakenly assumed that it is necessary on all platforms.

What if, instead of IDENTIFY, the transfer cmds are issued as the very first commands?
The IDENTIFY does succeed on h/w, so it can be commented out.

[mariuszp]

As far as i can tell, the CPU is cache-coherent with the PCI bus master on x86_64. Are there any steps your driver takes to manage the cache?

Apologies. You are correct. I mistakenly assumed that it is necessary on all platforms.

What if, instead of IDENTIFY, the transfer cmds are issued as the very first commands?
The IDENTIFY does succeed on h/w, so it can be commented out.

I have tried skipping over the IDENTIFY command spoofing the results like you suggested (note there is exactly one drive connected to the physical AHCI):

Code: Select all

// (ataInit)

	// issue the command and await completion
#if 0
	__sync_synchronize();
	if (ahciIssueCmd(dev->port) != 0)
	{
		kprintf("sdahci: error during identification\n");
		return;
	};
#endif

// ...
	// issue the flush command
#if 0
	int status = ahciIssueCmd(dev->port);
	kprintf("sdahci: cache flush status: %d\n", status);
#endif

After this change, the read still fails in the same way: SERR is zero, PRDC is zero, no data is read.

[linuxyne]

After this change, the read still fails in the same way: SERR is zero, PRDC is zero, no data is read.

Hmm, thanks.

I am out of ideas. Perhaps anybody else with more knowledge and experience can chime in.

There's RFIS that you may want to check to see if the hba stored any values in there; PxIS being 1 should mean that RFIS has been stored into the system memory, if it has been setup.

I can create a small app, 32-bit, protected-mode, without mmu, without interrupt-controller, to run on the h/w, by tomorrow, for testing.

[mariuszp]

After this change, the read still fails in the same way: SERR is zero, PRDC is zero, no data is read.

Hmm, thanks.

I am out of ideas. Perhaps anybody else with more knowledge and experience can chime in.

There's RFIS that you may want to check to see if the hba stored any values in there; PxIS being 1 should mean that RFIS has been stored into the system memory, if it has been setup.

I can create a small app, 32-bit, protected-mode, without mmu, without interrupt-controller, to run on the h/w, by tomorrow, for testing.

Thank you for your help so far and if the app isn't too much of a bother I'll appreciate that greatly too (And I'm sure it'll be useful to others).

In the meantime, I went and got a dump of the received FIS, both in VBox and real hardware.

In VBOX we have:

Meanwhile on real hardware:

I can see a FIS is received but it has some differences to the VBox one. I will analyze it more thoroughly now.

I am a little confused as to why the first 16 bytes are all 0 in the FIS: the fis_type field is at offset 0, and "0x00" does not appear to be a valid value for it (yet both VBox and the hardware show this value). I'll check all the alignment requirements again, although I think I already checked that. Ah, yes, the different FIS types are at different offsets.

[Octocontrabass]

Have you checked whether PIO reads work?

Have you tried QEMU? If your code fails the same way in QEMU, you can use its logging facilities to figure out why.

[linuxyne]

I can create a small app, 32-bit, protected-mode, without mmu, without interrupt-controller, to run on the h/w, by tomorrow, for testing.

The app is here. The download and extraction passwords are the same: ahci

A script is included that builds a grub-mkrescue iso.

The code requires matching with the state machine in the AHCI docs, to smooth out the many wrinkles. It also begins by resetting the controller; that and some of the following steps may not be required, if one relies on the setup already performed by the BIOS/hw.

The file ahci.c needs to be adjusted by setting the PCI b/d/f numbers of the controller device and the port number (PIX) of the port where the disk resides.

You may want to try it on an emulator first, before booting your hw machine.

The output when booting the iso, with a 8086:1c02 controller, is as below.


It prints the letter 'J' on detecting prdbc == 0x200 (1 sector).

[mariuszp]

Have you checked whether PIO reads work?

Have you tried QEMU? If your code fails the same way in QEMU, you can use its logging facilities to figure out why.

Annoyingly, in QEMU it reports a signature of 0xFFFFFFFF from the port and thus does not detect it as an ATA drive. This seems to be a separate issue

I'll do linuxyne's test first before I debug this part.

The joys of coming back to OSDev after ~3 years hahaha

[mariuszp]

I can create a small app, 32-bit, protected-mode, without mmu, without interrupt-controller, to run on the h/w, by tomorrow, for testing.

The app is here. The download and extraction passwords are the same: ahci

A script is included that builds a grub-mkrescue iso.

The code requires matching with the state machine in the AHCI docs, to smooth out the many wrinkles. It also begins by resetting the controller; that and some of the following steps may not be required, if one relies on the setup already performed by the BIOS/hw.

The file ahci.c needs to be adjusted by setting the PCI b/d/f numbers of the controller device and the port number (PIX) of the port where the disk resides.

You may want to try it on an emulator first, before booting your hw machine.

The output when booting the iso, with a 8086:1c02 controller, is as below.


It prints the letter 'J' on detecting prdbc == 0x200 (1 sector).

I booted your code on my physical machine and got this:

It does not print "E" but I think that's correct.

I see it prints the "J" which seems to indicate that it has read the first sector; correct me if I am wrong.

So it looks like something must be different between your code and mine; I will compare thoroughly.

[Octocontrabass]

Annoyingly, in QEMU it reports a signature of 0xFFFFFFFF from the port and thus does not detect it as an ATA drive. This seems to be a separate issue

What options are you passing to QEMU? Your drives might still be attached to an IDE controller even though you have an AHCI controller.

[mariuszp]

Annoyingly, in QEMU it reports a signature of 0xFFFFFFFF from the port and thus does not detect it as an ATA drive. This seems to be a separate issue

What options are you passing to QEMU? Your drives might still be attached to an IDE controller even though you have an AHCI controller.

I use the following command:

Code: Select all

qemu-system-x86_64 -drive id=disk,file=/dev/sda,if=none,format=raw -device ahci,id=ahci -device ide-hd,drive=disk,bus=ahci.0

/dev/sda is correct (I installed Glidix on it).

I see the '-device ide-hd' might be wrong, but according to my google searches so far, that's how people are adding SATA drives to QEMU. Is this the wrong option?

[mariuszp]

Here's what I have so far:

* My Command Header is identical to linuxyne's.
* My FIS is identical to linuxyne's
* Clearing IS, PxIS, PxSERR does not help (PxSERR is zero anyway).
* linuxyne's code works, but mine does not (mine reports PRDC=0).

This leads me to think I must be doing something wrong during initialization. I'm still looking.

Here's the code for ahciInit() (which calls ataInit() from above) in case anyone wants to see it:

Code: Select all

static void ahciInit(AHCIController *ctrl)
{
	// map MMIO regs
	ctrl->regs = mapPhysMemory((uint64_t) (ctrl->pcidev->bar[5] & ~0xF), sizeof(AHCIMemoryRegs));
	
	// Don't use the controller if it does not support 64-bit addressing.
	if ((ctrl->regs->cap & CAP_S64A) == 0)
	{
		kprintf("sdahci: AHCI controller does not support 64-bit addressing, skipping.");
		return;
	};

	// take ownership of the device from firmware
	ctrl->regs->bohc |= BOHC_OOS;
	while (ctrl->regs->bohc & BOHC_BOS);
	
	// Make sure bus mastering is enabled.
	pciSetBusMastering(ctrl->pcidev, 1);
	ctrl->numAtaDevices = 0;

	// Perform a HBA reset and enable AHCI mode.
	ctrl->regs->ghc |= GHC_AE | GHC_HR;
	while (ctrl->regs->ghc & GHC_HR);
	
	// Initialize the ports.
	int i;
	for (i=0; i<32; i++)
	{
		if (ctrl->regs->pi & (1 << i))
		{
			ahciStopCmd(&ctrl->regs->ports[i]);
			ctrl->regs->ports[i].cmd |= CMD_SUD | CMD_POD;
			ctrl->regs->ports[i].cmd = (ctrl->regs->ports[i].cmd & ~CMD_ICC_MASK) | CMD_ICC_ACTIVE;

			// If staggered spin-up is supported, spin up the device.
			if (ctrl->regs->cap & CAP_SSS)
			{
				ctrl->regs->ports[i].sctl = (ctrl->regs->ports[i].sctl & ~SCTL_DET_MASK) | SCTL_DET_COMRESET;

				sleep(10);

				ctrl->regs->ports[i].sctl &= ~SCTL_DET_MASK;

				sleep(10);
			};	

			ctrl->regs->ports[i].serr = ~0;
			uint32_t ssts = ctrl->regs->ports[i].ssts;
			
			uint8_t ipm = (ssts >> 8) & 0x0F;
			uint8_t det = ssts & 0x0F;
			
			if (det != SSTS_DET_OK)
			{
				continue;
			};
			
			if (ipm != SSTS_IPM_ACTIVE)
			{
				continue;
			};
			
			uint32_t sig = ctrl->regs->ports[i].sig;
			if (sig == AHCI_SIG_ATA)
			{
				kprintf("sdahci: detected ATA drive on port %d\n", i);
				ataInit(ctrl, i);
			}
			else if (sig == AHCI_SIG_ATAPI)
			{
				kprintf("sdahci: detected ATAPI drive on port %d\n", i);
				atapiInit(ctrl, i);
			}
			else
			{
				kprintf("sdahci: unknown device: signature 0x%08X (port %d)\n", sig, i);
			};
		};
	};
};

[linuxyne]

Some thoughts, pls ignore if not applicable:

Is there any difference in behaviour if you compile your driver with different/least/no optimization levels?
Was a volatile qualifier missing at places that need it?
Is the compiler optimizing away critical pieces of code?

----

As Octocontrabass suggested, it may be of benefit to the test with qemu. If the 0xffffffff sig problem is not with the qemu cmdline, then there could be other problems in the driver that are being exposed by qemu. If the driver isn't working with an emulator, it is likely to not work with the actual hw too.

From the qemu's monitor console, trying to read the PxSIG of the device @ port #0.

Code: Select all

qemu-system-i386 \
-m 1g -cpu IvyBridge \
-no-reboot -no-shutdown -serial mon:stdio \
-device ahci,id=ahci \
-device ide-hd,drive=drive0,bus=ahci.0 \
-drive file=disk.img,if=none,id=drive0,format=raw \
-cdrom ahci.iso \
-trace enable=ahci_* \
-trace enable=pci_cfg_*

Code: Select all

QEMU 8.1.50 monitor - type 'help' for more information
(qemu) info pci
  . . .
  Bus  0, device   4, function 0:
    SATA controller: PCI device 8086:2922
      PCI subsystem 1af4:1100
      IRQ 11, pin A
      BAR4: I/O at 0xc040 [0xc05f].
      BAR5: 32 bit memory at 0xfebf1000 [0xfebf1fff].
      id "ahci"

# Reading PxSIG @ port #0
(qemu) xp/1xw 0xfebf1000+(0x40 + 0x0 * 0x20 + 0x9) * 0x4
00000000febf1124: 0x00000101

# Reading PRDBC after the ahci.iso reads a sector
(qemu) xp/1xw 0xfebf1000 + (0x40 + 0x0 * 0x20 + 0x0) * 0x4
00000000febf1100: 0x00103000 # This is the cmd-header
(qemu) xp/1xw 0x00103000+0x4
00103004: 0x00000200