aarch64: ahci0: log page read failed, slot 31 was still active

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
>Synopsis: panic after ahci0: log page read failed, slot 31 was still active
>Category: kernel
>Environment:
        System      : OpenBSD 6.6
        Details     : OpenBSD 6.6-beta (GENERIC.MP) #245: Sat Sep 28 20:43:51 MDT 2019
                         [hidden email]:/usr/src/sys/arch/arm64/compile/GENERIC.MP

        Architecture: OpenBSD.arm64
        Machine     : arm64
>Description:
        While building lang/rust received some ahci0 messages then a panic.
        System is a RockPro64 with 4G memory. filesystem root is on uSD, the
        rest of the paritions are on SSD (including swap).
>How-To-Repeat:
        Not sure if reproducable yet. I was building lang/rust with
        ulimit -Sd 4194304.
>Fix:
        Unknown


ahci0: log page read failed, slot 31 was still active.
ahci0: device didn't come ready after reset, TFD: 0x84c1<BSY,ERR>
panic: uvm_fault failed: ffffff80003475b8
Stopped at      panic+0x150:        TID    PID    UID     PRFLAGS     PFLAGS  C
PU  COMMAND
 505395  33070     74    0x100012          0    1  pflogd
  61458   3099      0     0x14000      0x200    2  softnet
db_enter() at panic+0x14c
panic() at $x.0+0x6c
$x.0() at ahci_port_stop+0x8c
ahci_port_stop() at ahci_port_intr+0x680
ahci_port_intr() at ahci_intr+0x7c
ahci_intr() at agintc_irq_handler+0x104
agintc_irq_handler() at arm_cpu_intr+0x30
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports.  Insufficient info makes it difficult to find and fix bugs.
ddb{0}> show uvm
Current UVM status:
  pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
  961557 VM pages: 90296 active, 4572 inactive, 0 wired, 686147 free (85774 zer
o)
  min  10% (25) anon, 10% (25) vnode, 5% (12) vtext
  freemin=32051, free-target=42734, inactive-target=244702, wired-max=320519
  faults=49567984, traps=0, intrs=0, ctxswitch=18264067 fpuswitch=0
  softint=3652793, syscalls=75421600, kmapent=12
  fault counts:
    noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
    ok relocks(total)=796471(803713), anget(retries)=5216381(127523), amapcopy=
13574591
    neighbor anon/obj pg=648998/6550880, gets(lock/unlock)=7480414/669183
    cases: anon=5179486, anoncow=29888, obj=6943478, prcopy=536701, przero=3687
8491
  daemon and swap counts:
    woke=106, revs=49, scans=6967722, obscans=327390, anscans=3688313
    busy=0, freed=486843, reactivate=2952019, deactivate=3790084
    pageouts=220579, pending=10122, nswget=134530
    nswapdev=1
    swpages=1050088, swpginuse=12335, swpgonly=10542 paging=0
  kernel pointers:
    objs(kern)=0xffffff8000ca7020
ddb{0}> show bcstats
Current Buffer Cache status:
numbufs 15018 busymapped 14, delwri 1
kvaslots 12019 avail kva slots 12005
bufpages 118400, dmapages 118400, dirtypages 4
pendingreads 2, pendingwrites 12
highflips 0, highflops 0, dmaflips 0
ddb{0}> trace
db_enter() at panic+0x14c
panic() at $x.0+0x6c
$x.0() at ahci_port_stop+0x8c
ahci_port_stop() at ahci_port_intr+0x680
ahci_port_intr() at ahci_intr+0x7c
ahci_intr() at agintc_irq_handler+0x104
agintc_irq_handler() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{0}> machine ddbcpu 1
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at vn_read+0x3c
vn_read() at dofilereadv+0x114
dofilereadv() at sys_read+0x54
sys_read() at svc_handler+0x2bc
ddb{1}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at vn_read+0x3c
vn_read() at dofilereadv+0x114
dofilereadv() at sys_read+0x54
sys_read() at svc_handler+0x2bc
svc_handler() at do_el0_sync+0x120
do_el0_sync() at handle_el0_sync+0x74
handle_el0_sync() at 0x1c3c916600
--- trap ---
ddb{1}> machine ddbcpu 2
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at pf_purge+0x14
pf_purge() at taskq_thread+0x40
taskq_thread() at proc_trampoline+0x10
ddb{2}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at pf_purge+0x14
pf_purge() at taskq_thread+0x40
taskq_thread() at proc_trampoline+0x10
ddb{2}> machine ddbcpu 4
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{4}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{4}> machine ddbcpu 3
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{3}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{3}> machine ddbcpu 5
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{5}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{5}> ps
   PID     TID   PPID    UID  S       FLAGS  WAIT          COMMAND
 92380   16029   3218   1000  3        0x83  fsleep        rustc
 92380  325096   3218   1000  3   0x4000083  fsleep        rustc
 92380  282137   3218   1000  3   0x4000083  poll          rustc
 92380   56632   3218   1000  3   0x4000083  fsleep        rustc
 92380   56680   3218   1000  3   0x4000003  biowait       rustc
  3218  335599  99611   1000  3        0x83  fsleep        cargo.bin
  3218  245150  99611   1000  3   0x4000083  poll          cargo.bin
  3218  107165  99611   1000  3   0x4000083  poll          cargo.bin
 99611  473478  94723   1000  3        0x83  piperd        bootstrap
 94723  371444  27053   1000  3    0x200083  wait          python2.7
 27053  138421  25491   1000  3    0x10008b  pause         make
  7511  354199  69046   1000  3    0x100083  poll          top
 69046  149337  73740   1000  3    0x10008b  pause         ksh
 73740  495851  38623   1000  3        0x90  select        sshd
 38623  241697  60696      0  3        0x92  poll          sshd
 25491  279425  45067   1000  3    0x10008b  pause         make
 45067   31471  83956   1000  3    0x10008b  pause         make
 83956  507237   5258   1000  3    0x10008b  pause         sh
  5258  156652  66279   1000  3    0x10008b  pause         make
 66279  440827  32268   1000  3    0x10008b  pause         sh
 32268   30836   7219   1000  3    0x10008b  pause         make
  7219  454049   6934   1000  3    0x10008b  pause         make
  6934  343150  96354   1000  3    0x10008b  pause         sh
 96354  460346  34797   1000  3    0x10008b  pause         make
 34797  492570  45679   1000  3    0x10008b  pause         ksh
 45679  191848  35383   1000  3        0x90  select        sshd
 35383  390125  60696      0  3        0x92  poll          sshd
 83722  467723      1      0  3    0x100083  ttyin         getty
 16143   72169      1      0  3    0x100098  poll          cron
 83708  179690      1     99  3    0x100090  poll          sndiod
 98093  435995      1    110  3    0x100090  poll          sndiod
 81200  389643  86530     95  3    0x100092  kqread        smtpd
 37960  144083  86530    103  3    0x100092  kqread        smtpd
  7698  102212  86530     95  3    0x100092  kqread        smtpd
 13377  252430  86530     95  3    0x100092  kqread        smtpd
 20543  345477  86530     95  3    0x100092  kqread        smtpd
 44750  486817  86530     95  3    0x100092  kqread        smtpd
 86530   60303      1      0  3    0x100080  kqread        smtpd
 60696  402593      1      0  3        0x80  select        sshd
 89128  362665      1      0  3    0x100080  poll          ntpd
 67701  283393   9305     83  3    0x100092  poll          ntpd
  9305  184747      1     83  3    0x100092  poll          ntpd
 33070  505395  65342     74  7    0x100012                pflogd
 65342   90732      1      0  3        0x80  netio         pflogd
 78404  193525  32316     73  3    0x100010  biowait       syslogd
 32316  502911      1      0  3    0x100082  netio         syslogd
 48861  216132      1     77  3    0x100090  poll          dhclient
 98037   35893      1      0  3        0x80  poll          dhclient
 98304  172556   9190    115  3    0x100092  kqread        slaacd
 93363  100580   9190    115  3    0x100092  kqread        slaacd
  9190  515486      1      0  3    0x100080  kqread        slaacd
 93168  171600      0      0  3     0x14200  pgzero        zerothread
 67320   53578      0      0  3     0x14200  aiodoned      aiodoned
 63621  378519      0      0  3     0x14200  getblk        update
 41875  424443      0      0  3     0x14200  cleaner       cleaner
 80885  151695      0      0  3     0x14200  reaper        reaper
 79049  229274      0      0  3     0x14200  pgdaemon      pagedaemon
 22045  363628      0      0  3     0x14200  bored         crynlk
 78076   20425      0      0  3     0x14200  bored         crypto
 55220  512425      0      0  3     0x14200  bored         tztq
*21873   44702      0      0  7  0x40014200                idle5
 84585  317130      0      0  7  0x40014200                idle4
 65407   77545      0      0  7  0x40014200                idle3
 16626  112869      0      0  3  0x40014200                idle2
 45893  446419      0      0  3  0x40014200                idle1
 61453  294692      0      0  3     0x14200  bored         sensors
 57806  393241      0      0  3     0x14200  usbtsk        usbtask
 36706  175754      0      0  3     0x14200  usbatsk       usbatsk
   165  292999      0      0  3     0x14200  mmctsk        sdmmc1
 37675  225338      0      0  3     0x14200  mmctsk        sdmmc0
  3099   61458      0      0  7     0x14200                softnet
 19722  111917      0      0  3     0x14200  bored         systqmp
 98440  249996      0      0  3     0x14200  bored         systq
 95664  440021      0      0  2  0x40014200                softclock
 92178   22447      0      0  7  0x40014200                idle0
 81592   25022      0      0  3     0x14200  bored         smr
  6495  210233      0      0  3     0x14200  kmalloc       kmthread
     1   42452      0      0  3        0x82  wait          init
     0       0     -1      0  3     0x10200  scheduler     swapper

