linux-surface / kernel

Linux kernel with modifications for Microsoft Surface devices.
Other
118 stars 33 forks source link

SB3: system total power limit at 25 watts, including display backlight #117

Open yatli opened 2 years ago

yatli commented 2 years ago

This is observed by using s-tui to continuously monitor the power consumption, core frequency and utilization while compiling the kernel.

Running a "cold start", the system power peaks at 40 watts, and then drops to 25 watts (could be a thermal trip point, or a "long time power limit"?), where the CPU package draws 16 watts, resulting in all-core frequency at 1.6GHz. Core temperature stabilizes at 71C.

Curiously, I lowered the screen brightness to 5%, and the CPU package starts to draw more power (20+ watts) and all-core frequency goes up to 2.0GHz. Core temperature stabilizes at 78C.

So this does not solely look like a thermal throttle -- but where does that 25W limit come from?

qzed commented 2 years ago

Could be some total system limit for sustained power imposed by firmware. Did you try changing the performance mode?

yatli commented 2 years ago

I don't have "performance mode" -- there's no /sys/bus/surface_aggregator/devices/01:03:01:00:01/perf_mode. I did try all the profiles -- no difference it seems.

qzed commented 2 years ago

Yeah sorry, meant platform profiles (those and performance modes are the same).

yatli commented 2 years ago

Edit: see below.

After some more experiment with a stress tool I find it's thermal-related and not bound to a sustained loaded time. The peak power could sustain for 2 seconds, 5 seconds and so on.

And the power limit kicks in when the core goes over 90C degrees. I'll see if I can work out a thermald configuration for this model.

yatli commented 2 years ago

Just feel this is funny that I should share the story with you guys :D

yatli commented 2 years ago

Have to reopen this because thermald/rapl is not effective against this problem. It's like a power budget, not thermal throttle -- the same 25 watts can well push the core to 80C (dimmed screen) but a thermal limit at 70C (like ~20 watts in total) already triggers the power limit!

yatli commented 2 years ago

btw, the fan is not as fast (loud) as in Windows. A profile configuration issue?

yatli commented 2 years ago

So, is there a way I can intercept SAM messages under windows?

qzed commented 2 years ago

btw, the fan is not as fast (loud) as in Windows. A profile configuration issue?

AFAIK the fan is entirely controlled by SAM, and the only influence we or Windows can have on that is the platform profile/performance mode. Try setting that to "best performance".

So, is there a way I can intercept SAM messages under windows?

Yes, although it requires a bit of configuration and the dumps are not easily readable (you're of course welcome to write a better parser for that). There's an overview on how to do that here: https://github.com/linux-surface/surface-aggregator-module/wiki/Development. A script for transforming the output into json files is here. Documentation on the commands we know so far is here. An overall documentation on the protocol can be found at https://www.kernel.org/doc/html/latest/driver-api/surface_aggregator/ssh.html.

yatli commented 2 years ago

Here are the two related entries when I toggle between Better Performance vs. Best Performance:

{"ctrl": {"type": 128, "len": 12, "pad": 0, "seq": 42}, "cmd": {"type": 128, "tc": 3, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 83, "rqid_hi": 3, "cid": 3}, "payload": [3, 0, 0, 0]}
{"ctrl": {"type": 128, "len": 12, "pad": 0, "seq": 46}, "cmd": {"type": 128, "tc": 3, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 87, "rqid_hi": 3, "cid": 3}, "payload": [4, 0, 0, 0]}

...which matches the documented values. le32 though?

yatli commented 2 years ago

Just checked the module. le32 indeed no problem.

qzed commented 2 years ago

Yeah, le32 is correct.

qzed commented 2 years ago

All multi-byte values in the protocol are little-endian.

yatli commented 2 years ago

Let me check if profile get can return the correct answer. If so, the problem may be somewhere else?

qzed commented 2 years ago

I'm fairly sure that getting/setting profiles is working correctly. There may be other commands for the EC that I've missed as I've mostly developed this on the SB2 and through reverse engineering of the Windows drivers. But it's also possible that there are other factors in play besides the EC.

yatli commented 2 years ago

Yeah, I just checked. Performance profile readback is correct. The capture log is a huge stream of category 21(0x15) plus these two 0x03, and a few 0x01. Maybe I should also check the 0x01 ones. (Rebooting)

yatli commented 2 years ago

oh and this: warning: expected SYN, skipping data until next SYN

qzed commented 2 years ago

Could be a bug in the parser or missing/corrupted data. Essentially this says that it expected the start of a message but got something else, so it's looking for the next start of a message.

yatli commented 2 years ago

With only cat 21 filtered:

{"ctrl": {"type": 128, "len": 12, "pad": 0, "seq": 42}, "cmd": {"type": 128, "tc": 3, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 83, "rqid_hi": 3, "cid": 3}, "payload": [3, 0, 0, 0]}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 42}}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 43}}
{"ctrl": {"type": 128, "len": 8, "pad": 0, "seq": 44}, "cmd": {"type": 128, "tc": 1, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 85, "rqid_hi": 3, "cid": 51}, "payload": []}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 44}}
{"ctrl": {"type": 128, "len": 8, "pad": 0, "seq": 45}, "cmd": {"type": 128, "tc": 1, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 86, "rqid_hi": 3, "cid": 52}, "payload": []}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 45}}
{"ctrl": {"type": 128, "len": 9, "pad": 0, "seq": 226}, "cmd": {"type": 128, "tc": 1, "outgoing": 0, "incoming": 1, "iid": 0, "rqid_lo": 86, "rqid_hi": 3, "cid": 52}, "payload": [0]}
{"ctrl": {"type": 128, "len": 12, "pad": 0, "seq": 46}, "cmd": {"type": 128, "tc": 3, "outgoing": 1, "incoming": 0, "iid": 0, "rqid_lo": 87, "rqid_hi": 3, "cid": 3}, "payload": [4, 0, 0, 0]}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 46}}
{"ctrl": {"type": 64, "len": 0, "pad": 0, "seq": 47}}

