Investigate AER issues

[bluecmd]

On a cold-boot, a modprobe fejkon produces this:

 		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
 		UEMsk:	DLP- SDES- TLP+ FCP- CmpltTO- CmpltAbrt+ UnxCmplt+ RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
 		UESvrt:	DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
-		CESta:	RxErr+ BadTLP- BadDLLP+ Rollover- Timeout- NonFatalErr-
+		CESta:	RxErr+ BadTLP+ BadDLLP+ Rollover- Timeout- NonFatalErr+
 		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr+

I.e we have triggered BadTLP+ I guess?

[bluecmd]

Another data point: Disabling AER kills the system when doing the benchmark

[bluecmd]

With the new PCIe stack in master right now (currently fa813ab) stress-testing reports 48 Mbit/s with and without AER. So the AER hang seems to be gone at least.

lspci still reports:

	Capabilities: [800 v1] Advanced Error Reporting
		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
		UEMsk:	DLP- SDES- TLP+ FCP- CmpltTO- CmpltAbrt+ UnxCmplt+ RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
		UESvrt:	DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
		CESta:	RxErr+ BadTLP+ BadDLLP+ Rollover- Timeout- NonFatalErr-
		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr+
		AERCap:	First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-

[bluecmd]

After flashing the same build artifact and power cycling the AER issues are back. I've tried programming, and coldbooting, and various combinations without success.

The errors seems to be missing completions, since CmpltTO is logged.

The stats on the FPGA is:

% pcie
 My ID                : 0xb300
 TLP RX               : 0x00000001
 TLP Unsupported RX   : 0x00000000
 TLP TX Data          : 0x00000000
 TLP TX Instant       : 0x00000000
 TLP TX Response      : 0x00000001
 Last TLP RX          : 0x00000001 0xb200000f 0xfbe00004 0x00000000 0xffffffff 0xffffffff 0xffffffff 0xffffffff
 Last TLP TX Data     : 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 Last TLP TX Instant  : 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 Last TLP TX Response : 0x4a000001 0xb3000004 0xb2000004 0xdeadbeef 0xffffffff 0xffffffff 0xffffffff 0xffffffff

[bluecmd]

Trying to investigate spurious RxErr, BadTLP, and BadDLLP.

Running my test Tyan S7106 board with commit 571a297 while poking the phy_freq sys file as fast as possible causes the machine to reboot after a while (< 1 hour). When rebooted it seems to come up with the card again but this time the upstream has negotiated only Gen 2 x8.

Right now running a test in Gen 2 x8 to see if that makes the RxErr etc. disappear.

Card is up with two ports looped back to back (interfaces set to UP). Cooling is provided by fans blowing over the card, but the built-in fan is not active. Reported temperature appears steady at 46 degrees.

[bluecmd]

stress.sh:

#!/bin/bash
i=0
while true
do
  v=$(cat '/sys/devices/pci0000:b2/0000:b2:00.0/0000:b3:00.0/phy_freq')
  if [[ "$v" -lt 100000000 ]] || [[ "$v" -gt 110000000 ]]; then
    echo "[$(date)] Got weird value: $v"
  fi
  i=$((i+1))
  if [[ "$((i % 100))" == "0" ]]; then
    echo -ne "Round $i\r"
  fi
done

watching lspci output changes with:

#!/bin/bash
diff -u a <(sudo lspci -s b3:00.0  -vvnn)

[bluecmd]

Test started at Tue Aug 18 21:15:41 2020 UTC

[bluecmd]

Test ended successfully at Wed Aug 19 08:05:59 2020 UTC.

Temperature 46 degrees. No errors reported. lspci remains stable.
Again, this with Gen2 x8.

dmesg:

[  297.645700] fejkon 0000:b3:00.0: found card with version 1 (571a2973), ports = 2
[  297.645702] fejkon 0000:b3:00.0: PHY clock running at 106.252 MHz
[  297.645706] fejkon 0000:b3:00.0: bandwidth 32000 Mbit/s, Gen 2 (5.0 GT/s) x8 - limited by 0000:b2:00.0
[  297.645707] fejkon 0000:b3:00.0: WARNING: only Gen3 x8 operation is supported
[  297.645739] fejkon 0000:b3:00.0: bandwidth is limited upstream @ 0000:b2:00.0
[  297.645765] fejkon 0000:b3:00.0: only 32000 Mbit/s bandwidth available, at least 40000 Mbit/s is recommended for full usage
[  297.646705] fejkon 0000:b3:00.0 port0 i2c: rate=100000Hz per_clk=50MHz -> ratio=1:500
[  297.647030] fejkon 0000:b3:00.0 port0: registered port 0 netdev fc0
[  297.647119] fejkon 0000:b3:00.0 port1 i2c: rate=100000Hz per_clk=50MHz -> ratio=1:500
[  297.647318] fejkon 0000:b3:00.0 port1: registered port 1 netdev fc1
[11264.288025] perf: interrupt took too long (2517 > 2500), lowering kernel.perf_event_max_sample_rate to 79250
[14887.291077] perf: interrupt took too long (3169 > 3146), lowering kernel.perf_event_max_sample_rate to 63000
[20126.677868] perf: interrupt took too long (3969 > 3961), lowering kernel.perf_event_max_sample_rate to 50250
[28831.460631] perf: interrupt took too long (4966 > 4961), lowering kernel.perf_event_max_sample_rate to 40250

