DSDT Debugging/Tracing to system.log

RehabMan · October 16, 2013

Have you ever wanted to know if a certain DSDT method was being called? Or wanted to know more about the execution path (eg. know whether the If or Else part is being executed)? Have you wanted to print the values out of various variables, buffers and packages within your DSDT as methods are called?

So have I...

Trying to solve DSDT issues without knowing what code is executing, what the various variables are (whether normal Name objects, EC regions or SystemMemory regions), is very challenging. I have used some techiques in the past that were not very convenient, such as modifying ACPISensors.kext and HwMonitor so I could see select values in HwMonitor, but these were only good for one off snapshots and very cumbersome to use.

To make it easier, I have created ACPIDebug.kext. With this kext and a DSDT patch, you can cause print information to system.log for DSDT debugging.

It is available here: https://github.com/RehabMan/OS-X-ACPI-Debug

This is from the README:

Advanced Configuration and Power Interface (ACPI) based kernel extension for debugging DSDT code. This kext allows one to easily trace variables and execution path from DSDT (or SSDT) code.

Installation:

To use it you must install the two components that make up the software. First of all, you must patch your DSDT to add the RMDT (RehabMan Debug Trace) device. The presence of this device allows the kext to load. Apply the debug.txt patch via MaciASL. You can also add this repo as a MaciASL "source" in MaciASL preferences: http://raw.github.com/RehabMan/OS-X-ACPI-Debug/master.

Second, you must build and install the kext (ACPIDebug.kext). You can build it at the command line with 'make' and install it with Kext Wizard (or your favorite kext installer), or you can install it at the command line with 'make install'. Of course, you can also build it with Xcode. I'm using Xcode 5.0 at the moment.

Third, add code to your DSDT to where you wish to cause trace messages to system.log (call \RMDT.PUSH).

Using the tracing facility:

The DSDT patch adds the RMDT device at the root of your DSDT. There are several methods you can use from within the DSDT to "push" debug output to the kext:

PUSH: Takes a single parameter (of any type, including Packages and Buffers). The contents of this parameter will be displayed by the kext to system.log.

P1, P2 through P7. P1 does exactly the same as PUSH. Each of these utility methods takes 1 to 7 parameters (according to the name of the method). This makes it easy to provide descriptions for your data or have multiple variables displayed on one line in system.log.

The other methods COUN, and FTCH are part of the implementation. These methods are called by ACPIDebug.kext to pull information.

Examples:

\RMDT.PUSH("Entering _WAK")

output: ACPIDebug: "Entering _WAK"

\RMDT.PUSH(Local0)

example output: ACPIDebug: 0x10

\RMDT.P2("Local0", Local0)

example output: ACPIDebug: { "Local0", 0x10, }

\RMDT.P4("OSFL() returns", OSFL(), "OSVR is", OSVR)

example output: ACPIDebug: { "OSFL() returns", 0xABC, "OSVR is", 0x60, }