top:
load averages:  0.37,  0.82,  0.93             rocky.intricatesoftware.com 17:44:16
46 processes: 45 idle, 1 on processor                                      up  8:37
CPU0 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
CPU1 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
CPU2 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
CPU3 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
CPU4 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
CPU5 states:  0.0% user,  0.0% nice,  0.0% sys,  0.0% spin,  0.0% intr,  100% idle
Memory: Real: 353M/1076M act/tot Free: 2680M Cache: 463M Swap: 48M/4102M

  PID USERNAME PRI NICE  SIZE   RES STATE     WAIT      TIME    CPU COMMAND
92380 truk      10    0  477M  303M idle      fsleep   73:14  4.93% rustc
 7511 truk      28    0 1476K 1452K onproc/2  -         0:23  0.00% top
73740 truk       2    0 1260K  584K sleep/5   select    0:01  0.00% sshd
78404 _syslogd  -5    0 1356K  536K idle      biowait   0:00  0.00% syslogd
16143 root       2    0  732K  436K sleep/1   poll      0:00  0.00% cron
 9305 _ntp       2  -20 1168K  408K idle      poll      0:01  0.00% ntpd
33070 _pflogd    4    0  760K  172K sleep/1   bpf       0:04  0.00% pflogd
 3218 truk      10    0  293M    0K idle      fsleep    0:10  0.00% cargo.bin
99611 truk      -6    0   11M    0K idle      piperd    0:01  0.00% bootstrap
94723 truk      10    0 8336K    0K idle      wait      0:00  0.00% python2.7
86530 root       2    0 2012K    0K idle      kqread    0:00  0.00% smtpd
37960 _smtpq     2    0 1896K    0K idle      kqread    0:00  0.00% smtpd
20543 _smtpd     2    0 1896K    0K idle      kqread    0:00  0.00% smtpd
 7698 _smtpd     2    0 1824K    0K idle      kqread    0:00  0.00% smtpd
13377 _smtpd     2    0 1780K    0K idle      kqread    0:00  0.00% smtpd
44750 _smtpd     2    0 1696K    0K idle      kqread    0:00  0.00% smtpd
81200 _smtpd     2    0 1692K    0K idle      kqread    0:00  0.00% smtpd
27053 truk      18    0 1372K    0K idle      pause     0:00  0.00% make
38623 root       2    0 1340K    0K idle      poll      0:00  0.00% sshd
35383 root       2    0 1328K    0K idle      poll      0:00  0.00% sshd

firmware:
rkbin TPL layer (garbled output - different baud rate)

U-Boot SPL 2019.10-rc4 (Oct 03 2019 - 19:40:31 -0400)
Trying to boot from MMC1
NOTICE:  BL31: v2.1(debug):2.1
NOTICE:  BL31: Built : 10:16:34, Sep 27 2019
INFO:    GICv3 with legacy support detected. ARM GICV3 driver initialized in EL3
INFO:    plat_rockchip_pmu_init(1596): pd status 3e
INFO:    BL31: Initializing runtime services
WARNING: BL31: cortex_a53: CPU workaround for 819472 was missing!
WARNING: BL31: cortex_a53: CPU workaround for 824069 was missing!
WARNING: BL31: cortex_a53: CPU workaround for 827319 was missing!
INFO:    BL31: cortex_a53: CPU workaround for 855873 was applied
INFO:    BL31: Preparing for EL3 exit to normal world
INFO:    Entry point address = 0x200000
INFO:    SPSR = 0x3c9


U-Boot 2019.10-rc4 (Oct 03 2019 - 19:40:31 -0400)

Model: Pine64 RockPro64
DRAM:  3.9 GiB
MMC:   dwmmc@fe320000: 1, sdhci@fe330000: 0
Loading Environment from MMC... Card did not respond to voltage select!
*** Warning - No block device, using default environment

In:    serial@ff1a0000
Out:   serial@ff1a0000
Err:   serial@ff1a0000
Model: Pine64 RockPro64
rockchip_dnl_key_pressed: adc_channel_single_shot fail!
Net:   eth0: ethernet@fe300000
Hit any key to stop autoboot:  0
Card did not respond to voltage select!
switch to partitions #0, OK
mmc1 is current device
Scanning mmc 1:1...
Found EFI removable media binary efi/boot/bootaa64.efi
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
Scanning disk [hidden email]...
Card did not respond to voltage select!
Scanning disk [hidden email]...
Disk [hidden email] not ready
Found 3 disks
BootOrder not defined
EFI boot manager: Cannot load any image
161090 bytes read in 13 ms (11.8 MiB/s)
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
disks: sd0*
>> OpenBSD/arm64 BOOTAA64 0.19
boot>


dmesg:
OpenBSD 6.6-beta (GENERIC.MP) #245: Sat Sep 28 20:43:51 MDT 2019
    [hidden email]:/usr/src/sys/arch/arm64/compile/GENERIC.MP
real mem  = 4094251008 (3904MB)
avail mem = 3895132160 (3714MB)
mainbus0 at root: Pine64 RockPro64
cpu0 at mainbus0 mpidr 0: ARM Cortex-A53 r0p4
cpu0: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu0: 512KB 64b/line 16-way L2 cache
efi0 at mainbus0: UEFI 2.8
efi0: Das U-Boot rev 0x20191000
apm0 at mainbus0
psci0 at mainbus0: PSCI 1.1, SMCCC 1.1
agintc0 at mainbus0 sec shift 3:3 nirq 288 nredist 6 ipi: 0, 1: "interrupt-controller"
agintcmsi0 at agintc0
syscon0 at mainbus0: "qos"
syscon1 at mainbus0: "qos"
syscon2 at mainbus0: "qos"
syscon3 at mainbus0: "qos"
syscon4 at mainbus0: "qos"
syscon5 at mainbus0: "qos"
syscon6 at mainbus0: "qos"
syscon7 at mainbus0: "qos"
syscon8 at mainbus0: "qos"
syscon9 at mainbus0: "qos"
syscon10 at mainbus0: "qos"
syscon11 at mainbus0: "qos"
syscon12 at mainbus0: "qos"
syscon13 at mainbus0: "qos"
syscon14 at mainbus0: "qos"
syscon15 at mainbus0: "qos"
syscon16 at mainbus0: "qos"
syscon17 at mainbus0: "qos"
syscon18 at mainbus0: "qos"
syscon19 at mainbus0: "qos"
syscon20 at mainbus0: "qos"
syscon21 at mainbus0: "qos"
syscon22 at mainbus0: "qos"
syscon23 at mainbus0: "qos"
syscon24 at mainbus0: "qos"
syscon25 at mainbus0: "power-management"
"power-controller" at syscon25 not configured
syscon26 at mainbus0: "syscon"
"io-domains" at syscon26 not configured
syscon27 at mainbus0: "syscon"
syscon28 at mainbus0: "syscon"
rkclock0 at mainbus0
rkclock1 at mainbus0
syscon29 at mainbus0: "syscon"
"io-domains" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"phy" at syscon29 not configured
"pcie-phy" at syscon29 not configured
rkpinctrl0 at mainbus0: "pinctrl"
rkgpio0 at rkpinctrl0
rkgpio1 at rkpinctrl0
rkgpio2 at rkpinctrl0
rkgpio3 at rkpinctrl0
rkgpio4 at rkpinctrl0
"fit-images" at mainbus0 not configured
"pmu_a53" at mainbus0 not configured
"pmu_a72" at mainbus0 not configured
agtimer0 at mainbus0: tick rate 24000 KHz
"xin24m" at mainbus0 not configured
simplebus0 at mainbus0: "amba"
"dma-controller" at simplebus0 not configured
"dma-controller" at simplebus0 not configured
rkpcie0 at mainbus0
pci0 at rkpcie0
ppb0 at pci0 dev 0 function 0 "Rockchip RK3399 Root Complex" rev 0x00: msi
pci1 at ppb0 bus 1
ahci0 at pci1 dev 0 function 0 "ASMedia ASM1061 AHCI" rev 0x01: msi, AHCI 1.2
ahci0: port 1: 6.0Gb/s
scsibus0 at ahci0: 32 targets
sd0 at scsibus0 targ 1 lun 0: <ATA, Samsung SSD 840, EXT0> naa.50025388a003c28f
sd0: 476940MB, 512 bytes/sector, 976773168 sectors, thin
dwge0 at mainbus0
dwge0: address: 12:e7:22:42:f7:96
rgephy0 at dwge0 phy 0: RTL8169S/8110S/8211 PHY, rev. 6
dwmmc0 at mainbus0: 50 MHz base clock
sdmmc0 at dwmmc0: 4-bit, sd high-speed, mmc high-speed, dma
sdhc0 at mainbus0
sdhc0: SDHC 3.0, 200 MHz base clock
sdmmc1 at sdhc0: 8-bit, sd high-speed, mmc high-speed, dma
ehci0 at mainbus0
usb0 at ehci0: USB revision 2.0
uhub0 at usb0 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00 addr 1
ohci0 at mainbus0: version 1.0
ehci1 at mainbus0
usb1 at ehci1: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00 addr 1
ohci1 at mainbus0: version 1.0
rkdwusb0 at mainbus0: "usb"
xhci0 at rkdwusb0, xHCI 1.10
usb2 at xhci0: USB revision 3.0
uhub2 at usb2 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00 addr 1
rkdwusb1 at mainbus0: "usb"
xhci1 at rkdwusb1, xHCI 1.10
usb3 at xhci1: USB revision 3.0
uhub3 at usb3 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00 addr 1
"saradc" at mainbus0 not configured
rkiic0 at mainbus0
iic0 at rkiic0
rkiic1 at mainbus0
iic1 at rkiic1
com0 at mainbus0: ns16550, no working fifo
com1 at mainbus0: ns16550, no working fifo
com1: console
"thermal-zones" at mainbus0 not configured
rktemp0 at mainbus0
rkiic2 at mainbus0
iic2 at rkiic2
rkpmic0 at iic2 addr 0x1b: RK808
fanpwr0 at iic2 addr 0x40: SYR827, 1.20 VDC
fanpwr1 at iic2 addr 0x41: SYR828, 1.00 VDC
rkiic3 at mainbus0
iic3 at rkiic3
fusbtc0 at iic3 addr 0x22
"pwm" at mainbus0 not configured
"pwm" at mainbus0 not configured
"dmc" at mainbus0 not configured
"efuse" at mainbus0 not configured
"phy" at mainbus0 not configured
"phy" at mainbus0 not configured
"watchdog" at mainbus0 not configured
"rktimer" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"hdmi-sound" at mainbus0 not configured
"hdmi" at mainbus0 not configured
"gpu" at mainbus0 not configured
"opp-table0" at mainbus0 not configured
"opp-table1" at mainbus0 not configured
"opp-table2" at mainbus0 not configured
"external-gmac-clock" at mainbus0 not configured
"gpio-keys" at mainbus0 not configured
"leds" at mainbus0 not configured
"sdio-pwrseq" at mainbus0 not configured
"vcc12v-dcin" at mainbus0 not configured
"vcc1v8-s3" at mainbus0 not configured
"vcc3v3-pcie-regulator" at mainbus0 not configured
"vcc3v3-sys" at mainbus0 not configured
"vcc5v0-host-regulator" at mainbus0 not configured
"vcc5v0-typec-regulator" at mainbus0 not configured
"vcc5v0-sys" at mainbus0 not configured
"vcc5v0-usb" at mainbus0 not configured
"vdd-log" at mainbus0 not configured
cpu1 at mainbus0 mpidr 1: ARM Cortex-A53 r0p4
cpu1: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu1: 512KB 64b/line 16-way L2 cache
cpu2 at mainbus0 mpidr 2: ARM Cortex-A53 r0p4
cpu2: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu2: 512KB 64b/line 16-way L2 cache
cpu3 at mainbus0 mpidr 3: ARM Cortex-A53 r0p4
cpu3: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu3: 512KB 64b/line 16-way L2 cache
cpu4 at mainbus0 mpidr 100: ARM Cortex-A72 r0p2
cpu4: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu4: 1024KB 64b/line 16-way L2 cache
cpu5 at mainbus0 mpidr 101: ARM Cortex-A72 r0p2
cpu5: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu5: 1024KB 64b/line 16-way L2 cache
usb4 at ohci0: USB revision 1.0
uhub4 at usb4 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00 addr 1
usb5 at ohci1: USB revision 1.0
uhub5 at usb5 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00 addr 1
scsibus1 at sdmmc0: 2 targets, initiator 0
sd1 at scsibus1 targ 1 lun 0: <SD/MMC, SD16G, 0020> removable
sd1: 29862MB, 512 bytes/sector, 61157376 sectors
sdmmc1: can't enable card
vscsi0 at root
scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
bootfile: sd0a:/bsd
boot device: sd0
root on sd1a (4cbb6909064a3cdc.a) swap on sd1b dump on sd1b
WARNING: / was not properly unmounted

