On Wed, 30 Oct 2019 at 01:05, Yi Zheng <goodmenzy@xxxxxxxxx> wrote:
>
> Hi,
>
> I found that there may be a dead loop in omap-hsmmc driver:
> drivers/mmc/host/omap_hsmmc.c
>
> My testing is on v4.19.58-0-g7a6bfa08b938, but the latest
> kernel(v5.4-rc5-19-g8005803a2ca0) has the same bug(I guess).
>
> In omap_hsmmc_start_command(), the IRQ is enabled too early:
> omap_hsmmc_start_command(struct omap_hsmmc_host *host, struct
> mmc_command *cmd,
> struct mmc_data *data)
> {
> /* ..................... */
> omap_hsmmc_enable_irq(host, cmd);
>
> /* ..................... */
> /* If IRQ occurs here, we run in deadloop! */
>
> host->req_in_progress = 1;
>
> /* ..................... */
> }
>
> In OMAP-HSMMC ISR, the C code is:
> static irqreturn_t omap_hsmmc_irq(int irq, void *dev_id)
> {
> struct omap_hsmmc_host *host = dev_id;
> int status;
>
> status = OMAP_HSMMC_READ(host->base, STAT);
> while (status & (INT_EN_MASK | CIRQ_EN)) {
> if (host->req_in_progress)
> omap_hsmmc_do_irq(host, status);
>
> if (status & CIRQ_EN)
> mmc_signal_sdio_irq(host->mmc);
>
> /* Flush posted write */
> status = OMAP_HSMMC_READ(host->base, STAT);
> }
>
> return IRQ_HANDLED;
> }
>
> It checks the flag host->req_in_progress, only it is set,
> omap_hsmmc_do_irq() will be called. The STAT register will be
> written in omap_hsmmc_do_irq(), that will cause the interrupts to
> be reset.
>
> If MMC IRQ occurs in that danger time-window, my single core CPU
> will run into endless loop in the ISR omap_hsmmc_irq(), due to
> STAT register is never written to clean the IRQ.
>
> Due to the small time-window, this bug is some what difficult to
> be found. I add some debug info dumpping in that two functions,
> that will cause the code slower, the bug will occur easier. It is
> realy a bug. The debug version of the source and the debug log is
> some what tedious. I only add the snippet here:
>
> The bug log:
> [ 12.765560] omap_hsmmc_runtime_resume:2354: omap_hsmmc
> 48060000.mmc: enabled
> [ 12.773006] mmc_mrq_pr_debug:279: mmc0: starting CMD6 arg
> 03200101 flags 0000049d
> [ 12.780941] omap_hsmmc_start_command:853: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101
> [ 12.790396] omap_hsmmc_start_command:859: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.800662] omap_hsmmc_start_command:862: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.811054] omap_hsmmc_start_command:871: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.821331] omap_hsmmc_start_command:878: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.831596] omap_hsmmc_start_command:888: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.841861] omap_hsmmc_start_command:919: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.852124] omap_hsmmc_start_command:923: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 12.862393] omap_hsmmc_irq:1207: omap_hsmmc 48060000.mmc:
> mmc0: enter ISR, irq=34, status=1
> [ 12.871155] omap_hsmmc_do_irq:1157: omap_hsmmc
> 48060000.mmc: IRQ Status is 1
> [ 12.878553] omap_hsmmc_irq:1226: omap_hsmmc 48060000.mmc:
> mmc0: leave ISR, irq=34
> [ 12.886450] omap_hsmmc_start_command:939: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, tracing
> [ 12.894805] CPU: 0 PID: 95 Comm: kworker/0:1H Tainted: G
> W O 4.19.58-0-g7a6bfa08b-cp5502 #25
> [ 12.904878] Hardware name: Generic AM33XX (Flattened Device Tree)
> [ 12.911292] Workqueue: kblockd blk_mq_run_work_fn
> [ 12.916316] [<c010f7fc>] (unwind_backtrace) from
> [<c010ce4c>] (show_stack+0x18/0x1c)
> [ 12.924506] [<c010ce4c>] (show_stack) from [<c0629cac>]
> (omap_hsmmc_request+0x2b0/0x4b0)
> [ 12.933014] [<c0629cac>] (omap_hsmmc_request) from
> [<c06147b8>] (mmc_start_request+0xa4/0xb8)
> [ 12.942015] [<c06147b8>] (mmc_start_request) from
> [<c0614834>] (mmc_wait_for_req+0x68/0xd0)
> [ 12.950828] [<c0614834>] (mmc_wait_for_req) from
> [<c0614918>] (mmc_wait_for_cmd+0x7c/0xa4)
> [ 12.959552] [<c0614918>] (mmc_wait_for_cmd) from
> [<c061bbe0>] (__mmc_switch+0xe0/0x2cc)
> [ 12.967998] [<c061bbe0>] (__mmc_switch) from [<c061bdf8>]
> (mmc_switch+0x2c/0x34)
> [ 12.975805] [<c061bdf8>] (mmc_switch) from [<c061be58>]
> (mmc_flush_cache+0x58/0x84)
> [ 12.983844] [<c061be58>] (mmc_flush_cache) from
> [<c0626f84>] (mmc_blk_mq_issue_rq+0x5d8/0x76c)
> [ 12.992927] [<c0626f84>] (mmc_blk_mq_issue_rq) from
> [<c0627644>] (mmc_mq_queue_rq+0x158/0x1fc)
> [ 13.002056] [<c0627644>] (mmc_mq_queue_rq) from
> [<c0470590>] (blk_mq_dispatch_rq_list+0x384/0x4c4)
> [ 13.011521] [<c0470590>] (blk_mq_dispatch_rq_list) from
> [<c047531c>] (blk_mq_sched_dispatch_requests+0xfc/0x174)
> [ 13.022248] [<c047531c>] (blk_mq_sched_dispatch_requests)
> from [<c046f020>] (__blk_mq_run_hw_queue+0xcc/0x110)
> [ 13.032793] [<c046f020>] (__blk_mq_run_hw_queue) from
> [<c01520f0>] (process_one_work+0x364/0x64c)
> [ 13.042142] omap_hsmmc_irq:1207: omap_hsmmc 48060000.mmc:
> mmc0: enter ISR, irq=34, status=108000
> [ 13.042156] omap_hsmmc_do_irq:1157: omap_hsmmc
> 48060000.mmc: IRQ Status is 108000
> [ 13.042173] omap_hsmmc_dbg_report_irq:1088: omap_hsmmc
> 48060000.mmc: MMC IRQ 0x108000 : ERRI DTO
> [ 13.042196] omap_hsmmc_irq:1226: omap_hsmmc 48060000.mmc:
> mmc0: leave ISR, irq=34
> [ 13.076452] [<c01520f0>] (process_one_work) from
> [<c0153020>] (worker_thread+0x294/0x408)
> [ 13.085089] [<c0153020>] (worker_thread) from [<c0158624>]
> (kthread+0x140/0x15c)
> [ 13.092861] [<c0158624>] (kthread) from [<c01010b4>]
> (ret_from_fork+0x14/0x20)
> [ 13.100482] Exception stack(0xdd179fb0 to 0xdd179ff8)
> [ 13.105828] 9fa0:
> 00000000 00000000 00000000 00000000
> [ 13.114411] 9fc0: 00000000 00000000 00000000 00000000
> 00000000 00000000 00000000 00000000
> [ 13.123032] 9fe0: 00000000 00000000 00000000 00000000
> 00000013 00000000
> [ 13.130027] mmc_wait_for_req_done:433: mmc0: req failed
> (CMD6): -110, cmd->retries=3, retrying...
> [ 13.139390] omap_hsmmc_start_command:853: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101
> [ 13.148839] omap_hsmmc_start_command:859: omap_hsmmc
> 48060000.mmc: mmc0: CMD6, argument 0x03200101, tracing
> [ 13.148855] omap_hsmmc_irq:1207: omap_hsmmc 48060000.mmc:
> mmc0: enter ISR, irq=34, status=108000
> [ 13.168274] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108000, req_in_progress=0, loop=1
> [ 13.178489] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108000, req_in_progress=0, loop=2
> [ 13.188704] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108002, req_in_progress=0, loop=3
> [ 13.198920] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108002, req_in_progress=0, loop=4
> [ 13.209135] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108002, req_in_progress=0, loop=5
> [ 13.219351] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108002, req_in_progress=0, loop=6
> endless looping ..............
> [ 26.754257] omap_hsmmc 48060000.mmc: !! mmc0: ISR, irq=34,
> update status: 108002, req_in_progress=0, loop=1306
> yes, endless.....
>
> The source code with line number(to be a reference to the log info)
> omap_hsmmc.c:
> 847 │ static void
> 848 │ omap_hsmmc_start_command(struct omap_hsmmc_host *host,
> struct mmc_command *cmd,
> 849 │ struct mmc_data *data)
> 850 │ {
> 851 │ int cmdreg = 0, resptype = 0, cmdtype = 0;
> 852 │
> 853 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument 0x%08x\n",
> 854 │ mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 855 │ host->cmd = cmd;
> 856 │
> 857 │ omap_hsmmc_enable_irq(host, cmd);
> 858 │
> 859 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 860 │
> 861 │ host->response_busy = 0;
> 862 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 863 │
> 864 │ if (cmd->flags & MMC_RSP_PRESENT) {
> 865 │ if (cmd->flags & MMC_RSP_136){
> 866 │ resptype = 1;
> 867 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 868 │ }else if (cmd->flags & MMC_RSP_BUSY) {
> 869 │ resptype = 3;
> 870 │ host->response_busy = 1;
> 871 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 872 │ } else {
> 873 │ resptype = 2;
> 874 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 875 │ }
> 876 │ }
> 877 │
> 878 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 879 │
> 880 │ /*
> 881 │ * Unlike OMAP1 controller, the cmdtype does not
> seem to be based on
> 882 │ * ac, bc, adtc, bcr. Only commands ending an open
> ended transfer need
> 883 │ * a val of 0x3, rest 0x0.
> 884 │ */
> 885 │ if (cmd == host->mrq->stop)
> 886 │ cmdtype = 0x3;
> 887 │
> 888 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 889 │
> 890 │ cmdreg = (cmd->opcode << 24) | (resptype << 16) |
> (cmdtype << 22);
> 891 │
> 892 │ if ((host->flags & AUTO_CMD23) &&
> mmc_op_multi(cmd->opcode) &&
> 893 │ host->mrq->sbc) {
> 894 │ cmdreg |= ACEN_ACMD23;
> 895 │
> 896 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 897 │
> 898 │ OMAP_HSMMC_WRITE(host->base, SDMASA,
> host->mrq->sbc->arg);
> 899 │
> 900 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 901 │ }
> 902 │ if (data) {
> 903 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 904 │
> 905 │ cmdreg |= DP_SELECT | MSBS | BCE;
> 906 │ if (data->flags & MMC_DATA_READ)
> 907 │ cmdreg |= DDIR;
> 908 │ else
> 909 │ cmdreg &= ~(DDIR);
> 910 │
> 911 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d,
> argument 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode,
> cmd->arg);
> 912 │ }
> 913 │
> 914 │ if (host->use_dma)
> 915 │ cmdreg |= DMAE;
> 916 │
> 917 │ host->req_in_progress = 1;
> 918 │
> 919 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 920 │
> 921 │ OMAP_HSMMC_WRITE(host->base, ARG, cmd->arg);
> 922 │
> 923 │ dev_vdbg(mmc_dev(host->mmc), "%s: CMD%d, argument
> 0x%08x, tracing\n", mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> 924 │
> 925 │ OMAP_HSMMC_WRITE(host->base, CMD, cmdreg);
> 926 │
> 927 │ if(6 == cmd->opcode){
> 928 │ #define my_dynamic_dev_dbg(dev, fmt, ...) \
> 929 │ do { \
> 930 │ DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, fmt); \
> 931 │ if (DYNAMIC_DEBUG_BRANCH(descriptor)){ \
> 932 │ __dynamic_dev_dbg(&descriptor, dev, fmt, \
> 933 │ ##__VA_ARGS__); \
> 934 │ dump_stack(); \
> 935 │ } \
> 936 │ } while (0)
> 937 │
> 938 │ my_dynamic_dev_dbg(mmc_dev(host->mmc), "%s:
> CMD%d, tracing\n",
> 939 │ mmc_hostname(host->mmc), cmd->opcode);
> 940 │ #undef my_dynamic_dev_dbg
> 941 │ }
> 942 │ }
> ................
> 1200 │ static irqreturn_t omap_hsmmc_irq(int irq, void *dev_id)
> 1201 │ {
> 1202 │ struct omap_hsmmc_host *host = dev_id;
> 1203 │ int status;
> 1204 │ unsigned int loop_count = 0;
> 1205 │
> 1206 │ status = OMAP_HSMMC_READ(host->base, STAT);
> 1207 │ dev_vdbg(mmc_dev(host->mmc), "%s: enter ISR,
> irq=%d, status=%x\n", mmc_hostname(host->mmc), irq, status);
> 1208 │
> 1209 │ while (status & (INT_EN_MASK | CIRQ_EN)) {
> 1210 │ loop_count++;
> 1211 │
> 1212 │ if (host->req_in_progress)
> 1213 │ omap_hsmmc_do_irq(host, status);
> 1214 │
> 1215 │ if (status & CIRQ_EN)
> 1216 │ mmc_signal_sdio_irq(host->mmc);
> 1217 │
> 1218 │ /* Flush posted write */
> 1219 │ status = OMAP_HSMMC_READ(host->base, STAT);
> 1220 │ if(status){
> 1221 │ dev_warn(mmc_dev(host->mmc), "!! %s: ISR,
> irq=%d, update status: %x, req_in_progress=%d, loop=%u\n",
> 1222 │ mmc_hostname(host->mmc), irq, status,
> host->req_in_progress, loop_count);
> 1223 │ }
> 1224 │ }
> 1225 │
> 1226 │ dev_vdbg(mmc_dev(host->mmc), "%s: leave ISR,
> irq=%d\n", mmc_hostname(host->mmc), irq);
> 1227 │ return IRQ_HANDLED;
> 1228 │ }
>
>
>
> My patch to fixup that bug is here:
> diff -upr linux-git/drivers/mmc/host/omap_hsmmc.c
> linux-fixup/drivers/mmc/host/omap_hsmmc.c
> --- linux-git/drivers/mmc/host/omap_hsmmc.c 2019-10-29
> 21:33:05.127638851 +0800
> +++ linux-fixup/drivers/mmc/host/omap_hsmmc.c 2019-10-29
> 21:37:44.957637473 +0800
> @@ -852,8 +852,6 @@ omap_hsmmc_start_command(struct omap_hsm
> mmc_hostname(host->mmc), cmd->opcode, cmd->arg);
> host->cmd = cmd;
>
> - omap_hsmmc_enable_irq(host, cmd);
> -
> host->response_busy = 0;
> if (cmd->flags & MMC_RSP_PRESENT) {
> if (cmd->flags & MMC_RSP_136)
> @@ -891,7 +889,8 @@ omap_hsmmc_start_command(struct omap_hsm
> if (host->use_dma)
> cmdreg |= DMAE;
>
> - host->req_in_progress = 1;
> + host->req_in_progress = 1; /* the flag must be set BEFORE irq enabled */
> + omap_hsmmc_enable_irq(host, cmd);
>
> OMAP_HSMMC_WRITE(host->base, ARG, cmd->arg);
> OMAP_HSMMC_WRITE(host->base, CMD, cmdreg);
>
Thanks for the detailed description to the problem.
The patch above seems like a step in the right direction (I am fine to
apply something along those lines), however, I does look a bit odd
that ->host->req_in_progress isn't protected by a lock. Doesn't it?
In any case, I suggest you to repost this as proper patch with a
changelog. Also, please include some of the folkz from TI who has been
contributing to the driver lately.
Kind regards
Uffe
