Contribute
Register

DSDT Debugging/Tracing to system.log

RehabMan

Moderator
Joined
May 3, 2012
Messages
188,949
Motherboard
Intel DH67BL
CPU
i7-2600K
Graphics
HD 3000
Mac
MacBook Air
Mobile Phone
iOS
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:
README said:
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.tonymacx86.com/dsdt/111868-dsdt-debugging-tracing-system-log.html#post746732


For those that don't want to build it themselves, I've attached a binary:
 

Attachments

Joined
Jan 16, 2014
Messages
1
Motherboard
Dell Latitude E6520
CPU
i7-2720QM
Graphics
Intel HD3000/ Nvidia GF119
Mac
Classic Mac
Mobile Phone
[FONT=Verdana, Geneva, sans-serif]I'm trying to debug my DSDT's AMW0 (WMI) class to figure why my hotkeys aren't working properly. I have a Dell Latitude E6520. I want to be able to pass non-primitive data structures into your RMDT debugging methods, such as OperationRegions that contain fields, so I can see the output of a bunch of different variables in one-shot. Do you know if that is possible?[/FONT]
 

RehabMan

Moderator
Joined
May 3, 2012
Messages
188,949
Motherboard
Intel DH67BL
CPU
i7-2600K
Graphics
HD 3000
Mac
MacBook Air
Mobile Phone
iOS
[FONT=Verdana, Geneva, sans-serif]I'm trying to debug my DSDT's AMW0 (WMI) class to figure why my hotkeys aren't working properly. I have a Dell Latitude E6520. I want to be able to pass non-primitive data structures into your RMDT debugging methods, such as OperationRegions that contain fields, so I can see the output of a bunch of different variables in one-shot. Do you know if that is possible?[/FONT]
You can pass Buffers/Packages to PUSH (or the Px helpers). You cannot pass entire OperationRegions or entire Field "overlays" in OperationRegions. Individual members of a Field are ok (they are treated as their native type, or Buffer). Of course, you can define multibyte field members...

For an example, lets say you wanted to dump all 256 bytes of an EC. One would think you could do this:
Code:
// test method
Method(D_EC, 0, NotSerialized)
{
    OperationRegion(ERAM, EmbeddedControl, Zero, 256)
    Field (ERAM, ByteAcc, Lock, Preserve) { BITS, 2048 }
    \RMDT.P2("EC", BITS)
}
But the problem is OS X's implementation of ACPI is buggy and doesn't properly handle multi-byte EC fields (it fails, and aborts the ACPI call). The bug is why we have to patch DSDT for battery and other things that may access the EC.

