Message-ID: <CALAqxLXBGAEAQ6402JY_1_U2U0XJ8TymCJmVuFrxRJsWW232PA@mail.gmail.com>
Date:	Fri, 12 Aug 2016 16:33:15 -0700
From:	John Stultz <john.stultz@...aro.org>
To:	Jaehoon Chung <jh80.chung@...sung.com>
Cc:	Ulf Hansson <ulf.hansson@...aro.org>,
	Guodong Xu <guodong.xu@...aro.org>,
	lkml <linux-kernel@...r.kernel.org>,
	Zhangfei Gao <zhangfei.gao@...aro.org>,
	Shawn Lin <shawn.lin@...k-chips.com>
Subject: Re: WARNING: CPU: 0 PID: 1271 at drivers/mmc/core/core.c:991 mmc_release_host+0xa0/0xa8

On Fri, Aug 12, 2016 at 1:01 AM, Jaehoon Chung <jh80.chung@...sung.com> wrote:
> On 08/12/2016 04:13 PM, John Stultz wrote:
>> On Thu, Aug 4, 2016 at 9:52 PM, John Stultz <john.stultz@...aro.org> wrote:
>>> Hey Ulf,
>>>   Since moving my HiKey branch to pre-v4.8-rc1 (linus's HEAD), I've
>>> been seeing the following warning occasionally. Usually after seeing
>>> it, the system will refuse to reboot (system does the "Emergency
>>> remount complete" but then just sits there, and if I ctrl-c I can use
>>> the shell fine but many commands will get me stuck).
>>>
>>> Anyway, if you have any ideas...
>>>
>>> thanks
>>> -john
>>>
>>> [   24.154245] ------------[ cut here ]------------
>>> [   24.158903] WARNING: CPU: 2 PID: 1273 at
>>> drivers/mmc/core/core.c:991 mmc_release_host+0xa0/0xa8
>>> [   24.167605]
>>> [   24.169104] CPU: 2 PID: 1273 Comm: mmcqd/0 Not tainted
>>> 4.7.0-11945-gb30f1d6-dirty #706
>>> [   24.177024] Hardware name: HiKey Development Board (DT)
>>> [   24.182253] task: ffffffc0793d8c80 task.stack: ffffffc078c48000
>>> [   24.188178] PC is at mmc_release_host+0xa0/0xa8
>>> [   24.192725] LR is at mmc_put_card+0x18/0x3c
>>> [   24.196917] pc : [<ffffff80086c2550>] lr : [<ffffff80086c31f4>]
>>> pstate: 80000145
>>> [   24.204317] sp : ffffffc078c4bd20
>>> [   24.207636] x29: ffffffc078c4bd20 x28: 0000000000000000
>>> [   24.212975] x27: 0000000000000000 x26: ffffffc077903420
>>> [   24.216220] x25: ffffffc078788028 x24: ffffffc0787e8800
>>> [   24.216232] x23: ffffffc078788000 x22: 0000000000000000
>>> [   24.216243] x21: 0000000000000000 x20: ffffffc078788018
>>> [   24.216254] x19: ffffffc0787e8800 x18: 0000000000000000
>>> [   24.216265] x17: 0000000000000000 x16: 0000000000000000
>>> [   24.216276] x15: 0000000000000000 x14: ffffffc078789430
>>> [   24.216288] x13: 000000000000002f x12: 000000000000b853
>>> [   24.216299] x11: ffffffc077903420 x10: 0000000000000860
>>> [   24.216310] x9 : ffffffc078c48000 x8 : ffffffc0793d9540
>>> [   24.216322] x7 : 0000000000d3f8c7 x6 : 0000000000002bd0
>>> [   24.216333] x5 : 00000000021458fa x4 : 00ffffffffffffff
>>> [   24.216344] x3 : 00000000d0555555 x2 : ffffffc078c4bd5c
>>> [   24.216355] x1 : 0000000000000000 x0 : 0000000000000000
>>> [   24.216366]
>>> [   24.216372] ---[ end trace 74dade4766b71d8d ]---
>>> [   24.216377] Call trace:
>>> [   24.216386] Exception stack(0xffffffc078c4bb50 to 0xffffffc078c4bc80)
>>> [   24.216394] bb40:
>>> ffffffc0787e8800 0000008000000000
>>> [   24.216403] bb60: ffffffc078c4bd20 ffffff80086c2550
>>> ffffff8008ca6000 ffffffc0784fb200
>>> [   24.216411] bb80: ffffffc07bf4b7e8 0000000000000008
>>> ffffffc0793d8d00 ffffff8008c82780
>>> [   24.216420] bba0: ffffffc078c4bbe0 ffffff800843576c
>>> ffffffc078c4bbf0 ffffff800843576c
>>> [   24.216429] bbc0: ffffffc078c4bcc0 ffffffc078c4bc78
>>> ffffffc078c4bc10 ffffff800843576c
>>> [   24.216437] bbe0: ffffffc078c4bce0 ffffffc078c4bc98
>>> 0000000000000000 0000000000000000
>>> [   24.216445] bc00: ffffffc078c4bd5c 00000000d0555555
>>> 00ffffffffffffff 00000000021458fa
>>> [   24.216452] bc20: 0000000000002bd0 0000000000d3f8c7
>>> ffffffc0793d9540 ffffffc078c48000
>>> [   24.216460] bc40: 0000000000000860 ffffffc077903420
>>> 000000000000b853 000000000000002f
>>> [   24.216467] bc60: ffffffc078789430 0000000000000000
>>> 0000000000000000 0000000000000000
>>> [   24.216479] [<ffffff80086c2550>] mmc_release_host+0xa0/0xa8
>>> [   24.216486] [<ffffff80086c31f4>] mmc_put_card+0x18/0x3c
>>> [   24.216497] [<ffffff80086d30e4>] mmc_blk_issue_rq+0x11c/0x4a4
>>> [   24.216506] [<ffffff80086d3e44>] mmc_queue_thread+0x98/0x158
>>> [   24.216517] [<ffffff80080cfd7c>] kthread+0xd0/0xe4
>>> [   24.216527] [<ffffff8008082e90>] ret_from_fork+0x10/0x40
>>
>>
>> Hey Ulf,
>>   I *think* I've narrowed this down to
>> 6024e16654c1e1a2475e848d735963d05a12dba9 ("mmc: dw_mmc: set to
>> MMC_CAP_ERASE by default"). Its fairly sporadic so I may be seeing
>> this as a false positive, but after reverting that patch I've
>> seemingly stopped seeing the issue.
>
> Hmm, i don't think so. I *guess* it's not related with commit 6024e16654.

Well, with that patch reverted I've not seen the issue, but with it I
can trigger it fairly quickly.


> Before calling mmc_put_card(), is it issued the discard request?
>
>         if ((!req && !(mq->flags & MMC_QUEUE_NEW_REQUEST)) ||
>              (cmd_flags & MMC_REQ_SPECIAL_MASK))
>
> Which condition hit?

So I'm seeing those conditions hit quite a lot:

[   45.056827] JDB: !req: 0   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 1
[   45.066299] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0
[   45.135398] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0
[   45.143085] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0
[   45.152183] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0
[   45.161129] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0


But right before I saw a warning:

[   51.210393] JDB: !req: 0   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 1
[   51.218085] ------------[ cut here ]------------
[   51.222800] WARNING: CPU: 0 PID: 1273 at
drivers/mmc/core/core.c:264 mmc_start_request+0x100/0x108
[   51.231805]
[   51.233356] CPU: 0 PID: 1273 Comm: mmcqd/0 Not tainted
4.8.0-rc1-00056-gf1f4a8e-dirty #791
[   51.241667] Hardware name: HiKey Development Board (DT)
[   51.246940] task: ffffffc078c0b200 task.stack: ffffffc0786b4000
[   51.252913] PC is at mmc_start_request+0x100/0x108
[   51.257756] LR is at mmc_start_request+0x18/0x108
[   51.262508] pc : [<ffffff80086c3090>] lr : [<ffffff80086c2fa8>]
pstate: 00000145
[   51.269947] sp : ffffffc0786b7bf0
[   51.273308] x29: ffffffc0786b7bf0 x28: 0000000000000000
[   51.278743] x27: ffffffc078613018 x26: 0000000000000001
[   51.284172] x25: 0000000000000000 x24: ffffffc0786b7d5c
[   51.289602] x23: 0000000000000000 x22: ffffffc078613068
[   51.295033] x21: ffffffc0786131e8 x20: ffffffc078611800
[   51.300464] x19: ffffffc078613068 x18: 0000000000000000
[   51.305891] x17: 0000000000000000 x16: 0000000000000000
[   51.311320] x15: 00000000000011b1 x14: ffffff8008087f08
[   51.316749] x13: ffffffc0786b002f x12: ffffff8008087f5c
[   51.322179] x11: ffffffc0786b7d20 x10: 0000000000000000
[   51.327607] x9 : 0000000000000000 x8 : 0000000000001000
[   51.333036] x7 : ffffffc077392180 x6 : 000000001fde3fff
[   51.338464] x5 : 0000000000000000 x4 : 000000001fde3000
[   51.343892] x3 : 000000000000003f x2 : 0000000000000020
[   51.349319] x1 : 0000000000000001 x0 : 0000000000000020
[   51.354743]
[   51.356279] ---[ end trace 2c3d9b4e1f4fc435 ]---
[   51.360940] Call trace:
[   51.363440] Exception stack(0xffffffc0786b7a20 to 0xffffffc0786b7b50)
[   51.369942] 7a20: ffffffc078613068 0000008000000000
ffffffc0786b7bf0 ffffff80086c3090
[   51.377830] 7a40: 0000000000000040 000000000000003f
000000004c7bd000 0000000000000000
[   51.385719] 7a60: 000000001fde3fff ffffffc077392180
0000000000001000 0000000000000000
[   51.393609] 7a80: 0000000000000000 ffffffc0786b7d20
ffffff8008087f5c ffffffc0786b002f
[   51.401496] 7aa0: ffffff8008087f08 00000000000011b1
0000000000000000 0000000000000000
[   51.409383] 7ac0: 0000000000000020 0000000000000001
0000000000000020 000000000000003f
[   51.417271] 7ae0: 000000001fde3000 0000000000000000
000000001fde3fff ffffffc077392180
[   51.425158] 7b00: 0000000000001000 0000000000000000
0000000000000000 ffffffc0786b7d20
[   51.433046] 7b20: ffffff8008087f5c ffffffc0786b002f
ffffff8008087f08 00000000000011b1
[   51.440928] 7b40: 0000000000000000 0000000000000000
[   51.445863] [<ffffff80086c3090>] mmc_start_request+0x100/0x108
[   51.451754] [<ffffff80086c3fe8>] mmc_start_req+0x280/0x3c8
[   51.457305] [<ffffff80086d364c>] mmc_blk_issue_rw_rq+0xac/0x9b0
[   51.463285] [<ffffff80086d3fec>] mmc_blk_issue_rq+0x9c/0x4d8
[   51.469004] [<ffffff80086d4e00>] mmc_queue_thread+0x98/0x158
[   51.474725] [<ffffff80080d04dc>] kthread+0xd0/0xe4
[   51.479577] [<ffffff8008082e90>] ret_from_fork+0x10/0x40
[   51.488484] ------------[ cut here ]------------

[   51.774524] ------------[ cut here ]------------
[   51.779150] WARNING: CPU: 0 PID: 1273 at
drivers/mmc/core/core.c:264 mmc_start_request+0x100/0x108
[   51.788107]
[   51.789599] CPU: 0 PID: 1273 Comm: mmcqd/0 Tainted: G        W
 4.8.0-rc1-00056-gf1f4a8e-dirty #791
[   51.799078] Hardware name: HiKey Development Board (DT)
[   51.804302] task: ffffffc078c0b200 task.stack: ffffffc0786b4000
[   51.810222] PC is at mmc_start_request+0x100/0x108
[   51.815012] LR is at mmc_start_request+0x18/0x108
[   51.819715] pc : [<ffffff80086c3090>] lr : [<ffffff80086c2fa8>]
pstate: 40000145
[   51.827109] sp : ffffffc0786b79b0
[   51.830422] x29: ffffffc0786b79b0 x28: ffffffc0786b7bc8
[   51.835749] x27: ffffff8008bcd5f0 x26: ffffff8008a7f430
[   51.841075] x25: 0000000000000001 x24: ffffffc077a3f200
[   51.846401] x23: 0000000000000000 x22: 000000010001573e
[   51.851727] x21: ffffffc0786b7a40 x20: ffffffc078611800
[   51.857053] x19: ffffffc0786b7a20 x18: 0000000000000000
[   51.862378] x17: 0000000000000000 x16: 0000000000000000
[   51.867704] x15: 0000000000000002 x14: 0000000000000000
[   51.873030] x13: 0000000000000000 x12: 0000000000000002
[   51.878355] x11: ffffff80089df458 x10: 0000000000000860
[   51.883681] x9 : ffffffc0786b4000 x8 : ffffffc078c0bac0
[   51.889006] x7 : ffffffc07bf257a0 x6 : 0000000000000000
[   51.894333] x5 : 000000000000000d x4 : 0000000040000543
[   51.899658] x3 : 0000000000000195 x2 : ffffff8008d666d8
[   51.904983] x1 : 0000000000000002 x0 : 0000000000000000
[   51.910308]
[   51.911797] ---[ end trace 2c3d9b4e1f4fc437 ]---
[   51.916412] Call trace:
[   51.918858] Exception stack(0xffffffc0786b77e0 to 0xffffffc0786b7910)
[   51.925300] 77e0: ffffffc0786b7a20 0000008000000000
ffffffc0786b79b0 ffffff80086c3090
[   51.933131] 7800: ffffffc0786b7850 ffffff80089b8b88
ffffffc07bf25780 0000000000000000
[   51.940962] 7820: ffffffc078c0b200 ffffffc0387e1900
ffffffc077bdd400 ffffff80089b921c
[   51.948793] 7840: 0000000000000001 ffffffc07bf1f090
ffffffc0786b78b0 ffffff80089b921c
[   51.956625] 7860: ffffffc0786b4000 0000008000000000
ffffffc0786b7a00 ffffff80086c37ec
[   51.964456] 7880: 0000000000000000 0000000000000002
ffffff8008d666d8 0000000000000195
[   51.972287] 78a0: 0000000040000543 000000000000000d
0000000000000000 ffffffc07bf257a0
[   51.980118] 78c0: ffffffc078c0bac0 ffffffc0786b4000
0000000000000860 ffffff80089df458
[   51.987949] 78e0: 0000000000000002 0000000000000000
0000000000000000 0000000000000002
[   51.995778] 7900: 0000000000000000 0000000000000000
[   52.000656] [<ffffff80086c3090>] mmc_start_request+0x100/0x108
[   52.006490] [<ffffff80086c30e8>] __mmc_start_req+0x50/0x7c
[   52.011976] [<ffffff80086c37cc>] mmc_wait_for_cmd+0x50/0x74
[   52.017550] [<ffffff80086d2db8>] get_card_status.isra.30+0x50/0x68
[   52.023731] [<ffffff80086d2e44>] card_busy_detect.isra.31+0x74/0x150
[   52.030086] [<ffffff80086d2ff4>] mmc_blk_err_check+0xd4/0x544
[   52.035833] [<ffffff80086c3e44>] mmc_start_req+0xdc/0x3c8
[   52.041233] [<ffffff80086d364c>] mmc_blk_issue_rw_rq+0xac/0x9b0
[   52.047153] [<ffffff80086d4188>] mmc_blk_issue_rq+0x238/0x4d8
[   52.052901] [<ffffff80086d4e00>] mmc_queue_thread+0x98/0x158
[   52.058562] [<ffffff80080d04dc>] kthread+0xd0/0xe4
[   52.063355] [<ffffff8008082e90>] ret_from_fork+0x10/0x40

[   52.068862] JDB: !req: 1   !flags&MMC_QUEUE_NEW_REQUEST: 1
is_special(req): 0
[   52.076168] ------------[ cut here ]------------
[   52.080791] WARNING: CPU: 0 PID: 1273 at
drivers/mmc/core/core.c:991 mmc_release_host+0xa0/0xa8
[   52.089488]
[   52.090979] CPU: 0 PID: 1273 Comm: mmcqd/0 Tainted: G        W
 4.8.0-rc1-00056-gf1f4a8e-dirty #791
[   52.100458] Hardware name: HiKey Development Board (DT)
[   52.105682] task: ffffffc078c0b200 task.stack: ffffffc0786b4000
[   52.111601] PC is at mmc_release_host+0xa0/0xa8
[   52.116131] LR is at mmc_put_card+0x18/0x3c
[   52.120312] pc : [<ffffff80086c34d8>] lr : [<ffffff80086c417c>]
pstate: 80000145
[   52.127707] sp : ffffffc0786b7d20
[   52.131019] x29: ffffffc0786b7d20 x28: 0000000000000000
[   52.136346] x27: ffffffc078613018 x26: ffffffc077a3f140
[   52.141672] x25: ffffffc078613028 x24: ffffffc0786b4000
[   52.146998] x23: ffffffc078611800 x22: ffffffc078613000
[   52.152323] x21: 0000000000000001 x20: ffffffc078612800
[   52.157648] x19: ffffffc078611800 x18: 0000000000000000
[   52.162973] x17: 0000000000000000 x16: 0000000000000000
[   52.168298] x15: 0000000000001244 x14: 69202031203a5453
[   52.173623] x13: 45555145525f5745 x12: 4e5f45554555515f
[   52.178948] x11: 434d4d267367616c x10: 662120202031203a
[   52.184274] x9 : 71657221203a4244 x8 : 203a29716572286c
[   52.189598] x7 : 0000000000001245 x6 : ffffff8008f5a90b
[   52.194924] x5 : 0000000000000000 x4 : 0000000000000000
[   52.200249] x3 : 0000000000000002 x2 : 0000000000000001
[   52.205574] x1 : 0000000000000000 x0 : 0000000000000000
[   52.210899]
[   52.212387] ---[ end trace 2c3d9b4e1f4fc438 ]---
[   52.217002] Call trace:
[   52.219448] Exception stack(0xffffffc0786b7b50 to 0xffffffc0786b7c80)
[   52.225889] 7b40:
ffffffc078611800 0000008000000000
[   52.233719] 7b60: ffffffc0786b7d20 ffffff80086c34d8
ffffff8008cc39b8 0000000000000000
[   52.241551] 7b80: 0000000000000000 0000000000000042
0000000000000140 ffffffc0786b7c90
[   52.249382] 7ba0: ffffff8008d39000 0000000000000042
0000000000000000 ffffff8008b5a270
[   52.257214] 7bc0: 0000000100000004 ffffff8008cc39f8
ffffffc0786b7c80 ffffff80080f7e3c
[   52.265045] 7be0: ffffffc078611cc8 ffffffc078612800
0000000000000000 0000000000000000
[   52.272876] 7c00: 0000000000000001 0000000000000002
0000000000000000 0000000000000000
[   52.280707] 7c20: ffffff8008f5a90b 0000000000001245
203a29716572286c 71657221203a4244
[   52.288538] 7c40: 662120202031203a 434d4d267367616c
4e5f45554555515f 45555145525f5745
[   52.296369] 7c60: 69202031203a5453 0000000000001244
0000000000000000 0000000000000000
[   52.304199] [<ffffff80086c34d8>] mmc_release_host+0xa0/0xa8
[   52.309772] [<ffffff80086c417c>] mmc_put_card+0x18/0x3c
[   52.315000] [<ffffff80086d4094>] mmc_blk_issue_rq+0x144/0x4d8
[   52.320748] [<ffffff80086d4e00>] mmc_queue_thread+0x98/0x158
[   52.326409] [<ffffff80080d04dc>] kthread+0xd0/0xe4
[   52.331201] [<ffffff8008082e90>] ret_from_fork+0x10/0x40


>> Anyway, I'll do some further testing tomorrow w/ that removed. Usually
>> I see the issue 1-2 times an hour, so if I go the day w/o a problem
>> I'll let you know.
>>
>> Zhangfei/Guodong: Any ideas as to why ERASE might cause trouble on HiKey?
>
> Did you try to send the Erase command directly? e,g fstrim or other things?

Android's vold might be, but I'm not.

> Is it occurred on every booting time?

Unfortunately no. Sometimes it happens shortly after bootup, sometimes
I've seen it after suspend/resume cycle. Sometimes it triggers after a
while leaving the board idle. I've not sorted out the pattern.

thanks
-john

Powered by blists - more mailing lists