usbdevs:
Controller /dev/usb0:
addr 01: 0000:0000 Generic, EHCI root hub
         high speed, self powered, config 1, rev 1.00
         driver: uhub0
Controller /dev/usb1:
addr 01: 0000:0000 Generic, EHCI root hub
         high speed, self powered, config 1, rev 1.00
         driver: uhub1
Controller /dev/usb2:
addr 01: 0000:0000 Generic, xHCI root hub
         super speed, self powered, config 1, rev 1.00
         driver: uhub2
Controller /dev/usb3:
addr 01: 0000:0000 Generic, xHCI root hub
         super speed, self powered, config 1, rev 1.00
         driver: uhub3
Controller /dev/usb4:
addr 01: 0000:0000 Generic, OHCI root hub
         full speed, self powered, config 1, rev 1.00
         driver: uhub4
Controller /dev/usb5:
addr 01: 0000:0000 Generic, OHCI root hub
         full speed, self powered, config 1, rev 1.00
         driver: uhub5

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Jonathan Matthew-4
On Fri, Oct 04, 2019 at 06:24:16PM -0400, [hidden email] wrote:

> >Synopsis: panic after ahci0: log page read failed, slot 31 was still active
> >Category: kernel
> >Environment:
> System      : OpenBSD 6.6
> Details     : OpenBSD 6.6-beta (GENERIC.MP) #245: Sat Sep 28 20:43:51 MDT 2019
> [hidden email]:/usr/src/sys/arch/arm64/compile/GENERIC.MP
>
> Architecture: OpenBSD.arm64
> Machine     : arm64
> >Description:
> While building lang/rust received some ahci0 messages then a panic.
> System is a RockPro64 with 4G memory. filesystem root is on uSD, the
> rest of the paritions are on SSD (including swap).
> >How-To-Repeat:
> Not sure if reproducable yet. I was building lang/rust with
> ulimit -Sd 4194304.
> >Fix:
> Unknown
>
>
> ahci0: log page read failed, slot 31 was still active.
> ahci0: device didn't come ready after reset, TFD: 0x84c1<BSY,ERR>
> panic: uvm_fault failed: ffffff80003475b8

So, the 'log page read' happens when there are multiple commands active and the
port reports an error.  The log page read is supposed to tell us which command
failed.  If that fails, we fail all active commands, and if the device won't
reset after that, we shut the device off and all further io will fail.  If
that's your swap device, and the system is swapping, you're kind of screwed.

Perhaps disabling command queueing (which means there can only be one command
in flight, so no need to read the log page on errors) might help?  The diff
below should do that.  Checking the SSD out with smartctl is probably also a
good idea at this point.


