• State Resolved
  • Locked Locked
  • Replies 12 replies
  • Subscribers 99 subscribers
  • Views 738 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

TDA4VM: 4f80000.sdhci probe timeout error

Amit Kamath
Intellectual 800 points
Part Number: TDA4VM

Hi Ti,

I am seeing error detecting emmc card in some boards. Error seems to be in linux drivers as uBoot is able to detect emmc.

Looks like the SDHCI controller driver initialization fails. The emmc is powered directly with sys3v3 voltage so i think it it is powerred on.

Which power rail should affect the SDHCI controller.

sdhci-am654: probe of 4f80000.sdhci failed with error -110

PFA logs. Let me know what clocks need to be checked. No modifications are made to the J7 EVK dt files. The design and part of emmc looks same for both.

Best regards

Amitsdk_emmc_timeout.zip

  • 0
    TI__Guru**** 163290 points

    Amith,

    Was it working in the previous release or you are testing a new eMMC part?
    Looked through logs are you referring to the below error?

    "[    1.974299] sdhci-am654: probe of 4f80000.sdhci failed with error -110"

    Is the above 


    I believe you are using PSDKRA 7.1?


    - Keerthy

  • 0 in reply to Keerthy J
    Intellectual 800 points

    Hi Keerthy,

    1. We are currently using 7.2 release. This issue was seen in 7.0 release as well.

    2. The problem is seen in a specific board. But we have not tested all the boards yet. Safe to say 1/4 board might have the issue.

    3. All boards are manufactured at same time. Component wise there should not be difference.

    4. Also u-boot detects the emmc card. So likely some setting in linux side is cause.

    Can you let me clocks/power rails we can check to root cause the issue so i can compare working and non-working boards. Emmc card power supply and pinmux are same across the boards.

    Best regards

    Amit

  • 0 in reply to Amit Kamath
    Intellectual 800 points

    Hi Keerthy,

    Any pointers on the issue. 

    Best regards

    Amit

  • 0 in reply to Amit Kamath
    TI__Guru**** 163290 points

    Amit,

    I will check internally and get back in couple of days.

    - Keerthy

  • 0 in reply to Keerthy J
    Intellectual 800 points

    Hi TI,

    Thanks Keerthy, Following is additional information on the issue.
    I am reading the mmcsd registers for debugging.  CTRLMMR_EMMC0_CLKSEL and registers from MMCSD0 Subsystem Registers cause aborts. EMMC1 register reads pass.

    These domains are powerred off for some reason. Can you check in what case this can happen. These same reads pass when emmc is working correctly

    PFA the logs for the same.

    Best regards
    Amit

    Fullscreen emmc_debug_log_mahipal.txt Download 
    root@j7-evm:~# ./emmc_debug.sh
