65.9K
CodeProject 正在变化。 阅读更多。
Home

优化的进入/离开日志记录器

Santhosh G_
starIconstarIconstarIconstarIcon
emptyStarIcon
starIcon

4.73/5 (4投票s)

2013年7月14日

CPOL

18分钟阅读

viewsIcon

28553

downloadIcon

869

优化记录函数进入和离开信息的方法。

目录

引言

本文介绍了一种优化的代码进入和离开日志记录方法。有时我们会在所有函数中插入TRACE()或其他方法来识别我们软件系统的调用顺序。如果所有函数都调用TRACE()，指示某个线程进入了该函数或从该函数返回，那么稍后，或者在问题发生时，开发人员可以检查这些日志文件以识别不正确的调用顺序或错误的调用顺序。总之，软件系统中的进入和离开日志记录有助于稍后识别问题。这里用两个应用程序（LogTest和LogParser）实现了一个简单的概念。请发送您的建议和评论来改进这个日志记录机制，我很乐意更正/改进这个进入/离开日志记录方法。

背景

有很多方法可以为所有函数准备进入和离开日志。格式化日志的准备会消耗少量处理器时间。如果我们能在运行时以加密或原始形式准备所需数据，那将减少处理成本。加密或原始形式的数据将在稍后，或者在需要时，借助PDB文件转换为可读格式。PDB文件包含二进制文件的所有信息（源文件名、函数名等），然后稍后借助相应的PDB文件，可以轻松地将运行时指令地址转换为函数名。

详细信息

有许多方法可以为函数提供进入和离开日志。

示例代码将是这样的：

Class1::Fun1()
{
MyLogger::Log( “Entering  Class1::Fun1()”);
// …
Do necessary things of Fun1()
// 
MyLogger::Log( “Leaving Class1::Fun1()”);
}

其日志文件将是这样的：

 LogFile.txt
Time    	Log
---------------------------------------------
08:10:22:00 Entering Class1::Fun1()
08:10:22:10 Leaving  Class1::Fun1()

这里我介绍了一种优化记录函数进入和离开信息的方法。它适用于Windows操作系统。目前它是在32位架构上实现的，也可以准备64位版本。在软件系统中有很多方法可以准备日志或跟踪信息。最常见的方法是将进入/离开信息写入日志文件。

这里我提供了一个进入/离开日志记录机制的基本视图。日志文件中还可以包含许多其他信息，如线程ID、进入时间、离开时间、函数执行持续时间等。

普通日志记录机制有一些缺点。

  1. 处理成本：日志记录器会准备一个字符串，指示所有信息到日志文件，并将它们保存到磁盘。如果日志记录频率太高，函数输出文本格式化会有点昂贵。    
  2. 磁盘空间：所有错误日志都会保存在硬盘上（在大多数情况下），会占用一些硬盘空间。如果日志文件大小增加，下一个文件写入会变慢，并导致性能问题。  
  3. 记录不正确的几率：如果进入或离开日志放置不当，则Logger将提供错误信息，除非我们发现该函数存在问题。

有一个有趣的方法可以降低函数进入/离开日志的处理成本。为每个函数准备一个唯一的数字，并将这些数字记录到日志文件中。我建议为每个函数准备一个唯一的标识符，并记录该标识符而不是整个字符串，然后稍后您可以解析这些标识符并生成函数名。

一个例子将是这样的：

// Enumeration for each functions.
// These enums will be saved at runtime.
enum
{
    FUNCTION_1,
    FUNCTION_2
};
 
// String equivalents.
char* pFunctionNames[]=
{
    "Class1::Function1",
    "Class1::Function2",
};
 
// In code.
Class::Func1()
{
    Logger::Log(FUNCTION_1);
    // Here logger will keep integer value of FUNCTION _1 instead of lengthy string.
}
Class::Func2()
{
    Logger::Log(FUNCTION_2);
    // Here logger will keep integer value of FUNCTION _1 instead of lengthy string.
}

在这种情况下，数字（而不是整个函数名）将被保存在LogFile中，稍后（在进程执行完成后），这些数字将被转换为字符串。

上述建议不是在实际系统中实现的良好方法。它需要为每一个函数准备一个唯一的数字。当添加或删除新函数时，我们必须修改常量及其对应的枚举等。因此，在实际软件系统中实现此方法将非常困难。