diff --git sys/dev/pci/ahci_pci.c sys/dev/pci/ahci_pci.c
index 79044b52dd5..f61ae96b0cf 100644
--- sys/dev/pci/ahci_pci.c
+++ sys/dev/pci/ahci_pci.c
@@ -108,7 +108,8 @@ static const struct ahci_device ahci_devices[] = {
  { PCI_VENDOR_ATI, PCI_PRODUCT_ATI_SBX00_SATA_6,
     NULL, ahci_ati_sb700_attach },
 
- { PCI_VENDOR_ASMEDIA, PCI_PRODUCT_ASMEDIA_ASM1061_SATA },
+ { PCI_VENDOR_ASMEDIA, PCI_PRODUCT_ASMEDIA_ASM1061_SATA,
+    NULL, ahci_vt8251_attach },
 
  { PCI_VENDOR_INTEL, PCI_PRODUCT_INTEL_6SERIES_AHCI_1,
     NULL, ahci_intel_attach },

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
On Sun, 2019-10-06 at 09:20 +1000, Jonathan Matthew wrote:

> On Fri, Oct 04, 2019 at 06:24:16PM -0400, [hidden email] wrote:
> >
> > >
> > > Synopsis: panic after ahci0: log page read failed, slot 31 was still active
> > > Category: kernel
> > > Environment:
> > System      : OpenBSD 6.6
> > Details     : OpenBSD 6.6-beta (GENERIC.MP) #245: Sat Sep 28 20:43:51 MDT 2019
> >  [hidden email]:/usr/src/sys/arch/arm64/compile/GENERIC.MP
> >
> > Architecture: OpenBSD.arm64
> > Machine     : arm64
> > >
> > > Description:
> > While building lang/rust received some ahci0 messages then a panic.
> > System is a RockPro64 with 4G memory. filesystem root is on uSD, the
> > rest of the paritions are on SSD (including swap).
> > >
> > > How-To-Repeat:
> > Not sure if reproducable yet. I was building lang/rust with
> > ulimit -Sd 4194304.
> > >
> > > Fix:
> > Unknown
> >
> >
> > ahci0: log page read failed, slot 31 was still active.
> > ahci0: device didn't come ready after reset, TFD: 0x84c1<BSY,ERR>
> > panic: uvm_fault failed: ffffff80003475b8
> So, the 'log page read' happens when there are multiple commands active and the
> port reports an error.  The log page read is supposed to tell us which command
> failed.  If that fails, we fail all active commands, and if the device won't
> reset after that, we shut the device off and all further io will fail.  If
> that's your swap device, and the system is swapping, you're kind of screwed.
>
> Perhaps disabling command queueing (which means there can only be one command
> in flight, so no need to read the log page on errors) might help?  The diff
> below should do that.  Checking the SSD out with smartctl is probably also a
> good idea at this point.
>
>
> diff --git sys/dev/pci/ahci_pci.c sys/dev/pci/ahci_pci.c
> index 79044b52dd5..f61ae96b0cf 100644
> --- sys/dev/pci/ahci_pci.c
> +++ sys/dev/pci/ahci_pci.c
> @@ -108,7 +108,8 @@ static const struct ahci_device ahci_devices[] = {
>   { PCI_VENDOR_ATI, PCI_PRODUCT_ATI_SBX00_SATA_6,
>       NULL, ahci_ati_sb700_attach },
>  
> - { PCI_VENDOR_ASMEDIA, PCI_PRODUCT_ASMEDIA_ASM1061_SATA },
> + { PCI_VENDOR_ASMEDIA, PCI_PRODUCT_ASMEDIA_ASM1061_SATA,
> +     NULL, ahci_vt8251_attach },
>  
>   { PCI_VENDOR_INTEL, PCI_PRODUCT_INTEL_6SERIES_AHCI_1,
>       NULL, ahci_intel_attach },
>

Thank you for the diff to test.

I noticed that I can easily reproduce the problem using sysupgrade.
>50% of the time the problem will trip there. My /home partition is
on the SSD, so it is reading and writing from it while installing
the sets. I also have reproduced the problem using bsd.rd and
using http for source of the sets with less frequency of tripping
the error. Seems like the ramdisk environment increases the chances
of tripping the issue. While running in multiuser bsd.mp it is
much more difficult to reproduce. I have only been able to trip
it one more time using fio with a random read/write test but lots
of heavy ports building use has not tripped the issue.

I applied your diff and built RAMDISK to test it. However, the
boot failed with this (full boot message later on):

root on rd0a swap on rd0b dump on rd0b
panic: cannot open disk, 0x1100/0x2f02, error 2
syncing disks... done

smartmontools seems to indicate the SSD isn't failing but
I'm not that familiar with the output:

smartctl -a /dev/sd0c 
smartctl 7.0 2018-12-30 r4883 [aarch64-unknown-openbsd6.6] (local build)
Copyright (C) 2002-18, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Samsung based SSDs
Device Model:     Samsung SSD 840 EVO 500GB
Serial Number:    S1DHNSAD921017A
LU WWN Device Id: 5 002538 8a003c28f
Firmware Version: EXT0BB0Q
User Capacity:    500,107,862,016 bytes [500 GB]
Sector Size:      512 bytes logical/physical
Rotation Rate:    Solid State Device
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ACS-2, ATA8-ACS T13/1699-D revision 4c
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Sun Oct  6 18:31:59 2019 EDT
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART Status not supported: Incomplete response, ATA output registers missing
SMART overall-health self-assessment test result: PASSED
Warning: This result is based on an Attribute check.

General SMART Values:
Offline data collection status:  (0x00) Offline data collection activity
                                        was never started.
                                        Auto Offline Data Collection: Disabled.
Self-test execution status:      (  32) The self-test routine was interrupted
                                        by the host with a hard or soft reset.
Total time to complete Offline 
data collection:                ( 6600) seconds.
Offline data collection
capabilities:                    (0x53) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        No Offline surface scan supported.
                                        Self-test supported.
                                        No Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine 
recommended polling time:        (   2) minutes.
Extended self-test routine
recommended polling time:        ( 110) minutes.
SCT capabilities:              (0x003d) SCT Status supported.
                                        SCT Error Recovery Control supported.
                                        SCT Feature Control supported.
                                        SCT Data Table supported.

SMART Attributes Data Structure revision number: 1
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  5 Reallocated_Sector_Ct   0x0033   100   100   010    Pre-fail  Always       -       0
  9 Power_On_Hours          0x0032   095   095   000    Old_age   Always       -       21750
 12 Power_Cycle_Count       0x0032   099   099   000    Old_age   Always       -       399
177 Wear_Leveling_Count     0x0013   098   098   000    Pre-fail  Always       -       16
179 Used_Rsvd_Blk_Cnt_Tot   0x0013   100   100   010    Pre-fail  Always       -       0
181 Program_Fail_Cnt_Total  0x0032   100   100   010    Old_age   Always       -       0
182 Erase_Fail_Count_Total  0x0032   100   100   010    Old_age   Always       -       0
183 Runtime_Bad_Block       0x0013   100   100   010    Pre-fail  Always       -       0
187 Uncorrectable_Error_Cnt 0x0032   100   100   000    Old_age   Always       -       0
190 Airflow_Temperature_Cel 0x0032   075   054   000    Old_age   Always       -       25
195 ECC_Error_Rate          0x001a   200   200   000    Old_age   Always       -       0
199 CRC_Error_Count         0x003e   099   099   000    Old_age   Always       -       13
235 POR_Recovery_Count      0x0012   099   099   000    Old_age   Always       -       154
241 Total_LBAs_Written      0x0032   099   099   000    Old_age   Always       -       21761092635

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Short offline       Interrupted (host reset)      00%         0         -

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

Full boot messages with diff applied to bsd.rd:

U-Boot SPL 2019.10-rc4 (Oct 03 2019 - 19:40:31 -0400)
Trying to boot from MMC1
NOTICE:  BL31: v2.1(debug):2.1
NOTICE:  BL31: Built : 10:16:34, Sep 27 2019
INFO:    GICv3 with legacy support detected. ARM GICV3 driver initialized in EL3
INFO:    plat_rockchip_pmu_init(1596): pd status 3e
INFO:    BL31: Initializing runtime services
WARNING: BL31: cortex_a53: CPU workaround for 819472 was missing!
WARNING: BL31: cortex_a53: CPU workaround for 824069 was missing!
WARNING: BL31: cortex_a53: CPU workaround for 827319 was missing!
INFO:    BL31: cortex_a53: CPU workaround for 855873 was applied
INFO:    BL31: Preparing for EL3 exit to normal world
INFO:    Entry point address = 0x200000
INFO:    SPSR = 0x3c9


U-Boot 2019.10-rc4 (Oct 03 2019 - 19:40:31 -0400)

Model: Pine64 RockPro64
DRAM:  3.9 GiB
MMC:   dwmmc@fe320000: 1, sdhci@fe330000: 0
Loading Environment from MMC... Card did not respond to voltage select!
*** Warning - No block device, using default environment

In:    serial@ff1a0000
Out:   serial@ff1a0000
Err:   serial@ff1a0000
Model: Pine64 RockPro64
rockchip_dnl_key_pressed: adc_channel_single_shot fail!
Net:   eth0: ethernet@fe300000
Hit any key to stop autoboot:  0 
Card did not respond to voltage select!
switch to partitions #0, OK
mmc1 is current device
Scanning mmc 1:1...
Found EFI removable media binary efi/boot/bootaa64.efi
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
Scanning disk [hidden email]...
Card did not respond to voltage select!
Scanning disk [hidden email]...
Disk [hidden email] not ready
Found 3 disks
BootOrder not defined
EFI boot manager: Cannot load any image
161090 bytes read in 46 ms (3.3 MiB/s)
libfdt fdt_check_header(): FDT_ERR_BADMAGIC
disks: sd0*
>> OpenBSD/arm64 BOOTAA64 0.19
boot> bsd.rd
booting sd0a:bsd.rd: 2224220+622316+8769504+739568 [221760+109+519552+200640]=0xff7c80
type 0x2 pa 0x200000 va 0x200000 pages 0x4000 attr 0x8
type 0x7 pa 0x4200000 va 0x4200000 pages 0x3eec attr 0x8
type 0x4 pa 0x80ec000 va 0x80ec000 pages 0x28 attr 0x8
type 0x7 pa 0x8114000 va 0x8114000 pages 0xec099 attr 0x8
type 0x2 pa 0xf41ad000 va 0xf41ad000 pages 0xc3b attr 0x8
type 0x4 pa 0xf4de8000 va 0xf4de8000 pages 0x1 attr 0x8
type 0x2 pa 0xf4de9000 va 0xf4de9000 pages 0x3 attr 0x8
type 0x7 pa 0xf4dec000 va 0xf4dec000 pages 0x1 attr 0x8
type 0x2 pa 0xf4ded000 va 0xf4ded000 pages 0x100 attr 0x8
type 0x1 pa 0xf4eed000 va 0xf4eed000 pages 0x28 attr 0x8
type 0x0 pa 0xf4f15000 va 0xf4f15000 pages 0x7 attr 0x8
type 0x4 pa 0xf4f1c000 va 0xf4f1c000 pages 0x1 attr 0x8
type 0x6 pa 0xf4f1d000 va 0x8cb8de000 pages 0x1 attr 0x8000000000000008
type 0x4 pa 0xf4f1e000 va 0xf4f1e000 pages 0x2 attr 0x8
type 0x0 pa 0xf4f20000 va 0xf4f20000 pages 0x4 attr 0x8
type 0x4 pa 0xf4f24000 va 0xf4f24000 pages 0x2 attr 0x8
type 0x6 pa 0xf4f26000 va 0x8cb8e7000 pages 0x1 attr 0x8000000000000008
type 0x2 pa 0xf4f27000 va 0xf4f27000 pages 0x3019 attr 0x8
type 0x5 pa 0xf7f40000 va 0x8ce901000 pages 0x10 attr 0x8000000000000008
type 0x2 pa 0xf7f50000 va 0xf7f50000 pages 0xb0 attr 0x8
Copyright (c) 1982, 1986, 1989, 1991, 1993
        The Regents of the University of California.  All rights reserved.
Copyright (c) 1995-2019 OpenBSD. All rights reserved.  https://www.OpenBSD.org

OpenBSD 6.6 (RAMDISK) #1: Sun Oct  6 19:02:29 EDT 2019
    [hidden email]:/sys/arch/arm64/compile/RAMDISK
real mem  = 4093136896 (3903MB)
avail mem = 3891367936 (3711MB)
mainbus0 at root: Pine64 RockPro64
cpu0 at mainbus0 mpidr 0: ARM Cortex-A53 r0p4
cpu0: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu0: 512KB 64b/line 16-way L2 cache
efi0 at mainbus0: UEFI 2.8
efi0: Das U-Boot rev 0x20191000
psci0 at mainbus0: PSCI 1.1, SMCCC 1.1
agintc0 at mainbus0 sec shift 3:3 nirq 288 nredist 6: "interrupt-controller"
agintcmsi0 at agintc0
syscon0 at mainbus0: "qos"
syscon1 at mainbus0: "qos"
syscon2 at mainbus0: "qos"
syscon3 at mainbus0: "qos"
syscon4 at mainbus0: "qos"
syscon5 at mainbus0: "qos"
syscon6 at mainbus0: "qos"
syscon7 at mainbus0: "qos"
syscon8 at mainbus0: "qos"
syscon9 at mainbus0: "qos"
syscon10 at mainbus0: "qos"
syscon11 at mainbus0: "qos"
syscon12 at mainbus0: "qos"
syscon13 at mainbus0: "qos"
syscon14 at mainbus0: "qos"
syscon15 at mainbus0: "qos"
syscon16 at mainbus0: "qos"
syscon17 at mainbus0: "qos"
syscon18 at mainbus0: "qos"
syscon19 at mainbus0: "qos"
syscon20 at mainbus0: "qos"
syscon21 at mainbus0: "qos"
syscon22 at mainbus0: "qos"
syscon23 at mainbus0: "qos"
syscon24 at mainbus0: "qos"
syscon25 at mainbus0: "power-management"
"power-controller" at syscon25 not configured
syscon26 at mainbus0: "syscon"
"io-domains" at syscon26 not configured
syscon27 at mainbus0: "syscon"
syscon28 at mainbus0: "syscon"
rkclock0 at mainbus0
rkclock1 at mainbus0
syscon29 at mainbus0: "syscon"
"io-domains" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"phy" at syscon29 not configured
"pcie-phy" at syscon29 not configured
rkpinctrl0 at mainbus0: "pinctrl"
rkgpio0 at rkpinctrl0
rkgpio1 at rkpinctrl0
rkgpio2 at rkpinctrl0
rkgpio3 at rkpinctrl0
rkgpio4 at rkpinctrl0
"fit-images" at mainbus0 not configured
"pmu_a53" at mainbus0 not configured
"pmu_a72" at mainbus0 not configured
agtimer0 at mainbus0: tick rate 24000 KHz
"xin24m" at mainbus0 not configured
simplebus0 at mainbus0: "amba"
"dma-controller" at simplebus0 not configured
"dma-controller" at simplebus0 not configured
rkpcie0 at mainbus0
pci0 at rkpcie0
ppb0 at pci0 dev 0 function 0 "Rockchip RK3399 Root Complex" rev 0x00: msi
pci1 at ppb0 bus 1
ahci0 at pci1 dev 0 function 0 "ASMedia ASM1061 AHCI" rev 0x01: msi, AHCI 1.2
ahci0: port 1: 6.0Gb/s
scsibus0 at ahci0: 32 targets
sd0 at scsibus0 targ 1 lun 0: <ATA, Samsung SSD 840, EXT0> naa.50025388a003c28f
sd0: 476940MB, 512 bytes/sector, 976773168 sectors, thin
dwge0 at mainbus0: address 12:e7:22:42:f7:96
rgephy0 at dwge0 phy 0: RTL8169S/8110S/8211 PHY, rev. 6
dwmmc0 at mainbus0: 50 MHz base clock
sdmmc0 at dwmmc0: 4-bit, sd high-speed, mmc high-speed, dma
sdhc0 at mainbus0
sdhc0: SDHC 3.0, 200 MHz base clock
sdmmc1 at sdhc0: 8-bit, sd high-speed, mmc high-speed, dma
ehci0 at mainbus0
usb0 at ehci0: USB revision 2.0
uhub0 at usb0 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00 addr 1
ohci0 at mainbus0: version 1.0
ehci1 at mainbus0
usb1 at ehci1: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00 addr 1
ohci1 at mainbus0: version 1.0
rkdwusb0 at mainbus0: "usb"
xhci0 at rkdwusb0, xHCI 1.10
usb2 at xhci0: USB revision 3.0
uhub2 at usb2 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00 addr 1
rkdwusb1 at mainbus0: "usb"
xhci1 at rkdwusb1, xHCI 1.10
usb3 at xhci1: USB revision 3.0
uhub3 at usb3 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00 addr 1
"saradc" at mainbus0 not configured
rkiic0 at mainbus0
iic0 at rkiic0
rkiic1 at mainbus0
iic1 at rkiic1
com0 at mainbus0: ns16550, no working fifo
com1 at mainbus0: ns16550, no working fifo
com1: console
"thermal-zones" at mainbus0 not configured
"tsadc" at mainbus0 not configured
rkiic2 at mainbus0
iic2 at rkiic2
rkpmic0 at iic2 addr 0x1b: RK808
"silergy,syr827" at iic2 addr 0x40 not configured
"silergy,syr828" at iic2 addr 0x41 not configured
rkiic3 at mainbus0
iic3 at rkiic3
fusbtc0 at iic3 addr 0x22
"pwm" at mainbus0 not configured
"pwm" at mainbus0 not configured
"dmc" at mainbus0 not configured
"efuse" at mainbus0 not configured
"phy" at mainbus0 not configured
"phy" at mainbus0 not configured
"watchdog" at mainbus0 not configured
"rktimer" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"hdmi-sound" at mainbus0 not configured
"hdmi" at mainbus0 not configured
"gpu" at mainbus0 not configured
"opp-table0" at mainbus0 not configured
"opp-table1" at mainbus0 not configured
"opp-table2" at mainbus0 not configured
"external-gmac-clock" at mainbus0 not configured
"gpio-keys" at mainbus0 not configured
"leds" at mainbus0 not configured
"sdio-pwrseq" at mainbus0 not configured
"vcc12v-dcin" at mainbus0 not configured
"vcc1v8-s3" at mainbus0 not configured
"vcc3v3-pcie-regulator" at mainbus0 not configured
"vcc3v3-sys" at mainbus0 not configured
"vcc5v0-host-regulator" at mainbus0 not configured
"vcc5v0-typec-regulator" at mainbus0 not configured
"vcc5v0-sys" at mainbus0 not configured
"vcc5v0-usb" at mainbus0 not configured
"vdd-log" at mainbus0 not configured
usb4 at ohci0: USB revision 1.0
uhub4 at usb4 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00 addr 1
usb5 at ohci1: USB revision 1.0
uhub5 at usb5 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00 addr 1
scsibus1 at sdmmc0: 2 targets, initiator 0
sd1 at scsibus1 targ 1 lun 0: <SD/MMC, SD16G, 0020> removable
sd1: 29862MB, 512 bytes/sector, 61157376 sectors
sdmmc1: can't enable card
softraid0 at root
scsibus2 at softraid0: 256 targets
bootfile: sd0a:bsd.rd
boot device: sd0
root on rd0a swap on rd0b dump on rd0b
panic: cannot open disk, 0x1100/0x2f02, error 2
syncing disks... done

dump to dev 17,1 not possible
rebooting...

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Theo de Raadt-2
> I applied your diff and built RAMDISK to test it. However, the
> boot failed with this (full boot message later on):
>
> root on rd0a swap on rd0b dump on rd0b
> panic: cannot open disk, 0x1100/0x2f02, error 2

I believe your bsd.rd has no ramdisk filesystem inside it.

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
On Sun, 2019-10-06 at 17:47 -0600, Theo de Raadt wrote:
> >
> > I applied your diff and built RAMDISK to test it. However, the
> > boot failed with this (full boot message later on):
> >
> > root on rd0a swap on rd0b dump on rd0b
> > panic: cannot open disk, 0x1100/0x2f02, error 2
> I believe your bsd.rd has no ramdisk filesystem inside it.
>

You are correct, thank you. bsd.mp booted fine. I'll make
a proper bsd.rd and report back results of testing install
with it.

-Kurt

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
On Sun, 2019-10-06 at 20:01 -0400, Kurt Miller wrote:

> On Sun, 2019-10-06 at 17:47 -0600, Theo de Raadt wrote:
> >
> > >
> > >
> > > I applied your diff and built RAMDISK to test it. However, the
> > > boot failed with this (full boot message later on):
> > >
> > > root on rd0a swap on rd0b dump on rd0b
> > > panic: cannot open disk, 0x1100/0x2f02, error 2
> > I believe your bsd.rd has no ramdisk filesystem inside it.
> >
> You are correct, thank you. bsd.mp booted fine. I'll make
> a proper bsd.rd and report back results of testing install
> with it.

I completed 5 bsd.rd upgrades off /mnt/home/_sysupgrade
without issue and performed a series of fio tests also
without issue. The bsd.rd upgrades would not have survived
2 in a row prior to your change.

Disabling command queueing is looking like it stabilized
the card for me. I haven't noticed a drop in performance
either in an unscientific comparison to numbers I jotted
down on Sep 23.

Thank you for the quick fix.

-Kurt

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Theo de Raadt-2
Kurt Miller <[hidden email]> wrote:

> On Sun, 2019-10-06 at 20:01 -0400, Kurt Miller wrote:
> > On Sun, 2019-10-06 at 17:47 -0600, Theo de Raadt wrote:
> > >
> > > >
> > > >
> > > > I applied your diff and built RAMDISK to test it. However, the
> > > > boot failed with this (full boot message later on):
> > > >
> > > > root on rd0a swap on rd0b dump on rd0b
> > > > panic: cannot open disk, 0x1100/0x2f02, error 2
> > > I believe your bsd.rd has no ramdisk filesystem inside it.
> > >
> > You are correct, thank you. bsd.mp booted fine. I'll make
> > a proper bsd.rd and report back results of testing install
> > with it.
>
> I completed 5 bsd.rd upgrades off /mnt/home/_sysupgrade
> without issue and performed a series of fio tests also
> without issue. The bsd.rd upgrades would not have survived
> 2 in a row prior to your change.
>
> Disabling command queueing is looking like it stabilized
> the card for me. I haven't noticed a drop in performance
> either in an unscientific comparison to numbers I jotted
> down on Sep 23.
>
> Thank you for the quick fix.

I think that cynical workaround is fine for release, it probably
affects other people with this ahci block (which has a bad reputation
in other forums)

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
On Sun, 2019-10-06 at 19:23 -0600, Theo de Raadt wrote:

> Kurt Miller <[hidden email]> wrote:
>
> >
> > On Sun, 2019-10-06 at 20:01 -0400, Kurt Miller wrote:
> > >
> > > On Sun, 2019-10-06 at 17:47 -0600, Theo de Raadt wrote:
> > > >
> > > >
> > > > >
> > > > >
> > > > >
> > > > > I applied your diff and built RAMDISK to test it. However, the
> > > > > boot failed with this (full boot message later on):
> > > > >
> > > > > root on rd0a swap on rd0b dump on rd0b
> > > > > panic: cannot open disk, 0x1100/0x2f02, error 2
> > > > I believe your bsd.rd has no ramdisk filesystem inside it.
> > > >
> > > You are correct, thank you. bsd.mp booted fine. I'll make
> > > a proper bsd.rd and report back results of testing install
> > > with it.
> > I completed 5 bsd.rd upgrades off /mnt/home/_sysupgrade
> > without issue and performed a series of fio tests also
> > without issue. The bsd.rd upgrades would not have survived
> > 2 in a row prior to your change.
> >
> > Disabling command queueing is looking like it stabilized
> > the card for me. I haven't noticed a drop in performance
> > either in an unscientific comparison to numbers I jotted
> > down on Sep 23.
> >
> > Thank you for the quick fix.
> I think that cynical workaround is fine for release, it probably
> affects other people with this ahci block (which has a bad reputation
> in other forums)
>

I hit the issue again using the latest snapshot which
includes the work-around.

ahci0: log page read failed, slot 31 was still active.
ahci0: stopping the port, softreset slot 31 was still active.
ahci0: failed to reset port during timeout handling, disabling it

No panic this time.

The work-around helped with stability in the RAMDISK env where
it was very unstable. Perhaps it is still a good idea.

-Kurt

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-4
On Mon, 2019-10-07 at 13:15 -0400, Kurt Miller wrote:

> On Sun, 2019-10-06 at 19:23 -0600, Theo de Raadt wrote:
> >
> > Kurt Miller <[hidden email]> wrote:
> >
> > >
> > >
> > > On Sun, 2019-10-06 at 20:01 -0400, Kurt Miller wrote:
> > > >
> > > >
> > > > On Sun, 2019-10-06 at 17:47 -0600, Theo de Raadt wrote:
> > > > >
> > > > >
> > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > I applied your diff and built RAMDISK to test it. However, the
> > > > > > boot failed with this (full boot message later on):
> > > > > >
> > > > > > root on rd0a swap on rd0b dump on rd0b
> > > > > > panic: cannot open disk, 0x1100/0x2f02, error 2
> > > > > I believe your bsd.rd has no ramdisk filesystem inside it.
> > > > >
> > > > You are correct, thank you. bsd.mp booted fine. I'll make
> > > > a proper bsd.rd and report back results of testing install
> > > > with it.
> > > I completed 5 bsd.rd upgrades off /mnt/home/_sysupgrade
> > > without issue and performed a series of fio tests also
> > > without issue. The bsd.rd upgrades would not have survived
> > > 2 in a row prior to your change.
> > >
> > > Disabling command queueing is looking like it stabilized
> > > the card for me. I haven't noticed a drop in performance
> > > either in an unscientific comparison to numbers I jotted
> > > down on Sep 23.
> > >
> > > Thank you for the quick fix.
> > I think that cynical workaround is fine for release, it probably
> > affects other people with this ahci block (which has a bad reputation
> > in other forums)
> >
> I hit the issue again using the latest snapshot which
> includes the work-around.
>
> ahci0: log page read failed, slot 31 was still active.
> ahci0: stopping the port, softreset slot 31 was still active.
> ahci0: failed to reset port during timeout handling, disabling it
>
> No panic this time.
>
> The work-around helped with stability in the RAMDISK env where
> it was very unstable. Perhaps it is still a good idea.
>

This time I got a panic so perhaps there's something helpful
in the info below. I had 2x rm -rf on some larger directories
going at the time of this panic:

ahci0: log page read failed, slot 31 was still active.           
panic: uvm_fault failed: ffffff80002b4628
Stopped at      panic+0x150:        TID    PID    UID     PRFLAGS     PFLAGS  C
PU  COMMAND
db_enter() at panic+0x14c
panic() at $x.0+0x6c
$x.0() at ahci_port_softreset+0x104
ahci_port_softreset() at ahci_ata_cmd_timeout+0xc4
ahci_ata_cmd_timeout() at softclock+0x130
softclock() at softintr_biglock_wrap+0x1c
softintr_biglock_wrap() at softintr_dispatch+0x9c
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports.  Insufficient info makes it difficult to find and fix bugs.
ddb{0}> bt
db_enter() at panic+0x14c
panic() at $x.0+0x6c
$x.0() at ahci_port_softreset+0x104
ahci_port_softreset() at ahci_ata_cmd_timeout+0xc4
ahci_ata_cmd_timeout() at softclock+0x130
softclock() at softintr_biglock_wrap+0x1c
softintr_biglock_wrap() at softintr_dispatch+0x9c
softintr_dispatch() at arm_do_pending_intr+0xe0
arm_do_pending_intr() at agintc_irq_handler+0x278
agintc_irq_handler() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{0}> trace          
db_enter() at panic+0x14c
panic() at $x.0+0x6c
$x.0() at ahci_port_softreset+0x104
ahci_port_softreset() at ahci_ata_cmd_timeout+0xc4
ahci_ata_cmd_timeout() at softclock+0x130
softclock() at softintr_biglock_wrap+0x1c
softintr_biglock_wrap() at softintr_dispatch+0x9c
softintr_dispatch() at arm_do_pending_intr+0xe0
arm_do_pending_intr() at agintc_irq_handler+0x278
agintc_irq_handler() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{0}> machine ddbcpu 1
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{1}> trace
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{1}> machine ddbcpu 2
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{2}> trace
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{2}> machine ddbcp 3
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{3}> trace
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{3}> machine ddbcpu 4
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{4}> bt
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{4}> machine ddbcpu 5
Stopped at      agintc_ipi_ddb+0x1c:    db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{5}> trace
db_enter() at agintc_ipi_ddb+0x18
agintc_ipi_ddb() at arm_cpu_intr+0x30
arm_cpu_intr() at handle_el1h_irq+0x6c
handle_el1h_irq() at sched_idle+0x220
sched_idle() at proc_trampoline+0x10
ddb{5}> ps /o
    TID    PID    UID     PRFLAGS     PFLAGS  CPU  COMMAND
ddb{5}> ps 
   PID     TID   PPID    UID  S       FLAGS  WAIT          COMMAND
 36475  461032  41749   1000  3    0x100003  inode         ls
 52713  175583  41749      0  3    0x100003  biowait       rm
 10482  317217  41749      0  3    0x100003  biowait       rm
 41749  113421  24283   1000  3    0x10008b  pause         ksh
 24283   13517  89760   1000  3        0x90  select        sshd
 89760   75825  17053      0  3        0x92  poll          sshd
 84258   33546      1      0  3    0x100083  ttyin         ksh
 76357  432527      1      0  3    0x100098  poll          cron
 79562  239967      1     99  3    0x100090  poll          sndiod
 66858   49310      1    110  3    0x100090  poll          sndiod
 75045  271937  18580     95  3    0x100092  kqread        smtpd
 43519  395288  18580    103  3    0x100092  kqread        smtpd
 56090  418933  18580     95  3    0x100092  kqread        smtpd
 99024  370275  18580     95  3    0x100092  kqread        smtpd
 88978  455206  18580     95  3    0x100092  kqread        smtpd
 73147   64226  18580     95  3    0x100092  kqread        smtpd
 18580   27418      1      0  3    0x100080  kqread        smtpd
 17053  452596      1      0  3        0x80  select        sshd
  1697  131255      1      0  3    0x100080  poll          ntpd
 95614   56344  22050     83  3    0x100092  poll          ntpd
 22050  224947      1     83  3    0x100092  poll          ntpd
  5584  175979  42164     74  3    0x100092  bpf           pflogd
 42164  168512      1      0  3        0x80  netio         pflogd
 75784   23156  24896     73  3    0x100010  ffs_fsync     syslogd
 24896  236518      1      0  3    0x100082  netio         syslogd
 17545  494366      1     77  3    0x100090  poll          dhclient
 90523  330978      1      0  3        0x80  poll          dhclient
 51002   28152  34215    115  3    0x100092  kqread        slaacd
 45308  447710  34215    115  3    0x100092  kqread        slaacd
 34215  288252      1      0  3    0x100080  kqread        slaacd
 29951  158156      0      0  3     0x14200  pgzero        zerothread
  6723  366506      0      0  3     0x14200  aiodoned      aiodoned
 48695  474648      0      0  3     0x14200  bqwait        update
 74435  163002      0      0  3     0x14200  cleaner       cleaner
  2088  272467      0      0  3     0x14200  reaper        reaper
 74842  392793      0      0  3     0x14200  pgdaemon      pagedaemon
 45636  161139      0      0  3     0x14200  bored         crynlk
 37512   15756      0      0  3     0x14200  bored         crypto
 11342   37970      0      0  3     0x14200  bored         tztq
*20523  252715      0      0  7  0x40014200                idle5
 82218  153747      0      0  7  0x40014200                idle4
 90923   75218      0      0  7  0x40014200                idle3
 92620  362709      0      0  7  0x40014200                idle2
 44453  517988      0      0  7  0x40014200                idle1
 52190  332617      0      0  3     0x14200  bored         sensors
 16085  331753      0      0  3     0x14200  usbtsk        usbtask
 96363  218165      0      0  3     0x14200  usbatsk       usbatsk
 79032  522320      0      0  3     0x14200  mmctsk        sdmmc1
 92309  486467      0      0  3     0x14200  mmctsk        sdmmc0
 66781  357474      0      0  2     0x14200                softnet
 32037  254087      0      0  3     0x14200  bored         systqmp
 85348    4219      0      0  3     0x14200  bored         systq
 25652  481708      0      0  3  0x40014200  bored         softclock
 76554  183769      0      0  7  0x40014200                idle0
 15035  498790      0      0  3     0x14200  bored         smr
 82235  383808      0      0  3     0x14200  kmalloc       kmthread
     1  176461      0      0  3        0x82  wait          init
     0       0     -1      0  3     0x10200  scheduler     swapper
ddb{5}> show uvm
Current UVM status:
  pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
  961557 VM pages: 6093 active, 51173 inactive, 0 wired, 781467 free (97687 zer
o)
  min  10% (25) anon, 10% (25) vnode, 5% (12) vtext
  freemin=32051, free-target=42734, inactive-target=0, wired-max=320519
  faults=1769238, traps=0, intrs=0, ctxswitch=1526473 fpuswitch=0
  softint=56745, syscalls=990596, kmapent=14
  fault counts:
    noram=0, noanon=0, noamap=0, pgwait=0, pgrele=0
    ok relocks(total)=76263(76440), anget(retries)=1534607(0), amapcopy=65572
    neighbor anon/obj pg=4435/63903, gets(lock/unlock)=133427/76440
    cases: anon=1524599, anoncow=10008, obj=129456, prcopy=3794, przero=101380
  daemon and swap counts:
    woke=0, revs=0, scans=0, obscans=0, anscans=0
    busy=0, freed=0, reactivate=0, deactivate=0
    pageouts=0, pending=0, nswget=0
    nswapdev=1
    swpages=1050088, swpginuse=0, swpgonly=0 paging=0
  kernel pointers:
    objs(kern)=0xffffff8000cac3c0
ddb{5}> show bcstats
Current Buffer Cache status:
numbufs 23731 busymapped 128, delwri 143
kvaslots 12019 avail kva slots 11891
bufpages 100112, dmapages 100112, dirtypages 1140
pendingreads 2, pendingwrites 126
highflips 0, highflops 0, dmaflips 0
ddb{5}> dmesg
OpenBSD 6.6 (GENERIC.MP) #261: Sun Oct  6 23:03:15 MDT 2019
    [hidden email]:/usr/src/sys/arch/arm64/compile/GENERIC.MP
real mem  = 4094251008 (3904MB)
avail mem = 3895128064 (3714MB)
mainbus0 at root: Pine64 RockPro64
cpu0 at mainbus0 mpidr 0: ARM Cortex-A53 r0p4
cpu0: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu0: 512KB 64b/line 16-way L2 cache
efi0 at mainbus0: UEFI 2.8
efi0: Das U-Boot rev 0x20191000
apm0 at mainbus0
psci0 at mainbus0: PSCI 1.1, SMCCC 1.1
agintc0 at mainbus0 sec shift 3:3 nirq 288 nredist 6 ipi: 0, 1: "interrupt-cont
roller"
agintcmsi0 at agintc0
syscon0 at mainbus0: "qos"
syscon1 at mainbus0: "qos"
syscon2 at mainbus0: "qos"
syscon3 at mainbus0: "qos"
syscon4 at mainbus0: "qos"
syscon5 at mainbus0: "qos"
syscon6 at mainbus0: "qos"
syscon7 at mainbus0: "qos"
syscon8 at mainbus0: "qos"
syscon9 at mainbus0: "qos"
syscon10 at mainbus0: "qos"
syscon11 at mainbus0: "qos"
syscon12 at mainbus0: "qos"
syscon13 at mainbus0: "qos"
syscon14 at mainbus0: "qos"
syscon15 at mainbus0: "qos"
syscon16 at mainbus0: "qos"
syscon17 at mainbus0: "qos"
syscon18 at mainbus0: "qos"
syscon19 at mainbus0: "qos"
syscon20 at mainbus0: "qos"
syscon21 at mainbus0: "qos"
syscon22 at mainbus0: "qos"
syscon23 at mainbus0: "qos"
syscon24 at mainbus0: "qos"
syscon25 at mainbus0: "power-management"
"power-controller" at syscon25 not configured
syscon26 at mainbus0: "syscon"
"io-domains" at syscon26 not configured
syscon27 at mainbus0: "syscon"
syscon28 at mainbus0: "syscon"
rkclock0 at mainbus0
rkclock1 at mainbus0
syscon29 at mainbus0: "syscon"
"io-domains" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"usb2-phy" at syscon29 not configured
"phy" at syscon29 not configured
"pcie-phy" at syscon29 not configured
rkpinctrl0 at mainbus0: "pinctrl"
rkgpio0 at rkpinctrl0
rkgpio1 at rkpinctrl0
rkgpio2 at rkpinctrl0
rkgpio3 at rkpinctrl0
rkgpio4 at rkpinctrl0
pwmreg0 at mainbus0
"fit-images" at mainbus0 not configured
"pmu_a53" at mainbus0 not configured
"pmu_a72" at mainbus0 not configured
agtimer0 at mainbus0: tick rate 24000 KHz
"xin24m" at mainbus0 not configured
simplebus0 at mainbus0: "amba"
"dma-controller" at simplebus0 not configured
"dma-controller" at simplebus0 not configured
rkpcie0 at mainbus0
pci0 at rkpcie0
ppb0 at pci0 dev 0 function 0 "Rockchip RK3399 Root Complex" rev 0x00: msi
pci1 at ppb0 bus 1
ahci0 at pci1 dev 0 function 0 "ASMedia ASM1061 AHCI" rev 0x01: msi, AHCI 1.2
ahci0: port 1: 6.0Gb/s
scsibus0 at ahci0: 32 targets
sd0 at scsibus0 targ 1 lun 0: <ATA, Samsung SSD 840, EXT0> naa.50025388a003c28f

sd0: 476940MB, 512 bytes/sector, 976773168 sectors, thin
dwge0 at mainbus0: address 12:e7:22:42:f7:96
rgephy0 at dwge0 phy 0: RTL8169S/8110S/8211 PHY, rev. 6
dwmmc0 at mainbus0: 50 MHz base clock
sdmmc0 at dwmmc0: 4-bit, sd high-speed, mmc high-speed, dma
sdhc0 at mainbus0
sdhc0: SDHC 3.0, 200 MHz base clock
sdmmc1 at sdhc0: 8-bit, sd high-speed, mmc high-speed, dma
ehci0 at mainbus0
usb0 at ehci0: USB revision 2.0
uhub0 at usb0 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00
 addr 1
ohci0 at mainbus0: version 1.0
ehci1 at mainbus0
usb1 at ehci1: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Generic EHCI root hub" rev 2.00/1.00
 addr 1
ohci1 at mainbus0: version 1.0
rkdwusb0 at mainbus0: "usb"
xhci0 at rkdwusb0, xHCI 1.10
usb2 at xhci0: USB revision 3.0
uhub2 at usb2 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00
 addr 1
rkdwusb1 at mainbus0: "usb"
xhci1 at rkdwusb1, xHCI 1.10
usb3 at xhci1: USB revision 3.0
uhub3 at usb3 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00
 addr 1
"saradc" at mainbus0 not configured
rkiic0 at mainbus0
iic0 at rkiic0
rkiic1 at mainbus0
iic1 at rkiic1
com0 at mainbus0: ns16550, no working fifo
com1 at mainbus0: ns16550, no working fifo
com1: console
"thermal-zones" at mainbus0 not configured
rktemp0 at mainbus0
rkiic2 at mainbus0
iic2 at rkiic2
rkpmic0 at iic2 addr 0x1b: RK808
fanpwr0 at iic2 addr 0x40: SYR827, 1.00 VDC
fanpwr1 at iic2 addr 0x41: SYR828, 1.00 VDC
rkiic3 at mainbus0
iic3 at rkiic3
fusbtc0 at iic3 addr 0x22
"pwm" at mainbus0 not configured
"pwm" at mainbus0 not configured
"dmc" at mainbus0 not configured
"efuse" at mainbus0 not configured
"phy" at mainbus0 not configured
"phy" at mainbus0 not configured
"watchdog" at mainbus0 not configured
"rktimer" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"i2s" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"vop" at mainbus0 not configured
"iommu" at mainbus0 not configured
"hdmi-sound" at mainbus0 not configured
"hdmi" at mainbus0 not configured
"gpu" at mainbus0 not configured
"opp-table0" at mainbus0 not configured
"opp-table1" at mainbus0 not configured
"opp-table2" at mainbus0 not configured
"external-gmac-clock" at mainbus0 not configured
"gpio-keys" at mainbus0 not configured
"leds" at mainbus0 not configured
"sdio-pwrseq" at mainbus0 not configured
"vcc12v-dcin" at mainbus0 not configured
"vcc1v8-s3" at mainbus0 not configured
"vcc3v3-pcie-regulator" at mainbus0 not configured
"vcc3v3-sys" at mainbus0 not configured
"vcc5v0-host-regulator" at mainbus0 not configured
"vcc5v0-typec-regulator" at mainbus0 not configured
"vcc5v0-sys" at mainbus0 not configured
"vcc5v0-usb" at mainbus0 not configured
cpu1 at mainbus0 mpidr 1: ARM Cortex-A53 r0p4
cpu1: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu1: 512KB 64b/line 16-way L2 cache
cpu2 at mainbus0 mpidr 2: ARM Cortex-A53 r0p4
cpu2: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu2: 512KB 64b/line 16-way L2 cache
cpu3 at mainbus0 mpidr 3: ARM Cortex-A53 r0p4
cpu3: 32KB 64b/line 2-way L1 VIPT I-cache, 32KB 64b/line 4-way L1 D-cache
cpu3: 512KB 64b/line 16-way L2 cache
cpu4 at mainbus0 mpidr 100: ARM Cortex-A72 r0p2
cpu4: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu4: 1024KB 64b/line 16-way L2 cache
cpu5 at mainbus0 mpidr 101: ARM Cortex-A72 r0p2
cpu5: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu5: 1024KB 64b/line 16-way L2 cache
usb4 at ohci0: USB revision 1.0
uhub4 at usb4 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00
 addr 1
usb5 at ohci1: USB revision 1.0
uhub5 at usb5 configuration 1 interface 0 "Generic OHCI root hub" rev 1.00/1.00
 addr 1
scsibus1 at sdmmc0: 2 targets, initiator 0
sd1 at scsibus1 targ 1 lun 0: <SD/MMC, SD16G, 0020> removable
sd1: 29862MB, 512 bytes/sector, 61157376 sectors
sdmmc1: can't enable card
vscsi0 at root
scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
bootfile: sd0a:/bsd
boot device: sd0
root on sd1a (4cbb6909064a3cdc.a) swap on sd1b dump on sd1b

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Jonathan Matthew-4
On Mon, Oct 07, 2019 at 01:30:52PM -0400, Kurt Miller wrote:

> > I hit the issue again using the latest snapshot which
> > includes the work-around.
> >
> > ahci0: log page read failed, slot 31 was still active.
> > ahci0: stopping the port, softreset slot 31 was still active.
> > ahci0: failed to reset port during timeout handling, disabling it
> >
> > No panic this time.
> >
> > The work-around helped with stability in the RAMDISK env where
> > it was very unstable. Perhaps it is still a good idea.
> >
>
> This time I got a panic so perhaps there's something helpful
> in the info below. I had 2x rm -rf on some larger directories
> going at the time of this panic:

I've been running a similar load on a desktop pc (amd64), copying and deleting
ports trees, 4 in parallel, ~4k iops on average, on a SATA SSD through an
ASM1061 card (looks exactly the same as the one in the pine64 store) for
around a day with no problems at all.  Is it possible this is actually a
power problem?  How are you powering the board and the SSD?

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
On Fri, 2019-10-11 at 10:21 +1000, Jonathan Matthew wrote:

> On Mon, Oct 07, 2019 at 01:30:52PM -0400, Kurt Miller wrote:
> >
> > >
> > > I hit the issue again using the latest snapshot which
> > > includes the work-around.
> > >
> > > ahci0: log page read failed, slot 31 was still active.
> > > ahci0: stopping the port, softreset slot 31 was still active.
> > > ahci0: failed to reset port during timeout handling, disabling it
> > >
> > > No panic this time.
> > >
> > > The work-around helped with stability in the RAMDISK env where
> > > it was very unstable. Perhaps it is still a good idea.
> > >
> > This time I got a panic so perhaps there's something helpful
> > in the info below. I had 2x rm -rf on some larger directories
> > going at the time of this panic:
> I've been running a similar load on a desktop pc (amd64), copying and deleting
> ports trees, 4 in parallel, ~4k iops on average, on a SATA SSD through an
> ASM1061 card (looks exactly the same as the one in the pine64 store) for
> around a day with no problems at all.  Is it possible this is actually a
> power problem?  How are you powering the board and the SSD?
>

It is possible power is related. I did add a USB fan on to the
load of the RockPro64. My setup is RockPro64 with their PCIe
SATA controller and the SSD. Power supply is 5A per their
recommendation for this setup. The SSD is powered off the
DC out for SATA on the board #23 in board layout. However,
the USB fan is something I needed to do since the fan that
goes with the NAS case gets its power from PWM controlled
fan header (#4) that we don't have a driver for and provides
no power without a driver.

https://wiki.pine64.org/index.php/ROCKPro64_Main_Page#Board_layout

I have moved the power for the fan off of the RockPro64 USB
port. I will do some testing of an older snapshot without
the diff with sysupgrade where it reproduces easier and
let you know the outcome.

Thanks,
-Kurt

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-4
On Fri, 2019-10-11 at 12:43 -0400, Kurt Miller wrote:

> On Fri, 2019-10-11 at 10:21 +1000, Jonathan Matthew wrote:
> >
> > On Mon, Oct 07, 2019 at 01:30:52PM -0400, Kurt Miller wrote:
> > >
> > >
> > > >
> > > >
> > > > I hit the issue again using the latest snapshot which
> > > > includes the work-around.
> > > >
> > > > ahci0: log page read failed, slot 31 was still active.
> > > > ahci0: stopping the port, softreset slot 31 was still active.
> > > > ahci0: failed to reset port during timeout handling, disabling it
> > > >
> > > > No panic this time.
> > > >
> > > > The work-around helped with stability in the RAMDISK env where
> > > > it was very unstable. Perhaps it is still a good idea.
> > > >
> > > This time I got a panic so perhaps there's something helpful
> > > in the info below. I had 2x rm -rf on some larger directories
> > > going at the time of this panic:
> > I've been running a similar load on a desktop pc (amd64), copying and deleting
> > ports trees, 4 in parallel, ~4k iops on average, on a SATA SSD through an
> > ASM1061 card (looks exactly the same as the one in the pine64 store) for
> > around a day with no problems at all.  Is it possible this is actually a
> > power problem?  How are you powering the board and the SSD?
> >
> It is possible power is related. I did add a USB fan on to the
> load of the RockPro64. My setup is RockPro64 with their PCIe
> SATA controller and the SSD. Power supply is 5A per their
> recommendation for this setup. The SSD is powered off the
> DC out for SATA on the board #23 in board layout. However,
> the USB fan is something I needed to do since the fan that
> goes with the NAS case gets its power from PWM controlled
> fan header (#4) that we don't have a driver for and provides
> no power without a driver.
>
> https://wiki.pine64.org/index.php/ROCKPro64_Main_Page#Board_layout
>
> I have moved the power for the fan off of the RockPro64 USB
> port. I will do some testing of an older snapshot without
> the diff with sysupgrade where it reproduces easier and
> let you know the outcome.
>

Testing has not gone well for me. I can say I received the
error twice with the fan usb power moved off another source
so I think that rules out the fan load. However, I have been
trying recreate the frequent crashes I was receiving in
sysupgrade and bsd.rd upgrades without success. I'm using a
snapshot before the diff was introduced and have done over 5
upgrades and have not tripped the issue - this is with the
fan load put back on the RockPro64 too. Whatever was making
it easy to trip there previously seems to not be reproducible. 

-Kurt

Reply | Threaded
Open this post in threaded view
|

Re: aarch64: ahci0: log page read failed, slot 31 was still active

Kurt Miller-3
In reply to this post by Jonathan Matthew-4
On Fri, 2019-10-11 at 10:21 +1000, Jonathan Matthew wrote:

> On Mon, Oct 07, 2019 at 01:30:52PM -0400, Kurt Miller wrote:
> >
> > >
> > > I hit the issue again using the latest snapshot which
> > > includes the work-around.
> > >
> > > ahci0: log page read failed, slot 31 was still active.
> > > ahci0: stopping the port, softreset slot 31 was still active.
> > > ahci0: failed to reset port during timeout handling, disabling it
> > >
> > > No panic this time.
> > >
> > > The work-around helped with stability in the RAMDISK env where
> > > it was very unstable. Perhaps it is still a good idea.
> > >
> > This time I got a panic so perhaps there's something helpful
> > in the info below. I had 2x rm -rf on some larger directories
> > going at the time of this panic:
> I've been running a similar load on a desktop pc (amd64), copying and deleting
> ports trees, 4 in parallel, ~4k iops on average, on a SATA SSD through an
> ASM1061 card (looks exactly the same as the one in the pine64 store) for
> around a day with no problems at all.

I purchased a different AHCI SATA controller to see if
the problem continued with a different chipset. The new
card is Marvell 88SE9128 based (StarTech PEXSAT32). It has
been stable for me through a few days of testing, whereas
the ASMedia ASM1061 AHCI card would have crashed several
times under similar conditions. I think this points to
the ASMedia card perhaps needing some quirk.

-Kurt