Instead you must copy it to a temporary buffer one byte at a time, using helper functions (these helpers I've used in many of my battery patches for laptops):

Code:
// helper: Read EC 1-byte, Arg0 is offset
Method (RE1B, 1, NotSerialized)
{
    OperationRegion(ERAM, EmbeddedControl, Arg0, 1)
    Field(ERAM, ByteAcc, NoLock, Preserve) { BYTE, 8 }
    Return(BYTE)
}
// helper: Read EC buffer, Arg0 is offset, Arg1 is number of bits (multiple of 8)
Method (RECB, 2, Serialized)
{
    ShiftRight(Arg1, 3, Arg1)
    Name(TEMP, Buffer(Arg1) { })
    Add(Arg0, Arg1, Arg1)
    Store(0, Local0)
    While (LLess(Arg0, Arg1))
    {
        Store(RE1B(Arg0), Index(TEMP, Local0))
        Increment(Arg0)
        Increment(Local0)
    }
    Return(TEMP)
}
// test method
Method(D_EC, 0, NotSerialized)
{
    \RMDT.P2("EC (0-255)", RECB(0, 2048))  // dump entire EC
    \RMDT.P2("EC 128-191", RECB(128, 512)) // dump at 128, 64 bytes long
}
 

RehabMan

Moderator
Joined
May 3, 2012
Messages
188,949
Motherboard
Intel DH67BL
CPU
i7-2600K
Graphics
HD 3000
Mac
MacBook Air
Mobile Phone
iOS
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:

Code:
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:

Code:
# in Terminal
ioio -s org_rehabman_ACPIDebug dbg0 5
 
Joined
Jan 24, 2014
Messages
7
Motherboard
Lenovo Z410
CPU
i5 4200M
Graphics
HD4600+GT740m
Mac
Classic Mac
Mobile Phone
Is it possible to call other methods in dsdt like using acpi_call in linux?
 
Joined
Dec 27, 2011
Messages
150
CPU
i5-3317U
Graphics
HD4000
Mac
MacBook Air
Mobile Phone
iOS
Hi RehabMan, am trying to debug my dsdt to fix a problem with the wrong reading of battery level (116%), remember?
But am lost here.

This is what i have done:
1. Patch dsdt
2. Install ACPIDebug.kext
...
The step 3 is what i don't understand:

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

This is what console show: kernel[0]: ACPIDebug: Version 0.1.0 starting. Nothing more :(

What i miss?
Thanks man
 

RehabMan

Moderator
Joined
May 3, 2012
Messages
188,949
Motherboard
Intel DH67BL
CPU
i7-2600K
Graphics
HD 3000
Mac
MacBook Air
Mobile Phone
iOS
Hi RehabMan, am trying to debug my dsdt to fix a problem with the wrong reading of battery level (116%), remember?
But am lost here.

This is what i have done:
1. Patch dsdt
2. Install ACPIDebug.kext
...
The step 3 is what i don't understand:

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

This is what console show: kernel[0]: ACPIDebug: Version 0.1.0 starting. Nothing more :(

What i miss?
Thanks man
You need to insert code in your DSDT to output debug traces for whatever you want to debug.
 
Joined
Oct 23, 2010
Messages
902
Motherboard
GA-Z77X-UP5-TH
CPU
i7-3770K
Graphics
RX 580
Mac
iMac, MacBook Pro
Mobile Phone
Android, iOS,
Summary:
Excellent debug tool for DSDT.
Using this tool, I found my problem with Sleep/Wake on Yosemite.
But I like to know why I have the problem.

Background:
I have an old system (Inspiron 530) which boots Snow Leopard (SL) or Mavericks (MV).
On the third partition, I just did a fresh install of Yosemite (YS).

I use the SAME DSDT file on all three OS's.

Both SL and MV Sleep and Wake fine (Screen turns off, Fans turn off, Power light flashes while sleeping).
But on YS, the system sleeps fine just like SL & MV but crashes on Wake (screen stays black and peripherals are dead).

Does not matter if I use Chameleon, Chimera or Clover.

Details:
So I installed the ACPI debug kext on all three OS's and put debug PUSH statements at key places where I think there are problems.

I put PUSH statement in _PTS, _WAK and _INI methods (example seen below):
Code:
                [B]Method (^_INI, 0, NotSerialized)[/B] [COLOR=#008000] // _INI: Initialize[/COLOR]
                {
                    // output debug
[COLOR=#ff0000]                    \RMDT.P2("in Method _INI, _OS = ", _OS)[/COLOR]
                    If (STRC (_OS, "Microsoft Windows"))
                    {
                        Store (0x56, SMIP)
                    }
                    Else
                    {
                        If (STRC (_OS, "Microsoft Windows NT"))
                        {
                            If (CondRefOf (\_OSI, Local0))
                            {
                                If (_OSI ("Windows 2001"))
                                {
[COLOR=#ff0000]                                    \RMDT.P1("in Method _INI, _OSI = Windows 2001")[/COLOR]
                                    Store (0x59, SMIP)
                                    Store (Zero, OSFL)
                                    Store (0x03, OSFX)
                                }


                                If (_OSI ("Windows 2006"))
                                {
[COLOR=#ff0000]                                    \RMDT.P1("in Method _INI, _OSI = Windows 2006")[/COLOR]


                                    Store (0x59, SMIP)
                                    Store (Zero, OSFL)
                                    Store (0x04, OSFX)
                                }
                            }
                            Else
                            {
                                Store (0x58, SMIP)
                                Store (Zero, OSFL)
                                Store (Zero, OSFX)
                            }
                        }
                        Else [COLOR=#008000]// It's NOT Microsoft Windows, AND it's NOT WinNT so We MUST be running Darwin[/COLOR]
                        {
[COLOR=#ff0000]                            \RMDT.P1("in Method _INI, _OS NOT EQ to Microsoft Windows NT")[/COLOR]
                                    
                            Store (0x59, SMIP)
                            Store (0x00, OSFL)
                            Store (0x04, OSFX)
                        }
                    }
[COLOR=#ff0000]                    \RMDT.P6("Exit Method _INI, SMIP = ", SMIP, "OSFL =", OSFL, "OSFX =", OSFX)[/COLOR]
                }
In the system.log file I discovered that :
For SL, _OS = Darwin
For MV, _OS = Darwin
For YS, _OS = Microsoft Windows NT !

The conditions for Sleep/Wake to work, SMIP = 0x59, OSFL = 0x00 and OSFX = 0x04

BUT for YS, they are set as SMIP = 0xa1, OSFL = 0x01 and OSFX = 0x01
That, the method _INI does not set them up because _OS is NOT Darwin.

Questions:

1. What sets the value of _OS ?
2. Why is it "Microsoft Windows NT" on YS ?
3. How do I debug/track what is setting up _OS ?
4. I can simply fix it by taking out ALL the checks on _OS and simply setup SMIP, OSFL & OSFX but is there any consequences (I do sometimes boot Windows from another drive) ?
 

RehabMan

Moderator
Joined
May 3, 2012
Messages
188,949
Motherboard
Intel DH67BL
CPU
i7-2600K
Graphics
HD 3000
Mac
MacBook Air
Mobile Phone
iOS
...
1. What sets the value of _OS ?
No way to know. You didn't post your instrumented DSDT. Nor did you post the output of your debugging efforts in system.log.

FYI: According to ACPI spec, _OS is provided by the ACPI host OS. Interesting that it returns "Microsoft Windows NT" on Yosemite. Obviously a mistake by the folks in Cupertino.

Most DSDTs use _OSI to check the host version.
 
Joined
Oct 23, 2010
Messages
902
Motherboard
GA-Z77X-UP5-TH
CPU
i7-3770K
Graphics
RX 580
Mac
iMac, MacBook Pro
Mobile Phone
Android, iOS,
Wow it would be mighty weird for Cupertino to set _OS to "Microsoft Windows NT" :lol:
If they did, they are taking a **** cause it detects a hackingtosh.
Most likely is that the BIOS has default value of "Microsoft Windows NT" and YS never sets up the _OS variable ?

Anyway, I modified my DSDT to get Wake to work on all three OS's (SL, MV & YS).
Attached.

The latest YS output of system.log related to ACPI Debug is:
Code:
Nov  6 01:35:38 localhost kernel[0]: ACPIDebug: Version 0.1.2 startingNov  6 01:35:38 localhost kernel[0]: ACPIDebug: { "in Method _INI, _OS = ", "Microsoft Windows NT", }
Nov  6 01:35:38 localhost kernel[0]: ACPIDebug: "in Method _INI, _OSI = Darwin"
Nov  6 01:35:38 localhost kernel[0]: ACPIDebug: { "CondRefOf Method _INI, SMIP = ", 0x59, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 01:35:38 localhost kernel[0]: ACPIDebug: { "Exit Method _INI, SMIP = ", 0x59, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 01:38:06 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 01:38:06 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 03:25:59 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 03:25:59 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 05:14:58 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 05:14:58 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 05:14:58 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 05:14:58 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 07:03:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 07:03:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 07:03:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 07:03:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 08:52:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 08:52:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 08:52:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 08:52:57 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 10:41:56 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 10:41:56 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 10:41:56 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 10:41:56 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0x3, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
I started the system at 1:35 and put it to Sleep (and myself).
Looks like the System is waking up approx every 2 hours due to RTC Alarm (not sure what's causing that):
Code:
Nov  6 03:25:59 MacNB-Mac-Pro kernel[0]: Wake reason: RTC (Alarm)Nov  6 05:14:58 MacNB-Mac-Pro kernel[0]: Wake reason: RTC (Alarm)
Nov  6 07:03:57 MacNB-Mac-Pro kernel[0]: Wake reason: RTC (Alarm)
Nov  6 08:52:57 MacNB-Mac-Pro kernel[0]: Wake reason: RTC (Alarm)
Nov  6 10:41:56 MacNB-Mac-Pro kernel[0]: Wake reason: RTC (Alarm)
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: Wake reason: ?
Nov  6 11:19:38 MacNB-Mac-Pro kernel[0]: full wake promotion (reason 1) 72 ms
The Wake Reason is set to "?" when I wake it with keyboard (wired USB) which seems strange.

Also, MV debug output is:
Code:
05/11/2014 18:29:59.000 kernel[0]: ACPIDebug: { "in Method _INI, _OS = ", "Darwin", }05/11/2014 18:29:59.000 kernel[0]: ACPIDebug: { "Exit Method _INI, SMIP = ", 0x59, "OSFL =", 0x0, "OSFX =", 0x4, }
05/11/2014 18:31:49.000 kernel[0]: ACPIDebug: { "_PTS enter with Arg0 = ", 0x3, }
05/11/2014 18:31:49.000 kernel[0]: ACPIDebug: { "_PTS exit", "SMIP =", 0x59, "ESMI =", 0x0, "TRAP = ", 0x1, }
05/11/2014 18:31:49.000 kernel[0]: ACPIDebug: { "_WAK enter Arg0 =", 0xffffff7f808dbc50, "SMIP & OSFL =", 0xff, 0x0, "OSFX =", 0x4, }
05/11/2014 18:31:49.000 kernel[0]: ACPIDebug: { "_WAK exit, SMIP =", 0x88, "OSFL =", 0x0, "OSFX =", 0x4, }
SL output is identical to MV.

Is safe to take out all the code for OS checks in _INI and simply setup the SMIP, OSFL and OSFX to the values that works for all three OS's ?

Also, how do I PUSH out what _OSI contains as it seems like a function that return a Boolean ?

Thx for your help Rehabman.
 

Attachments

Top