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, dgorbachev@svn.reactos.org 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=4333... ============================================================================== --- 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 */