[ofw] Opensm & WinMad: a race, causing BSOD722
Smith, Stan
stan.smith at intel.com
Tue Jan 17 09:55:53 PST 2012
From: Leonid Keller [mailto:leonid at mellanox.com]
Sent: Tuesday, January 17, 2012 12:57 AM
To: Uri Habusha; Fab Tillier; Smith, Stan; Hefty, Sean
Cc: ofw_list; Irena Gannon
Subject: RE: Opensm & WinMad: a race, causing BSOD722
I believe, there are two questions here.
Why Opensm closes the port while the MAD receiving thread is still in work ?
Hello Leo. I suspect the above is the root of the problem. A long time ago, opensm 3.3.6, opensm would hang in shutdown due to the MAD receiving thread ignoring the destroy thread call if reader thread was in winmad read().
Consequently, the MAD receiver thread destroy was commented out and opensm shutdown cleanly.
Perhaps changes in IBAL have altered timing such that shutdown is delayed enough such that the MAD reader thread runs again/further?
A SWAG at this point - I'll experiment today and let you know.
Stan.
Why Winmad doesn't expect that WmIoRead and WmProviderCleanup can be called simultaneously from different threads ?
Please, look at the code below.
WmIoRead gets provider without any lock and without checking whether it is valid.
It then calls WmProviderRead, which doesn't increment any reference, but handles MAD under WdfObjectAcquireLock(pProvider->ReadQueue), which can be already destroyed (like it was in our case).
WmFileCleanup removes provider from the list under a mutex, unknown to WmIoRead, and then calls WmProviderCleanup.
The latter waits for some reference, unknown for WmIoRead, and then calls WdfIoQueuePurgeSynchronously(pProvider->ReadQueue) without WdfObjectAcquireLock(pProvider->ReadQueue).
No doubt, I'm missing here something, I just did a quick review of the code.
Maybe WinMad presumes that the application first stops I/O, then sends WM_IOCTL_DEREGISTER and only then closes the file handle and the right way for us is just to fix a bad boy opensm ? :)
As Uri stated, we do not know how to reproduce it: opensm gets started and stopped 1000 times during a night regression run, so it's not 1 to 100, it's 1 to 100000. :(
We'd very appreciate if you could find the time to review the code.
(Of course, the same problem may exist for WmIoWrite)
TIA
static VOID WmIoRead(WDFQUEUE Queue, WDFREQUEST Request, size_t Length)
{
WDFFILEOBJECT file;
WM_PROVIDER *prov;
UNREFERENCED_PARAMETER(Queue);
file = WdfRequestGetFileObject(Request);
prov = WmProviderGetContext(file);
WmProviderRead(prov, Request);
}
void WmProviderRead(WM_PROVIDER *pProvider, WDFREQUEST Request)
{
WM_REGISTRATION *reg;
NTSTATUS status;
WM_IO_MAD *wmad;
size_t outlen, len = 0;
status = WdfRequestRetrieveOutputBuffer(Request, sizeof(WM_IO_MAD), &wmad, &outlen);
if (!NT_SUCCESS(status)) {
goto out;
}
WdfObjectAcquireLock(pProvider->ReadQueue);
if (pProvider->MadHead == NULL) {
status = WdfRequestForwardToIoQueue(Request, pProvider->ReadQueue);
WdfObjectReleaseLock(pProvider->ReadQueue);
if (NT_SUCCESS(status)) {
return;
}
goto out;
}
len = outlen;
status = WmCopyMad(wmad, pProvider->MadHead, &len);
if (status == STATUS_SUCCESS) {
reg = (WM_REGISTRATION *) pProvider->MadHead->context1;
reg->pDevice->IbInterface.put_mad(__FILE__, __LINE__, WmRemoveMad(pProvider));
}
WdfObjectReleaseLock(pProvider->ReadQueue);
out:
WdfRequestCompleteWithInformation(Request, status, len);
}
static VOID WmFileCleanup(WDFFILEOBJECT FileObject)
{
WM_PROVIDER *prov = WmProviderGetContext(FileObject);
KeAcquireGuardedMutex(&Lock);
RemoveEntryList(&prov->Entry);
KeReleaseGuardedMutex(&Lock);
WmProviderCleanup(prov);
}
void WmProviderCleanup(WM_PROVIDER *pProvider)
{
WM_REGISTRATION *reg;
while ((reg = IndexListRemoveHead(&pProvider->RegIndex)) != NULL) {
WmRegFree(reg);
}
if (InterlockedDecrement(&pProvider->Ref) > 0) {
KeWaitForSingleObject(&pProvider->Event, Executive, KernelMode, FALSE, NULL);
}
WdfIoQueuePurgeSynchronously(pProvider->ReadQueue);
WdfObjectDelete(pProvider->ReadQueue);
IndexListDestroy(&pProvider->RegIndex);
}
From: Uri Habusha
Sent: Tuesday, January 17, 2012 7:16 AM
To: Fab Tillier; Smith, Stan; Leonid Keller; Hefty, Sean
Cc: ofw_list; Irena Gannon
Subject: RE: Opensm & WinMad: a race, causing BSOD722
Again you miss the point.
Not always we have a clear repro steps. If we have it the life was simple.
This issue happened during night run of our regression. The same test runs every night and this is the first time it happens, what means it is race/timing issue.
In such a case we need to review the code start thinking what can cause the issue and add instrumental code so next time it happens we understand better the scenario.
Uri
From: Fab Tillier [mailto:ftillier at microsoft.com]<mailto:[mailto:ftillier at microsoft.com]>
Sent: Tuesday, January 17, 2012 2:47 AM
To: Smith, Stan; Leonid Keller; Hefty, Sean
Cc: Uri Habusha; ofw_list; Irena Gannon
Subject: RE: Opensm & WinMad: a race, causing BSOD722
10D is the bugcheck code, WDF_VIOLATION. The next 4 parameters are the bugcheck arguments.
Leonid, there's good detail in this report, but you're missing a critical 'repro steps' section that would allow this to be reproduced and debugged by the bug owner. Just the crashdump information is only usually enough for simple bugs, and your analysis is probably on the right track. Still, if you want someone else to look into it, it's best to tell them how they too can see it - debugging things live is more productive than debugging by code inspection. How are Sean or Stan supposed to test that they have indeed fixed a bug, assuming they find something suspect and make code changes, when they have no idea how you triggered it? Is it a consistent repro? 1 in a 100?
Thanks,
-Fab
From: ofw-bounces at lists.openfabrics.org<mailto:ofw-bounces at lists.openfabrics.org> [mailto:ofw-bounces at lists.openfabrics.org]<mailto:[mailto:ofw-bounces at lists.openfabrics.org]> On Behalf Of Smith, Stan
Sent: Monday, January 16, 2012 4:37 PM
To: Leonid Keller; Hefty, Sean
Cc: Uri Habusha; ofw_list; Irena Gannon
Subject: Re: [ofw] Opensm & WinMad: a race, causing BSOD722
What are the conditions required to generate the BSOD?
>From the terse description it appears you are shutting down OpenSM. How is this accomplished?
Opensm - 10D, {b, 76157f00, 0, 8811d008}. Not clear what this statement implies? Please explain.
Stan.
From: Leonid Keller [mailto:leonid at mellanox.com]<mailto:[mailto:leonid at mellanox.com]>
Sent: Sunday, January 15, 2012 3:09 AM
To: Smith, Stan; Hefty, Sean
Cc: Uri Habusha; Irena Gannon; ofw_list
Subject: Opensm & WinMad: a race, cauing BSOD722
Hi guys,
We got a BSOD in Opensm - 10D, {b, 76157f00, 0, 8811d008}.
Could you take a look ?
My analysis:
Seems like BSOD has been caused by a race between the main and MAD reading threads of Opensm.
The main thread has already closed the port and is now found in osm_subn_destroy():
opensm_main
...
osm_mad_pool_destroy(&p_osm->mad_pool);
osm_vendor_delete(&p_osm->p_vendor); // port release
osm_subn_destroy(&p_osm->subn); // the thread is found here now
The reading thread is still in action:
opensm!umad_receiver
libibumad!umad_recv
...
winmad!WmIoRead
winmad!WmProviderRead
WdfObjectAcquireLock(pProvider->ReadQueue); // BSOD
A try to ReadQueue with !wdfqueue fails.
Seems like pProvider is already released. But there is no any checks of its validity in WmProviderRead().
Possible solution:
Maybe WmIoRead() should check, that the Provider is not being released and take some reference, while WmProviderRemoveHandler() should wait to this reference to be removed ?
Technical info:
// Bugcheck
WDF_VIOLATION (10d)
The Kernel-Mode Driver Framework has detected that Windows detected an error
in a framework-based driver. In general, the dump file will yield additional
information about the driver that caused this bug check.
Arguments:
Arg1: 0000000b, An attempt to acquire or release a lock was invalid. In this
case, Parameter 3 further specifies the error that has been
made.
Arg2: 76157f00, The handle value.
Arg3: 00000000, A handle passed to either WdfObjectAcquireLock or
WdfObjectReleaseLock represents an object that does not
support synchronization locks.
Arg4: 8811d008, Reserved.
// crash line
void WmProviderRead(WM_PROVIDER *pProvider, WDFREQUEST Request)
{
WM_REGISTRATION *reg;
NTSTATUS status;
WM_IO_MAD *wmad;
size_t outlen, len = 0;
status = WdfRequestRetrieveOutputBuffer(Request, sizeof(WM_IO_MAD), &wmad, &outlen);
if (!NT_SUCCESS(status)) {
goto out;
}
WdfObjectAcquireLock(pProvider->ReadQueue);
if (pProvider->MadHead == NULL) {
// Local parameters
3: kd> ?? pProvider
struct _WM_PROVIDER * 0x894761c0
+0x000 Entry : _LIST_ENTRY [ 0x8e3ea070 - 0x8e3ea070 ]
+0x008 RegIndex : _INDEX_LIST
+0x014 ReadQueue : 0x76157f00 WDFQUEUE__
+0x018 MadHead : (null)
+0x01c MadTail : 0xbc67ccc8 _ib_mad_element
+0x020 Lock : _KGUARDED_MUTEX
+0x040 Ref : 0
+0x044 Event : _KEVENT
+0x054 Pending : 0
+0x058 Active : 0
+0x05c SharedEvent : _KEVENT
+0x06c Exclusive : 0
+0x070 ExclusiveEvent : _KEVENT
// ReadQueue
3: kd> !wdfqueue 0x76157f00
Dumping WDFQUEUE 0x76157f00
=========================
Manualcouldn't read 00000044
, Deleted, Disposing, Not power-managed, PowerOn, Cannot accept, Can dispatch, Dispatching, ExecutionLevelDispatch, SynchronizationScopeNone
Number of driver owned requests: 0
Number of waiting requests: 0
// opensm
3: kd> !PROCESS a14ba6c0
PROCESS a14ba6c0 SessionId: 1 Cid: 13fc Peb: 7ffd9000 ParentCid: 10fc
DirBase: bd5feee0 ObjectTable: bf7fa7b8 HandleCount: 41.
Image: opensm.exe
VadRoot 89c8ca38 Vads 51 Clone 0 Private 271. Modified 3. Locked 0.
DeviceMap 81f41008
Token a6e81030
ElapsedTime 00:00:00.890
UserTime 00:00:00.015
KernelTime 00:00:00.062
QuotaPoolUsage[PagedPool] 0
QuotaPoolUsage[NonPagedPool] 0
Working Set Sizes (now,min,max) (913, 50, 345) (3652KB, 200KB, 1380KB)
PeakWorkingSetSize 930
VirtualSize 76 Mb
PeakVirtualSize 78 Mb
PageFaultCount 1047
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 8768
Job 89e04368
THREAD 89e05d48 Cid 13fc.1758 Teb: 7ffdf000 Win32Thread: fe333b18 RUNNING on processor 2
Not impersonating
DeviceMap 81f41008
Owning Process 0 Image: <Unknown>
Attached Process a14ba6c0 Image: opensm.exe
Wait Start TickCount 5900630 Ticks: 1 (0:00:00:00.015)
Context Switch Count 454
UserTime 00:00:00.015
KernelTime 00:00:00.578
Win32 Start Address opensm!mainCRTStartup (0x0042aaf5)
Stack Init adf03fd0 Current adf038d0 Base adf04000 Limit adf01000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr
adf03cec 826be3a4 nt!KdPollBreakIn+0xea
adf03cf0 826be381 nt!KdCheckForDebugBreak+0x17 (FPO: [0,0,0])
adf03d24 8261f430 nt!KeUpdateRunTime+0x164
adf03d24 003fd34a hal!HalpClockInterruptPn+0x158 (FPO: [0,2] TrapFrame @ adf03d34)
000b2918 003d6174 opensm!osm_subn_destroy+0x1da (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\opensm\user\opensm\osm_subnet.c @ 501]
000b2924 003ba03e opensm!osm_opensm_destroy+0x104 (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\opensm\user\opensm\osm_opensm.c @ 313]
000cfda8 003bab21 opensm!opensm_main+0x1c3e (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\opensm\user\opensm\main.c @ 1264]
000cfdf4 0042a9c4 opensm!main+0x191 (FPO: [Non-Fpo]) (CONV: cdecl) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\opensm\user\opensm\main.c @ 1305]
000cfe38 771c1194 opensm!__mainCRTStartup+0x102 (FPO: [Non-Fpo]) (CONV: cdecl) [d:\5359\minkernel\crts\crtw32\dllstuff\crtexe.c @ 695]
000cfe44 7753b3f5 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
000cfe84 7753b3c8 ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
000cfe9c 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])
THREAD c8974030 Cid 13fc.16f4 Teb: 7ffd6000 Win32Thread: 00000000 RUNNING on processor 3
IRP List:
89e505b0: (0006,0094) Flags: 00060970 Mdl: 00000000
Not impersonating
DeviceMap 81f41008
Owning Process 0 Image: <Unknown>
Attached Process a14ba6c0 Image: opensm.exe
Wait Start TickCount 5900629 Ticks: 2 (0:00:00:00.031)
Context Switch Count 24
UserTime 00:00:00.000
KernelTime 00:00:00.015
Win32 Start Address complib!cl_thread_callback (0x72f409f0)
Stack Init adf57fd0 Current adf57b44 Base adf58000 Limit adf55000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2 IoPriority 2 PagePriority 5
ChildEBP RetAddr
adf576d4 8272fe71 nt!RtlpBreakWithStatusInstruction (FPO: [1,0,0])
adf57724 8273096d nt!KiBugCheckDebugBreak+0x1c
adf57ae8 8272fd10 nt!KeBugCheck2+0x68b
adf57b08 8d956f9e nt!KeBugCheckEx+0x1e
adf57b24 8d955829 Wdf01000!FxVerifierBugCheck+0x24 (FPO: [Non-Fpo])
adf57b4c 8e3e6626 Wdf01000!imp_WdfObjectAcquireLock+0x26 (FPO: [Non-Fpo])
adf57b5c 8e3e6a3c winmad!WdfObjectAcquireLock+0x16 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfsync.h @ 61]
adf57b7c 8e3e5cdd winmad!WmProviderRead+0x3c (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\core\winmad\kernel\wm_provider.c @ 278]
adf57b94 8d94502a winmad!WmIoRead+0x2d (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\core\winmad\kernel\wm_driver.c @ 128]
adf57bb0 8d946256 Wdf01000!FxIoQueueIoRead::Invoke+0x2a (FPO: [Non-Fpo])
adf57bd8 8d9489ac Wdf01000!FxIoQueue::DispatchRequestToDriver+0x1a3 (FPO: [Non-Fpo])
adf57bf4 8d949a36 Wdf01000!FxIoQueue::DispatchEvents+0x3be (FPO: [Non-Fpo])
adf57c14 8d94b824 Wdf01000!FxIoQueue::QueueRequest+0x1ec (FPO: [Non-Fpo])
adf57c38 8d93aa3f Wdf01000!FxPkgIo::Dispatch+0x27d (FPO: [Non-Fpo])
adf57c44 8268f4bc Wdf01000!FxDevice::Dispatch+0x7f (FPO: [Non-Fpo])
adf57c5c 82890f6e nt!IofCallDriver+0x63
adf57c7c 828a2f32 nt!IopSynchronousServiceTail+0x1f8
adf57d08 8269644a nt!NtReadFile+0x644
adf57d08 775264f4 nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ adf57d34)
007cfb84 7752570c ntdll!KiFastSystemCallRet (FPO: [0,0,0])
007cfb88 757af249 ntdll!ZwReadFile+0xc (FPO: [9,0,0])
007cfbec 771bdafd KERNELBASE!ReadFile+0xaa (FPO: [Non-Fpo])
007cfc34 72fd1a25 kernel32!ReadFileImplementation+0xf0 (FPO: [Non-Fpo])
007cfc58 74272910 winmad_72fd0000!CWMProvider::Receive+0xa5 (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\core\winmad\user\wm_provider.cpp @ 227]
007cfc7c 0042d76a libibumad!umad_recv+0x50 (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\libibumad\src\umad.cpp @ 706]
007cfd0c 72f40a04 opensm!umad_receiver+0xba (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\ulp\opensm\user\libvendor\osm_vendor_ibumad.c @ 266]
007cfd18 771c1194 complib!cl_thread_callback+0x14 (FPO: [Non-Fpo]) (CONV: stdcall) [a:\builds\9565\branches\mlnx_winof-3_0_0\core\complib\user\cl_thread.c @ 49]
007cfd24 7753b3f5 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
007cfd64 7753b3c8 ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
007cfd7c 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openfabrics.org/pipermail/ofw/attachments/20120117/5fc962db/attachment.html>
More information about the ofw
mailing list