这是新方法。

指令指针（指令的虚拟地址）保存当前指令的地址。如果存在相应二进制文件的PDB（程序数据库）文件，稍后就可以从指令指针中检索函数名。基本概念是保存函数的指令指针，而不是写入整个函数名。稍后，无论何时需要软件的调用序列，指令地址都将被转换为实际的函数名。此转换可以通过PDB文件完成。这样就可以轻松检索所有函数和线程的调用序列。

它在一定程度上可以解决上述三个问题。

  1. 处理成本较低，因为保存的是地址而不是格式化的字符串。
  2. 磁盘空间会减少：在x86机器上，此方法保存4个字节，而不是长的类名和函数名。
  3. 记录不正确的几率将避免，因为它在运行时保存地址。然后就不会记录错误的字符串了。 
Class1::Fun1()
{
    MyLogger::Log();
    // …
    Do necessary things of Fun1()
        // 
        MyLogger::Log();
}
MyLogger::Log();
// It will retrieve the instruction pointer
// of calling function and save to file or memory.

实现

1. 如何获取函数的指令指针

调试应用程序时，寄存器窗口会显示一个名为EIP（扩展指令指针）的寄存器，但其内容无法以编程方式访问。我尝试通过编写内联汇编代码将EIP移到我的整数或DWORD成员中来检索EIP，就像检索其他寄存器一样。但这会产生编译错误，例如EIP标签未定义。

当调用一个函数时，会创建一个新的“堆栈帧”，以便访问函数参数和局部函数变量。当调用函数时，会创建一个新的堆栈帧，其地址将保存在ESP中。下图显示了X86机器上堆栈的布局。x86机器上的EBP寄存器保存堆栈基指针，并可用于访问与当前执行函数相关的各种信息。在这里，被调用函数的返回地址放置在EBP的下一个位置。因此，任何人都可以通过分析EBP寄存器来获取返回函数的地址。

X86机器上的堆栈布局。

然后可以使用以下代码获取函数的返回地址。

int* nAddress = new int;
__asm
{
    mov nAddress,EBP
}
nAdress++; // To get next location of EBP.
// Now nAdress pointing to the address of returned function.  

可以通过调试代码并分析EBP寄存器和内存的内容来证明上述信息。以下是上述场景的演示，我能否通过分析EBP寄存器和内存来获取调用者地址的指令指针？

上面的代码用于分析EBP寄存器和内存。在这里，_tmain()函数调用MyFunction1()，它将调用GetCallerAddress()。在MyFunction1()中设置一个断点，并记下调用GetCallerAddress()之后的下一条指令的地址。即0x0033144A。以下屏幕截图是MyFunction1()的反汇编。它在左侧列显示指令地址，在下一个右侧列显示相应的汇编指令。粗体行是实际源代码，其汇编代码将紧随其后，在下一行（或多行）中。因此，调用GetCallerAddress()位于0x331445。其汇编代码如下：

00331445 call GetCallerAdddress(3310Dch)  

执行GetCallerAddress()后，程序执行应切换到指令0x0033144A。

然后，在GetCallerAddress()中设置一个断点，并记下EBP寄存器的内容。并在内存监视器窗口中监视EBP附近的内容。EBP附近的下一个位置保存着返回GetCallerAddress()时应该调用的指令的地址，即0x0033144A。在下面的屏幕截图中，EBP的下一个位置的内容用内存监视窗口进行了监视，并在最近的位置显示了4A 14 33 00。0x0033144A以这种格式表示，因为Windows NT是围绕小端内存架构设计的。

 

内存监视器屏幕截图显示EBP寄存器的内容

可以通过处理EBP寄存器来检索调用者函数的地址。以下代码从EBP寄存器中检索调用者地址，并检索返回地址。

void GetCallerAddress()
{
    int nEBPContents;
    __asm mov nEBPContents, EBP; // Retriving 
    // Contents of EBP is converted as a pointer. Then very next location
    // indicates return address the current function 
    int* ptrAddress = (int*)nEBPContents;
    int nReturnIP = *( ++ptrAddress );
    // Here nReturnIP holds the address of caller function.
}

现在从被调用函数中检索函数的地址变得非常容易了。

