Re: mei: cancel stall timers in mei_reset

Re: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

Hi,

In case my previous mail went to /dev/null, it is all about the flood of 
error messages in the system log, like these:

mei_me 0000:00:16.0: reset: wrong host start response
mei_me 0000:00:16.0: unexpected reset: dev_state = INIT_CLIENTS
mei_me 0000:00:16.0: reset: unexpected enumeration response hbm.
mei_me 0000:00:16.0: unexpected reset: dev_state = INIT_CLIENTS

Even after the patches (https://lkml.org/lkml/2013/9/2/162) that went 
into kernel 3.10.15, the problem still shows up occasionally on my 
Lenovo X230 laptop with kernels 3.10.15, 3.10.16 and 3.11.6. It seems to 
be retated to IRQ handling now.

When the problem occurs, mei_reset() is called repeatedly and the system 
logs grow rapidly until they consume all free disk space.

Most of the messages are output by mei_hbm_dispatch().

I added debug prints to the code of mei_hbm_dispatch() and found the 
following:

1. When HOST_START_RES_CMD response is being handled, dev->hbm_state is 
0x2 sometimes, that is, MEI_HBM_ENUM_CLIENTS (!) rather than 
MEI_HBM_START what it probably should be. That's why the error message 
is printed and mei_reset() is called again.

2. When HOST_ENUM_RES_CMD response is being handled, dev->hbm_state is 
0x1 (MEI_HBM_START) while it should be MEI_HBM_ENUM_CLIENTS. This also 
results in an error message and mei_reset().

That is, dev->hbm_state contains a wrong value in both cases. I haven't 
figured out so far why it happens.

Do you know how to fix that?

Messages from the system log related to MEI:
-----------------
13:30:42 systemd-sleep[9364]: System resumed.
13:30:42 kernel: mei_me 0000:00:16.0: reset: properties response hbm 
wrong status.
13:30:42 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
<...>
13:30:47 kernel: mei_me 0000:00:16.0: wait hw ready failed. status = -110
<...>
13:31:17 kernel: mei_me 0000:00:16.0: reset: init clients timeout 
hbm_state = 1.
13:31:17 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
13:31:17 kernel: mei_me 0000:00:16.0: reset: wrong host start response 
(dev_state: 0x1, hbm_state: 0x2)
13:31:17 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
13:31:17 kernel: mei_me 0000:00:16.0: reset: unexpected enumeration 
response hbm (dev_state: 0x1, hbm_state: 0x1)
13:31:17 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
13:31:17 kernel: mei_me 0000:00:16.0: reset: wrong host start response 
(dev_state: 0x1, hbm_state: 0x2)
13:31:17 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
13:31:17 kernel: mei_me 0000:00:16.0: reset: unexpected enumeration 
response hbm (dev_state: 0x1, hbm_state: 0x1)
13:31:17 kernel: mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
-----------------

By the way, here is MEI hw info from lspci output:
-----------------
00:16.0 Communication controller [0780]: Intel Corporation 7 Series/C210 
Series Chipset Family MEI Controller #1 [8086:1e3a] (rev 04)
	Subsystem: Lenovo Device [17aa:21fa]
	Flags: bus master, fast devsel, latency 0, IRQ 11
	Memory at f2535000 (64-bit, non-prefetchable) [size=16]
	Capabilities: [50] Power Management version 3
	Capabilities: [8c] MSI: Enable- Count=1/1 Maskable- 64bit+
	Kernel modules: mei_me
-----------------

If you need other info, please let me know.

Regards,
Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com

RE: mei: cancel stall timers in mei_reset

[Winkler, Tomas]

> -----Original Message-----
> From: Eugene Shatokhin [mailto:eugene.shatokhin@rosalab.ru]
> Sent: Friday, November 01, 2013 14:27
> To: Winkler, Tomas
> Cc: Usyskin, Alexander; Nicolò Costanza; Alex Burmashev; LKML
> Subject: Re: mei: cancel stall timers in mei_reset
> 
> Hi,
> 
> In case my previous mail went to /dev/null, it is all about the flood of
> error messages in the system log, like these:
> 
> mei_me 0000:00:16.0: reset: wrong host start response
> mei_me 0000:00:16.0: unexpected reset: dev_state = INIT_CLIENTS
> mei_me 0000:00:16.0: reset: unexpected enumeration response hbm.
> mei_me 0000:00:16.0: unexpected reset: dev_state = INIT_CLIENTS
>

I would appreciate the full log and your .config 
Thanks
Tomas

 

RE: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

[-- Attachment #1: Type: text/plain, Size: 899 bytes --]

----- Original Message -----
> I would appreciate the full log and your .config 

I have attached the config and the log.

Meanwhile, I have found one suspicious place in the code that could be related: mei_reset() ignores the return value of mei_hw_start(). According to the logs, there was at least the following interesting call sequence before things went wrong:

mei_reset() => mei_hw_start() => .hw_start() callback, which is mei_me_hw_start() => mei_me_hw_ready_wait().

mei_me_hw_ready_wait() reported "wait hw ready failed" and returned -ETIMEDOUT, that error was propagated to mei_hw_start(). mei_reset(), however, does not check the return value of that function and goes on even if it returns an error: sets dev->dev_state to MEI_DEV_INIT_CLIENTS, calls mei_hbm_start_req(dev), etc.

I am not sure if this is intentional and if this is related to the problem, but still.

Regards,
Eugene

[-- Attachment #2: files.tar.bz2 --]
[-- Type: application/x-bzip-compressed-tar, Size: 62338 bytes --]

Re: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

On 11/04/2013 07:48 PM, Eugene Shatokhin wrote:
> ----- Original Message -----
>> I would appreciate the full log and your .config
>
> I have attached the config and the log.
>
> Meanwhile, I have found one suspicious place in the code that could be related: mei_reset() ignores the return value of mei_hw_start(). According to the logs, there was at least the following interesting call sequence before things went wrong:
>
> mei_reset() => mei_hw_start() => .hw_start() callback, which is mei_me_hw_start() => mei_me_hw_ready_wait().
>
> mei_me_hw_ready_wait() reported "wait hw ready failed" and returned -ETIMEDOUT, that error was propagated to mei_hw_start(). mei_reset(), however, does not check the return value of that function and goes on even if it returns an error: sets dev->dev_state to MEI_DEV_INIT_CLIENTS, calls mei_hbm_start_req(dev), etc.
>
> I am not sure if this is intentional and if this is related to the problem, but still.
>

Oh, looks like it is mei_hw_start() that first ignores the error. Might 
be a problem anyway.

Regards,
Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com

RE: mei: cancel stall timers in mei_reset

[Usyskin, Alexander]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 2174 bytes --]

Hi

The problem that you found was fixed in patch here: https://lkml.org/lkml/2013/6/23/169
And this patch merged into 3.11 according to http://lxr.free-electrons.com/source/drivers/misc/mei/mei_dev.h?v=3.11
Can you re-check with latest 3.11 point release?


Thanks
--
Sasha

-----Original Message-----
From: Eugene Shatokhin [mailto:eugene.shatokhin@rosalab.ru] 
Sent: Tuesday, November 05, 2013 10:07
To: Winkler, Tomas
Cc: Usyskin, Alexander; Nicolò Costanza; Alex Burmashev; LKML
Subject: Re: mei: cancel stall timers in mei_reset

On 11/04/2013 07:48 PM, Eugene Shatokhin wrote:
> ----- Original Message -----
>> I would appreciate the full log and your .config
>
> I have attached the config and the log.
>
> Meanwhile, I have found one suspicious place in the code that could be related: mei_reset() ignores the return value of mei_hw_start(). According to the logs, there was at least the following interesting call sequence before things went wrong:
>
> mei_reset() => mei_hw_start() => .hw_start() callback, which is mei_me_hw_start() => mei_me_hw_ready_wait().
>
> mei_me_hw_ready_wait() reported "wait hw ready failed" and returned -ETIMEDOUT, that error was propagated to mei_hw_start(). mei_reset(), however, does not check the return value of that function and goes on even if it returns an error: sets dev->dev_state to MEI_DEV_INIT_CLIENTS, calls mei_hbm_start_req(dev), etc.
>
> I am not sure if this is intentional and if this is related to the problem, but still.
>

Oh, looks like it is mei_hw_start() that first ignores the error. Might 
be a problem anyway.

Regards,
Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com
---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

Hi,

On 11/05/2013 01:58 PM, Usyskin, Alexander wrote:
> The problem that you found was fixed in patch here: https://lkml.org/lkml/2013/6/23/169
> And this patch merged into 3.11 according to http://lxr.free-electrons.com/source/drivers/misc/mei/mei_dev.h?v=3.11
> Can you re-check with latest 3.11 point release?

Thanks for the info!

Yes, I found this patch an hour ago as well as a similar one for hw_reset.

As we are currently more interested in kernel 3.10.x in ROSA (it is our 
main production kernel), I will apply these patches to it first and 
re-check.

Regards,

Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com

RE: mei: cancel stall timers in mei_reset

[Winkler, Tomas]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 851 bytes --]


> Hi,
> 
> On 11/05/2013 01:58 PM, Usyskin, Alexander wrote:
> > The problem that you found was fixed in patch here:
> https://lkml.org/lkml/2013/6/23/169
> > And this patch merged into 3.11 according to http://lxr.free-
> electrons.com/source/drivers/misc/mei/mei_dev.h?v=3.11
> > Can you re-check with latest 3.11 point release?
> 
> Thanks for the info!
> 
> Yes, I found this patch an hour ago as well as a similar one for hw_reset.
> 
> As we are currently more interested in kernel 3.10.x in ROSA (it is our
> main production kernel), I will apply these patches to it first and
> re-check.
>
This patches only catch the error, our goal is to discover why it is failing. 
Thanks
Tomas
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

[-- Attachment #1: Type: text/plain, Size: 1857 bytes --]

On 11/05/2013 03:49 PM, Winkler, Tomas wrote:
> This patches only catch the error, our goal is to discover why it is failing.

I have just applied these error-handling-related patches to kernel 
3.10.15 (without commenting out schedule_delayed_work(&dev->timer_work, 
HZ) yet) and checked the system again.

The full log is attached, the config is the same as I sent before.

Here are MEI-related messages from there:

---------------------------------------
[    1.011579] mei_me 0000:00:16.0: setting latency timer to 64
[    1.011616] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  215.552616] mei_me 0000:00:16.0: suspend
[  216.675402] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  250.390001] mei_me 0000:00:16.0: suspend
[  251.519709] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  289.780943] mei_me 0000:00:16.0: suspend
[  290.781338] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  319.506298] mei_me 0000:00:16.0: suspend
[  320.503153] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  348.110390] mei_me 0000:00:16.0: suspend
[  348.958731] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  386.344351] mei_me 0000:00:16.0: suspend
[  387.461297] mei_me 0000:00:16.0: irq 40 for MSI/MSI-X
[  387.513101] mei_me 0000:00:16.0: reset: properties response hbm wrong 
status.
[  387.513104] mei_me 0000:00:16.0: unexpected reset: dev_state = 
INIT_CLIENTS
[  394.514883] mei_me 0000:00:16.0: wait hw ready failed. status = -110
[  394.514890] mei_me 0000:00:16.0: hw_start failed disabling the device
---------------------------------------