Debug emmc failure
CTRLMMR_EMMC0_CLKSEL
/dev/mem opened.
Memory mapped at address 0xffff99180000.
Read at address  0x001ERROR:   Unhandled External Abort received on 0x80000001 from S-EL1
ERROR:   exception reason=0 syndrome=0xbf000000
Unhandled Exception from EL0
x0             = 0x0000ffffa00b11e0
x1             = 0x00000000004002e8
x2             = 0x0000000000000000
x3             = 0x0000000000000003
x4             = 0x0000ffffa00b2330
x5             = 0x0000000000400498
x6             = 0x0000000000000001
x7             = 0x000000000000000a
x8             = 0x0000000000000040
x9             = 0xffffff80ffffffc8
x10            = 0x0000000000000000
x11            = 0x0000ffffe715e850
x12            = 0x000000000000000c
x13            = 0x0000000000000010
x14            = 0x0000000000000001
x15            = 0x0000000000000000
x16            = 0x0000000000411ff8
x17            = 0x0000ffffa0092e38
x18            = 0x0000000000000000
x19            = 0x0000000000412010
x20            = 0x0000ffffa00b28a0
x21            = 0x0000ffffa00b30a0
x22            = 0x0000000000000003
x23            = 0x0000000000000003
x24            = 0x0000ffffe715e9d0
x25            = 0x0000ffffe715eb98
x26            = 0x0000ffffa0058000
x27            = 0x0000000000412000
x28            = 0x0000000000000000
x29            = 0x0000ffffe715e830
x30            = 0x0000ffffa0092e7c
scr_el3        = 0x000000000000073d
sctlr_el3      = 0x0000000030cd183f
cptr_el3       = 0x0000000000000000
tcr_el3        = 0x0000000080803520
daif           = 0x00000000000002c0
mair_el3       = 0x00000000004404ff
spsr_el3       = 0x0000000020000000
elr_el3        = 0x0000ffffa008d44c
ttbr0_el3      = 0x0000000070010b00
esr_el3        = 0x00000000bf000000
far_el3        = 0x0000000000000000
spsr_el1       = 0x0000000020000000
elr_el1        = 0x0000ffff9ff9e3d0
spsr_abt       = 0x0000000000000000
spsr_und       = 0x0000000000000000
spsr_irq       = 0x0000000000000000
spsr_fiq       = 0x0000000000000000
sctlr_el1      = 0x0000000034d4d91d
actlr_el1      = 0x0000000000000000
cpacr_el1      = 0x0000000000300000
csselr_el1     = 0x0000000000000000
sp_el1         = 0xffff8000170b0000
esr_el1        = 0x0000000056000000
ttbr0_el1      = 0x00000008d8cb0800
ttbr1_el1      = 0x0d4c000082df0000
mair_el1       = 0x0000bbff440c0400
amair_el1      = 0x0000000000000000
tcr_el1        = 0x00000034f5507510
tpidr_el1      = 0xffff80086ec00000
tpidr_el0      = 0x0000ffffa00b30a0
tpidrro_el0    = 0x0000000000000000
par_el1        = 0x0000000000000000
mpidr_el1      = 0x0000000080000001
afsr0_el1      = 0x0000000000000000
afsr1_el1      = 0x0000000000000000
contextidr_el1 = 0x0000000000000000
vbar_el1       = 0xffff800010081800
cntp_ctl_el0   = 0x0000000000000005
cntp_cval_el0  = 0x000000095643f83a
cntv_ctl_el0   = 0x0000000000000000
cntv_cval_el0  = 0x0000000000000000
cntkctl_el1    = 0x00000000000000e6
sp_el0         = 0x000000007000abd0
isr_el1        = 0x0000000000000040
dacr32_el2     = 0x0000000000000000
ifsr32_el2     = 0x0000000000000000
cpuectlr_el1   = 0x0000001b00000040
cpumerrsr_el1  = 0x0000000000000000
l2merrsr_el1   = 0x0000000000000000
080B0 (0xffff991880b0): 0x00000000
CTRLMMR_EMMC1_CLKSEL
/dev/mem opened.
Memory mapped at address 0xffffb1c10000.
Read at address  0x001080B4 (0xffffb1c180b4): 0x00000000
MMCSD0 Subsystem Registers
Range 0x4F8800 -- 0x4F88134
/dev/mem opened.
Memory mapped at address 0xffffa0050000.

