Re: [ros-dev] SMP - Recursive bugcheck

[Hartmut Birr]

David Kredba schrieb:

>   There is debug output.
>
>  It is truncated at the end. It is growing by many lines of this type 
>  (one about 750 ms) :
>
>
>  apic.c:834) MpsTimerHandler on CPU1, irql = 0, epi = c00b4aaa, KPCR = 
>  ff001000
>
>  occasionaly followed by this line :
>
>  (apic.c:834) MpsTimerHandler on CPU1, irql = 0, epi = c00b4aa9, KPCR = 
>  ff001000.
>
>  Should I send You full output ? It is still growing.
>
>
>  Thanks, David
>  
Hi David,

you have enabled the kernel debugger (KDBG). The current implementation 
of the kernel debuger doesn't work correctly on smp machines. You should 
disable it. There is a difference between the current debug output and 
the last one. Now the ipi functions are executed. The debug output 
within the ipi functions makes some delays. It seems that this delays 
fix a problem. I've found that some variables are set without the 'lock' 
prefix. I've implemented Ke386TestAndClearBit/Ke386TestAndSetBit. 
Possible it does fix the problem. Can you please attach my patch and try 
it again?

- Hartmut
 


E:\Sandbox\ros_mp\reactos>set CVS_RSH=SSH2 

E:\Sandbox\ros_mp\reactos>d:\programme\cvsnt\cvs.exe -z6 -d 
:ext:[e-mail]:/CVS/ReactOS diff -u ntoskrnl\include\internal\ke.h
ntoskrnl\include\internal\i386\ke.h ntoskrnl\ke\ipi.c     
Index: ntoskrnl/include/internal/ke.h
===================================================================
RCS file: /CVS/ReactOS/reactos/ntoskrnl/include/internal/ke.h,v
retrieving revision 1.68
diff -u -r1.68 ke.h
--- ntoskrnl/include/internal/ke.h	28 Nov 2004 12:58:32 -0000	1.68
+++ ntoskrnl/include/internal/ke.h	19 Dec 2004 17:04:06 -0000
@@ -43,9 +43,9 @@
 struct _KPCR;
 struct _KEXCEPTION_FRAME;
 
-#define IPI_REQUEST_FUNCTIONCALL    1
-#define IPI_REQUEST_APC		    2
-#define IPI_REQUEST_DPC		    4
+#define IPI_REQUEST_FUNCTIONCALL    0
+#define IPI_REQUEST_APC		    1
+#define IPI_REQUEST_DPC		    2
 
 /* ipi.c ********************************************************************/
 
Index: ntoskrnl/include/internal/i386/ke.h
===================================================================
RCS file: /CVS/ReactOS/reactos/ntoskrnl/include/internal/i386/ke.h,v
retrieving revision 1.16
diff -u -r1.16 ke.h
--- ntoskrnl/include/internal/i386/ke.h	20 Nov 2004 23:46:36 -0000	1.16
+++ ntoskrnl/include/internal/i386/ke.h	19 Dec 2004 17:04:06 -0000
@@ -219,6 +219,31 @@
 #define Ke386GetCr4()            _Ke386GetCr(4)
 #define Ke386SetCr4(X)           _Ke386SetCr(4,X)
 