Message 43 and 47 are missing. Intriguing!

yatli commented 2 years ago

The bug is caused probably because IRPComp piggyback'ed another HID message

This is message 42:

ID = 103109
Time = 2/18/2022 7:02:29 PM
Type = IRP
Device object = 0xFFFF9002959EBB70
Device name = \Device\00000040
Driver object = 0xFFFF900298294DF0
Driver name = \Driver\iaLPSS2_UART2
Result value = 0x103
Result constant = STATUS_PENDING
Major function = Write
Minor function = Normal
IRP address = 0xFFFF9002959B4AA0
File object = 0xFFFF9002B1EF5DF0
IRP flags = 0x0
Length = L: 22
Key = K: 0x0
Offset = O: 0x0
Thread ID = 10608
Process ID = 4
IRQL = Passive
Previous mode = KernelMode
Requestor mode = KernelMode
IOSB.Status value = 0x0
IOSB.Status constant = STATUS_SUCCESS
IOSB.Information = 0 (0x0000000000000000)
Requestor PID = 0
Emulated = False
Associated data = True
Data stripped = False
Data size = 22
Data (Hexer)
  00:   aa 55 80 0c 00 2a b1 a9 80 03 01 00 00 53 03 03 ªU?..*±©?....S..
  10:   03 00 00 00 1c b0                               .....°          

And a few lines down, there's 0x2b, message 43:

