Re: MMCCAM hang

On Wed, 27 Dec 2023, Warner Losh wrote:

> On Wed, Dec 27, 2023, 4:55 PM Bjoern A. Zeeb <[email protected]>
> wrote:
>
>> Hi,
>>
>> sdhci_fsl_fdt0: Desired SD/MMC freq: 50000000, actual: 50000000; base
>> 700000000 prescale 1 divisor 14
>> GEOM: new disk sdda0
>> sdda0 at sdhci_slot0 bus 0 scbus0 target 0 lun 0
>> sdda0: Relative addr: 00000002
>> Card features: <MMC Memory High-Capacity>
>> Card random: unblocking device.
>> GEOM: new disk sdda0boot0
>> memory OCR: 00ff8080
>> sdda0: Serial Number .......
>> sdda0: MMCHC .................................. by 17 0x0000
>> GEOM: new disk sdda0boot1
>> uhub0: 2 ports with 2 removable, self powered
>>
>> at which point basically anything hangs.  In auto-boot it is
>> before/during file-system checks.
>> In single user mode camcontrol devlist will show sdda0
>> but
>>
>> root@:/ # gpart show sdda0
>> load: 6.06  cmd: gpart 24 [g_waitfor_event] 1.28r 0.00u 0.00s 0% 2088k
>> {forever}
>>
>>
>> Unclear at which point I broke to debugger and this is where it seems to
>> hang:
>>
>> db> trace 100088
>> Tracing pid 4 tid 100088 td 0xffff0000dc527000
>> ipi_stop() at ipi_stop+0x34
>> arm_gic_v3_intr() at arm_gic_v3_intr+0xe4
>> intr_irq_handler() at intr_irq_handler+0x80
>> handle_el1h_irq() at handle_el1h_irq+0x14
>> --- interrupt
>> spinlock_exit() at spinlock_exit+0x44
>> callout_reset_sbt_on() at callout_reset_sbt_on+0x210
>> sdhci_cam_action() at sdhci_cam_action+0x284
>> xpt_run_devq() at xpt_run_devq+0x4c8
>> xpt_action_default() at xpt_action_default+0x470
>> sddastart() at sddastart+0x1bc
>> xpt_run_allocq() at xpt_run_allocq+0xa8
>> xpt_done_process() at xpt_done_process+0x610
>> xpt_done_td() at xpt_done_td+0x1a8
>> fork_exit() at fork_exit+0x8c
>> fork_trampoline() at fork_trampoline+0x18
>>
>>
>> Anyone an idea?
>>
>
>
> Looks like deadlock with another thread. Anybody else in the time keeping /
> callout code?

I need to a build a kernel with debugging on...

New boot ... so thread 100092 now... which seems to move ...


# gpart show

load: 9.90  cmd: gpart 20 [g_waitfor_event] 104.65r 0.00u 0.00s 0% 2048k

Tracing command kernel pid 0 tid 100011 td 0xffff0000dc2cc2c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
msleep_spin_sbt() at msleep_spin_sbt+0xf4
gtaskqueue_thread_loop() at gtaskqueue_thread_loop+0x160
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]

Tracing command kernel pid 0 tid 100027 td 0xffff0000dc4c2900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
msleep_spin_sbt() at msleep_spin_sbt+0xf4
gtaskqueue_thread_loop() at gtaskqueue_thread_loop+0x160
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command kernel pid 0 tid 100028 td 0xffff0000dc4c22c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
taskqueue_thread_loop() at taskqueue_thread_loop+0x124
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]

Tracing command kernel pid 0 tid 100175 td 0xffff0000f16fd900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
taskqueue_thread_loop() at taskqueue_thread_loop+0x124
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command kernel pid 0 tid 100177 td 0xffff0000f36eb2c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
msleep_spin_sbt() at msleep_spin_sbt+0xf4
taskqueue_thread_loop() at taskqueue_thread_loop+0x160
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]

Tracing command kernel pid 0 tid 100181 td 0xffff0000f2116900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
taskqueue_thread_loop() at taskqueue_thread_loop+0x124
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command init pid 1 tid 100002 td 0xffff0000dc2c5640
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
sleepq_catch_signals() at sleepq_catch_signals+0x424
sleepq_wait_sig() at sleepq_wait_sig+0xc
_sleep() at _sleep+0x1d8
kern_wait6() at kern_wait6+0x754
sys_wait4() at sys_wait4+0x84
do_el0_sync() at do_el0_sync+0x634
handle_el0_sync() at handle_el0_sync+0x48
--- exception, esr 0x56000000

Tracing command clock pid 2 tid 100057 td 0xffff0000dc4d82c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
softclock_thread() at softclock_thread+0x104
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command clock pid 2 tid 100058 td 0xffff0000dc4d7c80
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
softclock_thread() at softclock_thread+0x104
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]

Tracing command cam pid 4 tid 100088 td 0xffff0000dc527000
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
xpt_done_td() at xpt_done_td+0xfc
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command cam pid 4 tid 100089 td 0xffff0000dc52d000
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
xpt_done_td() at xpt_done_td+0xfc
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command cam pid 4 tid 100090 td 0xffff0000dc52c900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
xpt_async_td() at xpt_async_td+0xf4
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command cam pid 4 tid 100182 td 0xffff0000f21162c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
xpt_scanner_thread() at xpt_scanner_thread+0xfc
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]