2. 在发生问题时保存原始数据

我们可以按顺序将函数地址保存到文件中，并附带其他附加信息，如线程ID、进入时间、离开时间等。这些日志信息被写入日志文件。但是用户或开发人员无法从这些函数地址中识别调用顺序。也无法从地址中找出函数名。这时就遇到了下一个问题。如何从函数的地址（指令指针）中检索函数名？

3. 使用PDB文件从函数虚拟地址获取函数名

现在我们已经检索了所有被调用函数的虚拟地址，并将这些信息保存到日志文件中。而不是保存整个函数名[如Entering MyClass::MyFunction1]和进入离开信息，我们将保存函数的虚拟地址[如步骤1和2中所述]，并附带一些额外的字节指示时间、线程ID、进入或离开标志等。在传统的进入/离开日志记录机制中，函数名将被记录到文件中，并且其大小在所有情况下都大于四个字节。在大多数情况下，它将占用20到30个字节的数据。此机制保存函数的虚拟地址。对于所有函数，它将是4个字节，即使函数名是“MyClasssBlaBlaBlaBlaBlaBlaBlaBla::MyFunctionFooFooFooooFoooOooooo”。它只是在运行时保存函数的地址。稍后，另一个应用程序（LogParser，负责解析所有函数的4字节虚拟地址到其原始名称）应该读取这些地址并检索实际的函数名。在这里，PDB文件和DIA SDK在提供函数名（从虚拟地址）方面发挥了作用。

在此之前，让我简单说一下PDB文件，PDB文件为二进制文件（DLL或exe）提供所需的调试信息。它包含调试信息，包括函数名、源文件详细信息、源文件行号、函数原型和其他信息。PDB文件的格式是未公开的，并且是Microsoft专有的，信息可以通过DIA（调试接口访问）接口从PDB文件中提取。PDB格式是隐藏的，Microsoft不愿意与我们分享文件格式。Microsoft DIA SDK提供了访问二进制文件调试信息的各种接口。

有关DIA SDK的更多信息可以在Debug Interface Access SDK找到。

从虚拟地址获取函数名的步骤

要从其PDB和二进制文件以及DIA SDK获取指令地址的函数名，需要执行以下步骤。

  1. 创建一个IDiaDataSource对象，COM接口。  
    2. HRESULT hr = CoCreateInstance( CLSID_DiaSource, NULL,
                                   CLSCTX_INPROC_SERVER,
                                   __uuidof( IDiaDataSource ),
                                   (void **) &m_pSource);
  2. 调用m_pSource->loadDataForExe( binaryFileName, PdbSearchPath,0 )来加载模块的调试信息。   
    3. if( FAILED( m_pSource->loadDataForExe( m_ptszModuleName, m_ptszPDBPath, 0 )))
{
    return false;
}
  3. 通过调用openSession创建一个会话，用于从PDB查询符号。
    4. if( FAILED( m_pSource->openSession( &m_pSession )))
{
    return false;
}
  4. 通过调用m_pSession->put_loadAddress(nLoadAddress)提供相应模块的加载地址。 
    5. HRESULT hReturn = m_pSession->put_loadAddress( nLoadAdddress_i );
  5. 调用pSession->findSymbolByVA()来获取特定虚拟地址的符号。第一个参数是函数的虚拟地址，第二个参数是SymTagFunction，表示需要函数详细信息。将返回一个IDiaSymbol对象。 
    6. CComPtr<IDiaSymbol> pSymbol = 0;
HRESULT hResult = m_pSession->findSymbolByVA( nFunctionVA_i, SymTagFunction, &pSymbol );
  6. 调用返回的符号的get_name()，它将提供相应虚拟地址的函数名。  
    7. BSTR bFunctionName = 0;
pSymbol->get_name( &bFunctionName );   

4. 所有模块的加载地址

在步骤4中，put_loadAddress()函数是用模块的加载地址调用的。因此，我们需要检索模块的加载地址才能使用DIA SDK进行处理。在应用程序启动时，Windows加载器会识别依赖模块（DLL）并将它们加载到进程内存中。PE文件的导入部分包含来自不同DLL的导入函数的详细信息。这些依赖DLL将由Windows加载器加载，并可供进程稍后调用。依赖DLL将加载到相应DLL的首选加载地址。如果首选加载地址未被占用，则Windows加载器会将该特定DLL加载到进程中的任何可用地址，因此在进程执行之前或之后无法确定DLL的加载地址。

