SATA data logger

Logger data format

SATA controller implemented in FPGA has it own low level logger. It uses 4 KB circular buffer to record timestamps, each host to device and device to host FIS (first 5 DWORDs only for long FISes), FIS length and a few other values that were used while debugging the controller. It also can record software generated timestamps and IRQ line state changes. 28 bits timestamp counter stores timestamps with 1/75 microsecond resolution and rolls over every ~3.58 s. All DWORDs in log containing timestamps have the following format:

0x<4 bit tag><28 bit timestamp>

where the 4 MSB tag field can be one of the following:

Tag	Description
0x0	register H2D FIS
0x1	register D2H FIS
0x8…0xd	software generated tags
0xe	set IRQ
0xf	clear IRQ

Software generated and IRQ timestamps are single DWORDs and have no any other data after them. Each FIS timestamp is followed by minimum 8 DWORDs for single DWORD FISes and maximum 12 DWORDs for longer FISes. These DWORDs contain the following data:

• up to 5 first DWORDs of the FIS
• 0xffff0000 | <fis length>
• 0xaa000000 | <DWORD count in the current command>
• 0x55000000 | <last DMA command>, where <last DMA command> is one of 0x25 (READ DMA EXT), 0x35 (WRITE DMA EXT), 0xc8 (READ DMA), 0xca (WRITE DMA); see ATA/ATAPI Command Set for command codes and description
• 0x33333333 or FIS data in case this was not DMA activate FIS
• (<8-bit counter of FIFO not ready (Device asked to wait), rolling over>) << 24) | <0x100000 if there was DMATp primitive - never happened> | <22-bit_link_count latched - dwords passed link layer>

Getting logged data

To get the latest log, go to /usr/local/bin on camera and start python in this directory. Copy the following startup code to python console:

from __future__ import print_function
from __future__ import division
import x393sata
import x393_mem
mem = x393_mem.X393Mem(1,0,1)
sata = x393sata.x393sata()

Data log starts at address 0x80001000:

_=mem.mem_dump (0x80001000, 0x400,4)

But it is more convenient to use the following command to get data log along with the state of AHCI registers:

hex([((mem.read_mem(0x80000ffc) >> 10) & 0xffc) + 0x80001000,mem.mem_dump (0x80001000, 0x400,4),sata.reg_status()][0])+" "+hex(mem.read_mem(0x80000ffc))

The last line of the output contains the address where data logger had stopped. The first timestamp after this address has smaller value and was recorder during previous buffer run. The log should be analyzed starting from this address and in reverse order.

Analysing log

Here is an example of the log:

>>> hex([((mem.read_mem(0x80000ffc) >> 10) & 0xffc) + 0x80001000,mem.mem_dump (0x80001000, 0x400,4),sata.reg_status()][0])+" "+hex(mem.read_mem(0x80000ffc))
Turning OFF use of negative offsets in mmap

