Hi guys,
I have a simple IOCTL defined in my bus driver that allows user apps to send down chunks of data (mpeg to be specific). The bus driver forwards the request to an I/O queue, and schedules a system thread to process it.
I do this because it makes it easy to cancel the request while on the queue, and also because the data might not be sent down to the PCI hardware right away (it’s waiting on a semaphore to become available).
As mentioned, within the Thread proc, I am waiting on a sempahore. When it becomes available (meaning we can send data to the PCI device), I dequeue the request off of the queue, copy the data out of it into a non-paged kernel object, and then send that kernel object over the PCI bus.
Sooooo, I’m running into a problem where about 3 chunks of mpeg data make it through, and on about the 4th chunk, I get a PAGE_FAULT_IN_NONPAGED_AREA (50) bug check when I attempt to perform a memcpy from the request’s input buffer to the kernel buffer. After stepping through the debugger, it looks like it’s a bad address from the original request input buffer.
To summarize the detailed debugging output a few paragraphs below, here are the addresses that I’m seeing for each request that comes down. The mpegBuff is the kernel address (which looks totally valid), and the sourceBuff address is the address of the original request input buffer. ChunkSize is a valid value as well. This address remains the same except for the very last call, which is the call that the PAGE_FAULT_IN_NONPAGED_AREA (50) occurs on.
mpegBuff: 0x84800200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
mpegBuff: 0x85000200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
mpegBuff: 0x85800200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
mpegBuff: 0x86000200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
mpegBuff: 0x86800200 sourceBuff: 0x8a16c244 ChunkSize: 0x7ffd9c
So my question is this…Even though I have marked my routines below to be LOCKEDCODE(non pageable), is the memory within the request getting paged out, thus causing the issue that I’m seeing? Or, is there an IRQL conflict here? Am I doing something totally out of the norm here? What am I missing? I am open to suggestions and critiquing!
I have included debugger output and source code below:
=======================================================
DEBUGGER OUTPUT (single stepping through several frames)
0: kd> g
Breakpoint 0 hit
TSII_BUS!DecoderThreadProc+0x170:
b6a31d00 8b55c0 mov edx,dword ptr [ebp-40h]
6: kd> g
Breakpoint 1 hit
TSII_BUS!DecoderThreadProc+0x1eb:
b6a31d7b 8b55bc mov edx,dword ptr [ebp-44h]
6: kd> g
mpegBuff: 0x84800200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
Exit
Breakpoint 0 hit
TSII_BUS!DecoderThreadProc+0x170:
b6a31d00 8b55c0 mov edx,dword ptr [ebp-40h]
6: kd> g
Breakpoint 1 hit
TSII_BUS!DecoderThreadProc+0x1eb:
b6a31d7b 8b55bc mov edx,dword ptr [ebp-44h]
6: kd> g
mpegBuff: 0x85000200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
Exit
Breakpoint 0 hit
TSII_BUS!DecoderThreadProc+0x170:
b6a31d00 8b55c0 mov edx,dword ptr [ebp-40h]
4: kd> g
Breakpoint 1 hit
TSII_BUS!DecoderThreadProc+0x1eb:
b6a31d7b 8b55bc mov edx,dword ptr [ebp-44h]
4: kd> p
mpegBuff: 0x85800200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
TSII_BUS!DecoderThreadProc+0x20a:
b6a31d9a 8b55bc mov edx,dword ptr [ebp-44h]
4: kd> g
Exit
Adj vitc by: 000
Breakpoint 0 hit
TSII_BUS!DecoderThreadProc+0x170:
b6a31d00 8b55c0 mov edx,dword ptr [ebp-40h]
3: kd> p
TSII_BUS!DecoderThreadProc+0x176:
b6a31d06 8b45c8 mov eax,dword ptr [ebp-38h]
3: kd> g
Breakpoint 1 hit
TSII_BUS!DecoderThreadProc+0x1eb:
b6a31d7b 8b55bc mov edx,dword ptr [ebp-44h]
3: kd> p
mpegBuff: 0x86000200 sourceBuff: 0x89171a04 ChunkSize: 0x7ffd9c
TSII_BUS!DecoderThreadProc+0x20a:
b6a31d9a 8b55bc mov edx,dword ptr [ebp-44h]
3: kd> p
TSII_BUS!DecoderThreadProc+0x224:
b6a31db4 8b55d8 mov edx,dword ptr [ebp-28h]
3: kd> p
TSII_BUS!DecoderThreadProc+0x22d:
b6a31dbd 8b4dd8 mov ecx,dword ptr [ebp-28h]
3: kd> g
Exit
Adj vitc by: 000
T2 cc: 15 uid: 0x480e
Breakpoint 0 hit
TSII_BUS!DecoderThreadProc+0x170:
b6a31d00 8b55c0 mov edx,dword ptr [ebp-40h]
2: kd> g
Breakpoint 1 hit
TSII_BUS!DecoderThreadProc+0x1eb:
b6a31d7b 8b55bc mov edx,dword ptr [ebp-44h]
2: kd> p
mpegBuff: 0x86800200 sourceBuff: 0x8a16c244 ChunkSize: 0x7ffd9c
TSII_BUS!DecoderThreadProc+0x20a:
b6a31d9a 8b55bc mov edx,dword ptr [ebp-44h]
=======================================================
DEBUGGER OUTPUT (I hit go, and on very next request, bug check occurs)
2: kd> g
*** Fatal System Error: 0x00000050
(0x8A400000,0x00000000,0x804DAAB5,0x00000000)
Break instruction exception - code 80000003 (first chance)
A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.
A fatal system error has occurred.
Connected to Windows XP 2600 x86 compatible target at (Thu Sep 2 10:34:27.854 2010 (GMT-4)), ptr64 FALSE
Loading Kernel Symbols
…
Loading User Symbols
Loading unloaded module list
…
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
Use !analyze -v to get detailed debugging information.
BugCheck 50, {8a400000, 0, 804daab5, 0}
Probably caused by : TSII_BUS.SYS ( TSII_BUS!DecoderThreadProc+221 )
Followup: MachineOwner
nt!RtlpBreakWithStatusInstruction:
804e2a52 cc int 3
*** ERROR: Module load completed but symbols could not be loaded for hardlock.sys
*** ERROR: Module load completed but symbols could not be loaded for npf.sys
*** ERROR: Module load completed but symbols could not be loaded for Haspnt.sys
*** ERROR: Module load completed but symbols could not be loaded for dump_iaStor.sys
*** ERROR: Module load completed but symbols could not be loaded for ipnat.sys
*** ERROR: Module load completed but symbols could not be loaded for ipsec.sys
*** ERROR: Module load completed but symbols could not be loaded for Rtenicxp.sys
*** ERROR: Module load completed but symbols could not be loaded for nv4_mini.sys
*** ERROR: Module load completed but symbols could not be loaded for Ip6Fw.sys
*** ERROR: Module load completed but symbols could not be loaded for intelppm.sys
*** WARNING: Unable to verify timestamp for nv4_disp.dll
*** ERROR: Module load completed but symbols could not be loaded for nv4_disp.dll
*** WARNING: Unable to verify timestamp for ATMFD.DLL
*** ERROR: Module load completed but symbols could not be loaded for ATMFD.DLL
*** ERROR: Module load completed but symbols could not be loaded for jraid.sys
*** ERROR: Module load completed but symbols could not be loaded for isapnp.sys
*** ERROR: Module load completed but symbols could not be loaded for iaStor.sys
2: kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except,
it must be protected by a Probe. Typically the address is just plain bad or it
is pointing at freed memory.
Arguments:
Arg1: 8a400000, memory referenced.
Arg2: 00000000, value 0 = read operation, 1 = write operation.
Arg3: 804daab5, If non-zero, the instruction address which referenced the bad memory
address.
Arg4: 00000000, (reserved)
Debugging Details:
READ_ADDRESS: 8a400000
FAULTING_IP:
nt!memcpy+33
804daab5 f3a5 rep movs dword ptr es:[edi],dword ptr [esi]
MM_INTERNAL_CODE: 0
DEFAULT_BUCKET_ID: DRIVER_FAULT
BUGCHECK_STR: 0x50
PROCESS_NAME: System
TRAP_FRAME: ae701cd8 – (.trap 0xffffffffae701cd8)
ErrCode = 00000000
eax=8a96bfe0 ebx=00000000 ecx=0015aff8 edx=00000000 esi=8a400000 edi=86a93fbc
eip=804daab5 esp=ae701d4c ebp=ae701d54 iopl=0 nv up ei pl nz ac pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010216
nt!memcpy+0x33:
804daab5 f3a5 rep movs dword ptr es:[edi],dword ptr [esi]
Resetting default scope
LAST_CONTROL_TRANSFER: from 80536593 to 804e2a52
STACK_TEXT:
ae701824 80536593 00000003 8a400000 00000000 nt!RtlpBreakWithStatusInstruction
ae701870 80537066 00000003 80701a4c c0229000 nt!KiBugCheckDebugBreak+0x19
ae701c50 8053767a 00000050 8a400000 00000000 nt!KeBugCheck2+0x574
ae701c70 80529170 00000050 8a400000 00000000 nt!KeBugCheckEx+0x1b
ae701cc0 804e0944 00000000 8a400000 00000000 nt!MmAccessFault+0x77e
ae701cc0 804daab5 00000000 8a400000 00000000 nt!KiTrap0E+0xd0
ae701d54 b6a31db1 86800200 8a16c244 007ffd9c nt!memcpy+0x33
ae701dac 80575723 00000000 00000000 00000000 TSII_BUS!DecoderThreadProc+0x221 [c:\twc\he\thunderstorm\v1.1.0\src\driver\tsii_bus_driver_project\sys\tsii_offline_decoder.cpp @ 206]
ae701ddc 804ec6d9 b6a31b90 00000000 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
STACK_COMMAND: kb
FOLLOWUP_IP:
TSII_BUS!DecoderThreadProc+221 [c:\twc\he\thunderstorm\v1.1.0\src\driver\tsii_bus_driver_project\sys\tsii_offline_decoder.cpp @ 206]
b6a31db1 83c40c add esp,0Ch
FAULTING_SOURCE_CODE:
202:
203: DbgPrint(“mpegBuff: 0x%x sourceBuff: 0x%x ChunkSize: 0x%x\n”, mpegFrame->mpeg, mpegBuff, chunkSize);
204:
205: // Copy the mpeg from the packet into the frame memory:
206: memcpy((PVOID)mpegFrame->mpeg, (PVOID)mpegBuff, chunkSize);
207: mpegFrame->header.user.mpegSize = chunkSize;
208:
209: // Put it in a shared message
210: mpegMsg.hostIndex = mpegFrame->header.user.hostIndex;
211: mpegMsg.header.command = OFFLINE_DECODER_MPEG_SEND_CMD;
SYMBOL_STACK_INDEX: 7
SYMBOL_NAME: TSII_BUS!DecoderThreadProc+221
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: TSII_BUS
IMAGE_NAME: TSII_BUS.SYS
DEBUG_FLR_IMAGE_TIMESTAMP: 4c7fb062
FAILURE_BUCKET_ID: 0x50_TSII_BUS!DecoderThreadProc+221
BUCKET_ID: 0x50_TSII_BUS!DecoderThreadProc+221
Followup: MachineOwner
========================================================
SOURCE CODE:
#pragma LOCKEDCODE
void OfflineDecoderPutMpegPacket(WDFREQUEST request)
{
NTSTATUS status;
size_t length;
size_t chunkSize;
PVOID buffer;
PUCHAR mpegBuff;
PMpegFrame mpegFrame;
POfflineDecoderDataParams olddp;
if (!gPdx->offlineDecoder.opened)
{
DbgPrint(“Offline Decoder must be opened first\n”);
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
return;
}
status = CheckPermissions(request, Control);
if(!NT_SUCCESS(status))
{
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
return;
}
// Queue the request, we’ll complete it once it has finished:
status = WdfRequestForwardToIoQueue(request, gPdx->decoderQueue);
if(!NT_SUCCESS(status))
{
DbgPrint(“Unable to enqueue request onto DecoderQueue\n”);
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
return;
}
status = SpawnDecoderJob();
if (!NT_SUCCESS(status))
{
DbgPrint(“Unable to spawn decoder job!\n”);
// Pop request back off of queue & complete it:
status = TsiiGetPendingIoctlRequest(gPdx->decoderQueue,
IOCTL_TSII_DECODER_PUT_MPEG_PACKET, &request);
if(!NT_SUCCESS(status))
{
DbgPrint(“Unable to retrieve request from pending queue! 0x%08x\n”, status);
return
}
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
}
}
#pragma LOCKEDCODE
NTSTATUS SpawnDecoderJob()
{
OBJECT_ATTRIBUTES threadObjAttrs;
NTSTATUS status = STATUS_SUCCESS;
InitializeObjectAttributes(&threadObjAttrs, NULL, OBJ_KERNEL_HANDLE, NULL, NULL);
status = PsCreateSystemThread(&gPdx->board.decoderThread, THREAD_ALL_ACCESS, &threadObjAttrs, NULL, NULL,
DecoderThreadProc, NULL);
if (status != STATUS_SUCCESS)
{
DbgPrint(“Unable to create Decoder Thread\n”);
return FALSE;
}
return status;
}
#pragma LOCKEDCODE
void DecoderThreadProc(void * pContext)
{
NTSTATUS status = STATUS_SUCCESS;
WDFREQUEST request;
size_t length;
size_t chunkSize;
PVOID buffer;
PUCHAR mpegBuff;
PMpegFrame mpegFrame;
TsiiFrameMsg mpegMsg;
ULONG targetCredits;
POfflineDecoderDataParams olddp;
// Both semaphores must be true for the xmit thread to xmit a mpeg chunk to ppc:
PVOID sems = {
(PVOID) &gPdx->mpegCreditSem,
(PVOID) &gPdx->freeFrameSem,
};
// Block on mpeg credits and free frames:
status = KeWaitForMultipleObjects(2, sems, WaitAll, Executive,
KernelMode, FALSE, NULL, NULL);
if (!NT_SUCCESS(status))
{
DbgPrint(“KeWaitForMultipleObjects() failed: %d\n”, status);
status = TsiiGetPendingIoctlRequest(gPdx->decoderQueue,
IOCTL_TSII_DECODER_PUT_MPEG_PACKET, &request);
if(!NT_SUCCESS(status))
{
DbgPrint(“Unable to retrieve request from pending queue! 0x%08x\n”, status);
goto Exit;
}
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
goto Exit;
}
// Pop request off of queue:
status = TsiiGetPendingIoctlRequest(gPdx->decoderQueue,
IOCTL_TSII_DECODER_PUT_MPEG_PACKET, &request);
if(!NT_SUCCESS(status))
{
DbgPrint(“Unable to retrieve request from pending queue! 0x%08x\n”, status);
goto Exit;
}
// Read contents out of request, and store in non-paged memory:
status = WdfRequestRetrieveInputBuffer(request, sizeof
(OfflineDecoderDataParams), &buffer, &length);
if(!NT_SUCCESS(status))
{
DbgPrint(“WdfRequestRetrieveInputBuffer failed %x\n”, status);
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
return;
}
if (length > MPEG_FRAME_SIZE)
{
DbgPrint(“MPEG Buffer too large! 0x%08x\n”, length);
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
return;
}
// Extract the contents of the WDFRequest buffer out to non-paged memory:
olddp = (POfflineDecoderDataParams)buffer;
mpegBuff = (PUCHAR)&olddp->data;
chunkSize = olddp->chunkSize;
// Get pointer to PPC frame:
WdfSpinLockAcquire(gPdx->ppcFFQSpinLock);
mpegFrame = (PMpegFrame)gPdx->ppcFreeFrameQueue.Read();
WdfSpinLockRelease(gPdx->ppcFFQSpinLock);
if (!mpegFrame)
{
DbgPrint(“Invalid kernel Frame\n”);
WdfRequestCompleteWithInformation(request, STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
goto Exit;
}
DbgPrint(“mpegBuff: 0x%x sourceBuff: 0x%x ChunkSize: 0x%x\n”,
mpegFrame->mpeg, mpegBuff, chunkSize);
// Copy the mpeg from the packet into the frame memory:
memcpy((PVOID)mpegFrame->mpeg, (PVOID)mpegBuff, chunkSize);
mpegFrame->header.user.mpegSize = chunkSize;
// Put it in a shared message
mpegMsg.hostIndex = mpegFrame->header.user.hostIndex;
mpegMsg.header.command = OFFLINE_DECODER_MPEG_SEND_CMD;
mpegMsg.header.opcode = OFFLINE_DECODER_OPCODE;
mpegMsg.header.msgSize = sizeof(TsiiFrameMsg); // Header only…no message payload
mpegMsg.header.signature = HW_MSGQ_FRAME_BITS;
mpegMsg.header.dmaPtr = RtlUlongByteSwap(
mpegFrame->header.hostFrameKernelLogicalAddress.LowPart);
mpegMsg.header.dmaSize = RtlUlongByteSwap(0x800000); // DMA payload size;
// If we get here, it means we have at least 8MB of mpeg credits, and a free frame to send mpeg over…
// Send mpeg packet to PPC, and block:
if (!SendMessage((PTsiiMsgHeader)&mpegMsg))
{
DbgPrint(“Failed to send Rendered Frame Message Cmd\n”);
WdfRequestCompleteWithInformation(request,
STATUS_UNSUCCESSFUL, (ULONG_PTR) 0);
goto Exit;
}
// Reduce the amount of credits by the length that we just sent:
gPdx->mpegCredits -= chunkSize;
// Complete request:
WdfRequestCompleteWithInformation(request, STATUS_SUCCESS, 0);
Exit:
DbgPrint(“Exit\n”);
PsTerminateSystemThread(STATUS_SUCCESS);
}
Thanks guys! Your help is greatly appreciated!
Jason