在DIA（调试接口访问）接口中，在调用findSybolByVA()之前，调试会话应该调用相应模块的put_loadAddress()。

因此，有必要在运行时检索所有模块的加载地址，并将它们以某种格式保存到日志文件中。稍后LogParser（负责解析日志的应用程序）应该读取这些模块详细信息，并使用它们来调用DIA SDK函数（loadDataForExe、put_loadAddress）。

日志记录器的初始化将读取所有模块的加载地址并将其保存到日志文件中，稍后，LogParser将读取模块信息并调用DIA SDK的必要函数（put_loadAddress）。

GetModuleInformation和EnumProcessModules API用于读取当前进程中所有模块的信息（加载地址、映像大小）。枚举进程模块的源代码如下：

// To Enumerate all modules in the process.
bReturn = EnumProcessModules( hCurrentProcess, phModuleArray, sizeof( HMODULE ) * nModules, &nModules ); 
 
for( int nIndex =0; nIndex < nModules; nIndex++ )
{
    // Retrieve information of a module( Load address and Size ).
    GetModuleInformation( hCurrentProcess, phModuleArray[nIndex], &stModuleInfo, sizeof( stModuleInfo ));
    GetModuleFileName( phModuleArray[nIndex], tcBufferModule, MAX_BUFFER_SIZE );
 
}

findSymbolByVA()接受一个虚拟地址，并返回属于该虚拟地址或其最近地址的符号的IDiaSymbol接口。在调用此函数之前，应将模块的加载地址提供给IDiaSession，然后DIA SDK将执行从虚拟地址到相对虚拟地址的转换。之后，相应IDiaSymbol的get_name()将提供函数名。就是这样！我们借助PDB文件从其虚拟地址（运行时函数地址）获取了函数名。

检索到的函数名将与附加信息（如进入或离开、时间、线程ID）一起保存到输出文件中。这样，原始格式的日志文件就转换为可读的日志文件了。

5. 优化保存时间的方法

我们的目标是以更低的成本保存最少的数据，即函数的进入/离开信息应以最少的指令保存。可以使用GetLocalTime()在SYSTEMTIME结构中获取当前本地时间。此结构包含小时、分钟、秒和毫秒信息。

typedef struct _SYSTEMTIME {
    WORD wYear;
    WORD wMonth;
    WORD wDayOfWeek;
    WORD wDay;
    WORD wHour;
    WORD wMinute;
    WORD wSecond;
    WORD wMilliseconds;
} SYSTEMTIME, *PSYSTEMTIME, *LPSYSTEMTIME;

如果我们调用GetLocalTime() API，它将在SYSTEMTIME结构中检索当前系统时间。SYSTEMTIME结构的大小为16字节，因此每个函数在进入和离开函数时应保存16字节的数据。这里是获取当前系统时间的另一种优化方法。GetTickCount() API返回自系统启动以来已过的时间（以毫秒为单位，作为DWORD）。如果我们知道启动时间是SYSTEMTIME，那么很容易将返回的滴答计数转换为当前的SYSTEMTIME结构。

在我们的例子中，我们可以在启动时保存滴答计数和本地时间。将新的滴答计数（在进入/离开函数时检索）转换为SYSTEMTIME将如下所示：

  • DWORD TickCountStart表示应用程序启动时的时间滴答计数。
  • SYSTEMTIME stStartupTime保存SYSEMTIME结构，其中包含分钟、秒、毫秒信息。
  • DWORD dwNewTickCount，进入函数时检索到的新滴答计数。 
  1. 计算TickCountStart和dwNewTickCount之间的差值，并将其转换为秒。
  2. 在步骤1中，准备一个带有计算秒数的CTimeSpan实例timeSpan。 
  3. 准备一个带有stStartupTime的CTime实例，并将其与timeSpan相加，返回的CTime对象将是对应于dwNewTickCount的新时间。  
 /* 
This function receives a TickCount( DWORD ) and provides SYSTEMTIME as output.
The starttime( SYSTEMTIME instance) and its tickcount is used to convert
current tickcount to SYSTEMTIME.
 */