0x80001000:ffff0801 aa024800 55350540 33333333 00024048 176f79ad 00000039 ffff0001 aa024800 55350540 33333333 00024849 076f79cc 00000046 91b093c3 48e500c8 
0x80001040:93919300 f5f6199c ffff0801 aa025000 55350540 33333333 00024849 176f82f8 00000039 ffff0001 aa025000 55350540 33333333 0002504a 076f8317 00000046 
0x80001080:a9242796 4d70103c c5626548 c1be4255 ffff0801 aa025800 55350540 33333333 0002504a 176f8c44 00000039 ffff0001 aa025800 55350540 33333333 0002584b 
0x800010c0:076f8c63 00000046 ce495209 2c845250 ed6df9e6 422a1d21 ffff0801 aa026000 55350540 33333333 0002584b 176f9590 00000039 ffff0001 aa026000 55350540 
0x80001100:33333333 0002604c 076f95af 00000046 635c2c17 cacd1ced 39ea9573 92d51935 ffff0801 aa026800 55350540 33333333 0002604c 176f9edc 00000039 ffff0001 
0x80001140:aa026800 55350540 33333333 0002684d 076f9efb 00000046 6ed338a9 ba9623be a8b818a5 9cdaa6d1 ffff0801 aa027000 55350540 33333333 0002684d 176fa828 
0x80001180:00000039 ffff0001 aa027000 55350540 33333333 0002704e 076fa847 00000046 49f4885f 75296a4a 69e23265 2722170c ffff0801 aa027800 55350540 33333333 
0x800011c0:0002704e 176fb174 00000039 ffff0001 aa027800 55350540 33333333 0002784f 076fb193 00000046 5623759a 72ade510 6ae4e652 9c937192 ffff0801 aa028000 
0x80001200:55350540 33333333 0002784f 176fbac0 00000039 ffff0001 aa028000 55350540 33333333 00028050 076fbadf 00000046 d21e0a61 20158e3c 949354e1 f004a1d3 
0x80001240:ffff0801 aa028800 55350540 33333333 00028050 176fc40b 00000039 ffff0001 aa028800 55350540 33333333 00028851 076fc42a 00000046 751c7830 7a479324 
0x80001280:228181a4 0edac916 ffff0801 aa029000 55350540 33333333 00028851 176fcd57 00000039 ffff0001 aa029000 55350540 33333333 00029052 076fcd76 00000046 
0x800012c0:77db6a45 8d32964f 3ae5945a f425fd94 ffff0801 aa029800 55350540 33333333 00029052 176fd6a3 00000039 ffff0001 aa029800 55350540 33333333 00029853 
0x80001300:076fd6c2 00000046 65348f73 ca1915cb a993a46e b9c928ed ffff0801 aa02a000 55350540 33333333 00029853 176fdfeb 00504034 e0337c28 0000000c 00000540 
0x80001340:00000000 ffff0005 aa02a000 55350540 00504034 0002a054 f76fe01a e76fe42e 97711f30 07711f8b 00358027 e0338168 0000000c 08000180 00000000 ffff0005 
0x80001380:aa000000 55350180 33333333 00000000 17712314 00000039 ffff0001 aa000000 55350180 33333333 00000000 07712333 00000046 06301be9 310edf3e a7b547e4 
0x800013c0:c8c617e0 ffff0801 aa000800 55350180 33333333 00000000 17712c8a 00000039 ffff0001 aa000800 55350180 33333333 00000801 07712ca9 00000046 e9a4617d 
0x80001400:bfdf9dc6 b4931256 67bf182d ffff0801 aa001000 55350180 33333333 00000801 177135d4 00000039 ffff0001 aa001000 55350180 33333333 00001002 077135f3 
0x80001440:00000046 4e123c09 43c7f176 d54fcfc0 743f6499 ffff0801 aa001800 55350180 33333333 00001002 17713f1e 00000039 ffff0001 aa001800 55350180 33333333 
0x80001480:00001803 07713f3d 00000046 c3b5ce9f 18729b92 306ec39d 407dbfaa ffff0801 aa002000 55350180 33333333 00001803 1771486a 00000039 ffff0001 aa002000 
0x800014c0:55350180 33333333 00002004 07714889 00000046 d528cb25 a31ddc84 8513ce38 afc22945 ffff0801 aa002800 55350180 33333333 00002004 177151b4 00000039 
0x80001500:ffff0001 aa002800 55350180 33333333 00002805 077151d3 00000046 a919d6a0 54f99cd3 65b8447a 3ed8fd65 ffff0801 aa003000 55350180 33333333 00002805 
0x80001540:17715b02 00000039 ffff0001 aa003000 55350180 33333333 00003006 07715b21 00000046 cf480283 3ca92707 49dd8492 3aa9ab4a ffff0801 aa003800 55350180 
0x80001580:33333333 00003006 1771644f 00000039 ffff0001 aa003800 55350180 33333333 00003807 0771646e 00000046 2a27e273 35231c55 0facdc33 ad349418 ffff0801 
0x800015c0:aa004000 55350180 33333333 00003807 17716d99 00000039 ffff0001 aa004000 55350180 33333333 00004008 07716db8 00000046 0fae0300 5dba9c24 1f4116dd 
0x80001600:a42a94cb ffff0801 aa004800 55350180 33333333 00004008 177176e5 00000039 ffff0001 aa004800 55350180 33333333 00004809 07717704 00000046 2a46be7b 
0x80001640:2ac1a9ea 493ba770 d353e15f ffff0801 aa005000 55350180 33333333 00004809 17718031 00000039 ffff0001 aa005000 55350180 33333333 0000500a 07718050 
0x80001680:00000046 ed97e764 0acf6739 ce5e583f 67258f71 ffff0801 aa005800 55350180 33333333 0000500a 1771897b 00000039 ffff0001 aa005800 55350180 33333333 
0x800016c0:0000580b 0771899a 00000046 50a5d1ac 21e28936 da295470 ebfdfd58 ffff0801 aa006000 55350180 33333333 0000580b 177192c9 00000039 ffff0001 aa006000 
0x80001700:55350180 33333333 0000600c 077192e8 00000046 aaa8d2e9 3c5a7345 2e8d8abc a6758857 ffff0801 aa006800 55350180 33333333 0000600c 17719c14 00000039 
0x80001740:ffff0001 aa006800 55350180 33333333 0000680d 07719c33 00000046 5cbb8a1f 8db587f3 ac462925 6ed51827 ffff0801 aa007000 55350180 33333333 0000680d 
0x80001780:1771a55e 00000039 ffff0001 aa007000 55350180 33333333 0000700e 0771a57d 00000046 a5041d39 749c6e2a ae748d70 c55dea94 ffff0801 aa007800 55350180 
0x800017c0:33333333 0000700e 1771aeac 00000039 ffff0001 aa007800 55350180 33333333 0000780f 0771aecb 00000046 50f34801 e1401b17 70f9419d 4e0204c7 ffff0801 
0x80001800:aa008000 55350180 33333333 0000780f 1771b7f7 00000039 ffff0001 aa008000 55350180 33333333 00008010 0771b816 00000046 17e410c3 48304ec6 05e2871d 
0x80001840:139c04dc ffff0801 aa008800 55350180 33333333 00008010 1771c141 00000039 ffff0001 aa008800 55350180 33333333 00008811 0771c160 00000046 49a54ebd 
0x80001880:5329752a 6621559a d27e88e7 ffff0801 aa009000 55350180 33333333 00008811 1771ca8d 00000039 ffff0001 aa009000 55350180 33333333 00009012 0771caac 
0x800018c0:00000046 97124ea7 58ae2a3d 5aabd15a 83bc8d20 ffff0801 aa009800 55350180 33333333 00009012 1771d3d7 00000039 ffff0001 aa009800 55350180 33333333 
0x80001900:00009813 0771d3f6 00000046 4ea3d339 4a416a55 2925a76a 856bfba9 ffff0801 aa00a000 55350180 33333333 00009813 1771dd22 00000039 ffff0001 aa00a000 
0x80001940:55350180 33333333 0000a014 0771dd41 00000046 6aacd89d d98a6c83 09c6b862 e748f918 ffff0801 aa00a800 55350180 33333333 0000a014 1771e66e 00000039 
0x80001980:ffff0001 aa00a800 55350180 33333333 0000a815 0771e68d 00000046 635606e4 c00c7fec bfdb351a be053970 ffff0801 aa00b000 55350180 33333333 0000a815 
0x800019c0:1771efba 00000039 ffff0001 aa00b000 55350180 33333333 0000b016 0771efd9 00000046 2a491877 6269e149 4a376714 1937e7a4 ffff0801 aa00b800 55350180 
0x80001a00:33333333 0000b016 1771f905 00000039 ffff0001 aa00b800 55350180 33333333 0000b817 0771f924 00000046 3ec839f5 5047ce99 64c4b479 14ce9391 ffff0801 
0x80001a40:aa00c000 55350180 33333333 0000b817 1772024d 00504034 e0338168 0000000c 00000180 00000000 ffff0005 aa00c000 55350180 00504034 0000c018 f772027c
0x80001a80:e7720544 9d14768a 0d147721 00ca8027 e00c40c0 00000000 08000008 00000000 ffff0005 aa000000 55ca0008 33333333 00000000 33333333 0001a835 176ec90a
0x80001ac0:00000039 ffff0001 aa01b000 55350540 33333333 0001b036 076ec929 00000046 6020c72a 7390006d e5c6fc9e 73dbe206 ffff0801 aa01b800 55350540 33333333 
0x80001b00:0001b036 176ed258 00000039 ffff0001 aa01b800 55350540 33333333 0001b837 076ed277 00000046 6c281f96 0f7a3092 978f0097 edc2c79d ffff0801 aa01c000 
0x80001b40:55350540 33333333 0001b837 176edba3 00000039 ffff0001 aa01c000 55350540 33333333 0001c038 076edbc2 00000046 0ef941d5 e7799073 a1bc5559 0fa7d628 
0x80001b80:ffff0801 aa01c800 55350540 33333333 0001c038 176ee4f0 00000039 ffff0001 aa01c800 55350540 33333333 0001c839 076ee50f 00000046 30928bf6 aa4949b5 
0x80001bc0:caefabb2 e3848332 ffff0801 aa01d000 55350540 33333333 0001c839 176eee3c 00000039 ffff0001 aa01d000 55350540 33333333 0001d03a 076eee5b 00000046 
0x80001c00:94ab8e1a 934afb29 b9484587 2aab5353 ffff0801 aa01d800 55350540 33333333 0001d03a 176ef788 00000039 ffff0001 aa01d800 55350540 33333333 0001d83b 
0x80001c40:076ef7a7 00000046 e4d4eaed 504de754 1925e554 9dae9ece ffff0801 aa01e000 55350540 33333333 0001d83b 176f00d2 00000039 ffff0001 aa01e000 55350540 
0x80001c80:33333333 0001e03c 076f00f1 00000046 83620949 27956139 70125080 ed04010e ffff0801 aa01e800 55350540 33333333 0001e03c 176f0a1f 00000039 ffff0001 
0x80001cc0:aa01e800 55350540 33333333 0001e83d 076f0a3e 00000046 51e6730a fbe5548a a65453a8 e1a42595 ffff0801 aa01f000 55350540 33333333 0001e83d 176f136b 
0x80001d00:00000039 ffff0001 aa01f000 55350540 33333333 0001f03e 076f138a 00000046 18f7e039 03488e01 2919d7df 465978d6 ffff0801 aa01f800 55350540 33333333 
0x80001d40:0001f03e 176f1cb5 00000039 ffff0001 aa01f800 55350540 33333333 0001f83f 076f1cd4 00000046 35e1bcd1 2297b23a ab5219ab 70b1ba19 ffff0801 aa020000 
0x80001d80:55350540 33333333 0001f83f 176f2602 00000039 ffff0001 aa020000 55350540 33333333 00020040 076f2621 00000046 4932a6a7 a9072307 14ce9b07 d41b18c5 
0x80001dc0:ffff0801 aa020800 55350540 33333333 00020040 176f2f4e 00000039 ffff0001 aa020800 55350540 33333333 00020841 076f2f6d 00000046 82e08012 4b929c8f 
0x80001e00:80531876 43af07d9 ffff0801 aa021000 55350540 33333333 00020841 176f3898 00000039 ffff0001 aa021000 55350540 33333333 00021042 076f38b7 00000046 
0x80001e40:919459ca cb4182b4 98591b2f f5730e1c ffff0801 aa021800 55350540 33333333 00021042 176f41e5 00000039 ffff0001 aa021800 55350540 33333333 00021843 
0x80001e80:076f4204 00000046 6fa39e00 1e008224 3ccf9187 c20a05b0 ffff0801 aa022000 55350540 33333333 00021843 176f4b31 00000039 ffff0001 aa022000 55350540 
0x80001ec0:33333333 00022044 076f4b50 00000046 b015460f 263e97f1 c8618cab b44a27ea ffff0801 aa022800 55350540 33333333 00022044 176f547b 00000039 ffff0001 
0x80001f00:aa022800 55350540 33333333 00022845 076f549a 00000046 840ee418 9dd4c965 5a9d4638 b9949372 ffff0801 aa023000 55350540 33333333 00022845 176f5dca 
0x80001f40:00000039 ffff0001 aa023000 55350540 33333333 00023046 076f5de9 00000046 9607790e 47f244f5 09ac82f1 b1a45064 ffff0801 aa023800 55350540 33333333 
0x80001f80:00023046 176f6715 00000039 ffff0001 aa023800 55350540 33333333 00023847 076f6734 00000046 d20cde4f e4102eb0 ca0fac10 0e7237c8 ffff0801 aa024000 
0x80001fc0:55350540 33333333 00023847 176f7061 00000039 ffff0001 aa024000 55350540 33333333 00024048 076f7080 00000046 88a51355 abd96f4a daa45150 cb488d57 
Turning OFF use of negative offsets in mmap
HBA_PORT__PxIS: 0x00000000 [80000110]
HBA_PORT__PxCMD: 0x00048007 [80000118]
      1 : HPCP (Hot Plug Capable Port)
      1 : CR (Command List Running (section 5.3.2))
      1 : POD (Power On Device (RW with Cold Presence Detection))
      1 : SUD (Spin-Up Device (RW with Staggered Spin-Up Support))
      1 : ST (Start (HBA may process commands). See section 10.3.1)