+static inline LONG Ke386TestAndClearBit(ULONG BitPos, volatile PULONG Addr)
+{
+	LONG OldBit;
+
+	__asm__ __volatile__("lock btrl %2,%1\n\t"
+	                     "sbbl %0,%0\n\t"
+		             :"=r" (OldBit),"=m" (*Addr)
+		             :"Ir" (BitPos) 
+			     : "memory");
+	return OldBit;
+}
+
+static inline LONG Ke386TestAndSetBit(ULONG BitPos, volatile PULONG Addr)
+{
+	LONG OldBit;
+
+	__asm__ __volatile__("lock btsl %2,%1\n\t"
+	                     "sbbl %0,%0\n\t"
+		             :"=r" (OldBit),"=m" (*Addr)
+		             :"Ir" (BitPos) 
+			     : "memory");
+	return OldBit;
+}
+
+
 static inline void Ki386Cpuid(ULONG Op, PULONG Eax, PULONG Ebx, PULONG Ecx, PULONG Edx)
 {
     __asm__("cpuid"
Index: ntoskrnl/ke/ipi.c
===================================================================
RCS file: /CVS/ReactOS/reactos/ntoskrnl/ke/ipi.c,v
retrieving revision 1.4
diff -u -r1.4 ipi.c
--- ntoskrnl/ke/ipi.c	27 Nov 2004 16:32:10 -0000	1.4
+++ ntoskrnl/ke/ipi.c	19 Dec 2004 17:04:06 -0000
@@ -33,7 +33,7 @@
       if (TargetSet & (1 << i))
       {
          Pcr = (PKPCR)(KPCR_BASE + i * PAGE_SIZE);
-	 Pcr->PrcbData.IpiFrozen |= IpiRequest;
+	 Ke386TestAndSetBit(IpiRequest, &Pcr->PrcbData.IpiFrozen);
 	 HalRequestIpi(i);
       }
    }
@@ -51,30 +51,26 @@
    LARGE_INTEGER StartTime, CurrentTime, Frequency;
    ULONG Count = 5;
 #endif   
-   ULONG TargetSet, Processor;
-
    PKPCR Pcr;
 
    ASSERT(KeGetCurrentIrql() == IPI_LEVEL);
 
-   DPRINT("KiIpiServiceRoutine\n");
+//   DbgPrint("(%s:%d) CPU%d, KiIpiServiceRoutine\n", __FILE__, __LINE__,
KeGetCurrentProcessorNumber());
 
    Pcr = KeGetCurrentKPCR();
 
-   if (Pcr->PrcbData.IpiFrozen & IPI_REQUEST_APC)
+   if (Ke386TestAndClearBit(IPI_REQUEST_APC, &Pcr->PrcbData.IpiFrozen))
    {
-      Pcr->PrcbData.IpiFrozen &= ~IPI_REQUEST_APC;
       HalRequestSoftwareInterrupt(APC_LEVEL);
    }
 
-   if (Pcr->PrcbData.IpiFrozen & IPI_REQUEST_DPC)
+   if (Ke386TestAndClearBit(IPI_REQUEST_DPC, &Pcr->PrcbData.IpiFrozen))
    {
-      Pcr->PrcbData.IpiFrozen &= ~IPI_REQUEST_DPC;
       Pcr->PrcbData.DpcInterruptRequested = TRUE;
       HalRequestSoftwareInterrupt(DISPATCH_LEVEL);
    }
 
-   if (Pcr->PrcbData.IpiFrozen & IPI_REQUEST_FUNCTIONCALL)
+   if (Ke386TestAndClearBit(IPI_REQUEST_FUNCTIONCALL, &Pcr->PrcbData.IpiFrozen))
    {
      
InterlockedDecrement((PLONG)&Pcr->PrcbData.SignalDone->CurrentPacket[1]);
       if (Pcr->PrcbData.SignalDone->CurrentPacket[2])
@@ -88,18 +84,16 @@
             CurrentTime = KeQueryPerformanceCounter(NULL);
 	    if (CurrentTime.QuadPart > StartTime.QuadPart + Count * Frequency.QuadPart)
 	    {
-	       DPRINT1("Waiting longer than %d seconds to start the ipi routine\n",
Count);
+	       DbgPrint("(%s:%d) CPU%d, waiting longer than %d seconds to start the ipi
routine\n", __FILE__,__LINE__, KeGetCurrentProcessorNumber(), Count);
 	       KEBUGCHECK(0);
 	    }
 #endif	 
          }
       }