SYSTEMTIME TimeParser::ConvertTickCountToSysTime( const DWORD dwTickCount_i )
{
    DWORD dwDiff = dwTickCount_i - m_dwStartTime; // Ms after startup Time.
    // CTimeSpan timeSpanObj( dwDiff / 1000 );
    // CTime timeInSec = m_SystemStartTime + timeSpanObj;
    SYSTEMTIME stToAdd = m_stStartTime;
    stToAdd.wMilliseconds += dwDiff;
    long lSeconds = 0;
    if( stToAdd.wMilliseconds > 1000 )
    {
        lSeconds = ( stToAdd.wMilliseconds / 1000 );
    }
    // LONG lDays, int nHours, int nMins, int nSecs
    CTimeSpan timeSpan( 0, 0, 0, lSeconds ); 
    int nMsOutput = stToAdd.wMilliseconds % 1000;
 
    // Reset Millisecond to 0, avoid calculation from CTime class.
    stToAdd.wMilliseconds = 0;
    CTime       stToAddObj = stToAdd;
    stToAddObj = stToAddObj + timeSpan;
 
    stToAddObj.GetAsSystemTime( stToAdd );
    stToAdd.wMilliseconds = nMsOutput;
    return stToAdd;
}

6. 优化保存线程ID的方法

Windows提供了一个API函数GetCurrentThreadId()来获取当前线程的ID。经过在编程论坛上的一些搜索，我找到了一种在不调用任何Windows函数的情况下获取线程ID的方法：线程信息块，其中包含许多与线程相关的信息。TIB可用于在不调用Win32 API的情况下获取大量关于进程的信息。要检索TIB，我们必须在代码中编写内联汇编，如下所示。TIB在其0x24位置保存线程ID，并将其地址移到EAX寄存器。EAX的内容被移到dwThreadID，并可以保存到我们的日志文件中。下面是快速检索当前线程ID的代码。

// Get Thread ID from TIB.
DWORD dwThreadID;
__asm {
    mov EAX, FS:[0x24]
    mov [dwThreadID], EAX
}

如何在应用程序中使用LogEnterLeave

将Log.h、Logger.h添加到您的项目中。这些文件可以从本文的下载头文件部分下载。

Logger.h应该在您的应用程序中包含一次，例如在App.cpp中。Log.h包含LogEnterLeave类的声明和定义。要创建函数的进入和离开日志，请在函数的第一行创建一个LogEnterLeave实例。就是这样，LogEnterLeave的构造函数和析构函数将完成所需的工作。将创建LogDetails.bin和LegDetails.dat文件，其中包含带有LogEnterLeave对象的函数的进入和离开日志信息。以下是LogEnterLeave的类声明：

// Declaration of LogEnterLeave in Log.h
class LogEnterLeave
{
 
public:
    LogEnterLeave()
    {
        int nEBPContents;
        __asm mov nEBPContents, EBP;
        int* ptrAddress = (int*)nEBPContents;
        const int nReturnIP = *( ++ptrAddress );
        // Here nReturnIP holds the address of caller function.

        WriteToFile( nReturnIP, true ); // Here Enter flag is true
    }
    ~LogEnterLeave()
    {
        int nEBPContents;
        __asm mov nEBPContents, EBP;
        int* ptrAddress = (int*)nEBPContents;
        const int nReturnIP = *( ++ptrAddress );
        // Here nReturnIP holds the address of caller function.

        WriteToFile( nReturnIP, false ); // Here Enter flag is false
    }
 
private:
 
    void WriteToFile( const int nAddress_i, const bool bEnter_i )
    {
        // Get Thread ID from TIB.
        DWORD dwThreadID;
        __asm {
            mov EAX, FS:[0x24]
            mov [dwThreadID], EAX
        }
 
        const int nTickCount = GetTickCount();
        const LOG_DETAILS_t stLogDetails = { nAddress_i, dwThreadID, nTickCount, bEnter_i };
 
        FILE* pFile = fopen( "LogDetails.dat", "ab" );
        fwrite( &stLogDetails, sizeof( stLogDetails ), 1, pFile );
        fclose( pFile );
    }
};