No message flood anymore, which is good, but you are right, the problem 
seems to be somewhere deeper.

As far as kernel 3.11.6 is concerned, I see no message flood there but 
"wait hw ready failed. status = -110" is in the log, same as for 3.10.15.

Regards,
Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com

[-- Attachment #2: system_log_20131105.tar.bz2 --]
[-- Type: application/x-bzip, Size: 31901 bytes --]

Re: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

Hi,

 > Please try to comment out schedule_delayed_work(&dev->timer_work, 
HZ); in pci-me.c

You mean this call in mei_me_pci_resume() rather than in .probe, I 
suppose? There are two such calls in pci-me.c.

Regards,
Eugene

-- 
Eugene Shatokhin, ROSA Laboratory.
www.rosalab.com

RE: mei: cancel stall timers in mei_reset

[Winkler, Tomas]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 726 bytes --]



> -----Original Message-----
> From: Eugene Shatokhin [mailto:eugene.shatokhin@rosalab.ru]
> Sent: Wednesday, November 06, 2013 09:14
> To: Winkler, Tomas
> Cc: Usyskin, Alexander; Nicolò Costanza; Alex Burmashev; LKML
> Subject: Re: mei: cancel stall timers in mei_reset
> 
> Hi,
> 
>  > Please try to comment out schedule_delayed_work(&dev->timer_work,
> HZ); in pci-me.c
> 
> You mean this call in mei_me_pci_resume() rather than in .probe, I
> suppose? There are two such calls in pci-me.c.
>

