RE: Unwanted delayed execution of _Qxx EC methods

From: Zheng, Lv
Date: Thu Mar 05 2015 - 20:53:01 EST

Hi, Gabriele


I couldn't find this in my mail box, but saw it in the spinics.net.

For EC query, there is no spec definitions around its behavior.
Some EC firmware will have events queued (like edge triggering) while the others will keeps on reporting events when a condition is set (like level triggering).
I think this case is a "level triggering like events", it is very useful for us to learn.
We should be able to handle both firmware variations using one software architecture.
Supporting this becomes possible now because we are able to switch EC handling between polling/interrupt modes using enhanced ACPICA GPE APIs.
So we are able to switch EC into polling mode when SCI_EVT is detected and blocks further events and handles all transactions in polling mode.
After completing the _Qxx evaluation we then can switch back to the interrupt mode and unblock further events.

Could you please open a kernel Bugzilla entry at: https://bugzilla.kernel.org
So we can discuss there with more test cases considered.

Thanks and best regards
-Lv


From: Gabriele Mazzotta <gabriele.mzt@xxxxxxxxx>
Date: Fri, Mar 6, 2015 at 1:20 AM
Subject: Unwanted delayed execution of _Qxx EC methods
To: linux-acpi@xxxxxxxxxxxxxxx, linux-kernel@xxxxxxxxxxxxxxx
Cc: rjw@xxxxxxxxxxxxx, lenb@xxxxxxxxxx, Mario_Limonciello@xxxxxxxx


Hi,

I'd like to report a minor issue I have with the ACPI embedded controller
driver. My laptop (XPS13 9333) has two function keys to control the
screen brightness. When pressed, two _Qxx ACPI methods are called, one
to increase and one to decrease the brightness. Both the methods sleep
for 200ms.

This pause of 200ms is causing some problems when I keep one of the
function keys pressed. In this situation, more queries than needed
are scheduled for a delayed execution, making the screen brightness
change even after the function key is released.

Here below you can see some log lines that show the problem.

If I keep the function key pressed for X seconds, it will take roughly
2X seconds for all the queries to be executed.

Is there any way to prevent this from happening?

Thanks,
Gabriele