+//      DbgPrint("(%s:%d) CPU%d, before executing the worker routine\n",
__FILE__,__LINE__, KeGetCurrentProcessorNumber());
       ((VOID
STDCALL(*)(PVOID))(Pcr->PrcbData.SignalDone->WorkerRoutine))(Pcr->PrcbData.SignalDone->CurrentPacket[0]);
-      do
-      {
-         Processor = 1 << KeGetCurrentProcessorNumber();
-	 TargetSet = Pcr->PrcbData.SignalDone->TargetSet;
-      } while (Processor &
InterlockedCompareExchange(&Pcr->PrcbData.SignalDone->TargetSet, TargetSet &
~Processor, TargetSet)); 
+//      DbgPrint("(%s:%d) CPU%d, after executing the worker routine\n",
__FILE__,__LINE__, KeGetCurrentProcessorNumber());
+      Ke386TestAndClearBit(KeGetCurrentProcessorNumber(),
&Pcr->PrcbData.SignalDone->TargetSet);
       if (Pcr->PrcbData.SignalDone->CurrentPacket[2])
       {
 #ifdef DBG      	
@@ -111,16 +105,15 @@
 	    CurrentTime = KeQueryPerformanceCounter(NULL);
 	    if (CurrentTime.QuadPart > StartTime.QuadPart + Count * Frequency.QuadPart)
 	    {
-	       DPRINT1("Waiting longer than %d seconds after executing the ipi
routine\n", Count);
+	       DbgPrint("(%s:%d) CPU%d, waiting longer than %d seconds after executing the
ipi routine\n", __FILE__,__LINE__, KeGetCurrentProcessorNumber(), Count);
 	       KEBUGCHECK(0);
 	    }
 #endif	 
          }
       }
       InterlockedExchangePointer(&Pcr->PrcbData.SignalDone, NULL);
-      Pcr->PrcbData.IpiFrozen &= ~IPI_REQUEST_FUNCTIONCALL;
    }
-   DPRINT("KiIpiServiceRoutine done\n");
+//   DbgPrint("(%s:%d) CPU%d, KiIpiServiceRoutine done\n", __FILE__, __LINE__,
KeGetCurrentProcessorNumber());
    return TRUE;
 }
 
@@ -136,11 +129,11 @@
     ASSERT(KeGetCurrentIrql() == SYNCH_LEVEL);
 
     CurrentPcr = KeGetCurrentKPCR();
-    CurrentPcr->PrcbData.TargetSet = TargetSet;
-    CurrentPcr->PrcbData.WorkerRoutine = (ULONG_PTR)WorkerRoutine;
-    CurrentPcr->PrcbData.CurrentPacket[0] = Argument;
-    CurrentPcr->PrcbData.CurrentPacket[1] = (PVOID)Count;
-    CurrentPcr->PrcbData.CurrentPacket[2] = (PVOID)(ULONG)Synchronize;
+    InterlockedExchange(&CurrentPcr->PrcbData.TargetSet, TargetSet);
+    InterlockedExchange(&CurrentPcr->PrcbData.WorkerRoutine,
(ULONG_PTR)WorkerRoutine);
+    InterlockedExchangePointer(&CurrentPcr->PrcbData.CurrentPacket[0], Argument);
+    InterlockedExchangePointer(&CurrentPcr->PrcbData.CurrentPacket[1],
(PVOID)Count);
+    InterlockedExchangePointer(&CurrentPcr->PrcbData.CurrentPacket[2],
(PVOID)(ULONG)Synchronize);
 
     CurrentProcessor = 1 << KeGetCurrentProcessorNumber();
 
@@ -150,7 +143,7 @@
        {
           Pcr = (PKPCR)(KPCR_BASE + i * PAGE_SIZE);
           while(0 != InterlockedCompareExchange((PLONG)&Pcr->PrcbData.SignalDone,
(LONG)&CurrentPcr->PrcbData, 0));
-	  Pcr->PrcbData.IpiFrozen |= IPI_REQUEST_FUNCTIONCALL;
+	  Ke386TestAndSetBit(IPI_REQUEST_FUNCTIONCALL, &Pcr->PrcbData.IpiFrozen);
 	  if (Processor != CurrentProcessor)
 	  {
 	     HalRequestIpi(i);
@@ -171,7 +164,7 @@
    KIRQL oldIrql;
    ULONG TargetSet;
 
-   DPRINT("KeIpiGenericCall on CPU%d\n", KeGetCurrentProcessorNumber());
+//   DbgPrint("(%s:%d) KeIpiGenericCall on CPU%d\n", __FILE__, __LINE__,
KeGetCurrentProcessorNumber());
 
    KeRaiseIrql(SYNCH_LEVEL, &oldIrql);
 
@@ -185,7 +178,7 @@
    
    KeLowerIrql(oldIrql);
    
-   DPRINT("KeIpiGenericCall on CPU%d done\n", KeGetCurrentProcessorNumber());
+//   DbgPrint("(%s:%d) KeIpiGenericCall on CPU%d done\n", __FILE__, __LINE__,
KeGetCurrentProcessorNumber());
 }