[ros-dev] [ros-diffs] [dgorbachev] 43331: Fix logging to a file. In spite of limitations, it remains the only way to obtain desired logs for some people.
Alex Ionescu
ionucu at videotron.ca
Thu Oct 8 00:28:30 CEST 2009
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 at 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=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 */
>
>
>
More information about the Ros-dev
mailing list