posts - 20 , comments - 57 , trackbacks - 0

SetDbgZone

In my previous post I spoke about finding a problem with the Intel UHCI USB driver. In this post I will explain how we found the cause of problem and what tools we used.

Already a long time ago I wrote a little tool called ‘SetDbgZone.exe’. What is it and why did I wrote it? Well, sometimes your Windows CE image drivers suffer from intermittent problems that you didn’t encounter when you were developing and testing the driver. Even worse, a bug shows up in a RELEASE build and not in a DEBUG build. The latter reason is why I initially wrote ‘SetDbgZone.exe’. I based myself at that time on several of Sue Loh’s blogs.

In a DEBUG build, you can quite easily turn on ‘CE Debug Zones’ in Platform Builder. This will give you extra runtime logging (showing up in Output Window of Platform Builder) that can help you track down problems. These DEBUG messages are typically generated in your code by the DEBUGMSG macro in combination with ‘DBGPARAM dpCurSettings’ structure and DEBUGMASK macro. In a RELEASE build however, these macros are typically compiled out of your code. But I found out that you can keep this logging mechanism available in a RELEASE build as well. Let’s see how

First of all you need to change the DEBUGMSG to your own macro in your driver (and by extension you can adapt all the Microsoft sample drivers in the same way). I called it _LOGMSG

#ifdef DEBUG

#define _LOGMSG(x, y)  \

DEBUGMSG(x, y);

#else

#define _LOGMSG(x, y)  \

RETAILCELOGMSG (x, y);           // Make sure 'y' is surrounded with () when calling it, ex. _LOGMSG(ZONE,(L"", data1));

#endif