[Â Â47.213439] ACPI : EC: ===== IRQ (1) =====
[Â Â47.213455] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[Â Â47.213458] ACPI : EC: ***** Event started *****
[Â Â47.213509] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.213522] ACPI : EC: ===== TASK (1) =====
[Â Â47.213533] ACPI : EC: EC_SC(R) = 0x20 SCI_EVT=1 BURST=0 CMD=0 IBF=0 OBF=0
[Â Â47.213536] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.213544] ACPI : EC: ***** Event stopped *****
[Â Â47.213547] ACPI : EC: ***** Event started *****
[Â Â47.218812] ACPI : EC: ===== TASK (1) =====
[Â Â47.218829] ACPI : EC: EC_SC(R) = 0x2a SCI_EVT=1 BURST=0 CMD=1 IBF=1 OBF=0
[Â Â47.220195] ACPI : EC: ===== IRQ (1) =====
[Â Â47.220212] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.220219] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.220222] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.220251] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.220260] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.220273] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.220277] ACPI : EC: ===== TASK (1) =====
[Â Â47.220290] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.220293] ACPI : EC: ##### Query(0x80) started #####
[Â Â47.220301] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.220308] ACPI : EC: ***** Event stopped *****
[Â Â47.221021] ACPI : EC: ===== IRQ (0) =====
[Â Â47.221037] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.221045] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.221048] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.221063] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.422969] ACPI : EC: ##### Query(0x80) stopped #####
[Â Â47.487914] ACPI : EC: ===== IRQ (1) =====
[Â Â47.487926] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.487928] ACPI : EC: ***** Event started *****
[Â Â47.487962] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.487969] ACPI : EC: ===== TASK (1) =====
[Â Â47.487978] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.487981] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.487986] ACPI : EC: ***** Event stopped *****
[Â Â47.487988] ACPI : EC: ***** Event started *****
[Â Â47.488557] ACPI : EC: ===== IRQ (1) =====
[Â Â47.488580] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.488584] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.488585] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.488602] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.488607] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.488613] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.488615] ACPI : EC: ===== TASK (1) =====
[Â Â47.488623] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.488624] ACPI : EC: ##### Query(0x80) started #####
[Â Â47.488628] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.488633] ACPI : EC: ***** Event stopped *****
[Â Â47.490090] ACPI : EC: ===== IRQ (0) =====
[Â Â47.490100] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.490103] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.490104] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.490110] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.577686] ACPI : EC: ===== IRQ (1) =====
[Â Â47.577698] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.577699] ACPI : EC: ***** Event started *****
[Â Â47.577722] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.577724] ACPI : EC: ===== TASK (1) =====
[Â Â47.577731] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.577733] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.577736] ACPI : EC: ***** Event stopped *****
[Â Â47.577737] ACPI : EC: ***** Event started *****
[Â Â47.578309] ACPI : EC: ===== IRQ (1) =====
[Â Â47.578315] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.578319] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.578320] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.578328] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.578331] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.578334] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.578336] ACPI : EC: ===== TASK (1) =====
[Â Â47.578343] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.578345] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.578350] ACPI : EC: ***** Event stopped *****
[Â Â47.580030] ACPI : EC: ===== IRQ (1) =====
[Â Â47.580040] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.580044] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.580045] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.580063] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.667627] ACPI : EC: ===== IRQ (1) =====
[Â Â47.667638] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.667640] ACPI : EC: ***** Event started *****
[Â Â47.667669] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.667671] ACPI : EC: ===== TASK (1) =====
[Â Â47.667678] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.667680] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.667683] ACPI : EC: ***** Event stopped *****
[Â Â47.667684] ACPI : EC: ***** Event started *****
[Â Â47.668157] ACPI : EC: ===== IRQ (1) =====
[Â Â47.668167] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.668171] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.668172] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.668188] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.668192] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.668198] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.668200] ACPI : EC: ===== TASK (1) =====
[Â Â47.668209] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.668211] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.668216] ACPI : EC: ***** Event stopped *****
[Â Â47.669836] ACPI : EC: ===== IRQ (1) =====
[Â Â47.669847] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.669850] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.669852] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.669880] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.691187] ACPI : EC: ##### Query(0x80) stopped #####
[Â Â47.691192] ACPI : EC: ##### Query(0x80) started #####
[Â Â47.792343] ACPI : EC: ===== IRQ (1) =====
[Â Â47.792355] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.792357] ACPI : EC: ***** Event started *****
[Â Â47.792387] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.792389] ACPI : EC: ===== TASK (1) =====
[Â Â47.792396] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.792398] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.792401] ACPI : EC: ***** Event stopped *****
[Â Â47.792405] ACPI : EC: ***** Event started *****
[Â Â47.793445] ACPI : EC: ===== IRQ (1) =====
[Â Â47.793456] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.793460] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.793461] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.793480] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.793485] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.793491] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.793493] ACPI : EC: ===== TASK (1) =====
[Â Â47.793501] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.793504] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.793509] ACPI : EC: ***** Event stopped *****
[Â Â47.794994] ACPI : EC: ===== IRQ (1) =====
[Â Â47.795004] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.795007] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.795009] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.795022] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.882247] ACPI : EC: ===== IRQ (1) =====
[Â Â47.882260] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.882262] ACPI : EC: ***** Event started *****
[Â Â47.882299] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.882302] ACPI : EC: ===== TASK (1) =====
[Â Â47.882310] ACPI : EC: EC_SC(R) = 0x28 SCI_EVT=1 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.882312] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.882318] ACPI : EC: ***** Event stopped *****
[Â Â47.882319] ACPI : EC: ***** Event started *****
[Â Â47.882888] ACPI : EC: ===== IRQ (1) =====
[Â Â47.882896] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.882900] ACPI : EC: EC_DATA(R) = 0x80
[Â Â47.882901] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.882914] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.882919] ACPI : EC: ##### Query(0x80) scheduled #####
[Â Â47.882924] ACPI : EC: ***** Command(QR_EC) started *****
[Â Â47.882927] ACPI : EC: ===== TASK (1) =====
[Â Â47.882935] ACPI : EC: EC_SC(R) = 0x08 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=0
[Â Â47.882937] ACPI : EC: EC_SC(W) = 0x84
[Â Â47.882942] ACPI : EC: ***** Event stopped *****
[Â Â47.884614] ACPI : EC: ===== IRQ (1) =====
[Â Â47.884627] ACPI : EC: EC_SC(R) = 0x09 SCI_EVT=0 BURST=0 CMD=1 IBF=0 OBF=1
[Â Â47.884632] ACPI : EC: EC_DATA(R) = 0x00
[Â Â47.884634] ACPI : EC: ***** Command(QR_EC) hardware completion *****
[Â Â47.884655] ACPI : EC: ***** Command(QR_EC) stopped *****
[Â Â47.895378] ACPI : EC: ##### Query(0x80) stopped #####
[Â Â47.895388] ACPI : EC: ##### Query(0x80) started #####
[Â Â48.099496] ACPI : EC: ##### Query(0x80) stopped #####
[Â Â48.099502] ACPI : EC: ##### Query(0x80) started #####
[Â Â48.303660] ACPI : EC: ##### Query(0x80) stopped #####
[Â Â48.303665] ACPI : EC: ##### Query(0x80) started #####
[Â Â48.507823] ACPI : EC: ##### Query(0x80) stopped #####
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html