Skip site navigation (1)Skip section navigation (2)
Date:      Wed, 20 Nov 2019 18:12:03 -0800
From:      bob prohaska <fbsd@www.zefox.net>
To:        freebsd-arm@freebsd.org
Subject:   rpi3 panic: data pending interrupt pushed through SDHCI framework
Message-ID:  <20191121021203.GA1837@www.zefox.net>

next in thread | raw e-mail | index | archive | help
While trying to compile www/chromium on a Pi3 running r354909
the system reported a panic which is new, at least to me:

panic: data pending interrupt pushed through SDHCI framework
cpuid = 3
time = 1574299870
KDB: stack backtrace:
db_trace_self() at db_trace_self_wrapper+0x28
	 pc = 0xffff00000072978c  lr = 0xffff000000106548
	 sp = 0xffff00004026b4c0  fp = 0xffff00004026b6d0

db_trace_self_wrapper() at vpanic+0x18c
	 pc = 0xffff000000106548  lr = 0xffff000000400c58
	 sp = 0xffff00004026b6e0  fp = 0xffff00004026b790

vpanic() at panic+0x44
	 pc = 0xffff000000400c58  lr = 0xffff000000400a08
	 sp = 0xffff00004026b7a0  fp = 0xffff00004026b820

panic() at bcm_sdhci_will_handle_transfer+0x64
	 pc = 0xffff000000400a08  lr = 0xffff00000071a48c
	 sp = 0xffff00004026b830  fp = 0xffff00004026b840

bcm_sdhci_will_handle_transfer() at sdhci_generic_intr+0x69c
	 pc = 0xffff00000071a48c  lr = 0xffff00000022f44c
	 sp = 0xffff00004026b850  fp = 0xffff00004026b8b0

sdhci_generic_intr() at ithread_loop+0x1e8
	 pc = 0xffff00000022f44c  lr = 0xffff0000003c44e8
	 sp = 0xffff00004026b8c0  fp = 0xffff00004026b940

ithread_loop() at fork_exit+0x7c
	 pc = 0xffff0000003c44e8  lr = 0xffff0000003c0fac
	 sp = 0xffff00004026b950  fp = 0xffff00004026b980

fork_exit() at fork_trampoline+0x10
	 pc = 0xffff0000003c0fac  lr = 0xffff000000746994
	 sp = 0xffff00004026b990  fp = 0x0000000000000000

KDB: enter: panic
[ thread pid 12 tid 100051 ]
Stopped at      0
db> bt
Tracing pid 12 tid 100051 td 0xfffffd0000b9d000
db_trace_self() at db_stack_trace+0xf8
         pc = 0xffff00000072978c  lr = 0xffff00000010398c
         sp = 0xffff00004026b090  fp = 0xffff00004026b0c0

db_stack_trace() at db_command+0x228
         pc = 0xffff00000010398c  lr = 0xffff000000103604
         sp = 0xffff00004026b0d0  fp = 0xffff00004026b1b0

db_command() at db_command_loop+0x58
         pc = 0xffff000000103604  lr = 0xffff0000001033ac
         sp = 0xffff00004026b1c0  fp = 0xffff00004026b1e0

db_command_loop() at db_trap+0xf4
         pc = 0xffff0000001033ac  lr = 0xffff0000001066b0
         sp = 0xffff00004026b1f0  fp = 0xffff00004026b410

db_trap() at kdb_trap+0x1d8
         pc = 0xffff0000001066b0  lr = 0xffff0000004491f0
         sp = 0xffff00004026b420  fp = 0xffff00004026b4d0
        
kdb_trap() at do_el1h_sync+0xf4
         pc = 0xffff0000004491f0  lr = 0xffff000000746c08
         sp = 0xffff00004026b4e0  fp = 0xffff00004026b510

do_el1h_sync() at handle_el1h_sync+0x78
         pc = 0xffff000000746c08  lr = 0xffff00000072c078
         sp = 0xffff00004026b520  fp = 0xffff00004026b630

handle_el1h_sync() at kdb_enter+0x34
         pc = 0xffff00000072c078  lr = 0xffff00000044883c
         sp = 0xffff00004026b640  fp = 0xffff00004026b6d0

kdb_enter() at vpanic+0x1a8
         pc = 0xffff00000044883c  lr = 0xffff000000400c74
         sp = 0xffff00004026b6e0  fp = 0xffff00004026b790

vpanic() at panic+0x44
         pc = 0xffff000000400c74  lr = 0xffff000000400a08
         sp = 0xffff00004026b7a0  fp = 0xffff00004026b820
        
panic() at bcm_sdhci_will_handle_transfer+0x64
         pc = 0xffff000000400a08  lr = 0xffff00000071a48c
         sp = 0xffff00004026b830  fp = 0xffff00004026b840