Driver at f950e02 using the following diff:

diff --git a/driver/src/board.c b/driver/src/board.c
index 2ba1f13..0552f78 100644
--- a/driver/src/board.c
+++ b/driver/src/board.c
@@ -472,14 +472,13 @@ static int tune_pcie_parameters(struct pci_dev *pcidev) {
       "limited by %s", bandwidth, speed_str, width, pci_name(limdev));
 
   if (speed != PCIE_SPEED_8_0GT || width != PCIE_LNK_X8) {
-    dev_err(&pcidev->dev, "only Gen3 x8 operation is supported");
+    dev_err(&pcidev->dev, "WARNING: only Gen3 x8 operation is supported");
     if (limdev != pcidev) {
       dev_err(&pcidev->dev, "bandwidth is limited upstream @ %s",
           pci_name(limdev));
     } else {
       dev_err(&pcidev->dev, "bandwidth is limited by card");
     }
-    return -EINVAL;
   }
   if (bandwidth < 10 * 4 * 1000) {
     dev_warn(&pcidev->dev, "only %d Mbit/s bandwidth available, "
@@ -513,11 +512,13 @@ static int probe(struct pci_dev *pcidev, const struct pci_device_id *id)
     goto error_enable;
   }
 
+#ifdef FEJKON_AER
   ret = pci_enable_pcie_error_reporting(pcidev);
   if (ret < 0) {
     dev_err(&pcidev->dev, "pci_enable_pcie_error_reporting\n");
     goto error_enable_aer;
   }
+#endif
 
   ret = pci_request_region(pcidev, 0 /* bar */, KBUILD_MODNAME);
   if (ret < 0) {
@@ -542,7 +543,7 @@ static int probe(struct pci_dev *pcidev, const struct pci_device_id *id)
     ktime_t start = ktime_get();
     ktime_t end;
     int perf;
-    for (ret = 0; ret < 0x80000; ret++) {
+    for (ret = 0; ret < 0x10000; ret++) {
       if (ioread32(card->bar0 + 0x0) == ~0) {
         dev_err(&pcidev->dev, "stress test failed");
         ret = -EIO;
@@ -550,7 +551,7 @@ static int probe(struct pci_dev *pcidev, const struct pci_device_id *id)
       }
     }
     end = ktime_get();
-    perf = (0x80000*4*8)/((end - start) / 1000);
+    perf = (0x10000*4*8)/((end - start) / 1000);
     dev_dbg(&pcidev->dev, "debug performance result: %d Mbit/s", perf);
   }
 #endif
@@ -669,8 +670,10 @@ error_sanity:
 error_set_dma_mask:
   pci_release_region(pcidev, 0 /* bar */);
 error_request_region:
+#ifdef FEJKON_AER
 error_enable_aer:
   pci_disable_device(pcidev);
+#endif
 error_enable:
 error_card_alloc:
   return ret;

lspci was:

b3:00.0 Fibre Channel [0c04]: Device [f1c0:0de5] (rev 01)
	Subsystem: Device [f1c0:0de5]
	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx+
	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0, Cache Line Size: 32 bytes
	Interrupt: pin A routed to IRQ 62
	NUMA node: 0
	Region 0: Memory at fbe00000 (32-bit, non-prefetchable) [size=64K]
	Capabilities: [50] MSI: Enable+ Count=16/32 Maskable- 64bit+
		Address: 00000000fee00218  Data: 0000
	Capabilities: [78] Power Management version 3
		Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
	Capabilities: [80] Express (v2) Endpoint, MSI 00
		DevCap:	MaxPayload 512 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
			ExtTag+ AttnBtn- AttnInd- PwrInd- RBE+ FLReset- SlotPowerLimit 0.000W
		DevCtl:	CorrErr+ NonFatalErr+ FatalErr+ UnsupReq-
			RlxdOrd+ ExtTag+ PhantFunc- AuxPwr- NoSnoop+
			MaxPayload 256 bytes, MaxReadReq 512 bytes
		DevSta:	CorrErr+ NonFatalErr- FatalErr- UnsupReq+ AuxPwr- TransPend-
		LnkCap:	Port #1, Speed 8GT/s, Width x8, ASPM not supported
			ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
		LnkCtl:	ASPM Disabled; RCB 64 bytes Disabled- CommClk+
			ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
		LnkSta:	Speed 5GT/s (downgraded), Width x8 (ok)
			TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
		DevCap2: Completion Timeout: Range A, TimeoutDis+, NROPrPrP-, LTR-
			 10BitTagComp-, 10BitTagReq-, OBFF Not Supported, ExtFmt-, EETLPPrefix-
			 EmergencyPowerReduction Not Supported, EmergencyPowerReductionInit-
			 FRS-, TPHComp-, ExtTPHComp-
			 AtomicOpsCap: 32bit- 64bit- 128bitCAS-
		DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-, LTR-, OBFF Disabled
			 AtomicOpsCtl: ReqEn-
		LnkCtl2: Target Link Speed: 8GT/s, EnterCompliance- SpeedDis-
			 Transmit Margin: Normal Operating Range, EnterModifiedCompliance- ComplianceSOS-
			 Compliance De-emphasis: -6dB
		LnkSta2: Current De-emphasis Level: -3.5dB, EqualizationComplete+, EqualizationPhase1+
			 EqualizationPhase2+, EqualizationPhase3+, LinkEqualizationRequest-
	Capabilities: [100 v1] Virtual Channel
		Caps:	LPEVC=0 RefClk=100ns PATEntryBits=1
		Arb:	Fixed- WRR32- WRR64- WRR128-
		Ctrl:	ArbSelect=Fixed
		Status:	InProgress-
		VC0:	Caps:	PATOffset=00 MaxTimeSlots=1 RejSnoopTrans-
			Arb:	Fixed- WRR32- WRR64- WRR128- TWRR128- WRR256-
			Ctrl:	Enable+ ID=0 ArbSelect=Fixed TC/VC=01
			Status:	NegoPending- InProgress-
	Capabilities: [200 v1] Vendor Specific Information: ID=1172 Rev=0 Len=044 <?>
	Capabilities: [300 v1] Secondary PCI Express
		LnkCtl3: LnkEquIntrruptEn-, PerformEqu-
		LaneErrStat: LaneErr at lane: 0 1 2 3 4 5 6 7
	Capabilities: [800 v1] Advanced Error Reporting
		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
		UEMsk:	DLP- SDES- TLP+ FCP- CmpltTO- CmpltAbrt+ UnxCmplt+ RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
		UESvrt:	DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
		CESta:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr-
		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr+
		AERCap:	First Error Pointer: 00, ECRCGenCap+ ECRCGenEn- ECRCChkCap+ ECRCChkEn-
			MultHdrRecCap- MultHdrRecEn- TLPPfxPres- HdrLogCap-
		HeaderLog: 00000000 00000000 00000000 00000000
	Kernel driver in use: fejkon

[bluecmd]

Powering off the test motherboard and powering it up again returned with this diff on lspci:

--- a	2020-08-18 21:16:14.688358710 +0000
+++ /dev/fd/63	2020-08-19 08:10:48.856247296 +0000
@@ -1,13 +1,13 @@
 b3:00.0 Fibre Channel [0c04]: Device [f1c0:0de5] (rev 01)
 	Subsystem: Device [f1c0:0de5]
-	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx+
+	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx-
 	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
 	Latency: 0, Cache Line Size: 32 bytes
-	Interrupt: pin A routed to IRQ 62
+	Interrupt: pin A routed to IRQ 11
 	NUMA node: 0
 	Region 0: Memory at fbe00000 (32-bit, non-prefetchable) [size=64K]
-	Capabilities: [50] MSI: Enable+ Count=16/32 Maskable- 64bit+
-		Address: 00000000fee00218  Data: 0000
+	Capabilities: [50] MSI: Enable- Count=1/32 Maskable- 64bit+
+		Address: 0000000000000000  Data: 0000
 	Capabilities: [78] Power Management version 3
 		Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
 		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
@@ -22,7 +22,7 @@
 			ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
 		LnkCtl:	ASPM Disabled; RCB 64 bytes Disabled- CommClk+
 			ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-		LnkSta:	Speed 5GT/s (downgraded), Width x8 (ok)
+		LnkSta:	Speed 8GT/s (ok), Width x8 (ok)
 			TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
 		DevCap2: Completion Timeout: Range A, TimeoutDis+, NROPrPrP-, LTR-
 			 10BitTagComp-, 10BitTagReq-, OBFF Not Supported, ExtFmt-, EETLPPrefix-
@@ -53,10 +53,9 @@
 		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
 		UEMsk:	DLP- SDES- TLP+ FCP- CmpltTO- CmpltAbrt+ UnxCmplt+ RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
 		UESvrt:	DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
-		CESta:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr-
+		CESta:	RxErr+ BadTLP- BadDLLP+ Rollover- Timeout- AdvNonFatalErr-
 		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr+
 		AERCap:	First Error Pointer: 00, ECRCGenCap+ ECRCGenEn- ECRCChkCap+ ECRCChkEn-
 			MultHdrRecCap- MultHdrRecEn- TLPPfxPres- HdrLogCap-
 		HeaderLog: 00000000 00000000 00000000 00000000
-	Kernel driver in use: fejkon

It is clear that the speed is now Gen 3 but already it seems that the correctable error status (CESta) reports it has seen RxErr and BadDLLP.

[bluecmd]

Loading the module updates the diff to:

--- a	2020-08-18 21:16:14.688358710 +0000
+++ /dev/fd/63	2020-08-19 08:13:42.850777753 +0000
@@ -22,7 +22,7 @@
 			ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
 		LnkCtl:	ASPM Disabled; RCB 64 bytes Disabled- CommClk+
 			ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-		LnkSta:	Speed 5GT/s (downgraded), Width x8 (ok)
+		LnkSta:	Speed 8GT/s (ok), Width x8 (ok)
 			TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
 		DevCap2: Completion Timeout: Range A, TimeoutDis+, NROPrPrP-, LTR-
 			 10BitTagComp-, 10BitTagReq-, OBFF Not Supported, ExtFmt-, EETLPPrefix-
@@ -53,7 +53,7 @@
 		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
 		UEMsk:	DLP- SDES- TLP+ FCP- CmpltTO- CmpltAbrt+ UnxCmplt+ RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
 		UESvrt:	DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
-		CESta:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr-
+		CESta:	RxErr+ BadTLP+ BadDLLP+ Rollover- Timeout- AdvNonFatalErr-
 		CEMsk:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- AdvNonFatalErr+
 		AERCap:	First Error Pointer: 00, ECRCGenCap+ ECRCGenEn- ECRCChkCap+ ECRCChkEn-
 			MultHdrRecCap- MultHdrRecEn- TLPPfxPres- HdrLogCap-

I.e. it seems that the speed test in the beginning triggered a BadTLP error.

dmesg at this point:

[  215.332134] fejkon: loading out-of-tree module taints kernel.
[  215.332218] fejkon: module verification failed: signature and/or required key missing - tainting kernel
[  215.394564] fejkon 0000:b3:00.0: debug performance result: 34 Mbit/s
[  215.394568] fejkon 0000:b3:00.0: found card with version 1 (571a2973), ports = 2
[  215.394570] fejkon 0000:b3:00.0: PHY clock running at 106.253 MHz
[  215.394573] fejkon 0000:b3:00.0: bandwidth 63008 Mbit/s, Gen 3 (8.0 GT/s) x8 - limited by 0000:b2:00.0
[  215.394872] fejkon 0000:b3:00.0 port0 i2c: rate=100000Hz per_clk=50MHz -> ratio=1:500
[  215.395164] fejkon 0000:b3:00.0 port0: registered port 0 netdev fc0
[  215.395282] fejkon 0000:b3:00.0 port1 i2c: rate=100000Hz per_clk=50MHz -> ratio=1:500
[  215.395469] fejkon 0000:b3:00.0 port1: registered port 1 netdev fc1

Starting stress test at Wed 19 Aug 2020 08:14:50 AM UTC. Temperature still 46 degrees. Gen 3 x8 active.

[bluecmd]

Test failed at Wed Aug 19 08:20:46 2020 UTC (after 6 min).
Host system rebooted due to unknown issue (as is the common case). After reboot the link was still trained at Gen 3 x8.

New test started at Wed Aug 19 08:36:09 2020 UTC.

[bluecmd]

AER Timeout + endpoint AER RxErr reported at 08:49 UTC.

[bluecmd]

Crash at Wed Aug 19 08:57:05 2020 UTC. Host stuck in BIOS with red angry led shining.

[bluecmd]

Consider this done. AER works and stress testing using Gen 2 x8 on commit 571a297 works.

[yasirjamal87]

There is a setpci command exist that can clear the RxErr. By any chance does anyone know what it is?