HBA_PORT__PxTFD: 0x000000d0 [80000120]
      1 : STS.BSY (Latest Copy of Task File Status Register: BSY)
      5 : STS.64 (Latest Copy of Task File Status Register: command-specific bits 4..6 )
HBA_PORT__PxSIG: 0x8fe2af00 [80000124]
    101 : SIG (Data in the first D2H Register FIS)
HBA_PORT__PxSSTS: 0x00000123 [80000128]
      1 : IPM (Interface Power Management)
      2 : SPD (Interface Speed)
      3 : DET (Device Detection (should be detected if COMINIT is received))
HBA_PORT__PxSERR: 0x00000000 [80000130]
HBA_PORT__PxCI: 0x00000001 [80000138]
      1 : CI (Command Issued: bit per Port, only set when PxCMD.ST==1, also cleared by PxCMD.ST: 1->0 by soft)
'0x80001ab4L 0x966ad03cL'

Last DWORD was recorded at address 0x80001ab4 and the whole record is marked in green. Red mark is set for the timestamp from the previous buffer run. The analysis of last record is the following:

• 0d147721 FIS timestamp, 4 MSBs indicate that this was host to device FIS
• 00ca8027 e00c40c0 00000000 08000008 00000000 FIS data as described in SATA specification
• ffff0005 marks the end of FIS data and indicates that FIS data consists of 5 DWORDs
• aa000000 shows DWORD count in the current command
• 55ca0008 indicates that last DMA command was 0xca (WRITE DMA)
• 33333333
• 00000000 contains additional counter values

