Windows2000/private/ntos/ex/memprint.c

/*++
Copyright (c) 1989  Microsoft Corporation

Module Name:
    memprint.c

Abstract:
    This module contains the routines to implement in-memory DbgPrint.
    DbgPrint text is stored in a large circular buffer, and optionally written to a file and/or the debug console.
    Output to file is buffered to allow high performance by the file system.

Author:
    David Treadwell (davidtr) 05-Oct-1990
--*/

#include "exp.h"
#pragma hdrstop

#include <stdarg.h>
#include <string.h>
#include <memprint.h>
#undef DbgPrint

// Forward declarations.

VOID MemPrintWriteCompleteApc (IN PVOID ApcContext, IN PIO_STATUS_BLOCK IoStatusBlock, IN ULONG Reserved);
VOID MemPrintWriteThread (IN PVOID Dummy);


// The maximum message size is the largest message that can be written by a single call to MemPrint.
#define MEM_PRINT_MAX_MESSAGE_SIZE 256

// These macros aid in determining the size of a subbuffer and the subbuffer corresponding to an index into the circular buffer.

#define MEM_PRINT_SUBBUFFER_SIZE (MemPrintBufferSize / MemPrintSubbufferCount)
#define GET_MEM_PRINT_SUBBUFFER(i) ((CSHORT)( (i) / MEM_PRINT_SUBBUFFER_SIZE ))

// The definition of the header put before each message if the MEM_PRINT_FLAG_HEADER bit of MemPrintFlags is turned on.
typedef struct _MEM_PRINT_MESSAGE_HEADER {
    USHORT Size;
    USHORT Type;
} MEM_PRINT_MESSAGE_HEADER, *PMEM_PRINT_MESSAGE_HEADER;

// Global data.  It is all protected by MemPrintSpinLock.
CLONG MemPrintBufferSize = MEM_PRINT_DEF_BUFFER_SIZE;
CLONG MemPrintSubbufferCount = MEM_PRINT_DEF_SUBBUFFER_COUNT;
PCHAR MemPrintBuffer;

ULONG MemPrintFlags = MEM_PRINT_FLAG_CONSOLE;
KSPIN_LOCK MemPrintSpinLock;
CHAR MemPrintTempBuffer[MEM_PRINT_MAX_MESSAGE_SIZE];
BOOLEAN MemPrintInitialized = FALSE;

// MemPrintIndex stores the current index into the circular buffer.
CLONG MemPrintIndex = 0;

// MemPrintCurrentSubbuffer stores the index of the subbuffer currently being used to hold data.
// It has a range between 0 and MemPrintSubbufferCount-1.
CLONG MemPrintCurrentSubbuffer = 0;

// The MemPrintSubbufferWriting array is used to indicate when a subbuffer is being written to disk.
// While this occurs, new data cannot be written to the subbuffer.
BOOLEAN MemPrintSubbufferWriting[MEM_PRINT_MAX_SUBBUFFER_COUNT];

// The MemPrintSubbufferFullEvent array is used to communicate between threads calling MemPrintMemory and the thread that writes the log file.
// When a subbuffer is full and ready to be written to disk, the corresponding event in this array is signaled, which causes the write thread to wake up and perform the write.
KEVENT MemPrintSubbufferFullEvent[MEM_PRINT_MAX_SUBBUFFER_COUNT];