Tracing command intr pid 12 tid 100092 td 0xffff0000dc52bc80 (CPU 1)
ipi_stop() at ipi_stop+0x34
arm_gic_v3_intr() at arm_gic_v3_intr+0xe4
intr_irq_handler() at intr_irq_handler+0x80
handle_el1h_irq() at handle_el1h_irq+0x14
--- interrupt
generic_bs_r_4() at generic_bs_r_4+0xc
sdhci_generic_reset() at sdhci_generic_reset+0x140
sdhci_fsl_fdt_reset() at sdhci_fsl_fdt_reset+0x20
sdhci_finish_command() at sdhci_finish_command+0xf4
sdhci_generic_intr() at sdhci_generic_intr+0x388
ithread_loop() at ithread_loop+0x3ac
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]


Tracing command geom pid 13 tid 100067 td 0xffff0000dc4da900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
biowait() at biowait+0xc4
g_read_data() at g_read_data+0x88
g_raid_md_taste_ddf() at g_raid_md_taste_ddf+0x104
g_raid_taste() at g_raid_taste+0x184
g_new_provider_event() at g_new_provider_event+0xac
g_run_events() at g_run_events+0x2e4
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command geom pid 13 tid 100068 td 0xffff0000dc4da2c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_io_schedule_up() at g_io_schedule_up+0x74
g_up_procbody() at g_up_procbody+0x70
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command geom pid 13 tid 100069 td 0xffff0000dc4d9c80
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_io_schedule_down() at g_io_schedule_down+0x7c
g_down_procbody() at g_down_procbody+0x70
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

[...]


Tracing command gpart pid 20 tid 100206 td 0xffff000042a082c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_waitfor_event() at g_waitfor_event+0x118
sysctl_kern_geom_confany() at sysctl_kern_geom_confany+0xd0
sysctl_root_handler_locked() at sysctl_root_handler_locked+0x11c
sysctl_root() at sysctl_root+0x21c
userland_sysctl() at userland_sysctl+0x190
sys___sysctl() at sys___sysctl+0x6c
do_el0_sync() at do_el0_sync+0x634
handle_el0_sync() at handle_el0_sync+0x48
--- exception, esr 0x56000000
db>


{out and back in}

cpuid        = 1
dynamic pcpu = 0x41c17f00
curthread    = 0xffff0000dc52bc80: pid 12 tid 100092 critnest 1 "gic0,s28:-_fsl_fdt0"
curpcb       = 0xffff0000dc64ab20
fpcurthread  = none
idlethread   = 0xffff0000dc2c4900: tid 100004 "idle: cpu1"
curvnet      = 0


Tracing command intr pid 12 tid 100092 td 0xffff0000dc52bc80 (CPU 1)
ipi_stop() at ipi_stop+0x34
arm_gic_v3_intr() at arm_gic_v3_intr+0xe4
intr_irq_handler() at intr_irq_handler+0x80
handle_el1h_irq() at handle_el1h_irq+0x14
--- interrupt
spinlock_exit() at spinlock_exit+0x44
wakeup() at wakeup+0x34
xpt_done() at xpt_done+0x164
sdhci_generic_intr() at sdhci_generic_intr+0x388
ithread_loop() at ithread_loop+0x3ac
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command geom pid 13 tid 100067 td 0xffff0000dc4da900
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
biowait() at biowait+0xc4
g_read_data() at g_read_data+0x88
g_raid_md_taste_ddf() at g_raid_md_taste_ddf+0x104
g_raid_taste() at g_raid_taste+0x184
g_new_provider_event() at g_new_provider_event+0xac
g_run_events() at g_run_events+0x2e4
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18


Tracing command geom pid 13 tid 100068 td 0xffff0000dc4da2c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_io_schedule_up() at g_io_schedule_up+0x74
g_up_procbody() at g_up_procbody+0x70
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18

Tracing command geom pid 13 tid 100069 td 0xffff0000dc4d9c80
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_io_schedule_down() at g_io_schedule_down+0x7c
g_down_procbody() at g_down_procbody+0x70
fork_exit() at fork_exit+0x8c
fork_trampoline() at fork_trampoline+0x18


Tracing command gpart pid 20 tid 100206 td 0xffff000042a082c0
sched_switch() at sched_switch+0x890
mi_switch() at mi_switch+0x108
_sleep() at _sleep+0x1e4
g_waitfor_event() at g_waitfor_event+0x118
sysctl_kern_geom_confany() at sysctl_kern_geom_confany+0xd0
sysctl_root_handler_locked() at sysctl_root_handler_locked+0x11c
sysctl_root() at sysctl_root+0x21c
userland_sysctl() at userland_sysctl+0x190
sys___sysctl() at sys___sysctl+0x6c
do_el0_sync() at do_el0_sync+0x634
handle_el0_sync() at handle_el0_sync+0x48
--- exception, esr 0x56000000



-- 
Bjoern A. Zeeb                                                     r15:7