[  215.210606] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  215.216691] rcu:     1-...!: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=0
[  215.225799]  (detected by 0, t=5252 jiffies, g=32369, q=472)
[  215.231440] Task dump for CPU 1:
[  215.234653] devmem2         R  running task        0  1188   1185 0x00000002
[  215.241682] Call trace:
[  215.244125]  ret_from_fork+0x0/0x1c
[  215.247602] rcu: rcu_preempt kthread starved for 5252 jiffies! g32369 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1
[  215.258009] rcu: RCU grace-period kthread stack dump:
[  215.263041] rcu_preempt     I    0    10      2 0x00000028
[  215.268509] Call trace:
[  215.270944]  __switch_to+0x100/0x1c0
[  215.274509]  __schedule+0x2e0/0x640
[  215.277983]  schedule+0x40/0xe0
[  215.281110]  schedule_timeout+0x144/0x290
[  215.285105]  rcu_gp_kthread+0x480/0x8b8
[  215.288927]  kthread+0x138/0x158
[  215.292142]  ret_from_fork+0x10/0x1c
[  278.230605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  278.236691] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=7867
[  278.246060]  (detected by 0, t=21007 jiffies, g=32369, q=3568)
[  278.251873] Task dump for CPU 1:
[  278.255086] devmem2         R  running task        0  1188   1185 0x00000002
[  278.262116] Call trace:
[  278.264559]  ret_from_fork+0x0/0x1c
[  341.042614] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 5655 jiffies s: 161 root: 0x2/.
[  341.053219] rcu: blocking rcu_node structures:
[  341.057818] Task dump for CPU 1:
[  341.061082] devmem2         R  running task        0  1188   1185 0x00000002
[  341.068157] Call trace:
[  341.070602]  ret_from_fork+0x0/0x1c
[  341.250602] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  341.256679] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=15739
[  341.266133]  (detected by 0, t=36762 jiffies, g=32369, q=4337)
[  341.271946] Task dump for CPU 1:
[  341.275160] devmem2         R  running task        0  1188   1185 0x00000002
[  341.282188] Call trace:
[  341.284622]  ret_from_fork+0x0/0x1c
[  404.270605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  404.276691] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=23612
[  404.286145]  (detected by 0, t=52517 jiffies, g=32369, q=4981)
[  404.291959] Task dump for CPU 1:
[  404.295173] devmem2         R  running task        0  1188   1185 0x00000002
[  404.302202] Call trace:
[  404.304645]  ret_from_fork+0x0/0x1c
[  404.530610] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 21527 jiffies s: 161 root: 0x2/.
[  404.541290] rcu: blocking rcu_node structures:
[  404.545787] Task dump for CPU 1:
[  404.549044] devmem2         R  running task        0  1188   1185 0x00000002
[  404.556115] Call trace:
[  404.558551]  ret_from_fork+0x0/0x1c
[  467.290605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  467.296689] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=31484
[  467.306143]  (detected by 0, t=68272 jiffies, g=32369, q=5409)
[  467.311957] Task dump for CPU 1:
[  467.315172] devmem2         R  running task        0  1188   1185 0x00000002
[  467.322201] Call trace:
[  467.324644]  ret_from_fork+0x0/0x1c
[  468.018611] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 37399 jiffies s: 161 root: 0x2/.
[  468.029295] rcu: blocking rcu_node structures:
[  468.033809] Task dump for CPU 1:
[  468.037067] devmem2         R  running task        0  1188   1185 0x00000002
[  468.044138] Call trace:
[  468.046575]  ret_from_fork+0x0/0x1c
[  530.310605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  530.316687] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=39357
[  530.326143]  (detected by 0, t=84027 jiffies, g=32369, q=5848)
[  530.331957] Task dump for CPU 1:
[  530.335171] devmem2         R  running task        0  1188   1185 0x00000002
[  530.342200] Call trace:
[  530.344642]  ret_from_fork+0x0/0x1c
[  531.506612] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 53271 jiffies s: 161 root: 0x2/.
[  531.517299] rcu: blocking rcu_node structures:
[  531.521862] Task dump for CPU 1:
[  531.525122] devmem2         R  running task        0  1188   1185 0x00000002
[  531.532197] Call trace:
[  531.534681]  ret_from_fork+0x0/0x1c
[  593.330604] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  593.336688] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=47229
[  593.346143]  (detected by 0, t=99782 jiffies, g=32369, q=6286)
[  593.351957] Task dump for CPU 1:
[  593.355170] devmem2         R  running task        0  1188   1185 0x00000002
[  593.362199] Call trace:
[  593.364641]  ret_from_fork+0x0/0x1c
[  594.994610] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 69143 jiffies s: 161 root: 0x2/.
[  595.005290] rcu: blocking rcu_node structures:
[  595.009794] Task dump for CPU 1:
[  595.013050] devmem2         R  running task        0  1188   1185 0x00000002
[  595.020121] Call trace:
[  595.022557]  ret_from_fork+0x0/0x1c
[  656.350605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  656.356689] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=55102
[  656.366144]  (detected by 0, t=115537 jiffies, g=32369, q=6739)
[  656.372045] Task dump for CPU 1:
[  656.375260] devmem2         R  running task        0  1188   1185 0x00000002
[  656.382289] Call trace:
[  656.384731]  ret_from_fork+0x0/0x1c
[  658.482610] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 85015 jiffies s: 161 root: 0x2/.
[  658.493290] rcu: blocking rcu_node structures:
[  658.497794] Task dump for CPU 1:
[  658.501051] devmem2         R  running task        0  1188   1185 0x00000002
[  658.508123] Call trace:
[  658.510558]  ret_from_fork+0x0/0x1c
[  719.370605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  719.376690] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=62974
[  719.386145]  (detected by 0, t=131292 jiffies, g=32369, q=7199)
[  719.392046] Task dump for CPU 1:
[  719.395261] devmem2         R  running task        0  1188   1185 0x00000002
[  719.402290] Call trace:
[  719.404732]  ret_from_fork+0x0/0x1c
[  721.970613] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 100887 jiffies s: 161 root: 0x2/.
[  721.981389] rcu: blocking rcu_node structures:
[  721.985977] Task dump for CPU 1:
[  721.989238] devmem2         R  running task        0  1188   1185 0x00000002
[  721.996313] Call trace:
[  721.998798]  ret_from_fork+0x0/0x1c
[  782.390605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  782.396690] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=70846
[  782.406146]  (detected by 0, t=147047 jiffies, g=32369, q=8357)
[  782.412046] Task dump for CPU 1:
[  782.415260] devmem2         R  running task        0  1188   1185 0x00000002
[  782.422290] Call trace:
[  782.424734]  ret_from_fork+0x0/0x1c
[  785.458612] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 116759 jiffies s: 161 root: 0x2/.
[  785.469384] rcu: blocking rcu_node structures:
[  785.473925] Task dump for CPU 1:
[  785.477182] devmem2         R  running task        0  1188   1185 0x00000002
[  785.484255] Call trace:
[  785.486732]  ret_from_fork+0x0/0x1c
[  845.410605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  845.416691] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=78718
[  845.426147]  (detected by 0, t=162802 jiffies, g=32369, q=9045)
[  845.432048] Task dump for CPU 1:
[  845.435261] devmem2         R  running task        0  1188   1185 0x00000002
[  845.442291] Call trace:
[  845.444734]  ret_from_fork+0x0/0x1c
[  848.946610] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 132631 jiffies s: 161 root: 0x2/.
[  848.957381] rcu: blocking rcu_node structures:
[  848.961900] Task dump for CPU 1:
[  848.965159] devmem2         R  running task        0  1188   1185 0x00000002
[  848.972232] Call trace:
[  848.974708]  ret_from_fork+0x0/0x1c
[  908.430605] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  908.436689] rcu:     1-...0: (0 ticks this GP) idle=52a/1/0x4000000000000000 softirq=19334/19334 fqs=86590
[  908.446145]  (detected by 0, t=178557 jiffies, g=32369, q=10433)
[  908.452133] Task dump for CPU 1:
[  908.455347] devmem2         R  running task        0  1188   1185 0x00000002
[  908.462377] Call trace:
[  908.464820]  ret_from_fork+0x0/0x1c
[  912.434612] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-... } 148503 jiffies s: 161 root: 0x2/.
[  912.445385] rcu: blocking rcu_node structures:
[  912.449933] Task dump for CPU 1:
[  912.453193] devmem2         R  running task        0  1188   1185 0x00000002
[  912.460276] Call trace:
[  912.462757]  ret_from_fork+0x0/0x1c

  • 0 in reply to Amit Kamath
    TI__Guru**** 163290 points

    Amit,

    Thanks for the additional hints. If some boards are functional and some are not it could be hardware related as well.
    I will check with team internally and come back in couple of days.

    - Keerthy

  • 0 in reply to Keerthy J
    TI__Guru**** 163290 points

    Hi Amit,

    On the faulty boards are you able to boot from eMMC? I just want to know if the failing boards fail consistently.

    Best Regards,
    Keerthy

  • 0 in reply to Keerthy J
    Intellectual 800 points

    Hi Keerhty,

    Faulty boards are not able to boot from eMMC. That is exactly the problem. I think the uboot is up but linux boot fails.

    We need to give reason to HW teams so it can be fixed in next HW build cycles.

    Best regards

    Amit

  • 0 in reply to Amit Kamath
    TI__Guru**** 163290 points

    Hi Amit,

    Your boot logs attached start with:

    root@j7-evm:~# ./emmc_debug.sh
    Debug emmc failure
    CTRLMMR_EMMC0_CLKSEL
    /dev/mem opened.
    Memory mapped at address 0xffff99180000.
    Read at address 0x001ERROR: Unhandled External Abort received on 0x80000001 from S-EL1
    ERROR: exception reason=0 syndrome=0xbf000000
    Unhandled Exception from EL0
    x0 = 0x0000ffffa00b11e0
    x1 = 0x00000000004002e8
    x2 = 0x0000000000000000

    Could you please share the complete boot log from SPL to prompt with eMMC boot mode on the faulty boards?

    Best Regards,
    Keerthy

  • 0 in reply to Keerthy J
    Intellectual 800 points

    Hi Keerthy,

    I have already attached complete logs in the beginning. sdk_emmc_timeout.zip 

    The other log is when the EHCI register is accessed from memtool. This you can ignore.

    Best regards

    Amit

  • 0 in reply to Amit Kamath
    TI__Guru**** 163290 points

    Amit,

    Missed it. I went through the logs. It seems in the zip file logs you are booting from SD-MMC and the issue
    highlighted is the Kernel probe for eMMC is failing. -110 is timeout. Can you share the logs of entire boot from eMMC?
    Basically u-boot(passing) + kernel(Failing) logs. Since you have boards working with the same code. As you
    have mentioned might be related to Hardware. We will need data points.

    Best Regards,
    Keerthy

  • 0 in reply to Keerthy J
    Intellectual 800 points

    Keerthy

    After probing board found power supply issue. Fixed applied and not seeing the issue now.

    Best regards

    Amit