VOID MemPrintInitialize (VOID)
/*++
Routine Description:
    This is the initialization routine for the in-memory DbgPrint routine.
    It should be called before the first call to MemPrint to set up the various structures used and to start the log file write thread.
--*/
{
    CLONG i;
    NTSTATUS status;
    HANDLE threadHandle;

    if ( MemPrintInitialized ) {
        return;
    }

    // Allocate memory for the circular buffer that will receive the text and data.
    // If we can't do it, try again with a buffer half as large.
    // If that fails, quit trying.
    MemPrintBuffer = ExAllocatePoolWithTag( NonPagedPool, MemPrintBufferSize, 'rPeM' );
    if ( MemPrintBuffer == NULL ) {
        MemPrintBufferSize /= 2;
        DbgPrint( "Unable to allocate DbgPrint buffer--trying size = %ld\n", MemPrintBufferSize );
        MemPrintBuffer = ExAllocatePoolWithTag( NonPagedPool, MemPrintBufferSize, 'rPeM' );
        if ( MemPrintBuffer == NULL ) {
            DbgPrint( "Couldn't allocate DbgPrint buffer.\n" );
            return;
        } else {
            //DbgPrint( "MemPrint buffer from %lx to %lx\n", MemPrintBuffer, MemPrintBuffer + MemPrintBufferSize );
        }
    } else {
        //DbgPrint( "MemPrint buffer from %lx to %lx\n", MemPrintBuffer, MemPrintBuffer + MemPrintBufferSize );
    }

    // Allocate the spin lock that protects access to the various pointers and the circular buffer.
    // This ensures integrity of the buffer.
    KeInitializeSpinLock( &MemPrintSpinLock );

    // Make sure that the subbuffer count is in range.  (We assume that the number is a power of 2.)
    if ( MemPrintSubbufferCount < 2 ) {
        MemPrintSubbufferCount = 2;
    } else if ( MemPrintSubbufferCount > MEM_PRINT_MAX_SUBBUFFER_COUNT ) {
        MemPrintSubbufferCount = MEM_PRINT_MAX_SUBBUFFER_COUNT;
    }

    // Initialize the array of BOOLEANs that determines which subbuffers are being written to disk and therefore cannot be used to store new DbgPrint data.

    // Initialize the array of events that indicates that a subbuffer is ready to be written to disk.
    for ( i = 0; i < MemPrintSubbufferCount; i++ ) {
        MemPrintSubbufferWriting[i] = FALSE;
        KeInitializeEvent(&MemPrintSubbufferFullEvent[i], SynchronizationEvent, FALSE);
    }

    // Start the thread that writes subbuffers from the large circular buffer to disk.
    status = PsCreateSystemThread(&threadHandle, PROCESS_ALL_ACCESS, NULL, NtCurrentProcess(), NULL, MemPrintWriteThread, NULL);
    if ( !NT_SUCCESS(status) ) {
        DbgPrint( "MemPrintInitialize: PsCreateSystemThread failed: %X\n", status );
        return;
    }

    MemPrintInitialized = TRUE;
    ZwClose( threadHandle );
} // MemPrintInitialize


