Re: [REGRESSION] hwmon: (applesmc) avoid overlong udelay()

Brad Campbell
2020-11-03T00:17:50Z

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

On 6/10/20 6:02 pm, Andreas Kemnade wrote:
> On Thu, 1 Oct 2020 21:07:51 -0700
> Guenter Roeck <linux@roeck-us.net> wrote:
>
>> On 10/1/20 3:22 PM, Andreas Kemnade wrote:
>>> On Wed, 30 Sep 2020 22:00:09 +0200
>>> Arnd Bergmann <arnd@arndb.de> wrote:
>>>
>>>> On Wed, Sep 30, 2020 at 6:44 PM Guenter Roeck <linux@roeck-us.net> wrote:
>>>>>
>>>>> On Wed, Sep 30, 2020 at 10:54:42AM +0200, Andreas Kemnade wrote:
>>>>>> Hi,
>>>>>>
>>>>>> after the $subject patch I get lots of errors like this:
>>>>>
>>>>> For reference, this refers to commit fff2d0f701e6 ("hwmon: (applesmc)
>>>>> avoid overlong udelay()").
>>>>>
>>>>>> [ 120.378614] applesmc: send_byte(0x00, 0x0300) fail: 0x40
>>>>>> [ 120.378621] applesmc: LKSB: write data fail
>>>>>> [ 120.512782] applesmc: send_byte(0x00, 0x0300) fail: 0x40
>>>>>> [ 120.512787] applesmc: LKSB: write data fail
>>>>>>
>>>>>> CPU sticks at low speed and no fan is turning on.
>>>>>> Reverting this patch on top of 5.9-rc6 solves this problem.
>>>>>>
>>>>>> Some information from dmidecode:
>>>>>>
>>>>>> Base Board Information
>>>>>> Manufacturer: Apple Inc.
>>>>>> Product Name: Mac-7DF21CB3ED6977E5
>>>>>> Version: MacBookAir6,2
>>>>>>
>>>>>> Handle 0x0020, DMI type 11, 5 bytes OEM Strings String 1: Apple ROM Version. Model: …,
>>>>>> Handle 0x0020, DMI type 11, 5 bytes
>>>>>> OEM Strings
>>>>>> String 1: Apple ROM Version. Model: MBA61. EFI Version: 122.0.0
>>>>>> String 2: .0.0. Built by: root@saumon. Date: Wed Jun 10 18:
>>>>>> String 3: 10:36 PDT 2020. Revision: 122 (B&I). ROM Version: F000_B
>>>>>> String 4: 00. Build Type: Official Build, Release. Compiler: Appl
>>>>>> String 5: e clang version 3.0 (tags/Apple/clang-211.10.1) (based on LLVM
>>>>>> String 6: 3.0svn).
>>>>>>
>>>>>> Writing to things in /sys/devices/platform/applesmc.768 gives also the
>>>>>> said errors.
>>>>>> But writing 1 to fan1_maunal and 5000 to fan1_output turns the fan on
>>>>>> despite error messages.
>>>>>>
>>>>> Not really sure what to do here. I could revert the patch, but then we'd gain
>>>>> clang compile failures. Arnd, any idea ?
>>>>
>>>> It seems that either I made a mistake in the conversion and it sleeps for
>>>> less time than before, or my assumption was wrong that converting a delay to
>>>> a sleep is safe here.
>>>>
>>>> The error message indicates that the write fails, not the read, so that
>>>> is what I'd look at first. Right away I can see that the maximum time to
>>>> retry is only half of what it used to be, as we used to wait for
>>>> 0x10, 0x20, 0x40, 0x80, ..., 0x20000 microseconds for a total of
>>>> 0x3fff0 microseconds (262ms), while my patch went with the 131ms
>>>> total delay based on the comment saying "/* wait up to 128 ms for a
>>>> status change. */".
>>>>
>>> Yes, that is also what I read from the code. I just thought there must
>>> be something simple, which just needs a short look from another pair of
>>> eyes.
>>>
>>>> Since there is sleeping wait, I see no reason the timeout couldn't
>>>> be extended a lot, e.g. to a second, as in
>>>>
>>>> #define APPLESMC_MAX_WAIT 0x100000
>>>>
>>>> If that doesn't work, I'd try using mdelay() in place of
>>>> usleep_range(), such as
>>>>
>>>> mdelay(DIV_ROUND_UP(us, USEC_PER_MSEC)));
>>>>
>>>> This adds back a really nasty latency, but it should avoid the
>>>> compile-time problem.
>>>>
>>>> Andreas, can you try those two things? (one at a time,
>>>> not both)
>>>
>>> Ok, I tried. None of them works. I rechecked my work and created real
>>> git commits out of them and CONFIG_LOCALVERSION_AUTO is also set so
>>> the usual stupid things are rules out.
>>> In detail:
>>> On top of 5.9-rc6 + *reverted* patch:
>>> diff --git a/drivers/hwmon/applesmc.c b/drivers/hwmon/applesmc.c
>>> index fd99c9df8a00..2a9bd7f2b71b 100644
>>> --- a/drivers/hwmon/applesmc.c
>>> +++ b/drivers/hwmon/applesmc.c
>>> @@ -45,7 +45,7 @@
>>> /* wait up to 128 ms for a status change. */
>>> #define APPLESMC_MIN_WAIT 0x0010
>>> #define APPLESMC_RETRY_WAIT 0x0100
>>> -#define APPLESMC_MAX_WAIT 0x20000
>>> +#define APPLESMC_MAX_WAIT 0x8000
>>>
>>> #define APPLESMC_READ_CMD 0x10
>>> #define APPLESMC_WRITE_CMD 0x11
>>>
>>
>> Oh man, that code is so badlys broken.
>>
>> send_byte() repeats sending the data if it was not immediately successful.
>> That is done for both data and commands. Effectively that happens if
>> the command is not immediately accepted. However, send_argument()
>> clearly assumes that each data byte is sent exactly once. Sending
>> it more than once will mess up the key that is supposed to be sent.
>> The Apple SMC emulation code in qemu confirms that data bytes can not
>> be written more than once.
>>
>> Of course, theoretically it may be that the first data byte was not
>> accepted (after all, the ACK bit is not set), but the ACK bit is
>> not checked again after udelay(APPLESMC_RETRY_WAIT), so it may
>> well have been set in the 256 uS between its check and re-writing
>> the data.
>>
>> In other words, this entire code only works accidentally to start with.
>>
>> If you like, you could play around with the code and find out if and
>> when exactly bit 1 (busy) is set, if and when bit 2 (ack) is set, and
>> if and when any other bit is set. We could also try to read port 0x31e
>> (the error port). Maybe the we can figure out what the error actually
>> is. But then I don't really know what we could do with that information.
>>
> Smoe research results: the second data byte seems to cause problems, not the
> command byte.
>
>> Other than that, the only useful idea I have is something crazy like
>> if (us < 10000)
>> udelay(us);
>> else
>> mdelay(DIV_ROUND_CLOSEST(udelay, 1000));
>> in the hope that clang doesn't convert that back into a
>> compile-time constant and udelay().
>>
>> Overall it seems like the apple protocol may expect to receive data
>> bytes faster than 1ms apart, because that is the only real difference
>> between the original code and the new code using mdelay().
>
> Yes, that explanation makes sense. If I am trying something like that, only
> the last byte requires more than APPLESMC_MIN_WAIT. I have seen max. 256us.
> So we could probably even use msleep for us > 1000 and udelay for anything below.
>
> Regards,
> Andreas
>