bcm_sdhci_will_handle_transfer() at sdhci_generic_intr+0x69c
         pc = 0xffff00000071a48c  lr = 0xffff00000022f44c
         sp = 0xffff00004026b850  fp = 0xffff00004026b8b0

sdhci_generic_intr() at ithread_loop+0x1e8
         pc = 0xffff00000022f44c  lr = 0xffff0000003c44e8
         sp = 0xffff00004026b8c0  fp = 0xffff00004026b940

ithread_loop() at fork_exit+0x7c
         pc = 0xffff0000003c44e8  lr = 0xffff0000003c0fac
         sp = 0xffff00004026b950  fp = 0xffff00004026b980

fork_exit() at fork_trampoline+0x10
         pc = 0xffff0000003c0fac  lr = 0xffff000000746994
         sp = 0xffff00004026b990  fp = 0x0000000000000000
        
db> 

The last top window contains
last pid: 45350;  load averages:  1.98,  2.87,  4.04                                up 0+02:41:58  17:31:08
45 processes:  2 running, 43 sleeping
CPU: 13.0% user,  0.0% nice,  7.3% system,  9.0% interrupt, 70.7% idle
Mem: 417M Active, 72M Inact, 220M Laundry, 170M Wired, 97M Buf, 20M Free
Swap: 7194M Total, 410M Used, 6784M Free, 5% Inuse, 12M In, 18M Out

  PID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
45134 root          1  47    0   320M    36M CPU0     0   0:19  47.44% c++
45136 root          1  21    0   308M    28M swread   2   0:12   3.15% c++
45135 root          1  21    0   304M    27M swread   2   0:11   3.34% c++
45148 root          1  21    0   308M    26M swread   3   0:12   3.32% c++
45350 bob           1  52    0    12M  2392K nanslp   3   0:00   0.00% gstat
 1049 bob           1  20    0    19M  2020K select   1   0:03   0.03% sshd
 1554 bob           1  20    0    13M  1912K CPU1     1   0:25   0.23% top
 1058 bob           1  20    0    19M  1900K select   2   0:00   0.00% sshd
 1059 bob           1  20    0    13M  1816K ttyin    0   0:01   0.00% tcsh
  958 root          1  20    0    16M  1804K select   1   0:01   0.02% sendmail
 1055 root          1  21    0    19M  1796K select   2   0:00   0.00% sshd
 1046 root          1  24    0    19M  1788K select   2   0:00   0.00% sshd
 1028 bob           1  20    0    19M  1744K select   2   0:00   0.00% sshd
 1066 bob           1  20    0    19M  1744K select   1   0:00   0.00% sshd

The last of the I/O activity log contains

procs     memory       page                      disks     faults       cpu
r b w     avm     fre  flt  re  pi  po    fr   sr mm0 da0   in   sy   cs us sy id
 1  0 12 1410224    5316   902   2   1   0  1176  638   0   0 14925  2704  6210 21  7 72
dT: 1.050s  w: 1.000s
 L(q)  ops/s    r/s   kBps   ms/r    w/s   kBps   ms/w    d/s   kBps   ms/d   %busy Name
    0     91      3     65  328.1     89   6459   33.6      0      0    0.0   88.3  mmcsd0
    0     91      3     65  328.2     89   6459   33.7      0      0    0.0   88.3  mmcsd0s2
    0      2      2     61  484.6      0      0    0.0      0      0    0.0   92.3  mmcsd0s2a
    0     90      1      4   15.5     89   6459   33.7      0      0    0.0   88.2  mmcsd0s2b
    0      2      2     61  484.6      0      0    0.0      0      0    0.0   92.3  ufs/rootfs
    7    126      0      0    0.0    126   6021    3.8      0      0    0.0   30.1  da0
    5     83      0      0    0.0     83   6021    4.0      0      0    0.0   30.4  da0p6
Wed Nov 20 17:30:44 PST 2019
Device          1K-blocks     Used    Avail Capacity
/dev/mmcsd0s2b    4404252   138100  4266152     3%
/dev/da0p6        5242880   139496  5103384     3%
Total             9647132   277596  9369536     3%
Nov 20 17:27:25 www sshd[44294]: error: PAM: Authentication error for illegal user support from 103.133.104.114
Nov 20 17:27:26 www sshd[44294]: error: Received disconnect from 103.133.104.114 port 52227:14: No more user authentication methods available. [preauth]
procs     memory       page

suggesting the panic happened while vmstat was writing to the log.

For the moment I'll update /usr/src and rebuild. Please indicate if more useful
observations can be gathered.

Thanks for reading,

bob prohaska





Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20191121021203.GA1837>