VOID MemPrint (CHAR *Format, ...)
/*++
Routine Description:
    This routine is called in place of DbgPrint to process in-memory printing.
Arguments:
    Format - A format string in the style of DbgPrint.
           - formatting arguments.
--*/
{
    va_list arglist;
    KIRQL oldIrql;
    CLONG nextSubbuffer;
    PMEM_PRINT_MESSAGE_HEADER messageHeader;
    CHAR tempBuffer[MEM_PRINT_MAX_MESSAGE_SIZE];

    va_start(arglist, Format);
    _vsnprintf( tempBuffer, sizeof( tempBuffer ), Format, arglist );
    va_end(arglist);

    // If memory DbgPrint has not been initialized, simply print to the console.
    if ( !MemPrintInitialized ) {
        DbgPrint( "%s", tempBuffer );
        return;
    }

    // Acquire the spin lock that synchronizes access to the pointers and circular buffer.
    KeAcquireSpinLock( &MemPrintSpinLock, &oldIrql );

    // Make sure that the request will fit.
    // xx_sprintf will just dump all it gets, so assume the message is maximum size, and, if the request would go into the next subbuffer and it is writing, fail the request.
    nextSubbuffer = GET_MEM_PRINT_SUBBUFFER( MemPrintIndex + MEM_PRINT_MAX_MESSAGE_SIZE );
    if (  nextSubbuffer != MemPrintCurrentSubbuffer ) {
        // The request will go to a new subbuffer.
        // Check if we should wrap around to the first subbuffer (i.e. start of circular buffer).
        if ( nextSubbuffer == MemPrintSubbufferCount ) {
            nextSubbuffer = 0;
        }

        // Is that subbuffer available for use?
        if ( MemPrintSubbufferWriting[nextSubbuffer] ) {
            // It is in use.  Print to the console.  Oh well.
            KeReleaseSpinLock( &MemPrintSpinLock, oldIrql );
            DbgPrint( "%s", tempBuffer );
            return;
        }

        // If we went to subbuffer 0 and it is available to receive data, set up the "end of last subbuffer" conditions and reset the index into the circular buffer.
        // By setting a special type value in the message header that precedes the garbage at the end of the last subbuffer,
        // an interpreter program can know to skip over the garbage by using the size in the header.
        // This is done instead of writing only good data so that we can write just full sectors to disk, thereby enhancing write performance.
        if ( nextSubbuffer == 0 ) {
            // Set up the message header.
            // This always gets done at the end of the circular buffer, regardless of the flags bit.
            messageHeader = (PMEM_PRINT_MESSAGE_HEADER)&MemPrintBuffer[MemPrintIndex];
            RtlStoreUshort(&messageHeader->Size, (USHORT)(MemPrintBufferSize - MemPrintIndex - 1));
            RtlStoreUshort(&messageHeader->Type, (USHORT)0xffff);

            // Zero out the rest of the subbuffer.
            for ( MemPrintIndex += sizeof(MEM_PRINT_MESSAGE_HEADER); MemPrintIndex < MemPrintBufferSize; MemPrintIndex++ ) {
                MemPrintBuffer[MemPrintIndex] = 0;
            }

            // Reset the index to start at the beginning of the circular buffer.
            MemPrintIndex = 0;
        }
    }

    // Store a pointer to the location that will contain the message header.
    messageHeader = (PMEM_PRINT_MESSAGE_HEADER)&MemPrintBuffer[MemPrintIndex];
    if ( MemPrintFlags & MEM_PRINT_FLAG_HEADER ) {
        MemPrintIndex += sizeof(MEM_PRINT_MESSAGE_HEADER);
    }

    // Dump the formatted string to the subbuffer.  xx_sprintf is a special version of sprintf that takes a variable argument list.
    ASSERT( MemPrintIndex + MEM_PRINT_MAX_MESSAGE_SIZE - sizeof(MEM_PRINT_MESSAGE_HEADER) <= MemPrintBufferSize );
    RtlMoveMemory( &MemPrintBuffer[MemPrintIndex], tempBuffer, strlen(tempBuffer)+1 );
    MemPrintIndex += strlen(tempBuffer);

    // Write the total message size to the message header.
    if ( MemPrintFlags & MEM_PRINT_FLAG_HEADER ) {
        messageHeader->Size = (USHORT)( &MemPrintBuffer[MemPrintIndex] - (PCHAR)messageHeader );
        messageHeader->Type = (USHORT)0xdead;
        messageHeader++;
    }

    // If it was too large, there's a potential problem with writing off the end of the circular buffer.
    // Print the offending message to the console and breakpoint.
    if ( &MemPrintBuffer[MemPrintIndex] - (PCHAR)messageHeader > MEM_PRINT_MAX_MESSAGE_SIZE ) {
        DbgPrint( "Message too long!! :\n" );
        DbgPrint( "%s", messageHeader );
        DbgBreakPoint( );
    }

    // Print to the console if the appropriate flag is on.
    if ( MemPrintFlags & MEM_PRINT_FLAG_CONSOLE ) {
        DbgPrint( "%s", messageHeader );
    }

    // Calculate whether we have stepped into a new subbuffer.
    nextSubbuffer = GET_MEM_PRINT_SUBBUFFER( MemPrintIndex );
    if ( nextSubbuffer != MemPrintCurrentSubbuffer ) {
        //DbgPrint( "Subbuffer %ld complete.\n", MemPrintCurrentSubbuffer );

        // We did step into a new subbuffer, so set the boolean to indicate that the old subbuffer is writing to disk, thereby
        // preventing it from being overwritten until the write is complete.
        MemPrintSubbufferWriting[MemPrintCurrentSubbuffer] = TRUE;

        // Set the event that will wake up the thread writing subbuffers to disk.
        KeSetEvent(&MemPrintSubbufferFullEvent[MemPrintCurrentSubbuffer], 2, FALSE);

        // Update the current subbuffer.
        MemPrintCurrentSubbuffer = nextSubbuffer;
    }

    KeReleaseSpinLock( &MemPrintSpinLock, oldIrql );
} // MemPrint


VOID MemPrintFlush (VOID)
/*++
Routine Description:
    This routine causes the current subbuffer to be written to disk, regardless of how full it is.
    The unwritten part of the subbuffer is zeroed before writing.
--*/
{
    KIRQL oldIrql;
    PMEM_PRINT_MESSAGE_HEADER messageHeader;
    CLONG nextSubbufferIndex;
    LARGE_INTEGER delayInterval;

    // Acquire the spin lock that protects memory DbgPrint variables.
    KeAcquireSpinLock( &MemPrintSpinLock, &oldIrql );

    DbgPrint( "Flushing subbuffer %ld\n", MemPrintCurrentSubbuffer );

    // Set up the header that indicates that unused space follows.
    messageHeader = (PMEM_PRINT_MESSAGE_HEADER)&MemPrintBuffer[MemPrintIndex];
    messageHeader->Size = (USHORT)(MemPrintBufferSize - MemPrintIndex - 1);
    messageHeader->Type = (USHORT)0xffff;

    // Determine where the next subbuffer starts.
    nextSubbufferIndex = (MemPrintCurrentSubbuffer + 1) * MEM_PRINT_SUBBUFFER_SIZE;

    // Zero out the rest of the subbuffer.
    for ( MemPrintIndex += sizeof(MEM_PRINT_MESSAGE_HEADER); MemPrintIndex < nextSubbufferIndex; MemPrintIndex++ ) {
        MemPrintBuffer[MemPrintIndex] = 0;
    }

    // Indicate that the subbuffer should be written to disk.
    MemPrintSubbufferWriting[MemPrintCurrentSubbuffer] = TRUE;

    KeSetEvent(&MemPrintSubbufferFullEvent[MemPrintCurrentSubbuffer], 8, FALSE);

    // Increment the current subbuffer so that it corresponds with the buffer index.
    MemPrintCurrentSubbuffer++;

    KeReleaseSpinLock( &MemPrintSpinLock, oldIrql );

    // Delay so that the memory print write thread wakes up and performs the write to disk.

    // !!! This is obviously not a perfect solution--the write thread may never wake up, so this could complete before the flush is really done.
    delayInterval.QuadPart = -10*10*1000*1000;

    DbgPrint( "Delaying...\n" );
    KeDelayExecutionThread( KernelMode, TRUE, &delayInterval );
    DbgPrint( "Woke up.\n" );
} // MemPrintFlush


VOID MemPrintWriteThread (IN PVOID Dummy)
/*++
Routine Description:
    The log file write thread executes this routine.
    It sets up the log file for writing, then waits for subbuffers to fill, writing them to disk when they do.
    When the log file fills, new space for it is allocated on disk to prevent the file system from having to do it.
Arguments:
    Dummy - Ignored.
--*/
{
    NTSTATUS status;
    IO_STATUS_BLOCK ioStatusBlock[MEM_PRINT_MAX_SUBBUFFER_COUNT];
    IO_STATUS_BLOCK localIoStatusBlock;
    CLONG i;
    KPRIORITY threadPriorityLevel;
    NTSTATUS waitStatus;
    PVOID waitObjects[64];
    KWAIT_BLOCK waitBlockArray[MEM_PRINT_MAX_SUBBUFFER_COUNT];
    OBJECT_ATTRIBUTES objectAttributes;
    PCHAR fileName = MEM_PRINT_LOG_FILE_NAME;
    ANSI_STRING fileNameString;
    HANDLE fileHandle;
    LARGE_INTEGER fileAllocation;
    LARGE_INTEGER fileAllocationIncrement;
    LARGE_INTEGER totalBytesWritten;
    LARGE_INTEGER writeSize;
    LARGE_INTEGER delayInterval;
    ULONG attempts = 0;
    UNICODE_STRING UnicodeFileName;

    Dummy;

    // Initialize the string containing the file name and the object attributes structure that will describe the log file to open.
    RtlInitAnsiString( &fileNameString, fileName );
    status = RtlAnsiStringToUnicodeString(&UnicodeFileName,&fileNameString,TRUE);
    if ( !NT_SUCCESS(status) ) {
        NtTerminateThread( NtCurrentThread(), status );
    }

    InitializeObjectAttributes(&objectAttributes, &UnicodeFileName, OBJ_CASE_INSENSITIVE, NULL, NULL);

    // Set the allocation size of the log file to be three times the size of the circular buffer.  When it fills up, we'll extend it.
    fileAllocationIncrement.LowPart = MemPrintBufferSize * 8;
    fileAllocationIncrement.HighPart = 0;
    fileAllocation = fileAllocationIncrement;

    // Open the log file.

    // !!! The loop here is to help avoid a system initialization timing problem, and should be removed when the problem is fixed.
    while ( TRUE ) {
        status = NtCreateFile(
                     &fileHandle,
                     FILE_WRITE_DATA,
                     &objectAttributes,
                     &localIoStatusBlock,
                     &fileAllocation,
                     FILE_ATTRIBUTE_NORMAL,
                     FILE_SHARE_READ,
                     FILE_OVERWRITE_IF,
                     FILE_SEQUENTIAL_ONLY,
                     NULL,
                     0L
                     );
        if ( (status != STATUS_OBJECT_PATH_NOT_FOUND) || (++attempts >= 3) ) {
            RtlFreeUnicodeString(&UnicodeFileName);
            break;
        }

        delayInterval.QuadPart = -5*10*1000*1000;    // five second delay
        KeDelayExecutionThread( KernelMode, FALSE, &delayInterval );
    }

    if ( !NT_SUCCESS(status) ) {
        DbgPrint( "NtCreateFile for log file failed: %X\n", status );
        NtTerminateThread( NtCurrentThread(), status );
    }

    // Initialize the total bytes written and write size variables.
    totalBytesWritten.LowPart = 0;
    totalBytesWritten.HighPart = 0;
    writeSize.LowPart = MEM_PRINT_SUBBUFFER_SIZE;
    writeSize.HighPart = 0;

    // Set up the wait objects array for a call to KeWaitForMultipleObjects.
    for ( i = 0; i < MemPrintSubbufferCount; i++ ) {
        waitObjects[i] = &MemPrintSubbufferFullEvent[i];
    }

    // Set the priority of the write thread.
    threadPriorityLevel = LOW_REALTIME_PRIORITY + 1;
    status = NtSetInformationThread(NtCurrentThread(), ThreadPriority, &threadPriorityLevel, sizeof(threadPriorityLevel));
    if ( !NT_SUCCESS(status) ) {
        DbgPrint( "Unable to set error log thread priority: %X\n", status );
    }

    // Loop waiting for one of the subbuffer full events to be signaled.
    // When one is signaled, wake up and write the subbuffer to the log file.
    while ( TRUE ) {
        waitStatus = KeWaitForMultipleObjects((CCHAR)MemPrintSubbufferCount, waitObjects, WaitAny, Executive, KernelMode, TRUE, NULL, waitBlockArray);
        if ( !NT_SUCCESS(waitStatus) ) {
            DbgPrint( "KeWaitForMultipleObjects failed: %X\n", waitStatus );
            NtTerminateThread( NtCurrentThread(), waitStatus );
        } //else {
            //DbgPrint( "Writing subbuffer %ld...\n", waitStatus );
        //}

        ASSERT( (CCHAR)waitStatus < (CCHAR)MemPrintSubbufferCount );

        // Check the DbgPrint flags to see if we really want to write this.
        if ( (MemPrintFlags & MEM_PRINT_FLAG_FILE) == 0 ) {
            KIRQL oldIrql;

            KeAcquireSpinLock( &MemPrintSpinLock, &oldIrql );
            MemPrintSubbufferWriting[ waitStatus ] = FALSE;
            KeReleaseSpinLock( &MemPrintSpinLock, oldIrql );
            continue;
        }

        // Start the write operation.
        // The APC routine will handle checking the return status from the write and resetting the MemPrintSubbufferWriting boolean.
        status = NtWriteFile(
                     fileHandle,
                     NULL,
                     MemPrintWriteCompleteApc,
                     (PVOID)waitStatus,
                     &ioStatusBlock[waitStatus],
                     &MemPrintBuffer[waitStatus * MEM_PRINT_SUBBUFFER_SIZE],
                     MEM_PRINT_SUBBUFFER_SIZE,
                     &totalBytesWritten,
                     NULL
                     );
        if ( !NT_SUCCESS(status) ) {
            DbgPrint( "NtWriteFile for log file failed: %X\n", status );
        }

        // Update the count of bytes written to the log file.
        totalBytesWritten.QuadPart = totalBytesWritten.QuadPart + writeSize.QuadPart;

        // Extend the file if we have reached the end of what we have thus far allocated for the file.
        // This increases performance by extending the file here rather than in the file system, which would have to extend it each time a write past end of file comes in.
        if ( totalBytesWritten.QuadPart >= fileAllocation.QuadPart ) {
            fileAllocation.QuadPart = fileAllocation.QuadPart + fileAllocationIncrement.QuadPart;
            DbgPrint( "Enlarging log file to %ld bytes.\n", fileAllocation.LowPart );
            status = NtSetInformationFile(fileHandle, &localIoStatusBlock, &fileAllocation, sizeof(fileAllocation), FileAllocationInformation);
            if ( !NT_SUCCESS(status) ) {
                DbgPrint( "Attempt to extend log file failed: %X\n", status );
                fileAllocation.QuadPart = fileAllocation.QuadPart - fileAllocationIncrement.QuadPart;
            }
        }
    }
} // MemPrintWriteThread


VOID MemPrintWriteCompleteApc (IN PVOID ApcContext, IN PIO_STATUS_BLOCK IoStatusBlock, IN ULONG Reserved)
/*++
Routine Description:
    This APC routine is called when subbuffer writes to disk complete.
    It checks for success, printing a message if the write failed.
    It also sets the appropriate MemPrintSubbufferWriting location to FALSE so that the subbuffer can be reused.
Arguments:
    ApcContext - contains the index of the subbuffer just written.
    IoStatusBlock - the status block for the operation.
    Reserved - not used; reserved for future use.
--*/
{
    KIRQL oldIrql;

    if ( !NT_SUCCESS(IoStatusBlock->Status) ) {
        DbgPrint( "NtWriteFile for subbuffer %ld failed: %X\n", ApcContext, IoStatusBlock->Status );
        return;
    }

    //DbgPrint( "Write complete for subbuffer %ld.\n", ApcContext );
    DbgPrint( "." );

    // Acquire the spin lock that protects memory print global variables and set the subbuffer writing boolean to FALSE so that other threads can write to the subbuffer if necessary.
    KeAcquireSpinLock( &MemPrintSpinLock, &oldIrql );
    MemPrintSubbufferWriting[ (ULONG_PTR)ApcContext ] = FALSE;
    KeReleaseSpinLock( &MemPrintSpinLock, oldIrql );

    return;
    Reserved;
} // MemPrintWriteCompleteApc