Am 23.01.2023 11:46, schrieb Adrian Hunter:
On 21/01/23 15:37, sebastian.kloska@xxxxxxxx wrote:
Am 20.01.2023 13:08, schrieb Adrian Hunter:
On 20/01/23 13:14, sebastian.kloska@xxxxxxxx wrote:
So no mail with attachment on linux-mmc@xxxxxxxxxxxxxxx
but I linked the dmesgs on
https://bugzilla.kernel.org/show_bug.cgi?id=216255
<https://bugzilla.kernel.org/show_bug.cgi?id=216255>
I did receive the logs but it is good to attach them to the bug
anyway.
Am 19.01.2023 11:28, schrieb Adrian Hunter:
On 19/01/23 11:46, sebastian.kloska@xxxxxxxx
<mailto:sebastian.kloska@xxxxxxxx> wrote:
Am 19.01.2023 10:15, schrieb Adrian Hunter:
On 18/01/23 23:24, sebastian.kloska@xxxxxxxx
<mailto:sebastian.kloska@xxxxxxxx> wrote:
Hi,
Hardware: Acer Swift-1 SF114-34-P6U1
SD Host controller: Intel Corporation Device 4dc4 (rev 01) 8086:4dc4
eMMC: Kingston A29128
* A couple of seconds after boot access to the eMMC is completely
blocked. Can be triggered by extensive I/O (e.g, with
badblocks -w)
* Tested with stable branch linux-5.14.21 vs. linux-5.15.1
Latest highest version including the bug is a fedora 6.1.6
There is very little difference in drivers/mmc between 5.14.21
and 5.15.1. Are you sure the same issue is not present in
5.14.21?
Pretty sure. Using 5.14.21 day in day out 5.15.1 fails on me after
~10min
The "slowed down by pr_debug" version sometimes lives for >2h
(without stress
via badblocks etc)
So all of the following is now done on the latest stable, Which
currently
is 6.2.0-rc4+
That is a release candidate (rc). The latest stable kernel
is 6.1.7.
I know -just thought I should pull master/HEAD from the latest stable
You could try disabling runtime PM to see if that helps:
echo on > /sys/class/mmc_host/mmc0/device/power/control
Didn't help
Will try
Also it should be possible to disable cqhci by adding to the kernel
command line:
sdhci.debug_quirks=0x40a0000
Weird behavior: Seems to make it worse. System often freezes
during early boot-up.
HOWEVER: If I slow down the driver via dynamic debugging it seems to
be stable
Failed to crash it over a couple of hours. You can say it fixes the
issue if you
are willing to accept that 80% of one CPU core is busy with logging ;-)
That is interesting. Logging can have more side effects than you
might expect.
For example the logs might be written back to storage by syslog,
which causes
more logging, and more writing etc etc. That in turn is bumping up
the CPU
load.
Increasing the CPU load will decrease the chance of the CPU entering
a low-power
state (C-state).
And there was an issue with C-state transitions affecting Intel SDHCI
controllers,
so we need to check that possibility. You could try kernel command
line option:
intel_idle.max_cstate=1
This -- Sir -- works just wonderfully !!
Don't see any changes in
/sys/devices/system/cpu/cpu*/cpuidle/state*/disable,but
may be that's expected. Kernel runs just fine. works for stable/6.1.7
and fedora/6.1.6
So for me personally this workaround is fine. Guess it will hurt my
power consumption/battery live though but that's acceptable for me.
Don't hesitate to contact if I should test patches for you. The source
is checked out and ccache is filled.
It is probably possible to make a kernel patch to prevent
low-power C-States only when eMMC is in use. I will check
on that.
In the meantime, could you send an acpidump e.g.
sudo apt-get install acpica-tools
sudo acpidump -o /tmp/acpidump.txt
Also do you know if you have an up to date BIOS?
So this is pretty embarrassing. Finally found the means to update my
BIOS and turned out to fix the problem.
Should have been the first on my list to solve the issue.
THX for the effort
You can see the C-states and whether they are disabled:
grep -H . /sys/devices/system/cpu/cpu*/cpuidle/state*/disable
"disable" is writable by root, so you can disable them that way also.
In the meantime I will take a look at the logs.
Will try
* Spiked the code with a lot of pr_debug messages. As a side
effect the driver
seems to be much more stable, so to me it appears like a
timing issue where
the driver fails to wait for a specific state change which
seems to appear
less often when slowed down by logging
Ideally it would be good to see a full log with dynamic
debugging enabled for the latest kernel.
Latest torvalds/linux or stable/linux ?
Stable would be fine.
To enable mmc debug via kernel command line:
dyndbg="file drivers/mmc/core/* +p;file
drivers/mmc/host/* +p"
This for whatever reason did not work for me on the kernel cmdline
but I could trigger it via echo "..." ><debugfs>/dynamic_debug/control
so the attached dmesgs are missing early logs.
Kernel must be configured:
CONFIG_DYNAMIC_DEBUG=y
* Would love to have a decent reference documentation to the SD
Controller
especially a detailed description of the behavior of the
register map in
mmc/host/cqhci.h All intel documents I could find seem to describe
similar but not quite identical register maps
The JEDEC eMMC specification describes the CQHCI registers.
It looks like you need to register to get access to them
at www.jedec.org.
<http://www.jedec.org. ;> AFAICT older specs, which would be just
fine, are free to download after registering.
Uhh -- but the price for registration is hefty. THX anyway
THX
You can get SD Host Controller Simplified Specification
from www.sdcard.org <http://www.sdcard.org>.
I attach to dmesg logs
* One with dynamic debugging and without sdhci.debug_quirks=0x40a0000
* The other without dynamic debugging (as said I failed to crash the
system) and sdhci.debug_quirks=0x40a0000
Hope I filtered properly for the relevant stuff
The second one contains what seems to me a ton of kernel Oops but
that might be due to the preliminary status of 6.2.0-rc4
THX
THX
Regards
Sebastian
* dmesg
[ 347.583082] mmc0: cqhci: timeout for tag 3, qcnt
The timeout is pretty long, so it seems like the controller
has gotten stuck. It won't reset the command or data
circuits either, which is impossible if it is behaving
correctly.
[ 347.583086] mmc0: cqhci: ============ CQHCI REGISTER DUMP
===========
[ 347.583114] mmc0: cqhci: Caps: 0x000030c0 | Version:
0x00000510
[ 347.583117] mmc0: cqhci: Config: 0x00001101 | Control:
0x00000000
[ 347.583120] mmc0: cqhci: Int stat: 0x00000000 | Int enab:
0x00000016
[ 347.583123] mmc0: cqhci: Int sig: 0x00000016 | Int Coal:
0x00000000
[ 347.583157] mmc0: cqhci: TDL base: 0x7c2b5000 | TDL up32:
0x00000001
[ 347.583160] mmc0: cqhci: Doorbell: 0x0000000f | TCN:
0x00000000
[ 347.583163] mmc0: cqhci: Dev queue: 0x00000008 | Dev Pend:
0x00000008
[ 347.583166] mmc0: cqhci: Task clr: 0x00000000 | SSC1:
0x00010008
[ 347.583169] mmc0: cqhci: SSC2: 0x00000001 | DCMD rsp:
0x00000800
[ 347.583172] mmc0: cqhci: RED mask: 0xfdf9a080 | TERRI:
0x00000000
[ 347.583175] mmc0: cqhci: Resp idx: 0x0000002f | Resp arg:
0x00000900
[ 347.583176] mmc0: sdhci: ============ SDHCI REGISTER DUMP
===========
[ 347.583182] mmc0: sdhci: Sys addr: 0x00000080 | Version:
0x00001002
[ 347.583185] mmc0: sdhci: Blk size: 0x00000200 | Blk cnt:
0x00000070
[ 347.583188] mmc0: sdhci: Argument: 0x00030000 | Trn mode:
0x00000023
[ 347.583191] mmc0: sdhci: Present: 0x1fff0106 | Host ctl:
0x0000003c
[ 347.583194] mmc0: sdhci: Power: 0x0000000b | Blk gap:
0x00000080
[ 347.583197] mmc0: sdhci: Wake-up: 0x00000000 | Clock:
0x00000007
[ 347.583200] mmc0: sdhci: Timeout: 0x0000000e | Int stat:
0x00000000
[ 347.583203] mmc0: sdhci: Int enab: 0x02ff4000 | Sig enab:
0x02ff4000
[ 347.583206] mmc0: sdhci: ACmd stat: 0x00000000 | Slot int:
0x00000000
[ 347.583209] mmc0: sdhci: Caps: 0x546ec881 | Caps_1:
0x80000807
[ 347.583212] mmc0: sdhci: Cmd: 0x00002f3a | Max curr:
0x00000000
[ 347.583214] mmc0: sdhci: Resp[0]: 0x00000900 | Resp[1]:
0x00000000
[ 347.583217] mmc0: sdhci: Resp[2]: 0x00000000 | Resp[3]:
0x00000000
[ 347.583219] mmc0: sdhci: Host ctl2: 0x0000000d
[ 347.583223] mmc0: sdhci: ADMA Err: 0x00000000 | ADMA Ptr:
0x000000011eef1218
[ 347.583224] mmc0: sdhci:
============================================
[ 347.583229] mmc0: running CQE recovery
[ 347.690108] mmc0: Reset 0x2 never completed.
[ 347.690109] mmc0: sdhci: ============ SDHCI REGISTER DUMP
===========
[ 347.690115] mmc0: sdhci: Sys addr: 0x00000080 | Version:
0x00001002
[ 347.690118] mmc0: sdhci: Blk size: 0x00000200 | Blk cnt:
0x00000070
[ 347.690121] mmc0: sdhci: Argument: 0x00030000 | Trn mode:
0x00000023
[ 347.690124] mmc0: sdhci: Present: 0x1fff0106 | Host ctl:
0x0000003c
[ 347.690127] mmc0: sdhci: Power: 0x0000000b | Blk gap:
0x00000080
[ 347.690130] mmc0: sdhci: Wake-up: 0x00000000 | Clock:
0x00000007
[ 347.690133] mmc0: sdhci: Timeout: 0x0000000e | Int stat:
0x00000000
[ 347.690136] mmc0: sdhci: Int enab: 0x00ff0003 | Sig enab:
0x00ff0003
[ 347.690139] mmc0: sdhci: ACmd stat: 0x00000000 | Slot int:
0x00000000
[ 347.690141] mmc0: sdhci: Caps: 0x546ec881 | Caps_1:
0x80000807
[ 347.690144] mmc0: sdhci: Cmd: 0x00002f3a | Max curr:
0x00000000
[ 347.690147] mmc0: sdhci: Resp[0]: 0x00000900 | Resp[1]:
0x00000000
[ 347.690150] mmc0: sdhci: Resp[2]: 0x00000000 | Resp[3]:
0x00000000
[ 347.690152] mmc0: sdhci: Host ctl2: 0x0000000d
[ 347.690156] mmc0: sdhci: ADMA Err: 0x00000000 | ADMA Ptr:
0x000000011eef1218
[ 347.690157] mmc0: sdhci:
============================================
[ 347.790190] mmc0: Reset 0x4 never completed.
[ 347.790191] mmc0: sdhci: ============ SDHCI REGISTER DUMP
===========
[ 347.790193] mmc0: sdhci: Sys addr: 0x00000080 | Version:
0x00001002
[ 347.790196] mmc0: sdhci: Blk size: 0x00000200 | Blk cnt:
0x00000070
[ 347.790199] mmc0: sdhci: Argument: 0x00030000 | Trn mode:
0x00000023
[ 347.790202] mmc0: sdhci: Present: 0x1fff0106 | Host ctl:
0x0000003c
[ 347.790205] mmc0: sdhci: Power: 0x0000000b | Blk gap:
0x00000080
[ 347.790208] mmc0: sdhci: Wake-up: 0x00000000 | Clock:
0x00000007
[ 347.790211] mmc0: sdhci: Timeout: 0x0000000e | Int stat:
0x00000000
[ 347.790213] mmc0: sdhci: Int enab: 0x00ff0003 | Sig enab:
0x00ff0003
[ 347.790216] mmc0: sdhci: ACmd stat: 0x00000000 | Slot int:
0x00000000
[ 347.790219] mmc0: sdhci: Caps: 0x546ec881 | Caps_1:
0x80000807
[ 347.790222] mmc0: sdhci: Cmd: 0x00002f3a | Max curr:
0x00000000
[ 347.790225] mmc0: sdhci: Resp[0]: 0x00000900 | Resp[1]:
0x00000000
[ 347.790228] mmc0: sdhci: Resp[2]: 0x00000000 | Resp[3]:
0x00000000
[ 347.790230] mmc0: sdhci: Host ctl2: 0x0000000d
[ 347.790234] mmc0: sdhci: ADMA Err: 0x00000000 | ADMA Ptr:
0x000000011eef1218
[ 347.790234] mmc0: sdhci:
============================================
[ 347.803056] mmc0: Controller never released inhibit bit(s).
[ 347.803058] mmc0: sdhci: ============ SDHCI REGISTER DUMP
===========
[ 347.803077] mmc0: sdhci: Sys addr: 0x00000080 | Version:
0x00001002
[ 347.803080] mmc0: sdhci: Blk size: 0x00000200 | Blk cnt:
0x00000070
[ 347.803083] mmc0: sdhci: Argument: 0x00030000 | Trn mode:
0x00000023
[ 347.803086] mmc0: sdhci: Present: 0x1fff0106 | Host ctl:
0x0000003c
[ 347.803089] mmc0: sdhci: Power: 0x0000000b | Blk gap:
0x00000080
[ 347.803092] mmc0: sdhci: Wake-up: 0x00000000 | Clock:
0x00000007
[ 347.803095] mmc0: sdhci: Timeout: 0x0000000e | Int stat:
0x00000000
[ 347.803098] mmc0: sdhci: Int enab: 0x00ff0003 | Sig enab:
0x00ff0003
[ 347.803101] mmc0: sdhci: ACmd stat: 0x00000000 | Slot int:
0x00000000
[ 347.803103] mmc0: sdhci: Caps: 0x546ec881 | Caps_1:
0x80000807
[ 347.803106] mmc0: sdhci: Cmd: 0x00002f3a | Max curr:
0x00000000
[ 347.803109] mmc0: sdhci: Resp[0]: 0x00000900 | Resp[1]:
0x00000000
[ 347.803112] mmc0: sdhci: Resp[2]: 0x00000000 | Resp[3]:
0x00000000
[ 347.803114] mmc0: sdhci: Host ctl2: 0x0000000d
[ 347.803118] mmc0: sdhci: ADMA Err: 0x00000000 | ADMA Ptr:
0x000000011eef1218
[ 347.803119] mmc0: sdhci:
============================================
--
--
--