You can safely comment out all of the timer_work.
 
Thanks
Tomas
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

RE: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

[-- Attachment #1: Type: text/plain, Size: 254 bytes --]

Hi,

> You can safely comment out all of the timer_work.
 
Well, I rebuilt the kernel with the schedule_... commented out (in mei_me_pci_resume(), for the present). The errors are no longer visible in the log. The full log is attached.

Regards,

Eugene

[-- Attachment #2: system-log-20131107.tar.bz2 --]
[-- Type: application/x-bzip-compressed-tar, Size: 29094 bytes --]

RE: mei: cancel stall timers in mei_reset

[Winkler, Tomas]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 972 bytes --]



> -----Original Message-----
> From: Eugene Shatokhin [mailto:eugene.shatokhin@rosalab.ru]
> Sent: Thursday, November 07, 2013 08:38
> To: Winkler, Tomas
> Cc: Usyskin, Alexander; Nicol? Costanza; Alex Burmashev; LKML
> Subject: RE: mei: cancel stall timers in mei_reset
> 
> Hi,
> 
> > You can safely comment out all of the timer_work.
> 
> Well, I rebuilt the kernel with the schedule_... commented out (in
> mei_me_pci_resume(), for the present). The errors are no longer visible in the
> log. The full log is attached.
> 

Looks like there is a hiccup in scheduling during resume and timer work is kicked before its time and starts unnecessary  the reset flow.
Can you check  that the device is in good state (<debugfs>/mei/devastate , it should be ENABLED).

We will work on some solution. 

Thanks
Tomas
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

RE: mei: cancel stall timers in mei_reset

[Eugene Shatokhin]

Hi,

>Looks like there is a hiccup in scheduling during resume and timer work is kicked before its time and starts unnecessary  the reset flow.
>Can you check  that the device is in good state (<debugfs>/mei/devastate , it should be ENABLED).

Yes, /sys/kernel/debug/mei/devstate contains "ENABLED" (checked on kernel 3.10.15 I built with schedule_...() commented out).

>We will work on some solution. 

Thanks!

Regards,
Eugene