Name(TEST, Buffer() { 128, 255, 10, 127 }

\RMDT.P1(TEST)

output: ACPIDebug: { 0x80, 0xFF, 0x0A, 0x7F, }

Name(TEST, Package() { Package() { 128, 255 }, Package() { 1, 2, 3, 10 })

output: ACPIDebug: { { 0x80, 0xFF }, { 0x1, 0x2, 0x3, 0xA }, }

How it works:

Internally the RMDT device maintains a ring buffer of objects added via PUSH (ring buffer uses a Package). The ring buffer size is 256. The ACPIDebug.kext polls the RMDT device (via FTCH) every 100ms to see if any objects are available for printing. If they are they are pulled from the ring buffer and output to system.log (it is a FIFO ring). Objects added to the ring buffer when it is full are ignored.

Update 2014-01-18

See this post for information on the 2014-0118 version: http://www.insanelymac.com/forum/topic/292800-dsdt-debuggingtracing-to-systemlog/?do=findComment&comment=1986372

Note: I also posted this over at TMX, but it may well be more interesting to the more "developer oriented" community here at IM.

RehabMan · October 19, 2013

This tool has already revealed a bug in 10.8.5+.

OS X is passing garbage in Arg0 to DSDT _WAK (called upon wake from sleep). On wake from S3 it should be 3. Many DSDTs have code which compares Arg0==3 or Arg0==4 to restore state. Having Arg0==garbage could cause strange things to happen on wake from sleep, so watch out for it.

Here are a couple of DSDT patches that can work around the issue:

into method label _WAK code_regex \s(.?WAK\s+\([^)]*\)) replace_matched
begin
If (LOr(LLess(Arg0,1),LGreater(Arg0,5))) { Store(3,Arg0) }\n
%1
end;

Or:

into method label _WAK code_regex ([\s\S]*) replace_matched
begin
If (LOr(LLess(Arg0,1),LGreater(Arg0,5))) { Store(3,Arg0) }\n
%1
end;

Which one you might use depends on the specifics of the code in your _WAK method in your DSDT.

chris1111 · October 20, 2013

Great JOB Thanks Rehabman !

pere · October 20, 2013

Very, very interesting, thanks for your effords, will keep an eye on this thread.

RehabMan · January 18, 2014

FYI... Recently added a new feature to this kext. It allows you to invoke ACPI calls "on demand" from Terminal using ioio.

It is described in the README:

Forcing calls into RMDT from Terminal:

With the latest changes you can also force calls into methods in RMDT by using ioio. For ioio, see: https://github.com/RehabMan/OS-X-ioio

The mapping of properties to methods is as follows:

dbg0 -> DBG0

dbg1 -> DBG1

...

dbg9 -> DBG9

The methods will take one parameter (which is the value that the property was set to). The return value of the method is ignored.

So, in the RMDT device, you can add a method as such:
Method(DBG0, 1, Serialized)
{
   \RMDT.P2("DBG0 Arg0=", Arg0)
   If (LEqual(Arg0, 5))
   {
      \RMDT.P1("You set dbg0 to 5")
   }
   Else 
   { 
      \RMDT.P1("You set dbg0 to something other than 5")
   }
}
You could, of course, output any other DSDT data you wanted to in that method.

In order to trigger the method, set the 'dbg0' property with ioio:
# in Terminal
ioio -s org_rehabman_ACPIDebug dbg0 5

Kuebeker · February 11, 2014

If you want to use DSDT Editor.app...

Use MacASL to compile and save it as an AML

Open that AML with DSDT Editor.app and save it as .DSL

You will now be able to wor on it with DSDT Editor.app.

RehabMan · February 14, 2014

If you want to use DSDT Editor.app...

Use MacASL to compile and save it as an AML

Open that AML with DSDT Editor.app and save it as .DSL

You will now be able to wor on it with DSDT Editor.app.

Unless there are bugs in DSDT Editor, you should be able to apply the patch with DSDT Editor as well.

I don't use DSDT Editor, so I have not (will not) test with DSDT Editor. DSDT Editor being based on Java is just too buggy to use (for me), which is why I use MaciASL exclusively (it is a native app... not based on garbage like Java).

Kuebeker · February 14, 2014

Unless there are bugs in DSDT Editor, you should be able to apply the patch with DSDT Editor as well.

I don't use DSDT Editor, so I have not (will not) test with DSDT Editor. DSDT Editor being based on Java is just too buggy to use (for me), which is why I use MaciASL exclusively (it is a native app... not based on garbage like Java).

I don't think DSDT Editor.app have been updated in a while that is probably why it's buggy reading and or applying your patch. I've started to use MaciASL. There are some features I'd like to see but it's workable as it ls.

BTW. your kext is so freaking cool!!!!!

Kuebeker · February 14, 2014

I see some ACPIDebug log entries like the following:

2/14/2014 5:53:49.000 PM kernel[0]: ACPIDebug::message(-536707056, 0xffffff8012cc2c00, 0xffffff80f1e9be8c)

2/14/2014 5:53:49.000 PM kernel[0]: ACPIDebug::message(-536707056, 0xffffff8012cc2c00, 0xffffff80f1653e8c)

What does it mean?

RehabMan · February 15, 2014

I see some ACPIDebug log entries like the following:

2/14/2014 5:53:49.000 PM kernel[0]: ACPIDebug::message(-536707056, 0xffffff8012cc2c00, 0xffffff80f1e9be8c)

2/14/2014 5:53:49.000 PM kernel[0]: ACPIDebug::message(-536707056, 0xffffff8012cc2c00, 0xffffff80f1653e8c)

What does it mean?

Look at the source, line 117 in ACPIDebug.cpp, function ACPIDebug::message. That line should probably be changed to DEBUG_LOG.

Kuebeker · February 15, 2014

I've just did a change request from message to Debug log through https://github.com.

It's the first time I do something like that and I have no idea what I'm doing. Hope it worked ok.

wern apfel · April 28, 2015

I’ve tried to make brightness keys to work with your tool, there is only a single query method

ECRD 1 brightness down, 0 up, but its not working as it should boot keys degreases the brightness

is this patch right?

here is the patch

into method label _Q66 parent_label ECDV replace_content
begin
Store(ECRD, Local0)\n
If (LEqual(Local0,1))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0205)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0285)\n
}\n
If (LEqual(Local0,0))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0206)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0286)\n
}\n
end;