As you can see, the _LOGMSG macro reverts to DEBUGMSG in a DEBUG build, nothing new. However in a RELEASE build I redirect it to the RETAILCELOGMSG macro (see also #include <dbgapi.h>). This macro will send your runtime logging to CELOG. Now this is interesting as CELOG can also work in RELEASE. CELOG for instance is also used by KernelTracker to track kernel events. But you can add your own messages to CELOG. There is a lot to learn about CELOG, but for now you should know that CELOG is a circular log memory buffer in RAM and that you use ‘CeLogFlush.exe’ to dump the RAM contents to disk. You can also use ‘OsCapture.exe’, but I use ‘CeLogFlush.exe’ most of the time.

You can control CELOG via the Build Options of your project, but I prefer not to do it that way. Instead I add the required components myself in my image via OsDesign.bib

celog.dll $(_FLATRELEASEDIR)\celog.dll NK  SHK

celogflush.exe $(_FLATRELEASEDIR)\celogflush.exe NK  S

oscapture.exe $(_FLATRELEASEDIR)\oscapture.exe

and OsDesign.reg

[HKEY_LOCAL_MACHINE\System\CeLog]

    "Transport"="LocalFile"

    "ThreadPriority"=dword:64

    "FileName"="\\CeLog.clg" ; Write to root -> fast RAM disk

    "BufferSize"=dword:0800000

    "FlushTimeout"=dword:1388 ; Write every 5 sec

    "ZoneCE"=dword:40010000 ; CeLog kernel zones

You most likely also have to remove some #ifdef DEBUG statements around the DEBUGMASK macro definitions and ‘DBGPARAM dpCurSettings’ structure in your source code so that they are also known for your RELEASE compilation.

So far we have only made sure that our _LOGMSG macro logs to the CELOG buffer. But only if the DEBUGMASK bit is set in the dpCurSettings structure. By default - certainly in a RELEASE build - all DEBUGMASK bits are set to false (off). Note that the price we pay for _LOGMSG in RELEASE is an extra ‘small’ if-statement to see if any logging needs to be sent to CELOG. If the DEBUGMASK bit is off, nothing more will happen. This is the only runtime performance hit you will have, most of the time negligible according to my experience.

Now, how do you switch the DEBUGMASK bit to true (on)? That is where ‘SetDbgZone.exe’ comes into play. These days this API is well documented in MSDN, in the CE 4 era I looked at the shared source code of this API to see how it worked. ‘SetDbgZone.exe’ is a small command line tool that I also include with my image. At the end of the blog, you can find the source code. It basically uses the ToolHelp API to find the process (exe) or module (dll) of interest and calls SetDbgZone() API on it. This API will set the corresponding DEBUGMASK bits in the dpCurSettings structure, if it exists in the process or module. Note that the structure always has to have this name. If you work a lot with Windows CE, one of the first words you should learn is ’dpCurSettings’! It’s the same structure you need to search for in source code to know what registry name you have to set in the Pegasus registry key to have ‘Ce Debug Zones’ turned on from boot when debugging with Platform Builder, but that is another (well known?) story…

So, how do you use it?

  • Boot your Windows CE RELEASE image. The image includes
    • SetDbgZone.exe
    • CeLogFlush.exe
    • Registry settings for when CeLogFlush.exe is running
  • By default, no CeLog collecting is taking place  -> minimum performance impact
  • Open a Windows CE command prompt
  • Run ‘SetDebugZone.exe /m=YourDriver.dll:0xFFFF’  -> this will set the DEBUGMASK bits -> _LOGMSG macro in your driver will write to CeLog
  • Run ‘Start CeLogFlush.exe’  -> this will start writing CeLog RAM contents to disk according to what is set in the registry (time interval, location, size, etc… See MSDN for more information on CeLogFlush.exe registry settings
  • Once you have encountered your problem, copy CeLog.clg to a desktop Windows computer so you can analyze it further.
  • Run on desktop computer ‘Readlog.exe  CeLog.clg  CeLog.txt’  -> this will convert the binary CeLog.clg data to readable text. See MSDN for more information on Readlog.exe
With this scenario I can still debug and collect CeLog traces of my image, even when the image is already out-in-the-field. Also know that an end user application can also write to CeLog, this allows you to combine image and user application information, which might be crucial to track down some problems...

 Happy BugHunting J


#include <windows.h>

#include <windows.h>

#include <windows.h>

#include <toolhelp.h>

#include <tlhelp32.h>

#include <string>

#include <map>

#include <stdlib.h>

 

std::map<std::wstring, DWORD>    g_processes;

std::map<std::wstring, DWORD>    g_modules;

 

void EnumerateProcessesAndModules()

{

    HANDLE snapShotProcess = INVALID_HANDLE_VALUE;

    snapShotProcess = CreateToolhelp32Snapshot(TH32CS_SNAPPROCESS | TH32CS_SNAPNOHEAPS, 0);

 

    if (snapShotProcess != INVALID_HANDLE_VALUE)

    {

        // Build new list

        int c = 0;

        PROCESSENTRY32 processEntry;

        processEntry.dwSize = sizeof(PROCESSENTRY32);

        BOOL retProcess = Process32First(snapShotProcess, &processEntry);

        while (retProcess == TRUE)

        {

            wchar_t fullProcessName[256];

            wsprintf(fullProcessName, L"%08X-%s", processEntry.th32ProcessID, processEntry.szExeFile);

            g_processes[fullProcessName] = processEntry.th32ProcessID;

            HANDLE snapShotModule = INVALID_HANDLE_VALUE;

            snapShotModule = CreateToolhelp32Snapshot(TH32CS_SNAPMODULE, processEntry.th32ProcessID);

 

            if (snapShotModule != INVALID_HANDLE_VALUE)

            {

                MODULEENTRY32 moduleEntry;

                moduleEntry.dwSize = sizeof(MODULEENTRY32);

                BOOL retModule = Module32First(snapShotModule, &moduleEntry);

                while (retModule == TRUE)

                {

                    g_modules[moduleEntry.szModule] = moduleEntry.th32ModuleID;

                    retModule = Module32Next(snapShotModule, &moduleEntry);

                }

                CloseToolhelp32Snapshot(snapShotModule);

            }

            retProcess = Process32Next(snapShotProcess, &processEntry);

        }

        CloseToolhelp32Snapshot(snapShotProcess);

    }

}

 

void ListProcesses()

{

    wprintf(L"Current process list\r\n");

 

    size_t size = g_processes.size();

    int c = 0;

    std::map<std::wstring, DWORD>::const_iterator iter;

    for (iter = g_processes.begin(); iter != g_processes.end(); ++iter)

    {

        wprintf(L" %03d [%08X] : %s\r\n", ++c, iter->second, iter->first.c_str());

    }

}

 

void ListModules()

{

    wprintf(L"Current module list\r\n");

 

    size_t size = g_modules.size();

    int c = 0;

    std::map<std::wstring, DWORD>::const_iterator iter;

    for (iter = g_modules.begin(); iter != g_modules.end(); ++iter)

    {

        wprintf(L" %03d [%08X] : %s\r\n", ++c, iter->second, iter->first.c_str());

    }

}

 

DWORD GetProcessId(const wchar_t* process)

{

    if (process == NULL) return 0;

 

    std::map<std::wstring, DWORD>::const_iterator iter = g_processes.begin();

    while ((iter != g_processes.end()) && (wcsicmp(process, iter->first.c_str()) != 0))

    {

        ++iter;

    }

    if (iter != g_processes.end()) return iter->second;

    return 0;

}

 

DWORD GetModuleId(const wchar_t* module)

{

    if (module == NULL) return 0;

 

    std::map<std::wstring, DWORD>::const_iterator iter = g_modules.begin();

    while ((iter != g_modules.end()) && (wcsicmp(module, iter->first.c_str()) != 0))

    {

        ++iter;

    }

    if (iter != g_modules.end()) return iter->second;

    return 0;

}

 

void PrintHelp()

{

    wprintf(L" DbgZone.exe [/p|/m] [/?]\r\n");

    wprintf(L"  /p       : list all processes\r\n");

    wprintf(L"  /p=xx:yy : set dbg zone yy for process xx\r\n");

    wprintf(L"  /p=xx?   : get dbg zone of process xx\r\n");

    wprintf(L"  /m       : list all modules\r\n");

    wprintf(L"  /m=xx:yy : set dbg zone yy for module xx\r\n");

    wprintf(L"  /m=xx?   : get dbg zone of module xx\r\n");

    wprintf(L"\r\n");

    wprintf(L"Example : DbgZone.exe /m=httpd.dll?\r\n");

    wprintf(L"Example : DbgZone.exe /m=httpd.dll:0x20\r\n");

}

 

int _tmain(int argc, _TCHAR* argv[])

{

    bool parsingSucceeded = true;

    bool listProcesses = false;

    bool listModules = false;

    wchar_t process[64] = L"";

    wchar_t module[64] = L"";

    unsigned int zone = 0xFFFFFFFF;

 

    if (argc > 1)

    {

        for (int i = 1/*skip first arg*/; i < argc; i++)

        {

            // /p=xxx

            if (_wcsnicmp(argv[i], L"/p", 2) == 0)

            {

                if (argv[i][2] == L'=')

                {

                    const wchar_t* delimiter = NULL;

                    const wchar_t* processOption = &argv[i][3];

 

                    delimiter = wcschr(processOption, L':');

                    if (delimiter == NULL)

                    {

                        delimiter = wcschr(processOption, L'?');

                        if (delimiter != NULL)

                        {

                            int toCopy = delimiter - processOption;

                            wcsncpy(process, processOption, toCopy);

                            process[toCopy] = L'\0';

                            zone = 0xFFFFFFFF;

                        } else

                        {

                            parsingSucceeded = false;

                            break;

                        }

                    } else

                    {

                        int toCopy = delimiter - processOption;

                        wcsncpy(process, processOption, toCopy);

                        process[toCopy] = L'\0';

                        zone = _wtoi(delimiter + 1);

                    }

                } else

                {

                    listProcesses = true;

                }

            }

            // /m=xxx

            else if (_wcsnicmp(argv[i], L"/m", 2) == 0)

            {

                if (argv[i][2] == L'=')

                {

                    const wchar_t* delimiter = NULL;

                    const wchar_t* moduleOption = &argv[i][3];

 

                    delimiter = wcschr(moduleOption, L':');

                    if (delimiter == NULL)

                    {

                        delimiter = wcschr(moduleOption, L'?');

                        if (delimiter != NULL)

                        {

                            int toCopy = delimiter - moduleOption;

                            wcsncpy(module, moduleOption, toCopy);

                            module[toCopy] = L'\0';

                            zone = 0xFFFFFFFF;

                        } else

                        {

                            parsingSucceeded = false;

                            break;

                        }

                    } else

                    {

                        int toCopy = delimiter - moduleOption;

                        wcsncpy(module, moduleOption, toCopy);

                        module[toCopy] = L'\0';

                        zone = _wtoi(delimiter + 1);

                    }

                } else

                {

                    listModules = true;

                }

            }

            // /?

            else if (_wcsnicmp(argv[i], L"/?", 2) == 0)

            {

                wprintf(L"DbgZone utility to set/get debugzones.\r\n\rn");

                PrintHelp();

                return 0;

            }

            // huh, invalid sequence??

            else

            {

                parsingSucceeded = false;

            }

        }

    }

 

    if (parsingSucceeded == false)

    {

        wprintf(L"Failed parsing commandline options.\r\n\r\n");

        PrintHelp();

        return -1;

    }

 

    EnumerateProcessesAndModules();

 

    if (listProcesses)

    {

        ListProcesses();

        return 0;

    }

 

    if (listModules)

    {

        ListModules();

        return 0;

    }

 

    if ((process[0] != '\0') && (module[0] != '\0'))

    {

        wprintf(L"Both exe and dll could not be specified.\r\n");

        return -2;

    }

 

    if ((process[0] == '\0') && (module[0] == '\0'))

    {

        wprintf(L"At least one exe or dll should be specified.\r\n");

        return -3;

    }

 

    DWORD dwProcessId = GetProcessId(process);

    DWORD dwModuleId = GetModuleId(module);

    DWORD dwZone = zone;

    DBGPARAM dbg;

    const wchar_t* item = (process[0] != L'\0') ? process : module;

 

    if ((dwProcessId == 0) && (dwModuleId == 0))

    {

        wprintf(L"Could not find process or module '%s'.\r\n", item);

        return -4;

    }

 

    // Set (or get)

    SetDbgZone(dwProcessId, (LPVOID)dwModuleId, 0, dwZone, &dbg);

 

    // Get

    SetDbgZone(dwProcessId, (LPVOID)dwModuleId, 0, 0xFFFFFFFF, &dbg);

 

    wprintf(L"DBGPARAMs for '%s - %s' are :\r\n", item, dbg.lpszName);

    for (int i = 0; i < 16; i++)

    {

        wprintf(L"   '%s' : %s\r\n", ( (dbg.ulZoneMask & (1 << i)) != 0 ) ? L"On " : L"Off", dbg.rglpszZones[i]);

    }

    wprintf(L"   ZoneMask = 0x%08X\r\n", dbg.ulZoneMask);

 

    return 0;

}

 

Print | posted on Tuesday, December 31, 2013 4:51 PM | Filed Under [ Windows CE Windows Embedded Compact Embedded Microsoft CeLog ]

Feedback

No comments posted yet.
Post A Comment
Title:
Name:
Email:
Comment:
Verification:
 

Powered by: