This code has multiple synchronization issues, such as spinning on a test-for-spin-lock, which is non-atomic... might as well get rid of the spinlock.
Also, you should probably be using a worker thread instead of consuming system resources for a dedicated thread and mucking with priorities. Best regards, Alex Ionescu On Wed, Oct 7, 2009 at 3:57 PM, <[email protected]> wrote: > Author: dgorbachev > Date: Wed Oct 7 21:57:40 2009 > New Revision: 43331 > > URL: http://svn.reactos.org/svn/reactos?rev=43331&view=rev > Log: > Fix logging to a file. > > In spite of limitations, it remains the only way to obtain desired logs for > some people. > > Modified: > trunk/reactos/ntoskrnl/kd/kdio.c > > Modified: trunk/reactos/ntoskrnl/kd/kdio.c > URL: > http://svn.reactos.org/svn/reactos/trunk/reactos/ntoskrnl/kd/kdio.c?rev=43331&r1=43330&r2=43331&view=diff > ============================================================================== > --- trunk/reactos/ntoskrnl/kd/kdio.c [iso-8859-1] (original) > +++ trunk/reactos/ntoskrnl/kd/kdio.c [iso-8859-1] Wed Oct 7 21:57:40 2009 > @@ -14,16 +14,17 @@ > > /* GLOBALS > *******************************************************************/ > > -#define BufferSize 32*1024 > - > -HANDLE KdbLogFileHandle; > -BOOLEAN KdpLogInitialized; > -CHAR DebugBuffer[BufferSize]; > -ULONG CurrentPosition; > -WORK_QUEUE_ITEM KdpDebugLogQueue; > +#define KdpBufferSize (1024 * 512) > +BOOLEAN KdpLoggingEnabled = FALSE; > +PCHAR KdpDebugBuffer = NULL; > +volatile ULONG KdpCurrentPosition = 0; > +volatile ULONG KdpFreeBytes = 0; > +KSPIN_LOCK KdpDebugLogSpinLock; > +KEVENT KdpLoggerThreadEvent; > +HANDLE KdpLogFileHandle; > + > KSPIN_LOCK KdpSerialSpinLock; > -BOOLEAN ItemQueued; > -KD_PORT_INFORMATION SerialPortInfo = {DEFAULT_DEBUG_PORT, > DEFAULT_DEBUG_BAUD_RATE, 0}; > +KD_PORT_INFORMATION SerialPortInfo = { DEFAULT_DEBUG_PORT, > DEFAULT_DEBUG_BAUD_RATE, 0 }; > > /* Current Port in use. FIXME: Do we support more then one? */ > ULONG KdpPort; > @@ -32,56 +33,103 @@ > > VOID > NTAPI > -KdpPrintToLogInternal(PVOID Context) > -{ > +KdpLoggerThread(PVOID Context) > +{ > + ULONG beg, end, num; > IO_STATUS_BLOCK Iosb; > > - /* Write to the Debug Log */ > - NtWriteFile(KdbLogFileHandle, > - NULL, > - NULL, > - NULL, > - &Iosb, > - DebugBuffer, > - CurrentPosition, > - NULL, > - NULL); > - > - /* Clear the Current Position */ > - CurrentPosition = 0; > - > - /* A new item can be queued now */ > - ItemQueued = FALSE; > -} > - > -VOID > -NTAPI > -KdpPrintToLog(PCH String, > - ULONG StringLength) > -{ > - /* Don't overflow */ > - if ((CurrentPosition + StringLength) > BufferSize) return; > - > - /* Add the string to the buffer */ > - RtlCopyMemory(&DebugBuffer[CurrentPosition], String, StringLength); > - > - /* Update the Current Position */ > - CurrentPosition += StringLength; > - > - /* Make sure we are initialized and can queue */ > - if (!KdpLogInitialized || (ItemQueued)) return; > - > - /* > - * Queue the work item > - * Note that we don't want to queue if we are > DISPATCH_LEVEL... > - * The message is in the buffer and will simply be taken care of at > - * the next time we are at <= DISPATCH, so it won't be lost. > - */ > - if (KeGetCurrentIrql() <= DISPATCH_LEVEL) > - { > - ExQueueWorkItem(&KdpDebugLogQueue, HyperCriticalWorkQueue); > - ItemQueued = TRUE; > - } > + KdpLoggingEnabled = TRUE; > + > + while (TRUE) > + { > + KeWaitForSingleObject(&KdpLoggerThreadEvent, 0, KernelMode, FALSE, > NULL); > + > + /* Bug */ > + end = KdpCurrentPosition; > + num = KdpFreeBytes; > + beg = (end + num) % KdpBufferSize; > + num = KdpBufferSize - num; > + > + /* Nothing to do? */ > + if (num == 0) > + continue; > + > + if (end > beg) > + { > + NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb, > + KdpDebugBuffer + beg, num, NULL, NULL); > + } > + else > + { > + NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb, > + KdpDebugBuffer + beg, KdpBufferSize - beg, NULL, > NULL); > + > + NtWriteFile(KdpLogFileHandle, NULL, NULL, NULL, &Iosb, > + KdpDebugBuffer, end, NULL, NULL); > + } > + > + InterlockedExchangeAddUL(&KdpFreeBytes, num); > + } > +} > + > +VOID > +NTAPI > +KdpPrintToLogFile(PCH String, > + ULONG StringLength) > +{ > + ULONG beg, end, num; > + KIRQL OldIrql; > + > + if (KdpDebugBuffer == NULL) return; > + > + /* Acquire the printing spinlock without waiting at raised IRQL */ > + while (TRUE) > + { > + /* Wait when the spinlock becomes available */ > + while (!KeTestSpinLock(&KdpDebugLogSpinLock)); > + > + /* Spinlock was free, raise IRQL */ > + KeRaiseIrql(HIGH_LEVEL, &OldIrql); > + > + /* Try to get the spinlock */ > + if (KeTryToAcquireSpinLockAtDpcLevel(&KdpDebugLogSpinLock)) > + break; > + > + /* Someone else got the spinlock, lower IRQL back */ > + KeLowerIrql(OldIrql); > + } > + > + beg = KdpCurrentPosition; > + num = KdpFreeBytes; > + if (StringLength < num) > + num = StringLength; > + > + if (num != 0) > + { > + end = (beg + num) % KdpBufferSize; > + KdpCurrentPosition = end; > + KdpFreeBytes -= num; > + > + if (end > beg) > + { > + RtlCopyMemory(KdpDebugBuffer + beg, String, num); > + } > + else > + { > + RtlCopyMemory(KdpDebugBuffer + beg, String, KdpBufferSize - beg); > + RtlCopyMemory(KdpDebugBuffer, String + KdpBufferSize - beg, end); > + } > + } > + > + /* Release spinlock */ > + KiReleaseSpinLock(&KdpDebugLogSpinLock); > + > + /* Lower IRQL */ > + KeLowerIrql(OldIrql); > + > + /* Signal the logger thread */ > + if (OldIrql <= DISPATCH_LEVEL && KdpLoggingEnabled) > + KeSetEvent(&KdpLoggerThreadEvent, 0, FALSE); > } > > VOID > @@ -90,9 +138,11 @@ > ULONG BootPhase) > { > NTSTATUS Status; > + UNICODE_STRING FileName; > OBJECT_ATTRIBUTES ObjectAttributes; > - UNICODE_STRING FileName; > IO_STATUS_BLOCK Iosb; > + HANDLE ThreadHandle; > + KPRIORITY Priority; > > if (!KdpDebugMode.File) return; > > @@ -102,10 +152,20 @@ > > /* Write out the functions that we support for now */ > DispatchTable->KdpInitRoutine = KdpInitDebugLog; > - DispatchTable->KdpPrintRoutine = KdpPrintToLog; > + DispatchTable->KdpPrintRoutine = KdpPrintToLogFile; > > /* Register as a Provider */ > InsertTailList(&KdProviders, &DispatchTable->KdProvidersList); > + > + } > + else if (BootPhase == 1) > + { > + /* Allocate a buffer for debug log */ > + KdpDebugBuffer = ExAllocatePool(NonPagedPool, KdpBufferSize); > + KdpFreeBytes = KdpBufferSize; > + > + /* Initialize spinlock */ > + KeInitializeSpinLock(&KdpDebugLogSpinLock); > > /* Display separator + ReactOS version at start of the debug log */ > > DPRINT1("---------------------------------------------------------------\n"); > @@ -117,7 +177,7 @@ > } > else if (BootPhase == 3) > { > - /* Setup the Log Name */ > + /* Setup the log name */ > RtlInitUnicodeString(&FileName, L"\\SystemRoot\\debug.log"); > InitializeObjectAttributes(&ObjectAttributes, > &FileName, > @@ -125,9 +185,9 @@ > NULL, > NULL); > > - /* Create the Log File */ > - Status = NtCreateFile(&KdbLogFileHandle, > - FILE_ALL_ACCESS, > + /* Create the log file */ > + Status = NtCreateFile(&KdpLogFileHandle, > + FILE_APPEND_DATA | SYNCHRONIZE, > &ObjectAttributes, > &Iosb, > NULL, > @@ -138,9 +198,26 @@ > NULL, > 0); > > - /* Allow it to be used */ > - ExInitializeWorkItem(&KdpDebugLogQueue, &KdpPrintToLogInternal, > NULL); > - KdpLogInitialized = TRUE; > + if (!NT_SUCCESS(Status)) return; > + > + KeInitializeEvent(&KdpLoggerThreadEvent, SynchronizationEvent, TRUE); > + > + /* Create the logger thread */ > + Status = PsCreateSystemThread(&ThreadHandle, > + THREAD_ALL_ACCESS, > + NULL, > + NULL, > + NULL, > + KdpLoggerThread, > + NULL); > + > + if (!NT_SUCCESS(Status)) return; > + > + Priority = 7; > + NtSetInformationThread(ThreadHandle, > + ThreadPriority, > + &Priority, > + sizeof(Priority)); > } > } > > @@ -160,7 +237,7 @@ > /* Wait when the spinlock becomes available */ > while (!KeTestSpinLock(&KdpSerialSpinLock)); > > - /* Spinlock was free, raise irql */ > + /* Spinlock was free, raise IRQL */ > KeRaiseIrql(HIGH_LEVEL, &OldIrql); > > /* Try to get the spinlock */ > > > _______________________________________________ Ros-dev mailing list [email protected] http://www.reactos.org/mailman/listinfo/ros-dev