现在创建了LogDetails.bin和LegDetails.dat，这些是小型日志信息。LogParser应用程序应用于将LogDetails.bin文件转换为可读日志文件。LogParser期望PDB和exe文件保存在同一文件夹中。如果PDB文件在不同的路径下，可以使用“PDB搜索路径”按钮来提供PDB文件的搜索路径。

创建了一个基于对话框的示例应用程序来演示LogEnterLeave的用法。

请下载LogTest应用程序并检查其在LogTestDlg.cpp和LogTest.cpp中的代码更改。LogTest.cpp添加了一个头文件Logger.h，它将执行日志记录器的必要初始化。请不要将Logger.h添加到其他头文件或源文件中。之后，将“Log.h”添加到LogTestDlg.cpp中，并修改其函数以创建LogEnterLeave对象来记录进入和离开信息。下面显示了LogTestDlg.cpp的代码片段。

void CLogTestDlg::OnBnClickedButton2()
{
    LogEnterLeave LogObj; // To log Enter and Leave Information.
    AfxMessageBox( L"CLogTestDlg::OnBnClickedButton2()" );
}
 
void CLogTestDlg::OnBnClickedOk()
{
    LogEnterLeave LogObj; // To log Enter and Leave Information.
    AfxMessageBox( L"CLogTestDlg::OnBnClickedOk()" );
}
 
void CLogTestDlg::OnBnClickedCancel()
{
    LogEnterLeave LogObj; // To log Enter and Leave Information.
    AfxMessageBox( L"CLogTestDlg::OnBnClickedCancel()" );
    OnCancel();
}

以下是LogTest应用程序的示例执行所准备的输出：

LogParser应用程序

LogParser应用程序负责将二进制格式的日志信息转换为可读格式。它读取模块详细信息和日志详细信息，并以所需格式准备输出文件。

LogParser应用程序屏幕截图

类及其职责

  • LogParserDlg：显示应用程序主对话框并处理不同的GUI事件。此类使用所有其他支持类（ModuleParser、PdbParser和TimeParser）来准备输出日志文件。 
  • ModuleParser：它读取LogDetails.bin并保存模块信息（加载地址、模块名称、映像大小）。此文件包含进程中所有依赖模块的模块信息。 GetModuleFromVA 接收一个虚拟地址并返回包含指定虚拟地址加载的模块详细信息的MODULE_INFO_t。 
  • PdbParser：此类是DIA SDK的包装器，它提供了两个公共成员函数：Initialize()和GetFunctionNameFromVA()。Initialize()接收模块名称和模块加载地址。为该模块创建DIA组件实例（IDiaDataSource、IDiaSession）。然后使用这些组件实例进行函数名查询。GetFunctionNameFromVA()读取一个虚拟地址并返回相应函数的名称。
  • TimeParser：此类在其构造函数中接收启动时间（作为SYSTEMTIME）和启动滴答计数（DWORD）。然后可以使用ConvertTickCountToSysTime()将新的Tickcount转换为SYSTEMTIME。详细信息在本文章的优化保存时间的方法部分进行了说明。  

局限性

  • 此方法不能用于通过显式链接加载的模块。如果DLL是通过LoadLibrary()在运行时加载的，那么在启动时无法跟踪其模块加载地址。并且相同的加载地址可能会在稍后分配给其他模块。我计划挂钩LoadLibrary()和FreeLibarary()来跟踪通过显式链接方法加载的模块的加载地址。 
  • 此方法不能用于提供实时日志记录（如将日志记录到控制台），我们可以在程序执行期间看到。它以原始格式保存数据，不能直接理解。需要LogParser来将日志转换为可读格式。 
  • LogEnterLeave中未实现多线程日志记录。可以通过添加CriticalSection实例来锁定多个线程写入的日志文件。 
  • 如果PdbParser使用了不正确的PDB文件，那么这个机制将提供错误的信息。还有另一种机制来验证PDB及其相应的二进制文件。它在debuginfo文章中有详细解释。

值得关注的点

将文本内容和二进制数据写入同一个文件会导致问题。因此，将日志文件和模块详细信息分成两个文件。最初我准备了一个文件来保存模块信息和日志数据。但是读取二进制格式会产生错误的数据，所以我准备了两个文件，一个用于二进制写入（日志数据），另一个用于文本写入（模块信息）。

参考文献

历史

  • 2013年7月14日 - 初始版本。
© . All rights reserved.