WaldMeister · April 28, 2015

I’ve tried to make brightness keys to work with your tool, there is only a single query method

ECRD 1 brightness down, 0 up, but its not working as it should boot keys degreases the brightness

is this patch right?

here is the patch
into method label _Q66 parent_label ECDV replace_content
begin
Store(ECRD, Local0)\n
If (LEqual(Local0,1))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0205)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0285)\n
}\n
If (LEqual(Local0,0))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0206)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0286)\n
}\n
end;

Hi,

This depends on your PS2 device.

In my case it's PS2E, the debugging kext can also be used to find out this information.

RehabMan · April 28, 2015

I’ve tried to make brightness keys to work with your tool, there is only a single query method

ECRD 1 brightness down, 0 up, but its not working as it should boot keys degreases the brightness

is this patch right?

here is the patch
into method label _Q66 parent_label ECDV replace_content
begin
Store(ECRD, Local0)\n
If (LEqual(Local0,1))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0205)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0285)\n
}\n
If (LEqual(Local0,0))\n
{\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0206)\n
    Notify(\_SB.PCI0.LPCB.PS2K, 0x0286)\n
}\n
end;

ECRD is usually a variable which indicates "EC ready" and is set in _REG. It is not an indication of the key that was pressed.

If both keys (bright up, bright down) generate a call to _Q66, post the original code for _Q66.

wern apfel · April 28, 2015

thanks for reply, it seems that this query is battery related if i plug unplug the ac adaptor brightness is also changing

@LexHimself "PS2K" is the device name

here is the code

Method (_Q66, 0, NotSerialized)
            {
                If (LNotEqual (ECRD, One))
                {
                    Return (Zero)
                }

                NEVT ()
                Return (Zero)
            }

RehabMan · April 28, 2015

thanks for reply, it seems that this query is battery related if i plug unplug the ac adaptor brightness is also changing

That is normal behavior by the system... not related this query.

here is the code

Method (_Q66, 0, NotSerialized)
            {
                If (LNotEqual (ECRD, One))
                {
                    Return (Zero)
                }

                NEVT ()
                Return (Zero)
            }

Not enough info. It just calls NEVT. So you need to find that method and look at it.

wern apfel · April 28, 2015

I've also played with NEVT which end at wmi device, or i'm wrong?

NEVT EV8 WMNF AMW0

The AC plug in out is not the normal behavior, it does the same like the keystroke, every replug brightness goes down

here is the NEVT code

Method (NEVT, 0, NotSerialized)
    {
        Store (ECG1 (), Local0)
        If (And (Local0, One))
        {
            EV6 (One, Zero)
        }

        If (And (Local0, 0x40))
        {
            EV6 (0x02, Zero)
        }

        If (And (Local0, 0x04))
        {
            Store (ECG3 (), Local1)
            EV6 (0x03, Local1)
        }

        If (And (Local0, 0x10))
        {
            Store (ECBT (Zero, 0x80), Local1)
            Store (ECRB (0x2D), Local2)
            EV7 (Local1, Local2)
        }

        If (And (Local0, 0x0100))
        {
            EV8 (0x0100, Zero)
            If (ECG4 ())
            {
                GENS (0x1C, One, Zero)
            }
            Else
            {
                GENS (0x1C, Zero, Zero)
            }
        }

        If (And (Local0, 0x0200))
        {
            EV8 (0x0200, Zero)
        }

        If (And (Local0, 0x0400))
        {
            EV8 (0x0400, Zero)
        }

        If (And (Local0, 0x0800))
        {
            EV8 (0x0800, Zero)
        }

        If (And (Local0, 0x4000))
        {
            Store (ECRB (0x30), Local1)
            EV9 (0x4000, Zero)
        }

        If (And (Local0, 0x8000))
        {
            Store (ECRB (0x2E), Local1)
            EV10 (0x8000, Local1)
        }

        If (And (Local0, 0x08))
        {
            PWRE ()
        }

        If (And (Local0, 0x80))
        {
            SMIE ()
        }
    }