G'day Andreas,

I've examined the code in VirtualSMC and I'm not convinced we were not waiting on the wrong bits.

#define SMC_STATUS_AWAITING_DATA BIT0 ///< Ready to read data.
#define SMC_STATUS_IB_CLOSED BIT1 /// A write is pending.
#define SMC_STATUS_BUSY BIT2 ///< Busy processing a command.
#define SMC_STATUS_GOT_COMMAND BIT3 ///< The last input was a command.
#define SMC_STATUS_UKN_0x16 BIT4
#define SMC_STATUS_KEY_DONE BIT5
#define SMC_STATUS_READY BIT6 // Ready to work
#define SMC_STATUS_UKN_0x80 BIT7 // error

Any chance you could try this patch? It's ugly, hacked together and currently fairly undocumented, but if it works I'll figure out how to clean it up (suggestions welcome).
It works on my MacbookPro 11,1.

I've also attached a script I adapted from https://github.com/floe/smc_util.git that I use to hammer the SMC with reads.
The behavior pre 5.9 and post this patch is the same.

Regards,
Brad

[-- Attachment #2: smc.patch.2 --]
[-- Type: text/plain, Size: 3897 bytes --]

diff --git a/drivers/hwmon/applesmc.c b/drivers/hwmon/applesmc.c
index a18887990f4a..2500cc7ebca5 100644
--- a/drivers/hwmon/applesmc.c
+++ b/drivers/hwmon/applesmc.c
@@ -151,65 +151,58 @@ static unsigned int key_at_index;
static struct workqueue_struct *applesmc_led_wq;

/*
- * wait_read - Wait for a byte to appear on SMC port. Callers must
- * hold applesmc_lock.
+ * Wait for specific status bits on the SMC
*/
-static int wait_read(void)
+
+static int wait_status(u8 val, u8 mask)
{
- unsigned long end = jiffies + (APPLESMC_MAX_WAIT * HZ) / USEC_PER_SEC;
u8 status;
int us;
+ unsigned long end = jiffies + (APPLESMC_MAX_WAIT * HZ) / USEC_PER_SEC;

for (us = APPLESMC_MIN_WAIT; us < APPLESMC_MAX_WAIT; us <<= 1) {
- usleep_range(us, us * 16);
status = inb(APPLESMC_CMD_PORT);
- /* read: wait for smc to settle */
- if (status & 0x01)
+ if ((status & mask) == val)
return 0;
- /* timeout: give up */
if (time_after(jiffies, end))
break;
- }
-
- pr_warn("wait_read() fail: 0x%02x\n", status);
+ usleep_range(us, us * 16);
+ }
+ pr_warn("wait_status timeout: 0x%02x\n", status);
return -EIO;
}
-
+
/*
* send_byte - Write to SMC port, retrying when necessary. Callers
* must hold applesmc_lock.
*/
-static int send_byte(u8 cmd, u16 port)
-{
- u8 status;
- int us;
- unsigned long end = jiffies + (APPLESMC_MAX_WAIT * HZ) / USEC_PER_SEC;

+static int send_byte_data(u8 cmd, u16 port, bool skip)
+{
+ u8 wstat=0x44;
+ if (skip)
+ wstat=0x40;
+ if (wait_status(0x44, 0xF6))
+ goto fail;
outb(cmd, port);
- for (us = APPLESMC_MIN_WAIT; us < APPLESMC_MAX_WAIT; us <<= 1) {
- usleep_range(us, us * 16);
- status = inb(APPLESMC_CMD_PORT);
- /* write: wait for smc to settle */
- if (status & 0x02)
- continue;
- /* ready: cmd accepted, return */
- if (status & 0x04)
- return 0;
- /* timeout: give up */
- if (time_after(jiffies, end))
- break;
- /* busy: long wait and resend */
- udelay(APPLESMC_RETRY_WAIT);
- outb(cmd, port);
- }
-
- pr_warn("send_byte(0x%02x, 0x%04x) fail: 0x%02x\n", cmd, port, status);
+ if (! wait_status(wstat, 0xFE))
+ return 0;
+fail:
+ pr_warn("send_byte_data(0x%02x, 0x%04x) fail\n", cmd, APPLESMC_CMD_PORT);
return -EIO;
}

static int send_command(u8 cmd)
{
- return send_byte(cmd, APPLESMC_CMD_PORT);
+ if (wait_status(0x40, 0xF2)) { pr_warn("send_command fail 1\n");
+ goto fail;}
+ outb(cmd, APPLESMC_CMD_PORT);
+ if (wait_status(0x4C, 0xFF)) { pr_warn("send_command fail 2\n");
+ goto fail;}
+ return 0;
+fail:
+ pr_warn("send_cmd(0x%02x, 0x%04x) fail\n", cmd, APPLESMC_CMD_PORT);
+ return -EIO;
}

static int send_argument(const char *key)
@@ -217,7 +210,7 @@ static int send_argument(const char *key)
int i;

for (i = 0; i < 4; i++)
- if (send_byte(key[i], APPLESMC_DATA_PORT))
+ if (send_byte_data(key[i], APPLESMC_DATA_PORT,false))
return -EIO;
return 0;
}
@@ -233,13 +226,13 @@ static int read_smc(u8 cmd, const char *key, u8 *buffer, u8 len)
}

/* This has no effect on newer (2012) SMCs */
- if (send_byte(len, APPLESMC_DATA_PORT)) {
+ if (send_byte_data(len, APPLESMC_DATA_PORT,false)) {
pr_warn("%.4s: read len fail\n", key);
return -EIO;
}

for (i = 0; i < len; i++) {
- if (wait_read()) {
+ if (wait_status(0x45,0xFF)) {
pr_warn("%.4s: read data[%d] fail\n", key, i);
return -EIO;
}
@@ -269,14 +262,14 @@ static int write_smc(u8 cmd, const char *key, const u8 *buffer, u8 len)
return -EIO;
}

- if (send_byte(len, APPLESMC_DATA_PORT)) {
+ if (send_byte_data(len, APPLESMC_DATA_PORT,false)) {
pr_warn("%.4s: write len fail\n", key);
return -EIO;
}

for (i = 0; i < len; i++) {
- if (send_byte(buffer[i], APPLESMC_DATA_PORT)) {
- pr_warn("%s: write data fail\n", key);
+ if (send_byte_data(buffer[i], APPLESMC_DATA_PORT,(i==(len-1)))) {
+ pr_warn("%s: write data fail at %i\n", key, i);
return -EIO;
}
}

[-- Attachment #3: smc_dump_linux.sh --]
[-- Type: application/x-shellscript, Size: 797 bytes --]