ID = 103113
Time = 2/18/2022 7:02:29 PM
Type = IRP
Device object = 0xFFFF9002959EBB70
Device name = \Device\00000040
Driver object = 0xFFFF900298294DF0
Driver name = \Driver\iaLPSS2_UART2
Result value = 0x103
Result constant = STATUS_PENDING
Major function = Write
Minor function = Normal
IRP address = 0xFFFF9002B85D5A20
File object = 0xFFFF9002B1EF5DF0
IRP flags = 0x0
Length = L: 19
Key = K: 0x0
Offset = O: 0x0
Thread ID = 10608
Process ID = 4
IRQL = Passive
Previous mode = KernelMode
Requestor mode = KernelMode
IOSB.Status value = 0x0
IOSB.Status constant = STATUS_SUCCESS
IOSB.Information = 0 (0x0000000000000000)
Requestor PID = 0
Emulated = False
Associated data = True
Data stripped = False
Data size = 19
Data (Hexer)
  00:   aa 55 80 09 00 2b 60 52 80 17 02 00 01 54 03 01 ªU?..+`R?....T..
  10:   00 75 42                                        .uB             

Also, message 47 pairs with 46:

ID = 103481
Time = 2/18/2022 7:02:31 PM
Type = IRP
Device object = 0xFFFF9002959EBB70
Device name = \Device\00000040
Driver object = 0xFFFF900298294DF0
Driver name = \Driver\iaLPSS2_UART2
Result value = 0x103
Result constant = STATUS_PENDING
Major function = Write
Minor function = Normal
IRP address = 0xFFFF9002B12C24A0
File object = 0xFFFF9002B93E05F0
IRP flags = 0x0
Length = L: 19
Key = K: 0x0
Offset = O: 0x0
Thread ID = 13296
Process ID = 4
IRQL = Passive
Previous mode = KernelMode
Requestor mode = KernelMode
IOSB.Status value = 0x0
IOSB.Status constant = STATUS_SUCCESS
IOSB.Information = 0 (0x0000000000000000)
Requestor PID = 0
Emulated = False
Associated data = True
Data stripped = False
Data size = 19
Data (Hexer)
  00:   aa 55 80 09 00 2f e4 12 80 17 02 00 01 58 03 01 ªU?../ä.?....X..
  10:   00 47 0d                                        .G.             

0x17 BKL

🤔

qzed commented 2 years ago

Yeah, unfortunately the json converter script isn't very robust. I had the plan to write a better decoder at some point but never found the time for it...

yatli commented 2 years ago

Any ideas on the BKL message? It could be a random coincidence but intriguing :p

qzed commented 2 years ago

BKL could mean backlight maybe? Just a guess though.

qzed commented 2 years ago

Never seen that one before

yatli commented 2 years ago

Makes sense, could be backlight related stuff since I'm adjusting power profiles. I'm wondering if the module handles the piggybacks and incomplete frames?

qzed commented 2 years ago

Not sure what you mean by piggybacks. It's an exclusive UART channel on the driver side (IRPMon might pick up other stuff that's not sent via that channel). If we receive an incomplete or invalid frame. the driver rejects it (by sending the appropriate packet with type 0x04) and skips to the next SYN bytes (aa 55). The EC does the same on its side.

The communication above is from host to EC though, so it's host initiated. We probably won't see any of the TC=0x17 messages unless we either send them ourselves or we set up the appropriate events (in case that subsystem can actually send events).

qzed commented 2 years ago

If you want to play around, you can load the debug module on linux (modprobe surface_aggregator_cdev) and use the ctrl.py script to talk to the EC. So you could send the messages from your log.

yatli commented 2 years ago

aha. pretend we are 0x17 experts. 😎

yatli commented 2 years ago

By piggyback I mean, for example in this reply:

  00:   aa 55 40 00 00 2a 74 6f ff ff aa 55 00 26 00 df ªU@..*toÿÿªU.&.ß
  10:   34 8a 80 15 00 02 03 15 00 00 04 01 21 05 39 02 4??.........!.9.
  20:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................

It first ack'ed 0x2a, and then started another message..

qzed commented 2 years ago

aha. pretend we are 0x17 experts.

Pretty much xD

Should be ./ctrl.py request 0x17 0x02 0x01 0x01 0x01 0x00, or TC=0x17, TID=0x02, CID=0x01, IID=0x01, flags=sync (aka. 0x01) and payload = 0x00.

qzed commented 2 years ago

By piggyback I mean, for example in this reply:

  00: aa 55 40 00 00 2a 74 6f ff ff aa 55 00 26 00 df ªU@..*toÿÿªU.&.ß
  10: 34 8a 80 15 00 02 03 15 00 00 04 01 21 05 39 02 4??.........!.9.
  20: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................

It first ack'ed 0x2a, and then started another message..

Ah yeah those should be handled properly. The driver essentially loads all received data into a buffer and then evaluates the buffer, so there is no real differentiation between sending multiple messages vs. sending everything in one big message.

qzed commented 2 years ago

The other option would be to try and look at the windows drivers. I may have a look at that once I have some more time.

qzed commented 2 years ago

SurfaceOemPanel.dll has some SAM related strings. So could really have something to do with the backlight.

yatli commented 2 years ago

SAM waiting for CMD_APPLY_PROFILE_BKL ? I don't know, need to talk to it. Hopefully there are other SB3 users around who can confirm the 25W limit (and not a stupid setup issue on my side)

qzed commented 2 years ago

Maybe... Could definitely be some sort of callback like "power stuff has changed, run some updates please". The OEM panel driver references a PowerSettingRegisterNotification function. Any chance the command is being sent when you change the backlight?

~Also I just noticed another thing... The parser doesn't seem to handle Target IDs (or at least doesn't include them in the output). And the commands above have TID=0x02 instead of the more common TID=0x01.~ scratch that, I'm stupid and that's outgoing/incoming.

yatli commented 2 years ago

Any chance the command is being sent when you change the backlight?

I'll check this one when I boot back to Windows.

Currently playing with /dev/surface/aggregator :p

yatli commented 2 years ago
yatli@YATAO-SB ..surface-aggregator-module/scripts/ssam (git)-[master] % cat test.sh
#!/bin/bash

sudo surface profile set performance
sudo ./ctrl.py request 0x17 0x02 0x01 0x01 0x01 0x00
yatli@YATAO-SB ..surface-aggregator-module/scripts/ssam (git)-[master] % ./test.sh
Platform profile set to 'performance'
Traceback (most recent call last):
  File "/home/yatli/git/surface-aggregator-module/scripts/ssam/./ctrl.py", line 49, in <module>
    main()
  File "/home/yatli/git/surface-aggregator-module/scripts/ssam/./ctrl.py", line 43, in main
    rsp = ctrl.request(rqst)
  File "/home/yatli/git/surface-aggregator-module/scripts/ssam/libssam.py", line 355, in request
    return _request(self.fd, request)
  File "/home/yatli/git/surface-aggregator-module/scripts/ssam/libssam.py", line 263, in _request
    raise OSError(-raw.status, errno.errorcode.get(-raw.status))
TimeoutError: [Errno 110] ETIMEDOUT

Hmm.. Guess it's a "no thanks"?

qzed commented 2 years ago

That's not necessarily an error, it just times out waiting for a response. Based on your json log above it's likely that the command doesn't have any response (besides the standard ACK frame). Can you try ./ctrl.py request 0x17 0x02 0x01 0x01 0x00 0x00? The second-to-last byte essentially tells the driver whether it should expect a response (0x01) or not (0x00).

yatli commented 2 years ago

ooh I thought it wasn't even ACK'ed. Thanks for the tip!


Unfortunately it seems the profiles are not loading correctly still. Rebooting for more dumps;

yatli commented 2 years ago

FYI jq complements the parser script pretty well:

 ┌─┐ C:\Users\yatli\git\surface-aggregator-module\scripts\irpmon                                                                                                                    master ◇ ┆ yatli
 └─╜ ╰▷ python irpmon_to_json.py dump5.log | jq -c '(. | keys[]) as $i | [$i, .[$i]] | select(.[0] >= 401) | select(.[0] <= 513) | select(.[1].cmd.tc != 21)'
warning: expected SYN, skipping data until next SYN
data dropped: 0x2 0x0 0x1 0x39 0x20 0x1 0x0 0xb7 0xfd 0x0 0x0 0x0 0x0 0xd5 0x83 0x1 0x1 0x7e 0x57
[401,{"ctrl":{"type":128,"len":12,"pad":0,"seq":15},"cmd":{"type":128,"tc":3,"outgoing":1,"incoming":0,"iid":0,"rqid_lo":56,"rqid_hi":32,"cid":3},"payload":[3,0,0,0],"time":"2/20/2022 4:38:36 PM"}]
[402,{"ctrl":{"type":64,"len":0,"pad":0,"seq":15}}]
[404,{"ctrl":{"type":64,"len":0,"pad":0,"seq":16}}]
[508,{"ctrl":{"type":128,"len":12,"pad":0,"seq":17},"cmd":{"type":128,"tc":3,"outgoing":1,"incoming":0,"iid":0,"rqid_lo":58,"rqid_hi":32,"cid":3},"payload":[4,0,0,0],"time":"2/20/2022 4:38:37 PM"}]
[510,{"ctrl":{"type":64,"len":0,"pad":0,"seq":17}}]
[511,{"ctrl":{"type":128,"len":9,"pad":0,"seq":18},"cmd":{"type":128,"tc":23,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":59,"rqid_hi":32,"cid":1},"payload":[0],"time":"2/20/2022 4:38:37 PM"}]
[512,{"ctrl":{"type":64,"len":0,"pad":0,"seq":18}}]

Again, one tc=0x17,cid=1 per tc=3,cid=3.

yatli commented 2 years ago

Okay another interesting finding!

qzed commented 2 years ago

So could be battery/charger related.

I wonder if it's only pulling power directly from the battery instead of battery and charger.

yatli commented 2 years ago

Could you help take a look at this, I've hand annotated some logs when I pull the plug then plug back:

// incoming: power adapter [2] status changed.
{"ctrl":{"type":128,"len":8,"pad":0,"seq":16},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":2,"rqid_hi":0,"cid":23},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":21}
// ack
{"ctrl":{"type":64,"len":0,"pad":0,"seq":16},"time":"2/20/2022 6:15:30 PM","entry":24}
// req #176: ACPI/PSRC[2] (platform power source)
{"ctrl":{"type":128,"len":8,"pad":0,"seq":135},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":176,"rqid_hi":63,"cid":13},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":24}
// ack #176
{"ctrl":{"type":64,"len":0,"pad":0,"seq":135},"time":"2/20/2022 6:15:30 PM","entry":29}
// rsp #176: ACPI/PSRC[2]=[0,0,0,0]
{"ctrl":{"type":128,"len":12,"pad":0,"seq":17},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":176,"rqid_hi":63,"cid":13},"payload":[0,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":29}
// ack #176
{"ctrl":{"type":64,"len":0,"pad":0,"seq":17},"time":"2/20/2022 6:15:30 PM","entry":33}
// req #177: ACPI/_BTP[2]=[0,0,0,0] (battery trip points)
{"ctrl":{"type":128,"len":12,"pad":0,"seq":136},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":177,"rqid_hi":63,"cid":4},"payload":[0,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":33}
// ack #177
{"ctrl":{"type":64,"len":0,"pad":0,"seq":136},"time":"2/20/2022 6:15:30 PM","entry":37}
// req #178: ACPI/_BTP[2]=[226,228,0,0]
{"ctrl":{"type":128,"len":12,"pad":0,"seq":137},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":178,"rqid_hi":63,"cid":4},"payload":[226,228,0,0],"time":"2/20/2022 6:15:30 PM","entry":37}
// incoming: power adapter [1] status changed.
{"ctrl":{"type":128,"len":8,"pad":0,"seq":18},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":2,"rqid_hi":0,"cid":23},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":39}
// ack #178
{"ctrl":{"type":64,"len":0,"pad":0,"seq":137},"time":"2/20/2022 6:15:30 PM","entry":41}
// ack power adapter status changed
{"ctrl":{"type":64,"len":0,"pad":0,"seq":18},"time":"2/20/2022 6:15:30 PM","entry":43}
// req #179: ACPI/_BST[1] (battery present status)
{"ctrl":{"type":128,"len":8,"pad":0,"seq":138},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":179,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":43}
// ack #179
{"ctrl":{"type":64,"len":0,"pad":0,"seq":138},"time":"2/20/2022 6:15:30 PM","entry":45}
// incoming: TpUpdate(?)
{"ctrl":{"type":128,"len":29,"pad":0,"seq":19},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":2,"rqid_hi":0,"cid":83},"payload":[1,54,30,1,0,42,168,0,0,170,0,74,33,115,54,0,0,228,37,0,0],"time":"2/20/2022 6:15:30 PM","entry":45}
// ack 139 (missing!)
{"ctrl":{"type":64,"len":0,"pad":0,"seq":139},"time":"2/20/2022 6:15:30 PM","entry":51}
// ack TpUpdate(?)
{"ctrl":{"type":64,"len":0,"pad":0,"seq":19},"time":"2/20/2022 6:15:30 PM","entry":53}
// req #181: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":140},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":181,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":53}
// ack #181
{"ctrl":{"type":64,"len":0,"pad":0,"seq":140},"time":"2/20/2022 6:15:30 PM","entry":55}
// rsp #179: ACPI/_BST[1] = [1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":20},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":179,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0],"time":"2/20/2022 6:15:30 PM","entry":55}
// ack #179
{"ctrl":{"type":64,"len":0,"pad":0,"seq":20},"time":"2/20/2022 6:15:30 PM","entry":59}
// rsp #180: ACPI/PSRC[1] = [0,0,0,0] (rqid 180, request missing!)
{"ctrl":{"type":128,"len":12,"pad":0,"seq":21},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":180,"rqid_hi":63,"cid":13},"payload":[0,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":59}
// ack #180
{"ctrl":{"type":64,"len":0,"pad":0,"seq":21},"time":"2/20/2022 6:15:30 PM","entry":62}
// req #182: ACPI/_BTP[1]=[0,0,0,0]
{"ctrl":{"type":128,"len":12,"pad":0,"seq":141},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":182,"rqid_hi":63,"cid":4},"payload":[0,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":62}
// ack #182
{"ctrl":{"type":64,"len":0,"pad":0,"seq":141},"time":"2/20/2022 6:15:30 PM","entry":65}
// rsp #181: ACPI/_BST[2]=[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":22},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":181,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0],"time":"2/20/2022 6:15:30 PM","entry":65}
// ack #181
{"ctrl":{"type":64,"len":0,"pad":0,"seq":22},"time":"2/20/2022 6:15:30 PM","entry":69}
// req #183: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":142},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":183,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":69}
// ack #183
{"ctrl":{"type":64,"len":0,"pad":0,"seq":142},"time":"2/20/2022 6:15:30 PM","entry":71}
// rsp #183: ACPI/_BST[2]=[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":23},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":183,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0],"time":"2/20/2022 6:15:30 PM","entry":71}
// ack #183
{"ctrl":{"type":64,"len":0,"pad":0,"seq":23},"time":"2/20/2022 6:15:30 PM","entry":74}
// req #184: ACPI/_BTP[1] = [140,82,0,0]
{"ctrl":{"type":128,"len":12,"pad":0,"seq":143},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":184,"rqid_hi":63,"cid":4},"payload":[140,82,0,0],"time":"2/20/2022 6:15:30 PM","entry":74}
// ack #184
{"ctrl":{"type":64,"len":0,"pad":0,"seq":143},"time":"2/20/2022 6:15:30 PM","entry":79}
// req #185: profile=1
{"ctrl":{"type":128,"len":12,"pad":0,"seq":144},"cmd":{"type":128,"tc":3,"outgoing":1,"incoming":0,"iid":0,"rqid_lo":185,"rqid_hi":63,"cid":3},"payload":[1,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":79}
// ack #185
{"ctrl":{"type":64,"len":0,"pad":0,"seq":144},"time":"2/20/2022 6:15:30 PM","entry":83}
// req #186: ACPI/_BST[1]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":145},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":186,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":83}
// ack #186
{"ctrl":{"type":64,"len":0,"pad":0,"seq":145},"time":"2/20/2022 6:15:30 PM","entry":86}
// rsp #186: ACPI/_BST[1]=[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":24},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":186,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0],"time":"2/20/2022 6:15:30 PM","entry":86}
// ack #186
{"ctrl":{"type":64,"len":0,"pad":0,"seq":24},"time":"2/20/2022 6:15:30 PM","entry":89}
// req #187: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":146},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":187,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":89}
// ack #187
{"ctrl":{"type":64,"len":0,"pad":0,"seq":146},"time":"2/20/2022 6:15:30 PM","entry":92}
// rsp #187: ACPI/_BST[2]=[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":25},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":187,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0],"time":"2/20/2022 6:15:30 PM","entry":92}
// req #188: tc=0x17, cid=1, payload=[0]
{"ctrl":{"type":128,"len":9,"pad":0,"seq":147},"cmd":{"type":128,"tc":23,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":188,"rqid_hi":63,"cid":1},"payload":[0],"time":"2/20/2022 6:15:30 PM","entry":94}
// ack #187
{"ctrl":{"type":64,"len":0,"pad":0,"seq":25},"time":"2/20/2022 6:15:30 PM","entry":98}
// ack #188
{"ctrl":{"type":64,"len":0,"pad":0,"seq":147},"time":"2/20/2022 6:15:30 PM","entry":100}
// req #189: ACPI/_BST[1]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":148},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":189,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":100}
// ack #189
{"ctrl":{"type":64,"len":0,"pad":0,"seq":148},"time":"2/20/2022 6:15:30 PM","entry":103}
// rsp #189: ACPI/_BST[1]=[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":26},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":189,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0],"time":"2/20/2022 6:15:30 PM","entry":103}
// ack #189
{"ctrl":{"type":64,"len":0,"pad":0,"seq":26},"time":"2/20/2022 6:15:30 PM","entry":106}
// req #190: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":149},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":190,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":106}
// ack #190
{"ctrl":{"type":64,"len":0,"pad":0,"seq":149},"time":"2/20/2022 6:15:30 PM","entry":109}
// rsp #190: ACPI/_BST[2]=[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":27},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":190,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0],"time":"2/20/2022 6:15:30 PM","entry":109}
// ack #190
{"ctrl":{"type":64,"len":0,"pad":0,"seq":27},"time":"2/20/2022 6:15:30 PM","entry":112}
// req #191: profile=1
{"ctrl":{"type":128,"len":12,"pad":0,"seq":150},"cmd":{"type":128,"tc":3,"outgoing":1,"incoming":0,"iid":0,"rqid_lo":191,"rqid_hi":63,"cid":3},"payload":[1,0,0,0],"time":"2/20/2022 6:15:30 PM","entry":112}
// ack #191
{"ctrl":{"type":64,"len":0,"pad":0,"seq":150},"time":"2/20/2022 6:15:30 PM","entry":117}
// req #192: ACPI/_BST[1]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":151},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":192,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":117}
// ack #192
{"ctrl":{"type":64,"len":0,"pad":0,"seq":151},"time":"2/20/2022 6:15:30 PM","entry":120}
// rsp #192: ACPI/_BST[1] = [1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":28},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":192,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,8,0,0,0,248,82,0,0,74,33,0,0],"time":"2/20/2022 6:15:30 PM","entry":120}
// ack #192
{"ctrl":{"type":64,"len":0,"pad":0,"seq":28},"time":"2/20/2022 6:15:30 PM","entry":123}
// req #193: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":152},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":193,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:30 PM","entry":123}
// ack #193
{"ctrl":{"type":64,"len":0,"pad":0,"seq":152},"time":"2/20/2022 6:15:30 PM","entry":126}
// rsp #193: ACPI/_BST[2]=[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":29},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":193,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,165,4,0,0,10,230,0,0,241,49,0,0],"time":"2/20/2022 6:15:30 PM","entry":126}
// ack #193
{"ctrl":{"type":64,"len":0,"pad":0,"seq":29},"time":"2/20/2022 6:15:30 PM","entry":129}
// req #194: tc=0x17, cid=1, payload=[0]
{"ctrl":{"type":128,"len":9,"pad":0,"seq":153},"cmd":{"type":128,"tc":23,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":194,"rqid_hi":63,"cid":1},"payload":[0],"time":"2/20/2022 6:15:30 PM","entry":129}
// ack #194
{"ctrl":{"type":64,"len":0,"pad":0,"seq":153},"time":"2/20/2022 6:15:31 PM","entry":135}
// req #195: ACPI/_BST[1]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":154},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":195,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:31 PM","entry":135}
// ack #195
{"ctrl":{"type":64,"len":0,"pad":0,"seq":154},"time":"2/20/2022 6:15:31 PM","entry":139}
// rsp #195: ACPI/_BST[1]=[1,0,0,0,37,12,0,0,248,82,0,0,25,33,0,0]
{"ctrl":{"type":128,"len":24,"pad":0,"seq":30},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":195,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,37,12,0,0,248,82,0,0,25,33,0,0],"time":"2/20/2022 6:15:31 PM","entry":139}
// ack #195
{"ctrl":{"type":64,"len":0,"pad":0,"seq":30},"time":"2/20/2022 6:15:31 PM","entry":143}
// req #196: ACPI/_BST[2]
{"ctrl":{"type":128,"len":8,"pad":0,"seq":155},"cmd":{"type":128,"tc":2,"outgoing":2,"incoming":0,"iid":1,"rqid_lo":196,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:31 PM","entry":143}
// ack #196
{"ctrl":{"type":64,"len":0,"pad":0,"seq":155},"time":"2/20/2022 6:15:31 PM","entry":147}
{"ctrl":{"type":128,"len":8,"pad":0,"seq":156},"cmd":{"type":128,"tc":2,"outgoing":1,"incoming":0,"iid":1,"rqid_lo":197,"rqid_hi":63,"cid":3},"payload":[],"time":"2/20/2022 6:15:31 PM","entry":147}
{"ctrl":{"type":64,"len":0,"pad":0,"seq":156},"time":"2/20/2022 6:15:31 PM","entry":149}
{"ctrl":{"type":128,"len":24,"pad":0,"seq":31},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":1,"iid":1,"rqid_lo":197,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,37,12,0,0,248,82,0,0,25,33,0,0],"time":"2/20/2022 6:15:31 PM","entry":149}
{"ctrl":{"type":64,"len":0,"pad":0,"seq":31},"time":"2/20/2022 6:15:31 PM","entry":153}
{"ctrl":{"type":128,"len":24,"pad":0,"seq":32},"cmd":{"type":128,"tc":2,"outgoing":0,"incoming":2,"iid":1,"rqid_lo":196,"rqid_hi":63,"cid":3},"payload":[1,0,0,0,171,9,0,0,10,230,0,0,214,48,0,0],"time":"2/20/2022 6:15:31 PM","entry":153}
{"ctrl":{"type":64,"len":0,"pad":0,"seq":32},"time":"2/20/2022 6:15:31 PM","entry":157}
qzed commented 2 years ago

Looks all fairly standard to me. It gets a "power status changed" notification and then queries the power and power adapter state (_BST/PSRC) and sets some battery trip point (used for notifications when the battery reaches a certain level, _BTP).

The only thing that I don't know much about is the TpUpdate thing. That has something to do with DPTF (Intel's Dynamic Power and Thermal Framework). So it's possible (maybe even likely) that this is related to the power limit. But that's an incoming notification, so there's no way that this can directly influence the power limit. Meaning if it has something to do with it, the driver that picks that notification up does something to change the power limit without communicating back to the EC.

At the moment we're just ignoring this message on Linux, meaning we ACK it (so for all intents and purposes the communication above should be mostly equal on Windows and Linux), but we don't do anything else with it (i.e. there's no driver to pick it up).

yatli commented 2 years ago

When setting _BTP, it always first clear it: // req #182: ACPI/_BTP[1]=[0,0,0,0] then set it in a following request: // req #184: ACPI/_BTP[1] = [140,82,0,0]

Does that match the linux driver behavior?

edit: nvm I thought it's a safety feature but it looks like it's just a programmable battery meter

Thanks for taking a look. I'm done for the night. Recharging. :)

qzed commented 2 years ago

Yeah, _BTP is just a means to get a notification when the battery level moves over or under that programmed threshold. Basically, at that point you're guaranteed to get a "battery status changed" notification (which might also be sent regardless by the EC if the battery drops a couple of percent).

qzed commented 2 years ago

I guess since everything is implemented by the EC, targeting the Windows driver, it could have some side-effects. But I think that's probably rather unlikely. I don't think Linux really sets trip points (that's a thing that userspace tools like UPower should do, I think, and I'm not sure if that behavior is consistent with Windows), so you could try to play around with that, but again, I think it's rather unlikely that this has any side-effects.

yatli commented 2 years ago

Update: I have observed the same power clamping in Windows with AC plugged in. Just need to push it a bit harder.

This can be worked around with ThrottleStop with the following turbo power limit settings:

image

... so it turbo boosts to ~40W, and drops back to ~25W (cpu only, not system total) and stabilizes.

I'll try to figure out the equivalent for linux.

yatli commented 2 years ago

This is the best I can achieve:

{
    "MSR_PKG_POWER_LIMIT": 6053258197434505,
    "first": {
        "MSR_PKG_POWER_LIMIT": 6053258197434505,
        "power_limit": 17.125,
        "power_enabled": true,
        "power_clamping_limit": true,
        "power_limit_time_window": 3.0,
        "__types.SimpleNamespace": true
    },
    "second": {
        "MSR_PKG_POWER_LIMIT": 1409384,
        "power_limit": 45.0,
        "power_enabled": true,
        "power_clamping_limit": true,
        "power_limit_time_window": 1.0,
        "__types.SimpleNamespace": true
    },
    "lock": false,
    "__types.SimpleNamespace": true
}

TL;DR 3 secs of max turbo, then power limit the cpu package to 19W.

(in Windows I can achieve 6 secs max turbo, then down to 22W, but given that the fan is not spinning as fast, let's be conservative and not melt the machine).

This allows the system to sustain a total power of 27W without dropping to 25W.

But ideally, we should fix the fan problem.

qzed commented 2 years ago

But ideally, we should fix the fan problem.

The fan is controlled by the platform profile. Did you set that to "best performance"?