Three timestamps marked in yellow preceding this FIS are IRQ and software generated timestamps:

• f772027c indicates when IRQ was set
• e7720544 was set when IRQ was reset
• 9d14768a was set when new command was prepared in driver; this one is driver specific

The light blue background marks register device to host FIS which was logged before IRQ:

• 1772024d FIS timestamp, 4 MSB indicate that is was device to host FIS
• 00504034 e0338168 0000000c 00000180 00000000 FIS data as described in SATA specification
• ffff0005 marks the end of FIS data and indicates that FIS data consists of 5 DWORDs
• aa00c000 shows DWORD count in the current command, 0xc000 value indicates that 0x30000 bytes were transferred during last command
• 55350180 indicates that last DMA command was 0x35 (WRITE DMA EXT)
• 00504034 FIS data
• 0000c018

Long series of data starting from address 0x80001364 corresponds to WRITE DMA EXT command and consists of DMA activate plus data FISes.

Software timestamps

SATA data logger can record software generated timestamps. Only 3 bits of 4 MSBs in timestamp are available for software tags. These tags should be written to a vendor specific register PxVS in AHCI port 0 registers and will appear in the log combined with timestamp: 0x<software tag + 8><timestamp>. Software tag is written in data series marked in yellow in the example above. The address of the register for tags is 0x78. Driver code setting software tag may look like this:

static void set_dscope_tstamp(struct ata_port *ap, unsigned int cmd)
{
        void __iomem *port_mmio;
        uint32_t data = 0;

        port_mmio = ahci_port_base(ap);

        data |= (cmd & 0x7);
	iowrite32(data, port_mmio + PORT_TIMESTAMP_ADDR);
}

where PORT_TIMESTAMP_ADDR is defined as 0x78.