RehabMan · April 28, 2015

I've also played with NEVT which end at wmi device, or i'm wrong?

NEVT EV8 WMNF AMW0

The AC plug in out is not the normal behavior, it does the same like the keystroke, every replug brightness goes down

Probably something is not right about your battery status.

On plugin: brightness should go up

On unplug: brightness should go down (equal amount)

here is the NEVT code

Method (NEVT, 0, NotSerialized)
    {
        Store (ECG1 (), Local0)
        If (And (Local0, One))
        {
            EV6 (One, Zero)
        }

        If (And (Local0, 0x40))
        {
            EV6 (0x02, Zero)
        }

        If (And (Local0, 0x04))
        {
            Store (ECG3 (), Local1)
            EV6 (0x03, Local1)
        }

        If (And (Local0, 0x10))
        {
            Store (ECBT (Zero, 0x80), Local1)
            Store (ECRB (0x2D), Local2)
            EV7 (Local1, Local2)
        }

        If (And (Local0, 0x0100))
        {
            EV8 (0x0100, Zero)
            If (ECG4 ())
            {
                GENS (0x1C, One, Zero)
            }
            Else
            {
                GENS (0x1C, Zero, Zero)
            }
        }

        If (And (Local0, 0x0200))
        {
            EV8 (0x0200, Zero)
        }

        If (And (Local0, 0x0400))
        {
            EV8 (0x0400, Zero)
        }

        If (And (Local0, 0x0800))
        {
            EV8 (0x0800, Zero)
        }

        If (And (Local0, 0x4000))
        {
            Store (ECRB (0x30), Local1)
            EV9 (0x4000, Zero)
        }

        If (And (Local0, 0x8000))
        {
            Store (ECRB (0x2E), Local1)
            EV10 (0x8000, Local1)
        }

        If (And (Local0, 0x08))
        {
            PWRE ()
        }

        If (And (Local0, 0x80))
        {
            SMIE ()
        }
    }

You need to instrument NEVT (with ACPIDebug traces) to discover which path it takes when the brightness keys are pressed.

wern apfel · April 29, 2015

Probably something is not right about your battery status.

On plugin: brightness should go up

On unplug: brightness should go down (equal amount)

I now this behavior, the issue was only with patched q66 query where the brightness changed every replug to min or max value, but forget it q66 is the wrong place for the patch

The NEVT method points me to the wmi device where the brightness change depends on the EC0A value WMBU up=0xE048 down=0xE050 not like i think on inspiron models 0xe006 and 0xe005

I now that your PS2 kext can handle ACPI calls but it's not working with my alps pad

Scope (_SB.AMW0)
    {
        Name (WMEV, Zero)
        Name (WMBU, Buffer (0x80) {})
        Name (WM, Zero)
        Method (SWEV, 1, NotSerialized)
        {
            Or (WMEV, Arg0, WMEV)
        }

        Method (CWEV, 1, NotSerialized)
        {
            And (WMEV, Not (Arg0), WMEV)
        }

        Method (WVSP, 0, NotSerialized)
        {
            Acquire (WMIX, 0xFFFF)
            Store (Zero, WM)
            BCLR (WMBU)
        }

        Method (WVCU, 0, NotSerialized)
        {
            Acquire (WMIX, 0xFFFF)
            Store (Zero, WM)
        }

        Method (WVPT, 1, NotSerialized)
        {
            Store (WM, Local0)
            Add (Local0, 0x02, Local0)
            If (LLessEqual (Local0, SizeOf (WMBU)))
            {
                CreateWordField (WMBU, WM, WMWD)
                Store (Arg0, WMWD)
                Store (Local0, WM)
            }
        }

        Method (_WED, 1, NotSerialized)
        {
            WVSP ()
            If (LNotEqual (Arg0, 0xD0))
            {
                WVCU ()
                Return (WMBU)
            }

            If (LEqual (ECD0, Zero))
            {
                WVCU ()
                Return (WMBU)
            }

            If (And (WMEV, 0x0200))
            {
                CWEV (0x0200)
                WVPT (0x02)
                WVPT (Zero)
                WVPT (0xE045)
            }
            Else
            {
                If (And (WMEV, 0x0100))
                {
                    CWEV (0x0100)
                    If (ECG4 ())
                    {
                        WVPT (0x02)
                        WVPT (Zero)
                        WVPT (0xE043)
                    }
                    Else
                    {
                        WVPT (0x02)
                        WVPT (Zero)
                        WVPT (0xE044)
                    }
                }
                Else
                {
                    If (And (WMEV, 0x0800))
                    {
                        Store (EC0A (WMBU), WMBU)
                        CWEV (0x0800)
                    }
                }
            }

            WVCU ()
            Return (WMBU)
        }
    }

RehabMan · April 29, 2015

I now this behavior, the issue was only with patched q66 query where the brightness changed every replug to min or max value, but forget it q66 is the wrong

place for the patch

Yes, definitely the wrong place. It is clear _Q66 is a sink for many different events.

Which path was it taking in NEVT?

If you're not using my VoodooPS2Controller.kext with support for Notify, you won't be able to translate these ACPI events into key events. There is an ALPS version in my repo, you can try it (and try to merge latest changes into it). I quit supporting it due to lack of testing/feedback, and lack of a developer with the hardware (I don't have any ALPS hardware).

wern apfel · April 29, 2015

Which path was it taking in NEVT?

If (And (Local0, 0x0800))
        {
            EV8 (0x0800, Zero)
        }

and then

Method (EV8, 2, NotSerialized)
    {
        WMNF (Arg0, Arg1)
    }

thanks for your assistance

RehabMan · April 29, 2015

If (And (Local0, 0x0800))
        {
            EV8 (0x0800, Zero)
        }

and then

Method (EV8, 2, NotSerialized)
    {
        WMNF (Arg0, Arg1)
    }

thanks for your assistance

Is that for both brightness up and down? If so, you'll have to dig into WMNF to determine how the code disambiguates.

wern apfel · April 29, 2015

I dont't use your latest PS2 kext nor ACPIKeboard, but can send keystrokes isn't that strange ?

Boot keys do the same

RehabMan · April 29, 2015

I dont't use your latest PS2 kext nor ACPIKeboard, but can send keystrokes isn't that strange ?

It was added in v1.8.11.

2014-02-24 v1.8.11

Implement ability to send key strokes from ACPI. This is useful when certain keys are not handled via the PS2 bus, but instead are handled elsewhere in DSDT, usually via EC query methods. With this I was able to make the native brightness keys work as normal keys on a Lenovo U430.

Boot keys do the same

Assume you mean 'both'. You'll need to dig further into WMNF to find out codepath for each key and where the path diverges.

wern apfel · May 1, 2015

Of course i mean both keys, and i was wrong with the kext it was loaded

I've traced like crazy, and the keystrokes depends on this wmi event

If (And (WMEV, 0x0800))
                    {
                        Store (EC0A (WMBU), WMBU)
                        CWEV (0x0800)
                    }

where the wmi buffer depends on EC register

here the EC0A method

Method (EC0A, 1, NotSerialized)
        {
            Acquire (QSEV, 0xFFFF)
            Store (ECRB (0x2B), Local1)
            Store (Zero, Local0)
            While (LLess (Local0, Local1))
            {
                Store (ECRB (0x2C), Local2)
                If (LLess (Local0, SizeOf (Arg0)))
                {
                    BBWR (Arg0, Local0, Local2)
                }

                Increment (Local0)
            }

            Release (QSEV)
            Return (Arg0)
        }

or i'm doing something wrong?

DSDT Debugging/Tracing to system.log

Recommended Posts

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites