MCL/sf/os/kernelhwsrv: comparison kernel/eka/drivers/pbus/mmc/stack.cpp

equal deleted inserted replaced

-:0bf4040442f9
+:46fffbe7b5a7
 #include <drivers/mmc.h>
 #include <kernel/kern_priv.h>
 #include <drivers/locmedia.h>
 #include "stackbody.h"
+#include "OstTraceDefinitions.h"
+#ifdef OST_TRACE_COMPILER_IN_USE
+#include "locmedia_ost.h"
+#ifdef __VC32__
+#pragma warning(disable: 4127) // disabling warning "conditional expression is constant"
+#endif
+#include "stackTraces.h"
+#endif
 #ifdef __SMP__
 TSpinLock MMCLock(TSpinLock::EOrderGenericIrqHigh0);
 #endif
 #define ASSERT_NOT_ISR_CONTEXT	__ASSERT_DEBUG(NKern::CurrentContext()!=NKern::EInterrupt,DMMCSocket::Panic(DMMCSocket::EMMCUnblockingInWrongContext));
 * @return ETrue if ready, EFalse otherwise.
 */
 	{
 	const TUint state = iStatus.State();
 	__KTRACE_OPT(KPBUS1, Kern::Printf("=mcc:ir:%d,0x%08x", IsPresent(), state));
+	OstTraceExt2( TRACE_INTERNALS, TMMCARD_ISREADY, "IsPresent=%d; state=0x%08x", IsPresent(), state );
 	return IsPresent() && (state == ECardStateStby || state == ECardStateTran || state == ECardStateSlp);
 	}
 EXPORT_C TBool TMMCard::IsLocked() const
 /**
 * password locking but their CSD reports SPEC_VERS == 1.
 *
 * @return ETrue if locked, EFalse otherwise.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_ISLOCKED_ENTRY, this );
 	if ( !IsPresent() )
 		return( EFalse );
 	return( (TUint32(iStatus) & KMMCStatCardIsLocked) != 0 );
 	}
 /**
 * Returns the size of the MMC card in bytes
 * @return The size of the MMC card in bytes.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_DEVICESIZE64_ENTRY, this );
 	const TBool highCapacity = IsHighCapacity();
 	const TUint32 sectorCount = ExtendedCSD().SectorCount();
 	return ((highCapacity && sectorCount) ? (((TInt64)ExtendedCSD().SectorCount()) * 512) : (TInt64)CSD().DeviceSize());
 	}
 * Returns the write group length.  Provided by the variant.
 * Default implementation returns a multiple of the write block length, as indicated by the CSD.
 * @return The preferred write group length.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_PREFERREDWRITEGROUPLENGTH_ENTRY, this );
 	return(CSD().WriteBlockLength() << 5);	// 16K for a standard 512byte block length
 	}
 TInt TMMCard::GetFormatInfo(TLDFormatInfo& /*aFormatInfo*/) const
 /**
 * Return info. on erase services for this card
 * @param aEraseInfo A reference to the TMMCEraseInfo to be filled in with the erase information.
 * @return Symbian OS error code.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_GETERASEINFO_ENTRY, this );
 	// Check whether this card supports Erase Class Commands. Also, validate the erase group size
 	if ((CSD().CCC() & KMMCCmdClassErase) && IsPowerOfTwo(CSD().EraseGroupSize()))
 		{
 		// This card supports erase cmds. Also, all versions of MMC cards support Erase Group commands (i.e. CMD35, CMD36).
+		OstTrace0( TRACE_INTERNALS, TMMCARD_GETERASEINFO, "Card supports erase class commands" );
 		aEraseInfo.iEraseFlags=(KMMCEraseClassCmdsSupported|KMMCEraseGroupCmdsSupported);
 		// Return the preferred size to be used as the unit for format operations. We need to return a sensible
 		// multiple of the erase group size - as calculated by the CSD. A value around 1/32th of the total disk
 		// size generally results in an appropriate number of individual format calls.
 		aEraseInfo.iMinEraseSectorSize=CSD().EraseGroupSize();
 		}
 	else
 		aEraseInfo.iEraseFlags=0;
-	return(KErrNone);
+	OstTraceFunctionExitExt( TMMCARD_GETERASEINFO_EXIT, this, KErrNone );
+	return KErrNone;
 	}
 TUint TMMCard::MaxTranSpeedInKilohertz() const
 /**
 * Returns the maximum supported clock rate for the card, in Kilohertz.
 * @return Speed, in Kilohertz
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_MAXTRANSPEEDINKILOHERTZ_ENTRY, this );
 	// Default implementation obtains the transaction speed from the CSD
 	TUint32 highSpeedClock = HighSpeedClock();
 	return(highSpeedClock ? highSpeedClock : iCSD.MaxTranSpeedInKilohertz());
 	}
 * Normally this is the same as the READ_BL_LEN field in the CSD register,
 * but for high capacity cards (>- 2GB) this is set to a maximum of 512 bytes,
 * if possible, to try to avoid compatibility issues.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_MAXREADBLLEN_ENTRY, this );
 	const TInt KDefaultReadBlockLen = 9;	// 2^9 = 512 bytes
 	const TCSD& csd = CSD();
 	TInt blkLenLog2 = csd.ReadBlLen();
 	if (blkLenLog2 > KDefaultReadBlockLen)
 		{
 		__KTRACE_OPT(KPBUS1, Kern::Printf("=mmc:mrbl %d", blkLenLog2));
+		OstTrace1( TRACE_INTERNALS, TMMCARD_MAXREADBLLEN1, "Block length 1=%d", blkLenLog2 );
 		if (csd.ReadBlPartial() || CSD().SpecVers() >= 4)
 			{
 			//
 			// MMC System Spec 4.2 states that 512 bytes blocks are always supported,
 			// regardless of the state of READ_BL_PARTIAL
 			//
 			blkLenLog2 = KDefaultReadBlockLen;
 			__KTRACE_OPT(KPBUS1, Kern::Printf("=mmc:mrbl -> %d", blkLenLog2));
-			}
+			OstTrace1( TRACE_INTERNALS, TMMCARD_MAXREADBLLEN2, "Block length 2=%d", blkLenLog2 );
-		}
+			}
+		}
+	OstTraceFunctionExitExt( TMMCARD_MAXREADBLLEN_EXIT, this, blkLenLog2 );
 	return blkLenLog2;
 	}
 TInt TMMCard::MaxWriteBlLen() const
 * Normally this is the same as the WRITE_BL_LEN field in the CSD register,
 * but for high capacity cards (>- 2GB) this is set to a maximum of 512 bytes,
 * if possible, to try to avoid compatibility issues.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARD_MAXWRITEBLLEN_ENTRY, this );
 	const TInt KDefaultWriteBlockLen = 9;	// 2^9 = 512 bytes
 	const TCSD& csd = CSD();
 	TInt blkLenLog2 = csd.WriteBlLen();
 	if (blkLenLog2 > KDefaultWriteBlockLen)
 		{
 		__KTRACE_OPT(KPBUS1, Kern::Printf("=mmc:mrbl %d", blkLenLog2));
+		OstTrace1( TRACE_INTERNALS, TMMCARD_MAXWRITEBLLEN1, "Block length 1=%d", blkLenLog2 );
 		if (csd.WriteBlPartial() || CSD().SpecVers() >= 4)
 			{
 			//
 			// MMC System Spec 4.2 states that 512 bytes blocks are always supported,
 			// regardless of the state of READ_BL_PARTIAL
 			//
 			blkLenLog2 = KDefaultWriteBlockLen;
 			__KTRACE_OPT(KPBUS1, Kern::Printf("=mmc:mrbl -> %d", blkLenLog2));
-			}
+			OstTrace1( TRACE_INTERNALS, TMMCARD_MAXWRITEBLLEN2, "Block length 1=%d", blkLenLog2 );
-		}
+			}
+		}
+	OstTraceFunctionExitExt( TMMCARD_MAXWRITEBLLEN_EXIT, this, blkLenLog2 );
 	return blkLenLog2;
 	}
 //	--------  class TMMCardArray  --------
 * is no cleanup if it fails.
 *
 * @return KErrNone if successful, Standard Symbian OS error code otherwise.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARDARRAY_ALLOCCARDS_ENTRY, this );
 	for (TUint i = 0; i < KMaxMMCardsPerStack; ++i)
 		{
 		// zeroing the card data used to be implicit because embedded in
 		// CBase-derived DMMCStack.
 		if ((iCards[i] = new TMMCard) == 0)
+		    {
+			OstTraceFunctionExitExt( TMMCARDARRAY_ALLOCCARDS_EXIT1, this, KErrNoMemory );
 			return KErrNoMemory;
+		    }
 		iCards[i]->iUsingSessionP = 0;
 		if ((iNewCards[i] = new TMMCard) == 0)
+		    {
+			OstTraceFunctionExitExt( TMMCARDARRAY_ALLOCCARDS_EXIT2, this, KErrNoMemory );
 			return KErrNoMemory;
+		    }
 		iNewCards[i]->iUsingSessionP = 0;
 		}
+	OstTraceFunctionExitExt( TMMCARDARRAY_ALLOCCARDS_EXIT3, this, KErrNone );
 	return KErrNone;
 	}
 void TMMCardArray::InitNewCardScan()
 /**
 * Prepare card array for new scan.
 */
 	{
+	OstTraceFunctionEntry1( TMMCARDARRAY_INITNEWCARDSCAN_ENTRY, this );
 	iNewCardsCount=0;
+	OstTraceFunctionExit1( TMMCARDARRAY_INITNEWCARDSCAN_EXIT, this );
 	}
 void TMMCardArray::MoveCardAndLockRCA(TMMCard& aSrcCard,TMMCard& aDestCard,TInt aDestIndex)
 /**
 * Copy card object and lock RCA.
 */
 	{
+	OstTraceExt2(TRACE_FLOW, TMMCARDARRAY_MOVECARDANDLOCKRCA_ENTRY, "TMMCardArray::MoveCardAndLockRCA;aDestIndex=%d;this=%x", aDestIndex, (TUint) this);
 	__KTRACE_OPT(KPBUS1, Kern::Printf("=mca:mclr:%d", aDestIndex));
 	aDestCard.iCID=aSrcCard.iCID;
 	aDestCard.iRCA=aSrcCard.iRCA;
 	aDestCard.iCSD=aSrcCard.iCSD;
 	aSrcCard.iRCA = aSrcCard.iIndex = aSrcCard.iFlags = 0;
 	aSrcCard.iBusWidth = 1;
 	aSrcCard.iHighSpeedClock = 0;
 	aSrcCard.iUsingSessionP = NULL;
+	OstTraceFunctionExit1( TMMCARDARRAY_MOVECARDANDLOCKRCA_EXIT, this );
 	}
 EXPORT_C void TMMCardArray::AddNewCard(const TUint8* aCID,TRCA* aNewRCA)
 /**
 * Found a new card to add to the array. Add it to a separate array for now
 * since we need to know all the cards present before we start replacing old
 * entries.
 */
 	{
+	OstTraceFunctionEntryExt( TMMCARDARRAY_ADDNEWCARD_ENTRY, this );
 	// Store the CID in the next free slot
 	NewCard(iNewCardsCount).iCID = aCID;
 	*aNewRCA=0;
 		NewCard(iNewCardsCount).iIndex=0;
 		__ASSERT_ALWAYS( (*aNewRCA=iOwningStack->iRCAPool.GetFreeRCA())!=0,DMMCSocket::Panic(DMMCSocket::EMMCNoFreeRCA) );
 		}
 	__KTRACE_OPT(KPBUS1, Kern::Printf("mca:adn: assigning new card %d rca 0x%04x", iNewCardsCount, TUint16(*aNewRCA) ));
+	OstTraceExt2( TRACE_INTERNALS, TMMCARDARRAY_ADDNEWCARD, "iNewCardsCount=%d; RCA=0x%04x", iNewCardsCount, (TUint) *aNewRCA );
 	NewCard(iNewCardsCount).iRCA=*aNewRCA;
 	iNewCardsCount++;
+	OstTraceFunctionExit1( TMMCARDARRAY_ADDNEWCARD_EXIT, this );
 	}
 TInt TMMCardArray::MergeCards(TBool aFirstPass)
 /**
 * This function places newly acquired cards from the new card array into free
 * slots of the main card array.
 * Returns KErrNotFound if not able to successfully place all the new cards.
 */
 	{
+	OstTraceFunctionEntryExt( TMMCARDARRAY_MERGECARDS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mca:mc:%d,%d", aFirstPass, iNewCardsCount));
+	OstTrace1( TRACE_INTERNALS, TMMCARDARRAY_MERGECARDS1, "iNewCardsCount=%d", iNewCardsCount );
 	TUint i;	// New card index
 	TUint j;	// Main card index
 	// Only do this on first pass. Setup any new cards which were already there
 	if (aFirstPass)
 		{
 		for ( i=0 ; i<iNewCardsCount ; i++ )
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("-mca:fp,i=%d,idx=0x%x", i, NewCard(i).iIndex));
+			OstTraceExt2( TRACE_INTERNALS, TMMCARDARRAY_MERGECARDS2, "i=%d; Index=0x%x", i, NewCard(i).iIndex );
 			if( NewCard(i).iIndex != 0 ) // Signifies card was here before (iIndex has old slot number +1)
 				{
 				// Put it in the same slot as before
 				j=(NewCard(i).iIndex-1);
 				MoveCardAndLockRCA(NewCard(i),Card(j),(j+1));
 		if ( NewCard(i).iRCA != 0 )
 			{
 			// Find a spare slot in main array for this new card
 			while ( Card(j).IsPresent() )
 				if ( ++j==iOwningStack->iMaxCardsInStack )
-					return(KErrNotFound);
+				    {
+					OstTraceFunctionExitExt( TMMCARDARRAY_MERGECARDS_EXIT1, this, KErrNotFound );
+					return KErrNotFound;
+				    }
 			// Found a free slot; move the card info there
 			__KTRACE_OPT(KPBUS1, Kern::Printf("-mca:freej=%d,rca=0x%04x", j, TUint16(Card(j).iRCA) ));
+			OstTraceExt2( TRACE_INTERNALS, TMMCARDARRAY_MERGECARDS3, "j=%d; RCA=0x%04x", j, (TUint) (Card(j).iRCA) );
 			if ( Card(j).iRCA != 0 )
 				iOwningStack->iRCAPool.UnlockRCA(Card(j).iRCA);
 			__KTRACE_OPT(KPBUS1, Kern::Printf("merging new card %d to card %d dest index %d", i, j, j+1));
+			OstTraceExt3( TRACE_INTERNALS, TMMCARDARRAY_MERGECARDS4, "Merging new card %d to card %d; Destination index=%d", (TInt) i, (TInt) j, (TInt) j+1 );
 			MoveCardAndLockRCA(NewCard(i),Card(j),(j+1));
 			}
 		}
-	return(KErrNone);
+	OstTraceFunctionExitExt( TMMCARDARRAY_MERGECARDS_EXIT2, this, KErrNone );
+	return KErrNone;
 	}
 void TMMCardArray::UpdateAcquisitions(TUint* aMaxClock)
 /**
 * Called when we have successfully stored a new set of cards in the card array.
 * This performs final initialisation of the card entries and determines the
 * maximum bus clock that can be employed - by checking the CSD of each card.
 */
 	{
+	OstTraceFunctionEntryExt( TMMCARDARRAY_UPDATEACQUISITIONS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mca:uda"));
 	iCardsPresent=0;
 	TUint maxClk = iOwningStack->iMultiplexedBus ? 1 : 800000; // ???
 	for ( TUint i=0 ; i < (iOwningStack->iMaxCardsInStack) ; i++ )
 		{
 		}
 	// ??? Should also calculate here and return the data timeout and busy timeout
 	// instead of relying on ASSP defaults.
 	*aMaxClock=maxClk;
+	OstTraceFunctionExit1( TMMCARDARRAY_UPDATEACQUISITIONS_EXIT, this );
 	}
 EXPORT_C void TMMCardArray::DeclareCardAsGone(TUint aCardNumber)
 /**
 * Clears up a card info object in the main card array
 */
 	{
+	OstTraceFunctionEntryExt( TMMCARDARRAY_DECLARECARDASGONE_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mca:dcag"));
 	// If we thought this one was present then mark it as not present
 	TMMCard& card = Card(aCardNumber);
 	if (card.IsPresent())
 		{
 	card.iUsingSessionP=NULL;
 	card.iSetBlockLen=0;
 	card.iFlags=0; 		// Reset 'has password' and 'write protected' bit fields
 	card.iHighSpeedClock=0;
 	card.iBusWidth=1;
+	OstTraceFunctionExit1( TMMCARDARRAY_DECLARECARDASGONE_EXIT, this );
 	}
 // return this card's index in the array or KErrNotFound if not found
 TInt TMMCardArray::CardIndex(const TMMCard* aCard)
 	{
+	OstTraceFunctionEntryExt( TMMCARDARRAY_CARDINDEX_ENTRY, this );
 	TInt i;
 	for (i = KMaxMMCardsPerStack-1; i>= 0; i--)
 		{
 		if (iCards[i] == aCard)
 			break;
 		}
+	OstTraceFunctionExitExt( TMMCARDARRAY_CARDINDEX_EXIT, this, i );
 	return i;
 	}
 //	--------  class TMMCCommandDesc  --------
 EXPORT_C TInt TMMCCommandDesc::Direction() const
 /**
 * returns -1, 0 or +1 for DT directions read, none or write respectively
 */
 	{
+	OstTraceFunctionEntry1( TMMCCOMMANDDESC_DIRECTION_ENTRY, this );
 	TUint dir = iSpec.iDirection;
 	TInt result = dir;
+	TInt ret;
 	if( dir == 0 )
-		return( 0 );
+	    {
+	    ret = 0;
+		OstTraceFunctionExitExt( TMMCCOMMANDDESC_DIRECTION_EXIT1, this, ret );
+		return ret;
+	    }
 	if( dir & KMMCCmdDirWBitArgument )
 		result = TUint(iArgument) >> (dir & KMMCCmdDirIndBitPosition);
 	if( dir & KMMCCmdDirNegate )
 		result = ~result;
-	return( ((result&1)-1)|1 );
+	ret = ((result&1)-1)|1;
+	OstTraceFunctionExitExt( TMMCCOMMANDDESC_DIRECTION_EXIT2, this, ret );
+	return ret;
 	}
 TBool TMMCCommandDesc::AdjustForBlockOrByteAccess(const DMMCSession& aSession)
 	{
+	OstTraceExt2(TRACE_FLOW, TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_ENTRY, "TMMCCommandDesc::AdjustForBlockOrByteAccess;Session ID=%d;this=%x", (TInt) aSession.SessionID(), (TUint) this);
 /**
 * The MMC session provides both block and byte based IO methods, all of which can
 * be used on both block and byte based MMC cards.  This method adjusts the command
 * arguments so that they match the underlying cards access mode.
 *
 	if(iTotalLength == 0	||
 	   blockLength == 0	||
 	   iTotalLength % KMMCardHighCapBlockSize != 0	||	// always aligned on 512 bytes
 	   blockLength % KMMCardHighCapBlockSize != 0)
 		{
-		return(EFalse);
+		OstTraceFunctionExitExt( TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_EXIT1, this, (TUint) EFalse );
+		return EFalse;
 		}
 	if(aSession.CardP()->IsHighCapacity())
 		{
 		// high capacity (block-based) card
 			// The command arguments are using byte based addressing
 			//  - adjust to block-based addressing
 			if(iArgument % KMMCardHighCapBlockSize != 0)
 				{
 				// Block based media does not support misaligned access
-				return(EFalse);
+				OstTraceFunctionExitExt( TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_EXIT2, this, (TUint) EFalse );
+				return EFalse;
 				}
 			// adjust for block based access
 			iArgument = iArgument >> KMMCardHighCapBlockSizeLog2;
 			iFlags |= KMMCCmdFlagBlockAddress;
 			const TUint32 maxBlocks = 4 * 1024 * ((1024 * 1024) >> KMMCardHighCapBlockSizeLog2);
 			if(iArgument > maxBlocks)
 				{
 				// The address is out of range (>2G) - cannot convert
-				return(EFalse);
+				OstTraceFunctionExitExt( TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_EXIT3, this, (TUint) EFalse );
+				return EFalse;
 				}
 			// adjust for byte-based access
 			iArgument = iArgument << KMMCardHighCapBlockSizeLog2;
 			iFlags &= ~KMMCCmdFlagBlockAddress;
 			}
 		else if(iArgument % KMMCardHighCapBlockSize != 0)
 			{
 			// byte addressing, unaligned address
-			return(EFalse);
+			OstTraceFunctionExitExt( TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_EXIT4, this, (TUint) EFalse );
-			}
+			return EFalse;
-		}
+			}
+		}
-	return(ETrue);
+	OstTraceFunctionExitExt( TMMCCOMMANDDESC_ADJUSTFORBLOCKORBYTEACCESS_EXIT5, this, (TUint) ETrue );
+	return ETrue;
 	}
 void TMMCCommandDesc::Dump(TUint8* aResponseP, TMMCErr aErr)
 	{
 TRCA TMMCRCAPool::GetFreeRCA()
 /**
 * Returns a free RCA number from the pool or zero if none is available
 */
 	{
+	OstTraceFunctionEntry1( TMMCRCAPOOL_GETFREERCA_ENTRY, this );
 	TUint32 seekm = (iPool | iLocked) + 1;
 	iPool |= (seekm & ~iLocked);
+	TUint16 ret;
 	if( (seekm & 0xFFFFFFFF) == 0 )
-		return( 0 );
+	    {
+	    ret = 0;
+		OstTraceFunctionExitExt( TMMCRCAPOOL_GETFREERCA_EXIT1, this, (TUint) ret);
+		return ret;
+	    }
 	TUint16 pos = 1;
 	if ((seekm & 0xFFFF) == 0)	{ seekm >>= 16;	pos = 17; }
 	if ((seekm & 0xFF) == 0)	{ seekm >>= 8;	pos += 8; }
 	// for this adjustment.  These functions are only ever called in this file with the iRCA
 	// field of a TMMCard object, and not with arbitrary values.
 	// The iRCA field itself is only assigned values from iNewCards[] or zero.  iNewCards
 	// in turn is fed values from this function, in DMMCStack::CIMUpdateAcqSM() / EStSendCIDIssued.
-	return TUint16(pos << 8 | pos);
+	ret = TUint16(pos << 8 | pos);
+	OstTraceFunctionExitExt( TMMCRCAPOOL_GETFREERCA_EXIT2, this, (TUint) ret);
+	return ret;
 	}
 //	--------  class TMMCSessRing  --------
 TMMCSessRing::TMMCSessRing()
 /**
 * Constructor
 */
 	: iPMark(NULL),iPoint(NULL),iPrevP(NULL),iSize(0)
-	{}
+	{OstTraceFunctionEntry1( TMMCSESSRING_TMMCSESSRING_ENTRY, this );}
 void TMMCSessRing::Erase()
 /**
 * Erases all the ring content
 */
-	{iPMark = iPoint = iPrevP = NULL; iSize = 0;}
+	{
+	OstTraceFunctionEntry1( TMMCSESSRING_ERASE_ENTRY, this );
+	iPMark = iPoint = iPrevP = NULL; iSize = 0;
+	OstTraceFunctionExit1( TMMCSESSRING_ERASE_EXIT, this );
+	}
 DMMCSession* TMMCSessRing::operator++(TInt)
 /**
 * Post increment of Point
 TBool TMMCSessRing::Point(DMMCSession* aSessP)
 /**
 * Finds aSessP and sets Point to that position
 */
 	{
+	OstTraceFunctionEntryExt( TMMCSESSRING_POINT_ENTRY, this );
 	Point();
 	while( iPoint != NULL )
 		if( iPoint == aSessP )
-			return( ETrue );
+		    {
+			OstTraceFunctionExitExt( TMMCSESSRING_POINT_EXIT1, this, (TUint) ETrue );
+			return ETrue;
+		    }
 		else
 			this->operator++(0);
-	return( EFalse );
+	OstTraceFunctionExitExt( TMMCSESSRING_POINT_EXIT2, this, (TUint) EFalse );
+	return EFalse;
 	}
 void TMMCSessRing::Add(DMMCSession* aSessP)
 /**
 * Inserts aSessP before Marker. Point is moved into the Marker position.
 */
 	{
+	OstTraceFunctionEntryExt( TMMCSESSRING_ADD1_ENTRY, this );
 	if( iSize == 0 )
 		{
 		iPMark = iPrevP = iPoint = aSessP;
 		aSessP->iLinkP = aSessP;
 		iSize = 1;
+		OstTraceFunctionExit1( TMMCSESSRING_ADD1_EXIT1, this );
 		return;
 		}
 	iPoint = iPMark->iLinkP;
 	iPMark->iLinkP = aSessP;
 	aSessP->iLinkP = iPoint;
 	iPMark = iPrevP = aSessP;
 	iSize++;
+	OstTraceFunctionExit1( TMMCSESSRING_ADD1_EXIT2, this );
 	}
 void TMMCSessRing::Add(TMMCSessRing& aRing)
 /**
 * Inserts aRing before Marker. Point is moved into the Marker position.
 * aRing Marker becomes the fisrt inserted element.
 * Erases aRing.
 */
 	{
+	OstTraceFunctionEntry1( TMMCSESSRING_ADD2_ENTRY, this );
 	Point();
 	if( aRing.iSize == 0 )
+	    {
+		OstTraceFunctionExit1( TMMCSESSRING_ADD2_EXIT1, this );
 		return;
+	    }
 	if( iSize == 0 )
 		{
 		iPrevP = iPMark = aRing.iPMark;
 		iPoint = iPrevP->iLinkP;
 		iPrevP->iLinkP = iPoint;
 		iSize += aRing.iSize;
 		}
 	aRing.Erase();
+	OstTraceFunctionExit1( TMMCSESSRING_ADD2_EXIT2, this );
 	}
 DMMCSession* TMMCSessRing::Remove()
 /**
 * Removes an element pointed to by Point.
 * Point (and possibly Marker) move forward as in operator++
 */
 	{
+	OstTraceFunctionEntry1( TMMCSESSRING_REMOVE1_ENTRY, this );
 	DMMCSession* remS = iPrevP;
 	if( iSize < 2 )
 		Erase();
 	else
 			iPMark = iPrevP;
 			iPoint = NULL;
 			}
 		}
-	return( remS );
+	OstTraceFunctionExitExt( TMMCSESSRING_REMOVE1_EXIT, this, ( TUint )( remS ) );
+	return remS;
 	}
 void TMMCSessRing::Remove(DMMCSession* aSessP)
 /**
 * Removes a specified session from the ring
 */
 	{
+	OstTraceFunctionEntryExt( TMMCSESSRING_REMOVE2_ENTRY, this );
 	if( Point(aSessP) )
 		Remove();
 	else
 		DMMCSocket::Panic(DMMCSocket::EMMCSessRingNoSession);
+	OstTraceFunctionExit1( TMMCSESSRING_REMOVE2_EXIT, this );
 	}
 //	--------  class TMMCStateMachine  --------
 It also resets the stack and the exit code.
 */
 EXPORT_C void TMMCStateMachine::Reset()
 	{
+	OstTraceFunctionEntry1( TMMCSTATEMACHINE_RESET_ENTRY, this );
 	iAbort = EFalse;
 	iSP = 0; iExitCode = 0;
 	iStack[0].iState = 0; iStack[0].iTrapMask = 0;
+	OstTraceFunctionExit1( TMMCSTATEMACHINE_RESET_EXIT, this );
 	}
 @return The MultiMediaCard error code.
 */
 EXPORT_C TMMCErr TMMCStateMachine::Dispatch()
 	{
+	OstTraceFunctionEntry1( TMMCSTATEMACHINE_DISPATCH_ENTRY, this );
 	// If a state machine returns non-zero, i.e. a non-empty error set, then the second
 	// inner while loop is broken.  The errors are thrown like an exception where the
 	// stack is unravelled until it reaches a state machine which can handle at least
 	// one of the error codes, else this function returns with the exit code or'd with
 	// KMMCErrBypass.  If the state machine returns zero, then this function returns
 		iExitCode &= ~KMMCErrBypass;
 		if ( iExitCode )
 			{
 			__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:Err %x",iExitCode));
+			OstTrace1( TRACE_INTERNALS, TMMCSTATEMACHINE_DISPATCH, "iExitCode=0x%x", iExitCode );
 			}
 		while( iSP >= 0 && !iAbort )
 			{
 			__KTRACE_OPT(KPBUS1,Kern::Printf("-msm:dsp:%02x:%08x.%02x",iSP, TUint32(iStack[iSP].iFunction), State()));
+			OstTraceExt3( TRACE_INTERNALS, TMMCSTATEMACHINE_DISPATCH2, "iSP=%d; iStack[iSP].iFunction=0x%08x; State=0x%02x", (TInt) iSP, (TUint) iStack[iSP].iFunction, (TUint) State() );
 			iSuspend = ETrue;
 			const TMMCErr signal = iStack[iSP].iFunction(iContextP);
 			if (signal)
 				}
 			if( iSuspend )
 				{
 				__KTRACE_OPT(KPBUS1,Kern::Printf("<msm:dsp:exitslp"));
+				OstTraceFunctionExit1( TMMCSTATEMACHINE_DISPATCH_EXIT1, this );
 				return(0);
 				}
 			}
 		}
 	__KTRACE_OPT(KPBUS1,Kern::Printf("<msm:dsp:exit%08x", iExitCode));
+	OstTraceFunctionExit1( TMMCSTATEMACHINE_DISPATCH_EXIT2, this );
 	return( KMMCErrBypass | iExitCode );
 	}
 @see SMF_INVOKES
 @see SMF_INVOKEWAITS
 */
 EXPORT_C TMMCErr TMMCStateMachine::Push(TMMCErr (*anEntry)(TAny*), TBool aSuspend)
 	{
+	OstTraceFunctionEntry1( TMMCSTATEMACHINE_PUSH_ENTRY, this );
 	iSP++;
 	__ASSERT_ALWAYS(TUint(iSP)<KMaxMMCMachineStackDepth,
 		DMMCSocket::Panic(DMMCSocket::EMMCMachineStack));
 	iStack[iSP].iFunction = anEntry;
 	iStack[iSP].iState = 0;
 	iStack[iSP].iTrapMask = 0;
 	if( !aSuspend )
 		iSuspend = EFalse;
-	return( 0 );
+	OstTraceFunctionExit1( TMMCSTATEMACHINE_PUSH_EXIT, this );
+	return 0;
 	}
 @return KMMCErrNone
 */
 EXPORT_C TMMCErr TMMCStateMachine::Jump(TMMCErr (*anEntry)(TAny*), TBool aSuspend)
 	{
+	OstTraceFunctionEntry1( TMMCSTATEMACHINE_JUMP_ENTRY, this );
 	iStack[iSP].iFunction = anEntry;
 	iStack[iSP].iState = 0;
 	iStack[iSP].iTrapMask = 0;
 	if( !aSuspend )
 		iSuspend = EFalse;
-	return( 0 );
+	OstTraceFunctionExit1( TMMCSTATEMACHINE_JUMP_EXIT, this );
+	return 0;
 	}
 /**
 * Initialises the generic MMC stack.
 * @return KErrNone if successful, standard error code otherwise.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_INIT_ENTRY, this );
 	// allocate and initialize session object
 	if ((iStackSession = AllocSession(TMMCCallBack(StackSessionCBST, this))) == 0)
-		return(KErrNoMemory);
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_INIT_EXIT1, this, KErrNoMemory );
+		return KErrNoMemory;
+	    }
 	// create helper class
 	if ((iBody = new DBody(*this)) == NULL)
-		return(KErrNoMemory);
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_INIT_EXIT2, this, KErrNoMemory );
+		return KErrNoMemory;
+	    }
 	iStackSession->SetStack(this);
 	iStackDFC.SetDfcQ(&iSocket->iDfcQ);
 	if ( iMaxCardsInStack > KMaxMMCardsPerStack )
 		iMaxCardsInStack=KMaxMMCardsPerStack;
 	TInt r = iCardArray->AllocCards();
-	return(r);
+	OstTraceFunctionExitExt( DMMCSTACK_INIT_EXIT3, this, r );
+	return r;
 	}
 EXPORT_C void DMMCStack::PowerUpStack()
 /**
 * Enforce stack power-up and initialisation.
 * This is an asynchronous operation, which calls DMMCSocket::PowerUpSequenceComplete upon completion.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_POWERUPSTACK_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:pus"));
 	if (iPSLBuf == NULL)
 		{
 		GetBufferInfo(&iPSLBuf, &iPSLBufLen);
 		}
 	ReportPowerDown();							// ensure power will be switch on regardless
 	Scheduler( iInitialise );
+	OstTraceFunctionExit1( DMMCSTACK_POWERUPSTACK_EXIT, this );
 	}
 void DMMCStack::QSleepStack()
 /**
 * Schedules a session to place media in Sleep State
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_QSLEEPSTACK_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:qsleep"));
 	Scheduler( iSleep );
+	OstTraceFunctionExit1( DMMCSTACK_QSLEEPSTACK_EXIT, this );
 	}
 EXPORT_C void DMMCStack::PowerDownStack()
 /**
 * Enforce stack power down.
 * driver which may attempt to open immediately after this failed attempt won't have to re-power the card.
 * If no driver successfully opens on the card then the Controllers inactivity/not in use
 * timeout system can be left to power it down.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_POWERDOWNSTACK_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:pds"));
 	ReportPowerDown();
 	iInitState = EISPending;
 	DoPowerDown();
 	// The stack may have powered down while attempting to power up (e.g. because a card has not responded),
 	// so ensure stack doesn't attempt to initialize itself again until next PowerUpStack()
 	iInitialise = EFalse;
 	iStackState &= ~(KMMCStackStateInitInProgress | KMMCStackStateInitPending | KMMCStackStateBusInconsistent | KMMCStackStateWaitingDFC);
 	iSessionP = NULL;
+	OstTraceFunctionExit1( DMMCSTACK_POWERDOWNSTACK_EXIT, this );
 	}
 //
 // DMMCStack:: --- Stack Scheduler and its supplementary functions ---
 //
 DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedGetOnDFC()
 /**
 * Initiates stack DFC. Returns either Continue or Loop.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDGETONDFC_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sgd"));
 	if( iDFCRunning )
-		return( ESchedContinue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDGETONDFC_EXIT1, this, (TInt) ESchedContinue);
+		return ESchedContinue;
+	    }
 	if( (iStackState & KMMCStackStateWaitingDFC) == 0 )
 		{
 		__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sgd:q"));
 		iStackState |= KMMCStackStateWaitingDFC;
 			iStackDFC.Add();
 		else
 			iStackDFC.Enque();
 		}
-	return( ESchedLoop );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDGETONDFC_EXIT2, this, (TInt) ESchedLoop);
+	return ESchedLoop;
 	}
 void DMMCStack::SchedSetContext(DMMCSession* aSessP)
 /**
 * Sets up the specified session as the current session.
 * Invoked by JobChooser and Initialiser.
 * @param aSessP A pointer to the session.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDSETCONTEXT_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:ssc"));
 	if( (iStackState & (KMMCStackStateInitPending|KMMCStackStateBusInconsistent)) != 0 &&
 		aSessP->iSessionID != ECIMInitStack )
 		{
 		iInitialise = ETrue;
+		OstTraceFunctionExit1( DMMCSTACK_SCHEDSETCONTEXT_EXIT1, this );
 		return;
 		}
 	if( iSessionP != aSessP )
 		{
 		iSessionP = aSessP;
 		}
 	iSessionP->iState &= ~KMMCSessStateDoReSchedule;
+	OstTraceFunctionExit1( DMMCSTACK_SCHEDSETCONTEXT_EXIT2, this );
 	}
 void DMMCStack::SchedDoAbort(DMMCSession* aSessP)
 /**
 * Aborts asynchronous activities of a session aSessP
 * @param aSessP A pointer to the session to be aborted.
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_SCHEDDOABORT_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sda"));
 #ifdef __EPOC32__
 	if( aSessP->iBlockOn & KMMCBlockOnPollTimer )
 		aSessP->iPollTimer.Cancel();
 	(void)__e32_atomic_and_ord32(&aSessP->iBlockOn, ~(KMMCBlockOnPollTimer | KMMCBlockOnRetryTimer |
 						  							  KMMCBlockOnWaitToLock | KMMCBlockOnASSPFunction |
 						  							  KMMCBlockOnInterrupt | KMMCBlockOnDataTransfer) );
+	OstTraceFunctionExit1( DMMCSTACK_SCHEDDOABORT_EXIT, this );
 	}
 DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedResolveStatBlocks(DMMCSession* aSessP)
 /**
 * Checks static blocking conditions and removes them as necessary
 * @param aSessP A pointer to the session.
 * @return EschedContinue or ESchedLoop (if scheduler is to be restarted)
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_SCHEDRESOLVESTATBLOCKS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:srsb"));
 	if( (aSessP->iBlockOn & KMMCBlockOnCardInUse) && aSessP->iCardP->iUsingSessionP == NULL )
 		aSessP->SynchUnBlock( KMMCBlockOnCardInUse );
 		// ECIMLockStack processed here
 		iLockingSessionP = aSessP;					// in this order
 		iStackState &= ~KMMCStackStateWaitingToLock;
 		aSessP->SynchUnBlock( KMMCBlockOnWaitToLock );
 		MarkComplete( aSessP, KMMCErrNone );
-		return( ESchedLoop );
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDRESOLVESTATBLOCKS_EXIT1, this, (TInt) ESchedLoop );
-		}
+		return ESchedLoop;
+		}
-	return( ESchedContinue );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDRESOLVESTATBLOCKS_EXIT2, this, (TInt) ESchedContinue );
+	return ESchedContinue;
 	}
 DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedGroundDown(DMMCSession* aSessP, TMMCErr aReason)
 /**
 * Aborts all asynchronous activities of session aSessP with
 * @return ESchedLoop if the session can not be safely grounded (eg
 * iStackSession) and should therefore be aborted and/or completed by a
 * separate scheduler pass.
 */
 	{
+	OstTraceExt3(TRACE_FLOW, DMMCSTACK_SCHEDGROUNDDOWN_ENTRY, "DMMCStack::SchedGroundDown;aSessionP=%x;aReason=%d;this=%x", (TUint) aSessP, (TInt) aReason, (TUint) this);
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sgdn"));
 	if( (aSessP == iStackSession) || InitStackInProgress() )
-		return( ESchedLoop );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDGROUNDDOWN_EXIT1, this, (TInt) ESchedLoop );
+		return ESchedLoop;
+	    }
 	if( aSessP->iState & KMMCSessStateInProgress )
 		{
 		SchedDoAbort( aSessP );
 		//coverity[check_return]
 		aSessP->iMachine.SetExitCode( aReason );
 		aSessP->iState &= ~(KMMCSessStateSafeInGaps | KMMCSessStateDoReSchedule |
 							KMMCSessStateDoDFC);
 		}
-	return( ESchedContinue );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDGROUNDDOWN_EXIT2, this, (TInt) ESchedContinue );
+	return ESchedContinue;
 	}
 DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedEnqueStackSession(TMMCSessionTypeEnum aSessID)
 /**
 * Prepare internal session for InitStack and enque it into WorkSet.
 * @return EschedContinue or ESchedLoop
 */
 	{
+	OstTraceExt2(TRACE_FLOW, DMMCSTACK_SCHEDENQUESTACKSESSION_ENTRY ,"DMMCStack::SchedEnqueStackSession;aSessID=%d;this=%x", (TInt) aSessID, (TUint) this);
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sess"));
 		if( iStackSession->IsEngaged() )
 			{
 			MarkComplete( iStackSession, KMMCErrAbort );
-			return( ESchedLoop );
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDENQUESTACKSESSION_EXIT1, this, (TInt) ESchedLoop );
+			return ESchedLoop;
 			}
 		iStackSession->SetupCIMControl( aSessID );
 		iWorkSet.Add( iStackSession );
 		iStackSession->iState |= KMMCSessStateEngaged;
-		return( ESchedContinue );
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDENQUESTACKSESSION_EXIT2, this, (TInt) ESchedContinue );
+		return ESchedContinue;
 	}
 void DMMCStack::SchedGrabEntries()
 /**
 * Merges Entry queue into Ready queue. Invoked at the scheduler entry and
 * after the completion pass
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDGRABENTRIES_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sge"));
 	iAttention = EFalse;		// Strictly in this order
 	if( !iEntryQueue.IsEmpty() )
 		{
 		DISABLEPREEMPTION
 		iReadyQueue.Add( iEntryQueue );
 		RESTOREPREEMPTION
 		}
+	OstTraceFunctionExit1( DMMCSTACK_SCHEDGRABENTRIES_EXIT, this );
 	}
 void DMMCStack::SchedDisengage()
 /**
 * This function is called by AbortPass() and CompletionPass() to remove the session
 * at WorkSet Point, to abort its asynchronous activities (if any) and
 * clear up the dependent resources
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDDISENGAGE_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sd"));
 	DMMCSession* sessP = iWorkSet.Remove();
 	SchedDoAbort( sessP );
 	if( sessP->iState & KMMCSessStateASSPEngaged )
 		ASSPDisengage();
 	sessP->iState = 0;
+	OstTraceFunctionExit1( DMMCSTACK_SCHEDDISENGAGE_EXIT, this );
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedAbortPass()
 /**
 * DMMCStack Scheduler private inline functions. These functions were separated as inline functions
 * only for the sake of Scheduler() clarity.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDABORTPASS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sap"));
 	iAbortReq = EFalse;
 	SchedGrabEntries();
 	DMMCSession* sessP;
 			}
 		else
 			iReadyQueue++;
 	if( iAbortReq )
-		return( ESchedLoop );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDABORTPASS_EXIT1, this, (TInt) ESchedLoop );
+		return ESchedLoop;
+	    }
 	// Clearing iAbortAll here is a bit dodgy. It wouldn't work if somebody interrupted us
 	// at this point, enqued a session and then immediately called Reset() - that session
 	// would not be discarded. However, the correct solution (enque Reset() requests
 	// and process them in the Scheduler main loop) seems to be too expensive just to avoid
 	// this particular effect.
 	iAbortAll = EFalse;
-	return( ESchedContinue );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDABORTPASS_EXIT2, this, (TInt) ESchedContinue  );
+	return ESchedContinue;
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedCompletionPass()
 /**
 * This function calls back all the sessions waiting to be completed
 * Returns either Continue or Loop.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDCOMPLETIONPASS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:scp"));
 	iCompReq = EFalse;
 	DMMCSession* sessP;
 				 SchedGetOnDFC() )
 				{
 				// DFC has been queued so return back to main loop.  Next time
 				// SchedGetOnDfc() will return EFalse, and the callback will be called.
 				iCompReq = ETrue;
-				return( ESchedLoop );
+				OstTraceFunctionExitExt( DMMCSTACK_SCHEDCOMPLETIONPASS_EXIT1, this, (TInt) ESchedLoop );
+				return ESchedLoop;
 				}
 			SchedDisengage();					// calls iWorkSet.Remove
 			sessP->iMMCExitCode |= iCompleteAllExitCode;
 			// Update the controller store if a password operation was in progress.
 			}
 		else
 			iWorkSet++;
 	if( iCompReq )
-		return( ESchedLoop );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDCOMPLETIONPASS_EXIT2, this, (TInt) ESchedLoop );
+		return ESchedLoop;
+	    }
 	iCompleteAllExitCode = 0;
-	return( ESchedContinue );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDCOMPLETIONPASS_EXIT3, this, ( TInt) ESchedContinue );
+	return ESchedContinue;
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedInitStack()
 /**
 * "Immediate" InitStack initiator. Returns either Continue or Loop.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDINITSTACK_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sis"));
 	if( SchedGetOnDFC() )
-		return( ESchedLoop );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDINITSTACK_EXIT1, this, (TInt) ESchedLoop );
+		return ESchedLoop;
+	    }
 	if( iSessionP != NULL && (iStackState & KMMCStackStateJobChooser) == 0 )
 		{
 		if( (iSessionP->iState & KMMCSessStateInProgress) )
 			{
 			if( SchedGroundDown(iSessionP, KMMCErrPowerDown) )
 				{
 				MarkComplete( iSessionP, KMMCErrPowerDown );
-				return( ESchedLoop );
+				OstTraceFunctionExitExt( DMMCSTACK_SCHEDINITSTACK_EXIT2, this, (TInt) ESchedLoop );
+				return ESchedLoop;
 				}
 			}
 		else
 			iSessionP->iMachine.Reset();
 		}
 	// session isn't specifically ECIMInitStack (which it rarely will be) then we have to use
 	// the stack session to perform the stack init.
 	if( iSessionP == NULL || iSessionP->iSessionID != ECIMInitStack )
 		{
 		if( SchedEnqueStackSession(ECIMInitStack) )
-			return( ESchedLoop );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDINITSTACK_EXIT3, this, (TInt) ESchedLoop );
+			return ESchedLoop;
+		    }
 		SchedSetContext( iStackSession );	// make the internal session to be current job
 		}
 	// Neither client nor internal session could be blocked here, not even on "BrokenLock"
 	DMMCSocket::Panic(DMMCSocket::EMMCInitStackBlocked) );
 	iStackState |= KMMCStackStateInitInProgress;
 	// nothing can stop this session now; it's safe to clear iInitialise here.
 	iInitialise = EFalse;
-	return( ESchedContinue );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDINITSTACK_EXIT4, this, (TInt) ESchedContinue );
+	return ESchedContinue;
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedSleepStack()
 /**
 * "Immediate" Stack sleep mode. Returns either Continue or Loop.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDSLEEPSTACK_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:SchdSlp!"));
 	// Make sure Stack DFC is Running!
 	if( SchedGetOnDFC() )
 		{
 		__KTRACE_OPT(KPBUS1, Kern::Printf("mst:SchdSlp - DFC not running"));
-		return( ESchedLoop );
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSLEEPSTACK_EXIT1, this, (TInt) ESchedLoop );
+		return ESchedLoop;
 		}
 	if( iSessionP != NULL && (iStackState & KMMCStackStateJobChooser) == 0 )
 		{
 		if( (iSessionP->iState & KMMCSessStateInProgress) )
 			{
 			// A session has been queued before sleep,
 			// cancel sleep and loop for next session
 			iSleep = EFalse;
-			return( ESchedLoop );
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDSLEEPSTACK_EXIT2, this, (TInt) ESchedLoop );
+			return ESchedLoop;
 			}
 		}
 	// Use the stack session to perform the stack sleep.
 	if( SchedEnqueStackSession(ECIMSleep) )
 		{
 		__KTRACE_OPT(KPBUS1,Kern::Printf("SchdSlp: already Enqued"));
 		// Stack already busy cancel sleep
 		iSleep = EFalse;
-		return( ESchedLoop );
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSLEEPSTACK_EXIT3, this, (TInt) ESchedLoop );
+		return ESchedLoop;
 		}
 	SchedSetContext( iStackSession );	// make the internal session to be current job
 	// Sleep has now been queued
 	iSleep = EFalse;
 	iStackState |= KMMCStackStateSleepinProgress;
 	__KTRACE_OPT(KPBUS1, Kern::Printf("<mst:SchdSlp"));
-	return( ESchedLoop );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDSLEEPSTACK_EXIT4, this, (TInt) ESchedLoop );
+	return ESchedLoop;
 	}
 inline TBool DMMCStack::SchedPreemptable()
 /**
 * Checks if the current session can be preempted
 */
 	{	// strictly in the following order
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDPREEMPTABLE_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:spe"));
 	if( (iStackState & KMMCStackStateJobChooser) ||
 		(iSessionP->iState & KMMCSessStateDoReSchedule) )
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT1, this, (TUint) ETrue );
+		return ETrue;
+	    }
 	if( (iSessionP->iBlockOn & KMMCBlockOnASSPFunction) )
-		return( EFalse );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT2, this, (TUint) EFalse );
+		return EFalse;
+	    }
 	TBool preemptDC = EFalse;
 	if (iSessionP->iBlockOn & KMMCBlockOnYielding)
 		{
 		{
 		// Added for SDIO Read/Wait and SDC support.  This condition
 		// is set at the variant, and determines whether commands may be
 		// issued during the data transfer period.
 		if(!(iSessionP->iState & KMMCSessStateAllowDirectCommands))
-			return( EFalse );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT3, this, (TUint) EFalse );
+			return EFalse;
+		    }
 		// We must consider the remaining blocking conditions
 		// before being sure that we can enable pre-emtion of this session
 		preemptDC = ETrue;
 		}
 	if( (iSessionP->iBlockOn & (KMMCBlockOnCardInUse | KMMCBlockOnNoRun)) )
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT4, this, (TUint) ETrue );
+		return ETrue;
+	    }
 	if( (iConfig.iModes & KMMCModeEnablePreemption) == 0 )
-		return( EFalse );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT5, this, (TUint) EFalse );
+		return EFalse;
+	    }
 	if( (iSessionP->iBlockOn & KMMCBlockOnGapTimersMask) &&
 		(iConfig.iModes & KMMCModePreemptInGaps) &&
 		(iSessionP->iState & KMMCSessStateSafeInGaps) )
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT6, this, (TUint) ETrue );
+		return ETrue;
+	    }
 	if( iSessionP->iBlockOn & KMMCBlockOnInterrupt )
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT7, this, (TUint) ETrue );
+		return ETrue;
+	    }
 	if(preemptDC)
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DDMMCSTACK_SCHEDPREEMPTABLE_EXIT8, this, (TUint) ETrue );
+		return ETrue;
+	    }
-	return( EFalse );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDPREEMPTABLE_EXIT9, this, (TUint) EFalse );
+	return EFalse;
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedSession()
 /**
 * Current context analyser. Returns Exit, Loop or ChooseJob.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDSESSION_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:ss"));
 	// If no current session selected then we need to choose one
 	if (iSessionP == NULL)
-		return(ESchedChooseJob);
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT1, this, (TInt) ESchedChooseJob );
+		return ESchedChooseJob;
+	    }
 	// Check any static blocking conditions on the current session and remove if possible
 	if (SchedResolveStatBlocks(iSessionP)==ESchedLoop)
-		return(ESchedLoop);
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT2, this, (TInt) ESchedLoop );
+		return ESchedLoop;
+	    }
 	// If current session is still blocked, see if we could pre-empt the session
 	if (iSessionP->iBlockOn)
 		{
 		if( SchedPreemptable() )
-			return(ESchedChooseJob);
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT3, this, (TInt) ESchedChooseJob );
-		return( ESchedExit );	// No preemption possible
+			return ESchedChooseJob;
+		    }
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT4, this, (TInt) ESchedExit );
+		return ESchedExit;	// No preemption possible
 		}
 	// If the current session has been marked to be 'un-scheduled' then we
 	// need to choose another session if ones available
 	if ( (iSessionP->iState & KMMCSessStateDoReSchedule) )
-		return( ESchedChooseJob );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT5, this, (TInt) ESchedChooseJob );
+		return ESchedChooseJob;
+	    }
 	// Check if this session requires to be run in DFC context - loop if necessary
 	if ( (iSessionP->iState & KMMCSessStateDoDFC) )
 		{
 		iSessionP->iState &= ~KMMCSessStateDoDFC;
 		if( SchedGetOnDFC()==ESchedLoop )
-			return( ESchedLoop );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT6, this, (TInt) ESchedLoop );
+			return ESchedLoop;
+		    }
 		}
 	// Now we actually execute the current session
 	if( iLockingSessionP != NULL )
 		{
 	iStackState &= ~KMMCStackStateReScheduled;
 	if( exitCode )
 		MarkComplete( iSessionP, (exitCode & ~KMMCErrBypass) );
-	return(ESchedLoop);
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDSESSION_EXIT7, this, (TInt) ESchedLoop );
+	return ESchedLoop;
 	}
 TBool DMMCStack::SchedYielding(DMMCSession* aSessP)
 /**
 * Check whether the scheduler should yield to another command
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_SCHEDYIELDING_ENTRY, this );
 	// Test whether a full loop through the sessions has occurred during a yield
 	if ((aSessP->iBlockOn & KMMCBlockOnYielding) && (iStackState & KMMCStackStateYielding))
 		{
 		// We've looped, now stop yielding
 		aSessP->iBlockOn &= ~KMMCBlockOnYielding;
 		iStackState &= ~KMMCStackStateYielding;
 		}
-	return(iStackState & KMMCStackStateYielding) != 0;
+	TBool ret = (iStackState & KMMCStackStateYielding) != 0;
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDYIELDING_EXIT, this, ret );
+	return ret;
 	}
 TBool DMMCStack::SchedAllowDirectCommands(DMMCSession* aSessP)
 /**
 * Check whether direct only commands can be run.
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_SCHEDALLOWDIRECTCOMMANDS_ENTRY, this );
 	TBool allowDirectCommands = EFalse;
 	// Test the remaining sessions to see if they have a DMA data transfer blockage which allow direct commands only
 	DMMCSession* testSessP = aSessP;
 	do
 			allowDirectCommands = ETrue;
 		testSessP = testSessP->iLinkP;
 		}
 	while((aSessP != testSessP) && (testSessP != NULL));
-	return(allowDirectCommands);
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDALLOWDIRECTCOMMANDS_EXIT, this, allowDirectCommands );
+	return allowDirectCommands;
 	}
 inline DMMCStack::TMMCStackSchedStateEnum DMMCStack::SchedChooseJob()
 /**
 * Find an unblocked job to run. Returns Exit or Loop.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_SCHEDCHOOSEJOB_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:scj"));
 	iStackState |= KMMCStackStateJobChooser;
 	SchedGrabEntries();
 	DMMCSession* sessP = NULL;
 	while( (sessP = iWorkSet) != NULL )
 		{
 		// first, remove all static blocking conditions
 		if( SchedResolveStatBlocks(sessP) )
-			return( ESchedLoop );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDCHOOSEJOB_EXIT1, this, (TInt) ESchedLoop );
+			return ESchedLoop;
+		    }
 		TBool scheduleSession = ETrue;
 		// Test whether we are yielding
 		if (SchedYielding(sessP) && (sessP->Command().iSpec.iCommandType != iYieldCommandType))
 			scheduleSession = EFalse;
 		if (scheduleSession)
 			{
 			iWorkSet.SetMarker();
 			SchedSetContext( sessP );
-			return( ESchedLoop );
+			OstTraceFunctionExitExt( DMMCSTACK_SCHEDCHOOSEJOB_EXIT2, this, (TInt) ESchedLoop );
+			return ESchedLoop;
 			}
 		iWorkSet++;
 		}
-	return( ESchedExit );
+	OstTraceFunctionExitExt( DMMCSTACK_SCHEDCHOOSEJOB_EXIT3, this, (TInt) ESchedExit );
+	return ESchedExit;
 	}
 void DMMCStack::StackDFC(TAny* aStackP)
 /**
 * This DFC is used to startup Stack Scheduler from the background.
 */
 	{
+	OstTraceFunctionEntry0( DMMCSTACK_STACKDFC_ENTRY );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sdf"));
 	DMMCStack* const stackP = static_cast<DMMCStack*>(aStackP);
 	stackP->Scheduler( stackP->iDFCRunning );
+	OstTraceFunctionExit0( DMMCSTACK_STACKDFC_EXIT );
 	}
 void DMMCStack::Scheduler(volatile TBool& aFlag)
 /**
 * This is the main function which controls, monitors and synchronises session execution.
 * It's divided into the entry function Scheduler() and the scheduling mechanism itself,
 * DoSchedule()
 */
 	{
+	OstTraceFunctionEntry0( DMMCSTACK_SCHEDULER_ENTRY );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sch"));
 	DISABLEPREEMPTION
 	aFlag = ETrue;
 		}
 	iStackState |= KMMCStackStateRunning;
 	RESTOREPREEMPTION
 	DoSchedule();
+	OstTraceFunctionExit0( DMMCSTACK_SCHEDULER_EXIT );
 	}
 void DMMCStack::DoSchedule()
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_DOSCHEDULE_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf(">mst:dos"));
 	for(;;)
 		{
 		for(;;)
 			iStackState &= ~KMMCStackStateRunning;
 			iDFCRunning = EFalse;
 			RESTOREPREEMPTION
 			__KTRACE_OPT(KPBUS1,Kern::Printf("<mst:dos"));
+			OstTraceFunctionExit1( DMMCSTACK_DOSCHEDULE_EXIT1, this );
 			return;
 			}
 		RESTOREPREEMPTION
 		}
 void DMMCStack::Add(DMMCSession* aSessP)
 /**
 * Adds session aSessP to the EntryQueue (asynchronous function)
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_ADD_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:Add %d",TUint(aSessP->iSessionID)));
 	DISABLEPREEMPTION
 	iEntryQueue.Add( aSessP );
 	aSessP->iState |= KMMCSessStateEngaged;
 	RESTOREPREEMPTION
 	Scheduler( iAttention );
+	OstTraceFunctionExit1( DMMCSTACK_ADD_EXIT, this );
 	}
 void DMMCStack::Abort(DMMCSession* aSessP)
 /**
 * Aborts a session
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_ABORT_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:abt"));
 	if( !aSessP->IsEngaged() )
+	    {
+		OstTraceFunctionExit1( DMMCSTACK_ABORT_EXIT1, this );
 		return;
+	    }
 	aSessP->iDoAbort = ETrue;
 	aSessP->iMachine.Abort();
 	Scheduler( iAbortReq );
+	OstTraceFunctionExit1( DMMCSTACK_ABORT_EXIT2, this );
 	}
 void DMMCStack::Stop(DMMCSession* aSessP)
 /**
 * Signals session to stop
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_STOP1_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:stp"));
 	if( !aSessP->IsEngaged() )
+	    {
+		OstTraceFunctionExit1( DMMCSTACK_STOP1_EXIT1, this );
 		return;
+	    }
 	aSessP->iDoStop = ETrue;
+	OstTraceFunctionExit1( DMMCSTACK_STOP1_EXIT2, this );
 	}
 EXPORT_C void DMMCStack::Block(DMMCSession* aSessP, TUint32 aFlag)
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_BLOCK_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:blk"));
 	if( !aSessP->IsEngaged() )
+	    {
+		OstTraceFunctionExit1( DMMCSTACK_BLOCK_EXIT1, this );
 		return;
+	    }
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:blk:[aFlag=%08x, iBlockOn=%08x]", aFlag, aSessP->iBlockOn));
+	OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_BLOCK, "aFlag=0x%08x; iBlockOn=0x%08x", aFlag, aSessP->iBlockOn );
 	(void)__e32_atomic_ior_ord32(&aSessP->iBlockOn, aFlag);
+	OstTraceFunctionExit1( DMMCSTACK_BLOCK_EXIT2, this );
 	}
 EXPORT_C void DMMCStack::UnBlock(DMMCSession* aSessP, TUint32 aFlag, TMMCErr anExitCode)
 /**
 * aFlag is a bitset of KMMCBlockOnXXX events that have occured.  If the stack's
 * session is waiting on all of these events, then it is scheduled.
 */
 	{
+	OstTraceExt4(TRACE_FLOW, DMMCSTACK_UNBLOCK_ENTRY , "DMMCStack::UnBlock;aSessP=%x;aFlag=%x;anExitCode=%d;this=%x", (TUint) aSessP, (TUint) aFlag, (TInt) anExitCode, (TUint) this);
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:ubl"));
 	if (aSessP != NULL)
 		{
 		__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:ubl:[aFlag=%08x, iBlockOn=%08x", aFlag, aSessP->iBlockOn));
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_UNBLOCK, "aFlag=0x%08x; iBlockOn=0x%08x", aFlag, aSessP->iBlockOn );
 		if( (aSessP->iBlockOn & aFlag) == 0 )
+		    {
+			OstTraceFunctionExit1( DMMCSTACK_UNBLOCK_EXIT1, this );
 			return;
+		    }
 		// Must be either in a DFC or have the KMMCSessStateDoDFC flag set
 		__ASSERT_DEBUG(
 			(aSessP->iState & KMMCSessStateDoDFC) != 0 ||
 			NKern::CurrentContext() != NKern::EInterrupt,
 		aSessP->iMachine.SetExitCode( anExitCode );
 		if( aSessP->iBlockOn == 0 )
 			Scheduler( iAttention );
 		}
+	OstTraceFunctionExit1( DMMCSTACK_UNBLOCK_EXIT2, this );
 	}
 void DMMCStack::UnlockStack(DMMCSession* aSessP)
 /**
 * Removes stack lock. Asynchronous function.
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_UNLOCKSTACK_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:ust"));
 	aSessP->iBrokenLock = EFalse;
 	if( aSessP == iLockingSessionP )
 		{
 		iLockingSessionP = NULL;
 		Scheduler( iAttention );
 		}
+	OstTraceFunctionExit1( DMMCSTACK_UNLOCKSTACK_EXIT1, this );
 	}
 EXPORT_C TInt DMMCStack::Stop(TMMCard* aCardP)
 /**
 * Completes all sessions operating with a specified card with KMMCErrAbort.
 * Returns either KErrNone or KErrServerBusy.
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_STOP2_ENTRY, this );
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:stp"));
 	DISABLEPREEMPTION
 	if( iStackState & KMMCStackStateRunning )
 		{
 		RESTOREPREEMPTION
-		return( KErrServerBusy );	// can not operate in foreground
+		return KErrServerBusy;	// can not operate in foreground
 		}
 	iStackState |= KMMCStackStateRunning;
 	RESTOREPREEMPTION
 		else
 			iReadyQueue++;
 	SchedGetOnDFC();
 	DoSchedule();
-	return( KErrNone );
+	OstTraceFunctionExitExt( DMMCSTACK_STOP2_EXIT, this, KErrNone );
+	return KErrNone;
 	}
 void DMMCStack::MarkComplete(DMMCSession* aSessP, TMMCErr anExitCode)
 /**
 * Marks session to be completed on the next scheduler pass.
 */
 	{
+	OstTraceExt3(TRACE_FLOW, DMMCSTACK_MARKCOMPLETE_ENTRY ,"DMMCStack::MarkComplete;aSessP=%x;anExitCode=%d;this=%x", (TUint) aSessP, (TInt) anExitCode, (TUint) this);
 	ASSERT_NOT_ISR_CONTEXT
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:mcp"));
 	aSessP->SynchBlock( KMMCBlockOnNoRun );
 	aSessP->iMMCExitCode = anExitCode;
 	aSessP->iDoComplete = ETrue;
 	iCompReq = ETrue;
+	OstTraceFunctionExit1( DMMCSTACK_MARKCOMPLETE_EXIT, this );
 	}
 //
 // DMMCStack:: --- Miscellaneous ---
 //
 EXPORT_C TUint32 DMMCStack::EffectiveModes(const TMMCStackConfig& aClientConfig)
 /**
 * Calculates effective client modes as real client modes merged with iMasterConfig modes
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_EFFECTIVEMODES_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:em"));
 	const TUint32 masterMode = (iMasterConfig.iModes & iMasterConfig.iUpdateMask) |
 								(KMMCModeDefault & ~iMasterConfig.iUpdateMask);
 							((masterMode & KMMCModeMasterOverrides) | ~KMMCModeMasterOverrides);
 	const TUint32 effectiveMode = (userMode & userMask) | (masterMode & ~userMask);
 	if( effectiveMode & KMMCModeEnableClientConfig )
-		return( effectiveMode );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_EFFECTIVEMODES_EXIT1, this, ( TUint )( effectiveMode ) );
+		return effectiveMode;
+	    }
 	else
-		return( (effectiveMode & KMMCModeClientOverrides) |
+	    {
-				(masterMode & ~(KMMCModeClientOverrides | KMMCModeClientMask)) );
+		TUint32 ret = (effectiveMode & KMMCModeClientOverrides) |
+				(masterMode & ~(KMMCModeClientOverrides | KMMCModeClientMask));
+		OstTraceFunctionExitExt( DMMCSTACK_EFFECTIVEMODES_EXIT2, this, ( TUint )( ret ) );
+		return ret;
+	    }
 	}
 void DMMCStack::MergeConfig(DMMCSession* aSessP)
 /**
 * Merges client and master configuration into iConfig
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_MERGECONFIG_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:mc"));
 	TMMCStackConfig& cC = aSessP->iConfig;
 	TMMCStackConfig& mC = iMasterConfig;
 	const TUint32 modes = EffectiveModes( cC );
 							: mC.iBusConfig.iDataTimeOut;
 	iConfig.iBusConfig.iBusyTimeOut = (modes & KMMCModeClientBusyTimeOut)
 							? cC.iBusConfig.iBusyTimeOut
 							: mC.iBusConfig.iBusyTimeOut;
+	OstTraceFunctionExit1( DMMCSTACK_MERGECONFIG_EXIT, this );
 	}
 TBool DMMCStack::StaticBlocks()
 /**
 * This function realises the potential blocking conditions of the current session.
 * Returns ETrue if the session has to be stopped right now
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_STATICBLOCKS_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:stb"));
 	if( iSessionP->iDoStop )
 		{
 		MarkComplete( iSessionP, KMMCErrAbort );
-		return( ETrue );
+		OstTraceFunctionExitExt( DMMCSTACK_STATICBLOCKS_EXIT1, this, (TUint) ETrue );
+		return ETrue;
 		}
 	if( !iDFCRunning && (iSessionP->iState & KMMCSessStateDoDFC) )
-		return( ETrue );
+	    {
+		OstTraceFunctionExitExt( DMMCSTACK_STATICBLOCKS_EXIT2, this, (TUint) ETrue );
-	return( (iSessionP->iState & KMMCSessStateDoReSchedule) != 0 );
+		return ETrue;
+	    }
+	TBool ret = (iSessionP->iState & KMMCSessStateDoReSchedule) != 0;
+	OstTraceFunctionExitExt( DMMCSTACK_STATICBLOCKS_EXIT3, this, ret );
+	return ret;
 	}
 EXPORT_C TBool DMMCStack::CardDetect(TUint /*aCardNumber*/)
 /**
 void DMMCStack::StackSessionCBST(TAny* aStackP)
 /**
 * Stack Session completion routine.
 */
 	{
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sscbs"));
 	static_cast<DMMCStack *>(aStackP)->StackSessionCB();
 	}
 TInt DMMCStack::StackSessionCB()
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_STACKSESSIONCB_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:sscb "));
 	if (iStackState & KMMCStackStateSleepinProgress)
 		{
 		// Sleep completed update stack state
 		iStackState &= ~KMMCStackStateSleepinProgress;
-		return( 0 );
+		OstTraceFunctionExit1( DMMCSTACK_STACKSESSIONCB_EXIT1, this );
+		return 0;
 		}
 	TMMCErr mmcError = iStackSession->MMCExitCode();
 	iStackState &= ~KMMCStackStateInitInProgress;
 				errCode = iAutoUnlockSession.Engage();
 				if(errCode == KErrNone)
 					{
 					// don't complete power up request yet
 					//  - This will be done in DMMCStack::AutoUnlockCB()
+					OstTraceFunctionExit1( DMMCSTACK_STACKSESSIONCB_EXIT2, this );
 					return 0;
 					}
 				}
 			}	// else ( !iCardArray->CardsPresent() )
 		}
 		iSocket->PowerUpSequenceComplete(errCode);
 		iStackState |= KMMCStackStateRunning;
 		}
-	return( 0 );
+	OstTraceFunctionExit1( DMMCSTACK_STACKSESSIONCB_EXIT3, this );
+	return 0;
 	}
 void DMMCStack::AutoUnlockCBST(TAny *aStackP)
 	{
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:aucbs"));
 	}
 TInt DMMCStack::AutoUnlockCB()
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_AUTOUNLOCKCB_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf("=mst:aucb"));
 	// This is the session end callback for iAutoUnlockSession,
 	// called at the end of the power up and initialisation process.
 	if (epocErr != KErrNone)
 		iStackState &= ~KMMCStackStateRunning;
 	iSocket->PowerUpSequenceComplete(epocErr);
 	iStackState |= KMMCStackStateRunning;
+	OstTraceFunctionExit1( DMMCSTACK_AUTOUNLOCKCB_EXIT, this );
 	return 0;
 	}
 inline TMMCErr DMMCStack::AttachCardSM()
 			EStAttStatus,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_ATTACHCARDSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ATTACHCARDSM2, "EStBegin" );
 		if( s.iCardP == NULL )
-			return( KMMCErrNoCard );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_ATTACHCARDSM_EXIT1, this, (TInt) KMMCErrNoCard );
+			return KMMCErrNoCard;
+		    }
 		if( s.iCardP->iUsingSessionP != NULL && s.iCardP->iUsingSessionP != &s )
 			{
 			s.SynchBlock( KMMCBlockOnCardInUse );
 			SMF_WAIT
 			}
 		if( s.iCardP->IsPresent() && s.iCardP->iCID == s.iCID )
 			s.iCardP->iUsingSessionP = &s;
 		else
-			return( KMMCErrNoCard );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_ATTACHCARDSM_EXIT2, this, (TInt) KMMCErrNoCard );
+			return KMMCErrNoCard;
+		    }
 		s.iConfig.SetMode( KMMCModeCardControlled );	// for future context switching
 		iConfig.SetMode( KMMCModeCardControlled );		// for this context
 		// read card status if there are sticky bits in it
 		m.SetTraps( KMMCErrBasic );		// to restore command stack position to its original level
 		SMF_INVOKES( ExecCommandSMST, EStAttStatus )
 	SMF_STATE(EStAttStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ATTACHCARDSM3, "EStAttStatus" );
 		s.PopCommandStack();
+		OstTraceFunctionExitExt( DMMCSTACK_ATTACHCARDSM_EXIT3, this, (TInt) err );
 		SMF_RETURN( err )
 	SMF_END
 	}
 			};
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:InitStackSM"));
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMINITSTACKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMINITSTACKSM2, "EStBegin" );
 		m.SetTraps( KMMCErrAll );	// to prevent this macro from infinite restarts via iInitialise
 		SMF_INVOKES( CIMUpdateAcqSMST, EStInitDone )
 	SMF_STATE(EStInitDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMINITSTACKSM3, "EStInitDone" );
 		s.iState &= ~KMMCSessStateInProgress;	// now we won't be restarted
 		SchedGetOnDFC();						// StackSessionCB must be on DFC
+		OstTraceFunctionExitExt( DMMCSTACK_CIMINITSTACKSM_EXIT, this, (TInt) err );
 		SMF_RETURN( err )						// _?_ power cycles can be performed here if error
 	SMF_END
 	}
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:UpdAcqSM"));
 		DMMCSession& s=Session();
 		DMMCPsu* psu=(DMMCPsu*)iSocket->iVcc;
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM2, "EStBegin" );
 		// This macro works naked and must not be preempted
 		iConfig.RemoveMode( KMMCModeEnablePreemption | KMMCModeCardControlled );
 		// Ensure DFC is running before and after powering up
 		if( SchedGetOnDFC() )	// Such a direct synchronisation with Scheduler() can only
 			SMF_WAIT			// be used in this macro
 		psu->SetVoltage(iCurrentOpRange);
 		SMF_INVOKES( DoPowerUpSMST, EStPoweredUp )
 	SMF_STATE(EStPoweredUp)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM3, "EStPoweredUp" );
 		// Switch on the bus clock in identification mode
 		SetBusConfigDefaults(iMasterConfig.iBusConfig, KMMCBusClockFOD);
 		DoSetClock(KMMCBusClockFOD);
 		// Make sure controller is in 1-bit bus width mode
 		iConfig.RemoveMode( KMMCModeEnablePreemption | KMMCModeCardControlled );
 		SMF_INVOKES( InitClockOnSMST, EStClockOn )	// Feed init clock to the bus
 	SMF_STATE(EStClockOn)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM4, "EStClockOn" );
 		// Check if there are any cards present in the stack
 		if (!HasCardsPresent())
 			SMF_GOTOS( EStCheckStack )
 		if( !InitStackInProgress() )
 			iInitContext++;				// Pass number must never be zero
 		s.iInitContext = iInitContext;	// this session is always in a proper context
 	SMF_STATE(EStStartInterrogation)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM5, "EStStartInterrogation" );
 		// NB: RCAs are not unlocked here. They will be unlocked one by one during the update of card info array.
 		SMF_INVOKES( AcquireStackSMST, EStCheckStack )
 	SMF_STATE(EStCheckStack)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM6, "EStCheckStack" );
 		// Check that all known cards are still present by issuing select/deselect
 		SMF_INVOKES( CheckStackSMST, EStCardCap )
 	SMF_STATE(EStCardCap)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM7, "EStCardCap" );
 		// Call a licencee-specific state machine to allow card capabilities to be modified.
 		SMF_INVOKES( ModifyCardCapabilitySMST, EStIssueDSR )
 	SMF_STATE(EStIssueDSR)
 		// If the bus is not multiplexed (ie - MMC stack), then the max clock is set to
 		// the lowest common denominator of all cards in the stack.  Otherwise (in the case
 		// of a multiplexed bus such as SD), the highest clock is returned and the clock
 		// rate is changed when a new card is selected.
 		//
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM8, "EStIssueDSR" );
 		TUint maxClk;
 		iCardArray->UpdateAcquisitions(&maxClk);
 		SetBusConfigDefaults( iMasterConfig.iBusConfig, maxClk );
 		DoSetClock(maxClk);
 		// switch to normal iConfig clock mode
 		InitClockOff();
 	SMF_STATE(EStFinishUp)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMUPDATEACQSM9, "EStFinishUp" );
 		s.iState &= ~(KMMCSessStateInProgress | KMMCSessStateCritical);
 		// Update/Init stack has been completed.
 	SMF_END
 			EStEnd
 			};
 	DMMCSession& s = Session();
 	TBool initSingleCard = (s.CardP() == NULL) ? (TBool)EFalse : (TBool)ETrue;
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM2, "EStBegin" );
 		if(initSingleCard)
 			{
 			iSelectedCardIndex = iCxCardCount;
 			TMMCard* cardP = iCardArray->CardP(iSelectedCardIndex);
 		// ...fall through...
 	SMF_STATE(EStTestNextCard)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM3, "EStTestNextCard" );
 		// any more cards ?
 		if (++iSelectedCardIndex >= iCxCardCount)
 			SMF_GOTOS(EStNoMoreCards);
 		// if no card in this slot, try next one
 		if(cardP->IsLocked())
 			SMF_GOTOS(EStTestNextCard);
 	SMF_STATE(EStGetExtendedCSD)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM4, "EStGetExtendedCSD" );
 		// Get the Extended CSD if this is an MMC version 4 card
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), SpecVers() %u", s.CardP()->CSD().SpecVers()));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM5, "SpecVers()=%u", s.CardP()->CSD().SpecVers() );
 		// clear the Extended CSD contents in case this is a pre-version 4 card or the read fails.
 		memset(s.CardP()->iExtendedCSD.Ptr(), 0, KMMCExtendedCSDLength);
 		if (s.CardP()->CSD().SpecVers() < 4)
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), Sending ECmdSendExtendedCSD"));
 		SMF_INVOKES(CIMReadWriteBlocksSMST, EStGotExtendedCSD)
 	SMF_STATE(EStGotExtendedCSD)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM6, "EStGotExtendedCSD" );
 		if (err != KMMCErrNone)
 			{
 			SMF_GOTOS(EStExit);
 			}
 		// Call a licencee-specific state machine to allow the Extended CSD register to be modified.
 		SMF_INVOKES( ModifyCardCapabilitySMST, EStGotModifiedExtendedCSD )
 	SMF_STATE(EStGotModifiedExtendedCSD)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM7, "EStGotExtendedCSD" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("Extended CSD"));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("CSDStructureVer:            %u", s.CardP()->ExtendedCSD().CSDStructureVer()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("ExtendedCSDRev:             %u", s.CardP()->ExtendedCSD().ExtendedCSDRev()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("-------------------------------"));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("SupportedCmdSet:            %u", s.CardP()->ExtendedCSD().SupportedCmdSet()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("SleepCurrentVccQ:           %u", s.CardP()->ExtendedCSD().SleepCurrentVccQ()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("SleepAwakeTimeout:          %u", s.CardP()->ExtendedCSD().SleepAwakeTimeout()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("BootConfig:                 %u", s.CardP()->ExtendedCSD().BootConfig()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("BootBusWidth:               %u", s.CardP()->ExtendedCSD().BootBusWidth()));
 		__KTRACE_OPT(KPBUS1, Kern::Printf("EraseGroupDef:              %u", s.CardP()->ExtendedCSD().EraseGroupDef()));
+		OstTraceDefExt3( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM8, "CSDStructureVer=%u; ExtendedCSDRev=%u; SupportedCmdSet=%u", s.CardP()->ExtendedCSD().CSDStructureVer(), s.CardP()->ExtendedCSD().ExtendedCSDRev(), s.CardP()->ExtendedCSD().SupportedCmdSet() );
+		OstTraceDefExt4( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM9, "PowerClass26Mhz360V=0x%02x; PowerClass52Mhz360V=0x%02x; PowerClass26Mhz195V=0x%02x; PowerClass52Mhz195V=0x%02x", s.CardP()->ExtendedCSD().PowerClass26Mhz360V(), s.CardP()->ExtendedCSD().PowerClass52Mhz360V(), s.CardP()->ExtendedCSD().PowerClass26Mhz195V(), s.CardP()->ExtendedCSD().PowerClass52Mhz195V() );
+		OstTraceDefExt5( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM10, "CardType=%u; CmdSet=%u; CmdSetRev=%u; PowerClass=%u; HighSpeedTiming=%u", s.CardP()->ExtendedCSD().CardType(), s.CardP()->ExtendedCSD().CmdSet(), s.CardP()->ExtendedCSD().CmdSetRev(), s.CardP()->ExtendedCSD().PowerClass(), s.CardP()->ExtendedCSD().HighSpeedTiming() );
+		OstTraceDefExt5( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM11, "HighCapacityEraseGroupSize=%u; AccessSize=%u; BootInfo=%u; BootSizeMultiple=%u; EraseTimeoutMultiple=%u", s.CardP()->ExtendedCSD().HighCapacityEraseGroupSize(), s.CardP()->ExtendedCSD().AccessSize(), s.CardP()->ExtendedCSD().BootInfo(), s.CardP()->ExtendedCSD().BootSizeMultiple(), s.CardP()->ExtendedCSD().EraseTimeoutMultiple() );
+		OstTraceDefExt5( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM12, "ReliableWriteSector=%u; HighCapWriteProtGroupSize=%u; SleepCurrentVcc=%u; SleepCurrentVccQ=%u; SleepAwakeTimeout=%u", s.CardP()->ExtendedCSD().ReliableWriteSector(), s.CardP()->ExtendedCSD().HighCapacityWriteProtectGroupSize(), s.CardP()->ExtendedCSD().SleepCurrentVcc(), s.CardP()->ExtendedCSD().SleepCurrentVccQ(), s.CardP()->ExtendedCSD().SleepAwakeTimeout() );
+		OstTraceDefExt3( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_INITSTACKAFTERUNLOCKSM13, "BootConfig=%u; BootBusWidth=%u; EraseGroupDef=%u", s.CardP()->ExtendedCSD().BootConfig(), s.CardP()->ExtendedCSD().BootBusWidth(), s.CardP()->ExtendedCSD().EraseGroupDef() );
 		if (s.CardP()->ExtendedCSD().ExtendedCSDRev() >= 3)
 			{
 			if (!(s.CardP()->ExtendedCSD().EraseGroupDef()) && s.CardP()->ExtendedCSD().HighCapacityEraseGroupSize())
 				{
 				// Need to ensure that media is using correct erase group sizes.
 					TExtendedCSD::EEraseGroupDefIndex,
 					TExtendedCSD::EEraseGrpDefEnableHighCapSizes,
 					0);
 				__KTRACE_OPT(KPBUS1, Kern::Printf(">Writing to EXT_CSD (EEraseGroupDefIndex), arg %08X", (TUint32) arg));
+				OstTrace1( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM14, "Writing to EXT_CSD (EEraseGroupDefIndex); arg=0x%08x", (TUint32) arg );
 				s.FillCommandDesc(ECmdSwitch, arg);
 				SMF_INVOKES(ExecSwitchCommandST, EStEraseGroupDefSet)
 				}
 			}
 		SMF_GOTOS(EStDetermineBusWidthAndClock)
 	SMF_STATE(EStEraseGroupDefSet)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM15, "EStEraseGroupDefSet" );
 		if (err == KMMCErrNone)
 			{
 			// EEraseGroupDef has been updated succussfully,
 			// update the Extended CSD to reflect this
 			memset( s.CardP()->iExtendedCSD.Ptr()+TExtendedCSD::EEraseGroupDefIndex, TExtendedCSD::EEraseGrpDefEnableHighCapSizes, 1);
 			}
 	SMF_STATE(EStDetermineBusWidthAndClock)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM16, "EStDetermineBusWidthAndClock" );
 		SMF_INVOKES( DetermineBusWidthAndClockSMST, EStGotBusWidthAndClock )
 SMF_STATE(EStGotBusWidthAndClock)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM17, "EStGotBusWidthAndClock" );
 		SMF_NEXTS(initSingleCard ? EStExit : EStTestNextCard)
 		if(iMultiplexedBus || iCardArray->CardsPresent() == 1)
 			{
 			SMF_CALL( ConfigureHighSpeedSMST )
 		SMF_GOTONEXTS
 	SMF_STATE(EStNoMoreCards)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM18, "EStNoMoreCards" );
 	SMF_STATE(EStExit)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_INITSTACKAFTERUNLOCKSM19, "EStExit" );
 		m.ResetTraps();
 	SMF_END
 	}
 			EStEnd
 			};
 	DMMCSession& s = Session();
 	TMMCard* cardP = iCardArray->CardP(iSelectedCardIndex);
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM2, "EStBegin" );
 		// Trap Switch errors & no-response errors
 		m.SetTraps(KMMCErrResponseTimeOut | KMMCErrStatus);
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), iCxCardCount %u", iCxCardCount));
 	SMF_STATE(EStWritePowerClass)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM3, "EStWritePowerClass" );
 		// Check the card type is valid
 		// The only currently valid values for this field are 0x01 or 0x03
 		TUint cardType = cardP->iExtendedCSD.CardType();
 		if (cardType != (TExtendedCSD::EHighSpeedCard26Mhz) &&
 			cardType != (TExtendedCSD::EHighSpeedCard26Mhz | TExtendedCSD::EHighSpeedCard52Mhz))
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("Unsupported card type %u", cardType));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM4, "Unsupported card type=%u", cardType );
 			SMF_GOTOS(EStExit);
 			}
 		// determine the optimum bus width & clock speed which match the power constraints
 		TUint powerClass;
 				TExtendedCSD::EPowerClassIndex,
 				powerClass,
 				0);
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), Writing to EXT_CSD (EPowerClass), arg %08X", (TUint32) arg));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM5, "Writing to EXT_CSD (EPowerClass); arg=0x%08x", (TUint32) arg );
 			s.FillCommandDesc(ECmdSwitch, arg);
 			SMF_INVOKES(ExecSwitchCommandST, EStStartBusTest)
 			}
 	SMF_STATE(EStStartBusTest)
+OstTrace0( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM6, "EStStartBusTest" );
 		if (err != KMMCErrNone)
 			{
 			SMF_GOTOS(EStExit);
 			}
 		// We have determined the capabilities of the host and card.
 		//  - Before switching to the required bus width, perform the BUSTEST sequence
 		SMF_INVOKES(ExecBusTestSMST, EStExit);
 	SMF_STATE(EStExit)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCKSM7, "EStExit" );
 		m.ResetTraps();
 	SMF_END
 	}
 			EStEnd
 			};
 	DMMCSession& s = Session();
 	TMMCard* cardP = iCardArray->CardP(iSelectedCardIndex);
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+OstTrace0( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM2, "EStBegin" );
 		// Trap Switch errors & no-response errors
 		m.SetTraps(KMMCErrResponseTimeOut | KMMCErrStatus);
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), iCxCardCount %u", iCxCardCount));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM3, "iCxCardCount=%d", iCxCardCount );
 		cardP->SetHighSpeedClock(0);
 		// Check the card type is valid
 		// The only currently valid values for this field are 0x01 or 0x03
 		TUint cardType = cardP->iExtendedCSD.CardType();
 		if (cardType != (TExtendedCSD::EHighSpeedCard26Mhz) &&
 			cardType != (TExtendedCSD::EHighSpeedCard26Mhz | TExtendedCSD::EHighSpeedCard52Mhz))
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("Unsupported card type %u", cardType));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM4, "Unsupported card type=%u", cardType );
 			SMF_GOTOS(EStExit);
 			}
 		// If the bus width is 4 or 8, send SWITCH cmd and write the BUS_WIDTH byte of the EXT_CSD register
 				TExtendedCSD::EBusWidthModeIndex,
 				(iBusWidthAndClock & E4BitMask) ? TExtendedCSD::EExtCsdBusWidth4 : TExtendedCSD::EExtCsdBusWidth8,
 				0);
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), Writing to EXT_CSD (EBusWidthMode), arg %08X", (TUint32) arg));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM5, "Writing to EXT_CSD (EBusWidthMode); arg=0x%x", (TUint32) arg );
 			s.FillCommandDesc(ECmdSwitch, arg);
 			SMF_INVOKES(ExecSwitchCommandST, EStConfigureBusWidth)
 			}
 	SMF_STATE(EStConfigureBusWidth)
+OstTrace0( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM6, "EStConfigureBusWidth" );
 		if (err != KMMCErrNone)
 			{
 			SMF_GOTOS(EStExit);
 			}
 			DoSetBusWidth(EBusWidth8);
 			}
 		// fall through to next state
 	SMF_STATE(EStWriteHsTiming)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM7, "EStWriteHsTiming" );
 		if (iBusWidthAndClock == E1Bit20Mhz)
 			SMF_GOTOS(EStExit);
 		TMMCArgument arg = TExtendedCSD::GetWriteArg(
 			TExtendedCSD::EWriteByte,
 			TExtendedCSD::EHighSpeedInterfaceTimingIndex,
 			1,	// turn on high speed (26 or 52 Mhz, depending on the card type)
 			0);
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ConfigureHighSpeed(), Writing to EXT_CSD (EHighSpeedInterfaceTiming), arg %08X", (TUint32) arg));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM8, "Writing to EXT_CSD (EHighSpeedInterfaceTiming); arg=0x%x", (TUint32) arg );
 		s.FillCommandDesc(ECmdSwitch, arg);
 		SMF_INVOKES(ExecSwitchCommandST, EStConfigureClock)
 	SMF_STATE(EStConfigureClock)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM9, "EStConfigureClock" );
 		if (err != KMMCErrNone)
 			{
 			DoSetBusWidth(EBusWidth1);
 			SMF_GOTOS(EStExit);
 			}
 			MHZ_TO_KHZ(((iBusWidthAndClock & E52MhzMask) ?
 			            TMMCMachineInfoV4::EClockSpeed52Mhz:
 			            TMMCMachineInfoV4::EClockSpeed26Mhz)));
 	SMF_STATE(EStExit)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CONFIGUREHIGHSPEEDSM10, "EStExit" );
 		m.ResetTraps();
 	SMF_END
 	}
 			EStGetStatus,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECSWITCHCOMMAND1, "Current session=0x%x", &s );
 	SMF_BEGIN
-		SMF_INVOKES(ExecCommandSMST, EStSendStatus)
+	OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSWITCHCOMMAND2, "EStBegin" );
+	SMF_INVOKES(ExecCommandSMST, EStSendStatus)
 	SMF_STATE(EStSendStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSWITCHCOMMAND3, "EStSendStatus" );
 		s.FillCommandDesc(ECmdSendStatus, 0);
 		SMF_INVOKES(ExecCommandSMST, EStGetStatus)
 	SMF_STATE(EStGetStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSWITCHCOMMAND4, "EStGetStatus" );
 		const TMMCStatus st(s.ResponseP());
 		const TMMCardStateEnum st1 = st.State();
 		if (st1 == ECardStatePrg)
 			{
 			EStDone,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM2, "EStBegin" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ExecSleepCommandSM()"));
 		iAutoUnlockIndex = -1;
 		// drop through....
 	SMF_STATE(EStIndexNxtCard)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM3, "EStIndexNxtCard" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">EStIndexNxtCard"));
 		// the cycle is finished when iAutoUnlockIndex == KMaxMultiMediaCardsPerStack
 		if(iAutoUnlockIndex >= TInt(KMaxMMCardsPerStack))
 			{
 			SMF_GOTOS(EStUpdateStackState);
 			// don't increment iAutoUnlockIndex in continuation loop
 			if (useIndex)
 				{
 				__KTRACE_OPT(KPBUS1, Kern::Printf(">Card[%d]: is v4.3 device",iAutoUnlockIndex));
+				OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM4, "Card[%d]: is v4.3+ device", iAutoUnlockIndex );
 				break;
 				}
 			}
 		if (!useIndex)
 		// CMD5 is an AC command, ExecCommandSMST will automatically issue a deselect
 		SMF_INVOKES(ExecCommandSMST, EStSleepAwakeIssued)
 	SMF_STATE(EStSleepAwakeIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM5, "EStSleepAwakeIssued" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">EStSleepAwakeIssued!"));
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 		if(status.State() == ECardStateStby || status.State() == ECardStateSlp)
 			{
 			// R1b is issued before Sleep state is achieved and
 			// will therefore return the previous state which was Standby
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">Card[%d]: SLEEP",iAutoUnlockIndex));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM6, "Card[%d]: SLEEP", iAutoUnlockIndex );
 			// Ensure card status is ECardStateSlp
 			s.CardP()->iStatus.UpdateState(ECardStateSlp);
 			// Update Stack state to indicate media is sleep mode
 			iStackState |= KMMCStackStateSleep;
 			}
 		else
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">Card[%d]: UNKNOWN",iAutoUnlockIndex));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM7, "Card[%d]: UNKNOWN", iAutoUnlockIndex );
 			return (KMMCErrStatus);
 			}
 		SMF_GOTOS(EStIndexNxtCard)
 	SMF_STATE(EStUpdateStackState)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM8, "EStUpdateStackState" );
 		if (iStackState & KMMCStackStateSleep)
 			{
 			// Media has been transitioned to sleep state
 			iStackState &= ~KMMCStackStateSleep;
 			// No media transitioned to sleep state or media was already in sleep state,
 			// nothing to do...
 	SMF_STATE(EStDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECSLEEPCOMMANDSM9, "EStDone" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("<ExecSleepCommandSM()"));
 	SMF_END
 	}
 			EStDone,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM2, "EStBegin" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">ExecAwakeCommandSM()"));
 		// Call PSL to ensure VccQ is powered up before continuing
 		SMF_INVOKES( DoWakeUpSMST, EStPoweredUp )
 	SMF_STATE(EStPoweredUp)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM3, "EStPoweredUp" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("VccQ Powered Up"));
 		//Issue CMD5 to awaken media
 		s.PushCommandStack();
 		s.FillCommandDesc(ECmdSleepAwake);
 		SMF_INVOKES(IssueCommandCheckResponseSMST, EStAwakeIssued)
 	SMF_STATE(EStAwakeIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM4, "EStAwakeIssued" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf(">>EStAwakeIssued!"));
 		TMMCStatus status(s.ResponseP());
 		if(status.State() == ECardStateStby || status.State() == ECardStateSlp)
 			{
 			// R1b is issued before Standby state is achieved and
 			// will therefore return the previous state which was Sleep
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">Card[%d]: STANDBY",iAutoUnlockIndex));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM5, "Card[%d]: STANDBY", iAutoUnlockIndex );
 			s.CardP()->iStatus.UpdateState(ECardStateStby);
 			}
 		else
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf(">Card[%d]: UNKNOWN",iAutoUnlockIndex));
-			return (KMMCErrStatus);
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM6, "Card[%d]: UNKNOWN", iAutoUnlockIndex );
+			OstTraceFunctionExitExt( DMMCSTACK_EXECAWAKECOMMANDSM_EXIT, this, (TInt) KMMCErrStatus );
+			return KMMCErrStatus;
 			}
 		s.PopCommandStack();
 	SMF_STATE(EStDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECAWAKECOMMANDSM7, "EStDone" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("<ExecAwakeCommandSM()"));
 	SMF_END
 	}
 	const TMMCard& aCard,
 	TBool aLowVoltage,
 	TUint& aPowerClass,
 	TBusWidthAndClock& aBusWidthAndClock)
 	{
+	OstTraceExt2(TRACE_FLOW, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCK_ENTRY, "DMMCStack::DetermineBusWidthAndClock;aLowVoltage=%d;this=%x", (TInt) aLowVoltage, (TUint) this);
 	// Set default return values - in case power constraints aren't matched
 	aPowerClass = 0;
 	aBusWidthAndClock = E1Bit20Mhz;
 	// NB If the PSL doesn not support TMMCMachineInfoV4, return
 	TMMCMachineInfoV4 machineInfo;
 	TMMCMachineInfoV4Pckg machineInfoPckg(machineInfo);
 	MachineInfo(machineInfoPckg);
 	if (machineInfo.iVersion < TMMCMachineInfoV4::EVersion4)
+	    {
+		OstTraceFunctionExit1( DMMCSTACK_DETERMINEBUSWIDTHANDCLOCK_EXIT1, this );
 		return;
+	    }
 	TBusWidth maxBusWidth = machineInfo.iMaxBusWidth;
 	TInt maxClockSpeedInMhz = machineInfo.iMaxClockSpeedInMhz;
 	TUint32 controllerWidthAndClock = E1Bit20Mhz;
 		aBusWidthAndClock = TBusWidthAndClock(targetWidthAndClock);
 		break;
 		}
 	__KTRACE_OPT(KPBUS1, Kern::Printf("aPowerClass %u, targetWidthAndClock = %08X", aPowerClass, aBusWidthAndClock));
+	OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_DETERMINEBUSWIDTHANDCLOCK, "aPowerClass=%u; targetWidthAndClock=0x%08x", aPowerClass, (TUint) aBusWidthAndClock );
+	OstTraceFunctionExit1( DMMCSTACK_DETERMINEBUSWIDTHANDCLOCK_EXIT2, this );
 	}
 TUint DMMCStack::GetPowerClass(const TMMCard& aCard, TBusWidthAndClock aWidthAndClock, TBool aLowVoltage)
 	{
+	OstTraceExt3(TRACE_FLOW, DMMCSTACK_GETPOWERCLASS_ENTRY, "DMMCStack::GetPowerClass;aWidthAndClock=%d;aLowVoltage=%d;this=%x", (TInt) aWidthAndClock, (TInt) aLowVoltage, (TUint) this);
 	// The power class for 4 bit bus configurations is in the low nibble,
 	// The power class for 8 bit bus configurations is in the high nibble,
 	#define LO_NIBBLE(val) (val & 0x0F)
 	#define HI_NIBBLE(val) ((val >> 4) & 0x0F)
 				powerClass = 0;
 				break;
 			}
 		}
+		OstTraceFunctionExitExt( DMMCSTACK_GETPOWERCLASS_EXIT, this, powerClass );
 		return powerClass;
 	}
 //
 // Execute the BUSTEST procedure for a given bus width
 		EStExit,
 		EStEnd
 		};
 	DMMCSession& s = Session();
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
 		//
 		// Start the BUSTEST sequence at the maximum supported by the PSL
 		//  - iSpare[0] keeps track of the current bus width
 		//
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM2, "EStBegin" );
 		if (iBusWidthAndClock & E8BitMask)
 			{
 			iSpare[0] = EBusWidth8;
 			__KTRACE_OPT(KPBUS1, Kern::Printf("...Hardware supports 8-bit bus"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM3, "Hardware supports 8-bit bus" );
 			}
 		else if(iBusWidthAndClock & E4BitMask)
 			{
 			iSpare[0] = EBusWidth4;
 			__KTRACE_OPT(KPBUS1, Kern::Printf("...Hardware supports 4-bit bus"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM4, "Hardware supports 4-bit bus" );
 			}
 		else
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("...Hardware supports 1-bit bus"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM5, "Hardware supports 1-bit bus" );
 			iSpare[0] = EBusWidth1;
 			}
 		// remove KMMCModeCardControlled so that IssueCommandCheckResponseSMST doesn't try to
 		// override the bus width & clock rate using the card settings
 	SMF_STATE(EstSendBusTest_W)
 		//
 		// Issue the BUSTEST_W command
 		//
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM6, "EStSendBusTest_W" );
 		TInt length = 2;
 		switch(iSpare[0])
 			{
 			case EBusWidth8:
 				// Set the host to 8-bit mode
 				__KTRACE_OPT(KPBUS1, Kern::Printf("BUSTEST : EBusWidth8"));
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM7, "BUSTEST : EBusWidth8" );
 				DoSetBusWidth(EBusWidth8);
 				iPSLBuf[0] = 0x55;
 				iPSLBuf[1] = 0xaa;
 				break;
 			case EBusWidth4:
 				// Set the host to 4-bit mode
 				__KTRACE_OPT(KPBUS1, Kern::Printf("BUSTEST : EBusWidth4"));
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM8, "BUSTEST : EBusWidth4" );
 				DoSetBusWidth(EBusWidth4);
 				iPSLBuf[0] = 0x5a;
 				iPSLBuf[1] = 0x00;
 				break;
 			case EBusWidth1:
 			default:
 				// Set the host to 1-bit mode
 				__KTRACE_OPT(KPBUS1, Kern::Printf("BUSTEST : EBusWidth1"));
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM9, "BUSTEST : EBusWidth1" );
 				DoSetBusWidth(EBusWidth1);
 				iPSLBuf[0] = 0x40;
 				iPSLBuf[1] = 0x00;
 				break;
 			}
 		// Issue BUSTEST_W
 		__KTRACE_OPT(KPBUS1, Kern::Printf("...Issue BUSTEST_W [%02x:%02x]", iPSLBuf[1], iPSLBuf[0]));
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM10, "Issue BUSTEST_W [%02x:%02x]", (TUint) iPSLBuf[1], (TUint) iPSLBuf[0] );
 		m.SetTraps(KMMCErrDataCRC); // CRC check is optional for BUSTEST
 		s.FillCommandDesc(ECmdBustest_W);
 		s.FillCommandArgs(0, length, &iPSLBuf[0], length);
 	SMF_STATE(EstSendBusTest_R)
 		//
 		// Issue the BUSTEST_R command
 		//
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM11, "EStSendBusTest_R" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("...got BUSTEST_W response : %02x", err));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM12, "Got BUSTEST_W response=0x%02x", err );
 		if(err == KMMCErrNone || err == KMMCErrDataCRC)
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("...sending BUSTEST_R"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM13, "Sending BUSTEST_R" );
 			iPSLBuf[0] = 0;
 			iPSLBuf[1] = 0;
 			s.FillCommandDesc(ECmdBustest_R);
 			s.FillCommandArgs(0, 2, &iPSLBuf[0], 2);
 			SMF_INVOKES(IssueCommandCheckResponseSMST, EstGotBusTest_R)
 			}
 		else
 			{
+			OstTraceFunctionExitExt( DMMCSTACK_EXECBUSTESTSM_EXIT, this, (TInt) KMMCErrNotSupported );
 			SMF_RETURN(KMMCErrNotSupported);
 			}
 	SMF_STATE(EstGotBusTest_R)
 		//
 		// Validate the BUSTEST_R data with that issued by BUSTEST_W
 		//
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM14, "EStGotBusTest_R" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("...got BUSTEST_R response [%02x:%02x] : err(%02x)", iPSLBuf[1], iPSLBuf[0], err));
+		OstTraceExt3( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM15, "Got BUSTEST_R response [%02x:%02x]; err(%x)", (TUint) iPSLBuf[1], (TUint) iPSLBuf[0], (TUint) err );
 		TBool retry = EFalse;
 		TBool is52MHzSupported = (iBusWidthAndClock & E52MhzMask) ? (TBool)ETrue : (TBool)EFalse;
 		switch(iSpare[0])
 			}
 		if(retry)
 			{
 			__KTRACE_OPT(KPBUS1, Kern::Printf("...BUSTEST Failed : Retry"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM16, "BUSTEST Failed : Retry" );
 			SMF_GOTOS(EstSendBusTest_W);
 			}
 		switch(iBusWidthAndClock)
 			{
 				iCardArray->CardP(iSelectedCardIndex)->SetBusWidth(8);
 				break;
 			}
 		__KTRACE_OPT(KPBUS1, Kern::Printf("...BUSTEST OK"));
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM17, "BUSTEST OK" );
 		DoSetBusWidth(EBusWidth1);
 	SMF_STATE(EStExit)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECBUSTESTSM18, "EStExit" );
 		iConfig.SetMode( KMMCModeCardControlled );
 	SMF_END
 	}
 * The default implementation here does nothing
 * Replaces Dummy2()
 */
 EXPORT_C void DMMCStack::GetInterface(TInterfaceId aInterfaceId, MInterface*& aInterfacePtr)
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_GETINTERFACE_ENTRY, this );
 	if (aInterfaceId == KInterfaceCancelSession)
 		{
 		DMMCSession* session = (DMMCSession*&) aInterfacePtr;
 		Abort(session);
 		UnlockStack(session);
 		}
+	OstTraceFunctionExit1( DMMCSTACK_GETINTERFACE_EXIT, this );
 	}
 TMMCErr DMMCStack::GoIdleSM()
 /**
 			EStIdleEndCheck,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_GOIDLESM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_GOIDLESM2, "EStBegin" );
 		s.FillCommandDesc( ECmdGoIdleState, 0 );
 		iCxPollRetryCount = KMMCIdleCommandsAtRestart;
 	SMF_STATE(EStIdleLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_GOIDLESM3, "EStIdleLoop" );
 		SMF_INVOKES( ExecCommandSMST, EStIdleEndCheck )
 	SMF_STATE(EStIdleEndCheck)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_GOIDLESM4, "EStIdleEndCheck" );
 		if( --iCxPollRetryCount > 0 )
 			SMF_INVOKES( RetryGapTimerSMST, EStIdleLoop )
 		iStackState &= ~(KMMCStackStateDoDeselect|KMMCStackStateBusInconsistent);
 		iSelectedCard = 0;
 			EStEnd
 			};
 		DMMCSession& s=Session();
 		DMMCPsu* psu=(DMMCPsu*)iSocket->iVcc;
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM2, "EStBegin" );
 		iRCAPool.ReleaseUnlocked();
 		iCxPollRetryCount = 0; // Reset max number of poll attempts on card busy
 		SMF_INVOKES( GoIdleSMST, EStIdle )
 	SMF_STATE(EStIdle)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM3, "EStIdle" );
 		// If this platform doesn't support an adjustable voltage PSU then there is
 		// no point in interogating the card(s) present for their supported range
 		if ( !(psu->VoltageSupported()&KMMCAdjustableOpVoltage) )
 			{
 			// if the PSU isn't adjustable then it can't support low voltage mode
 		SMF_INVOKES( ExecCommandSMST, EStFullRangeDone )
 	SMF_STATE(EStFullRangeDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM4, "EStFullRangeDone" );
 		if( err )												// If timeout
 			{
 			iConfig.RemoveMode( KMMCModeEnableTimeOutRetry );	// There is no point to do it second time
 			}
 		else
 			if (newrange==0)
 				{
 				// One or more card is incompatible with our h/w
 				if (iMaxCardsInStack<=1)
-					return( KMMCErrNotSupported ); // There can only be one card - we don't support it.
+				    {
+					OstTraceFunctionExitExt( DMMCSTACK_ACQUIRESTACKSM_EXIT1, this, (TInt) KMMCErrNotSupported );
+					return KMMCErrNotSupported; // There can only be one card - we don't support it.
+				    }
 				else
 					// Force the default range
 					iCurrentOpRange=(psu->VoltageSupported() & ~KMMCAdjustableOpVoltage);
 				}
 			else
 			SMF_INVOKES( SwitchToLowVoltageSMST, EStSetRangeLoop )
 			}
 	SMF_STATE(EStSetRangeLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM5, "EStSetRangeLoop" );
 		// Repeat CMD1 this time setting Current Op Range
 		s.Command().iArgument = iCurrentOpRange | KMMCOCRAccessModeHCS | KMMCOCRBusy;
 		m.SetTraps( KMMCErrResponseTimeOut );
 		SMF_INVOKES( ExecCommandSMST, EStSetRangeBusyCheck )
 	SMF_STATE(EStSetRangeBusyCheck)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM6, "EStSetRangeLoop" );
 		if( !err )
 			{
 			// Bit31 of the OCR response is low if the cards are still powering up.
 			const TUint32 ocrResponse = TMMC::BigEndian32(s.ResponseP());
 			const TBool isBusy = ((ocrResponse & KMMCOCRBusy) == 0);
 			__KTRACE_OPT(KPBUS1,Kern::Printf("-mmc:upd:bsy%d", isBusy));
+			OstTrace1( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM7, "MMC busy status=%d", isBusy );
 			if (isBusy)
 				{
 				// Some cards are still busy powering up. Check if we should timeout
 				if ( ++iCxPollRetryCount > iConfig.OpCondBusyTimeout() )
-					return( KMMCErrBusTimeOut );
+				    {
+					OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM8, "Peripheral bus timeout" );
+					OstTraceFunctionExitExt( DMMCSTACK_ACQUIRESTACKSM_EXIT2, this, (TInt) KMMCErrBusTimeOut );
+					return KMMCErrBusTimeOut;
+				    }
 				m.ResetTraps();
 				SMF_INVOKES( RetryGapTimerSMST, EStSetRangeLoop )
 				}
 			iSpare[0] = 0;
 			if((ocrResponse & KMMCOCRAccessModeMask) == KMMCOCRAccessModeHCS)
 				{
 				__KTRACE_OPT(KPBUS1, Kern::Printf("Found large MMC card."));
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM9, "Found large MMC card" );
 				iSpare[0] = KMMCardIsHighCapacity;
 				}
 			}
 		iConfig.SetMode( EffectiveModes(s.iConfig) & KMMCModeEnableTimeOutRetry );	// Restore original setting
 		// All cards are now ready and notified of the voltage range - ask ASSP to set it up
 		psu->SetVoltage(iCurrentOpRange);
 		if (psu->SetState(EPsuOnFull) != KErrNone)
-			return(KMMCErrHardware);
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_ACQUIRESTACKSM_EXIT3, this, (TInt) KMMCErrHardware );
+			return KMMCErrHardware;
+		    }
 		iCardArray->InitNewCardScan(); // Collect new cards, one by one
 	SMF_STATE(EStCIDLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM10, "EStCIDLoop" );
 		if ( iCardArray->NewCardCount() >= iMaxCardsInStack )
 			SMF_GOTOS( EStCIDsDone )
 		s.FillCommandDesc( ECmdAllSendCID, 0 );
 		m.SetTraps( KMMCErrResponseTimeOut );
 		SMF_INVOKES( ExecCommandSMST, EStSendCIDIssued )
 	SMF_STATE(EStSendCIDIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM11, "EStSendCIDIssued" );
 		if( !err )
 			{
 			// A card responded with a CID. Create a new card entry in the card array
 			// and initialise this entry with the CID. The card array allocates it an
 			// RCA, either the old RCA if we have seen this card before, or a new one.
 			SMF_INVOKES( ExecCommandSMST, EStCIDLoop )
 			}
 	SMF_STATE(EStCIDsDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM12, "EStCIDsDone" );
 		// All cards are initialised; get all their CSDs
 		m.ResetTraps();				// We are no longer processing any errors
 		if( iCardArray->NewCardCount()==0 )
 			SMF_EXIT						// No new cards acquired
 		iCxCardCount=0;							// New cards index
 		s.FillCommandDesc( ECmdSendCSD );
 	SMF_STATE(EStCSDLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM13, "EStCSDLoop" );
 		s.Command().iArgument = TMMCArgument(iCardArray->NewCardP(iCxCardCount)->iRCA);
 		SMF_INVOKES( ExecCommandSMST, EStSendCSDDone )
 	SMF_STATE(EStSendCSDDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM14, "EStSendCSDDone" );
 		// Store the CSD in the new card entry
 		TMMCard* cardP = iCardArray->NewCardP(iCxCardCount);
 		cardP->iCSD = s.ResponseP();
 		// Perform MMC Specific parsing of the CSD structure
 		SMF_NEXTS(EStMergeCards)
 	SMF_STATE(EStMergeCards)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM15, "EStMergeCards" );
 		// Merging the old card info with newly acquired cards (we will ask each card for status
 		// to determine whether it's really present later).
 		if( SchedGetOnDFC() )
 			SMF_WAIT
 		if ( iCardArray->MergeCards(ETrue)==KErrNone )
 		SMF_INVOKES( CheckStackSMST, EStReMergeCards ) // No space so check if any cards have gone
 	SMF_STATE(EStReMergeCards)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ACQUIRESTACKSM16, "EStReMergeCards" );
 		if( SchedGetOnDFC() )
 			SMF_WAIT
 		if ( iCardArray->MergeCards(EFalse)!=KErrNone ) // There are more cards in the stack than we can handle
-			return(KMMCErrTooManyCards);
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_ACQUIRESTACKSM_EXIT4, this, (TInt) KMMCErrTooManyCards );
+			return KMMCErrTooManyCards;
+		    }
 	SMF_END
 	}
 		};
 	__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:SwLowVolt"));
 	DMMCPsu* psu=(DMMCPsu*)iSocket->iVcc;
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_SWITCHTOLOWVOLTAGESM1, "Current PSU=0x%x", psu );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_SWITCHTOLOWVOLTAGESM2, "EStBegin" );
 		// turn power off
 		DoPowerDown();
 		psu->SetState(EPsuOff);
 		// turn power back on in low voltage mode
 		psu->SetVoltage(iCurrentOpRange);
 		if (psu->SetState(EPsuOnFull) != KErrNone)
-			return(KMMCErrHardware);
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_SWITCHTOLOWVOLTAGESM_EXIT, this, (TInt) KMMCErrHardware );
+			return KMMCErrHardware;
+		    }
 		SMF_INVOKES( DoPowerUpSMST, EStPoweredUp )
 	SMF_STATE(EStPoweredUp)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_SWITCHTOLOWVOLTAGESM3, "EStPoweredUp" );
 		// turn the clock back on
 		SMF_INVOKES( InitClockOnSMST, EStClockOn )	// Feed init clock to the bus
 	SMF_STATE(EStClockOn)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_SWITCHTOLOWVOLTAGESM4, "EStClockOn" );
 		// wait for 1ms and then 74 clock cycles
 		// 74 clock cylces @ 400 Khz = 74 / 400,000 = 0.000185 secs = 0.185 ms
 		// so total wait = 1.185 ms
 		SMF_INVOKES(LowVoltagePowerupTimerSMST, EStEnd);
 			EStFinish,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMCHECKSTACKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMCHECKSTACKSM2, "EStBegin" );
 		// This macro works naked and must not be preempted
 		iConfig.RemoveMode( KMMCModeEnablePreemption | KMMCModeCardControlled );
 		s.iState |= KMMCSessStateInProgress;
 		SMF_INVOKES( CheckStackSMST, EStFinish )
 	SMF_STATE(EStFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMCHECKSTACKSM3, "EStFinish" );
 		s.iState &= ~KMMCSessStateInProgress;
 	SMF_END
 	}
 			EStCardDeselected,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM2, "EStBegin" );
 		iCxCardCount=-1;
 		m.SetTraps( KMMCErrResponseTimeOut );
 	SMF_STATE(EStLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM3, "EStLoop" );
 		if ( ++iCxCardCount == (TInt)iMaxCardsInStack )
 			SMF_EXIT
 		if ( !iCardArray->CardP(iCxCardCount)->IsPresent() )
 			SMF_GOTOS( EStLoop )					// card's not present
 		s.FillCommandDesc(ECmdSelectCard, arg);
 		SMF_INVOKES(ExecCommandSMST, EStCardSelectedGotStatus)
 	SMF_STATE(EStCardSelectedGotStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM4, "EStCardSelectedGotStatus" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("-mst:cssm:err%08x", err));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM5, "err=0x%08x", err );
 		if(err)
 			{
 			// Timeout - the card is no longer present so remove from the card array
 			iCardArray->DeclareCardAsGone(iCxCardCount);
 		s.FillCommandDesc(ECmdSelectCard, 0);
 		SMF_INVOKES(ExecCommandSMST, EStCardDeselected)
 	SMF_STATE(EStCardDeselected)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKSTACKSM6, "EStCardDeselected" );
 		SMF_GOTOS( EStLoop )
 	SMF_END
 	}
 			EStCardDeselected,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM2, "EStBegin" );
 		iCxCardCount=-1;
 		m.SetTraps( KMMCErrResponseTimeOut );
 		iMinorBufLen = KMinMinorBufSize;
 	SMF_STATE(EStLoop)
 		s.FillCommandDesc(ECmdSelectCard, arg);
 		SMF_INVOKES(ExecCommandSMST, EStCardSelectedGotStatus)
 	SMF_STATE(EStCardSelectedGotStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM3, "EStCardSelectedGotStatus" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("-mst:cssm:err%08x", err));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM4, "err=0x%08x", err );
 		if ( !err )
 			{
 			TMMCard& card=*(iCardArray->CardP(iCxCardCount));
 			card.iStatus=s.ResponseP(); // Got the response
 		SMF_GOTOS( EStLoop )
 	SMF_STATE(EStCheckLockStatus)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM5, "EStCheckLockStatus" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("-mst:cssm:err%08x", err));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM6, "err=0x%08x", err );
 		if ((err & KMMCErrUpdPswd) ||
 		   ((err & KMMCErrStatus) && (s.LastStatus().Error() == KMMCStatErrLockUnlock)))
 			{
 			// ECMDLockUnlock (with LockUnlockLockUnlock param) succeeded.
 		s.FillCommandDesc(ECmdSelectCard, 0);
 		SMF_INVOKES(ExecCommandSMST, EStCardDeselected)
 	SMF_STATE(EStCardDeselected)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CHECKLOCKSTATUSSM7, "EStCardDeselected" );
 		SMF_GOTOS( EStLoop )
 	SMF_END
 	}
 			EStBegin=0,
 			EStEnd
 			};
 #ifdef __EPOC32__
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_POLLGAPTIMERSM1, "Current session=0x%x", &s );
 #endif
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_POLLGAPTIMERSM2, "EStBegin" );
 #ifdef __EPOC32__
 		s.SynchBlock( KMMCBlockOnPollTimer );
 		s.iPollTimer.OneShot(KMMCPollGapInMilliseconds,EFalse);
 		SMF_EXITWAIT
 			EStBegin=0,
 			EStEnd
 			};
 #ifdef __EPOC32__
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_RETRYGAPTIMERSM1, "Current session=0x%x", &s );
 #endif
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_RETRYGAPTIMERSM2, "EStBegin" );
 #ifdef __EPOC32__
 		s.SynchBlock( KMMCBlockOnRetryTimer );
 		s.iRetryTimer.OneShot(KMMCRetryGapInMilliseconds,EFalse);
 		SMF_EXITWAIT
 		EStEnd
 		};
 #ifdef __EPOC32__
 	DMMCSession &s = Session();
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_PROGRAMTIMERSM1, "Current session=0x%x", &s );
 #endif
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_PROGRAMTIMERSM2, "EStBegin" );
 #ifdef __EPOC32__
 		s.SynchBlock(KMMCBlockOnPgmTimer);
 		s.iProgramTimer.Cancel();
 		s.iProgramTimer.OneShot(ProgramPeriodInMilliSeconds(),EFalse);
 		EStEnd
 		};
 #ifdef __EPOC32__
 	DMMCSession &s = Session();
+	OstTrace1( TRACE_INTERNALS, DMMCSTACK_LOWVOLTAGEPOWERUPTIMERSM1, "Current session=0x%x", &s );
 #endif
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_LOWVOLTAGEPOWERUPTIMERSM2, "EStBegin" );
 #ifdef __EPOC32__
 		s.SynchBlock(KMMCBlockOnRetryTimer);
 		s.iRetryTimer.OneShot(KMMCLowVoltagePowerUpTimeoutInMilliseconds,EFalse);
 		SMF_EXITWAIT
 			EStErrRecover,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM2, "EStBegin" );
 		if ( ( s.CardRCA() != 0 ) && ( (s.CardP()->iStatus.State()) == ECardStateSlp) )
 			{
 			// Currently selected media is asleep, so it must be awoken
 			SMF_INVOKES(ExecAwakeCommandSMST,EStExecCmd)
 			}
 	SMF_STATE(EStExecCmd)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM3, "EStExecCmd" );
 		TMMCCommandDesc& cmd = s.Command();
 		// clearup some internally used flags
 		cmd.iFlags &= ~(KMMCCmdFlagExecTopBusy|KMMCCmdFlagExecSelBusy);
 		cmd.iPollAttempts = cmd.iTimeOutRetries = cmd.iCRCRetries = 0;
 	SMF_STATE(EStRetry)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM4, "EStRetry" );
 		TMMCCommandDesc& cmd = s.Command();
 		m.SetTraps( KMMCErrBasic & ~Command().iExecNotHandle);	// Processing all trappable errors
 		if (iMultiplexedBus)
 			{
 		s.PushCommandStack();
 		s.FillCommandDesc( ECmdSelectCard, 0 );		// Deselect - RCA=0
 		iCxDeselectCount=iDeselectsToIssue;
 	SMF_STATE(EStDeselectLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM5, "EStDeselectLoop" );
 		SMF_INVOKES(IssueCommandCheckResponseSMST,EStDeselectEndCheck)
 	SMF_STATE(EStDeselectEndCheck)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM6, "EStDeselectEndCheck" );
 		// If we got an error and this is the last de-select then give up
 		if (err && iCxDeselectCount == 1)
 			{
 			s.PopCommandStack();
+			OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT1, this, (TInt) err );
 			SMF_RETURN(err)
 			}
 		if (--iCxDeselectCount > 0)
 			SMF_INVOKES(RetryGapTimerSMST,EStDeselectLoop)
 		s.PopCommandStack();
 		iStackState &= ~KMMCStackStateDoDeselect;
 	SMF_STATE(EStAnalyseCommand)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM7, "EStAnalyseCommand" );
 		TMMCCommandDesc& cmd = s.Command();
 		// Check if its un-important whether the card is in transfer state (i.e
 		// selected) or not for the command we are about to execute. Such
 		// commands are CMD0, CMD7 and CMD13.
 		// This state machine should never send CMD55
 		if (cmd.iCommand == ECmdAppCmd)
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT2, this, (TInt) KMMCErrNotSupported );
 			SMF_RETURN (KMMCErrNotSupported)
+		    }
 		SMF_NEXTS( EStTestAppCommand )
 		if (cmd.iCommand == ECmdGoIdleState || cmd.iCommand == ECmdSelectCard || cmd.iCommand == ECmdSendStatus)
 			{
 			SMF_GOTONEXTS
 				{
 				if ( (iConfig.iModes & KMMCModeCardControlled) == 0 )
 					SMF_GOTONEXTS
 				// Get the RCA of the card
 				if ( (targetRCA = s.CardRCA()) == 0 )
+				    {
+				    OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT3, this, (TInt) KMMCErrNoCard );
 					SMF_RETURN( KMMCErrNoCard )
+				    }
 				break;
 				}
 			default:
 				SMF_GOTONEXTS
 			}
 		s.FillCommandDesc(ECmdSelectCard,targetRCA);
 		SMF_INVOKES(IssueCommandCheckResponseSMST,EStSelectDone)
 	SMF_STATE(EStSelectDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM8, "EStSelectDone" );
 		TMMCCommandDesc& cmd = s.Command();
 		if ( err )
 			{
 			cmd.iFlags &= ~(KMMCCmdFlagASSPFlags|KMMCCmdFlagExecSelBusy);
 			if (err == KMMCErrBusyTimeOut)
 				cmd.iFlags |= KMMCCmdFlagExecSelBusy;
 			s.PopCommandStack();
 			SMF_NEXTS(EStErrRecover)
-			return(err);		// re-enter the next state with that error
+			OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT4, this, (TInt) err );
+			return err;		// re-enter the next state with that error
 			}
 		// Are we trying to recover from a top-level command returning busy (by de-selecting and re-selecting)
 		if ( cmd.iFlags & KMMCCmdFlagExecTopBusy )
 			{
 			SMF_GOTOS( EStTestAppCommand )
 			}
 	SMF_STATE(EStBlockCountCmdIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM9, "EStBlockCountCmdIssued" );
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 		if (status.Error())
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT5, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus)
+		    }
 		if(err & KMMCErrNotSupported)
 			{
 			// Not supported by the PSL, so use standard Stop Transmission mode
 			s.Command().iSpec.iUseStopTransmission = ETrue;
 			}
 		// Fall through...
 	SMF_STATE(EStTestAppCommand)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM10, "EStTestAppCommand" );
 		TMMCCommandDesc& cmd = s.Command();
 		if (cmd.iSpec.iCommandClass != KMMCCmdClassApplication)
 			SMF_GOTOS( EStIssueCommand )
 		s.PushCommandStack();
 		s.FillCommandDesc(ECmdAppCmd, s.CardRCA()); // Send APP_CMD (CMD55)
 		SMF_INVOKES(IssueCommandCheckResponseSMST,EStIssueAppCommandDone)
 	SMF_STATE(EStIssueAppCommandDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM11, "EStIssueAppCommandDone" );
 		s.PopCommandStack();
 		if ( err )
 			{
 			SMF_NEXTS(EStErrRecover)
-			return(err);		// re-enter the next state with that error
+OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT6, this, (TInt) err );
+			return err;		// re-enter the next state with that error
 			}
 	SMF_STATE(EStIssueCommand)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM12, "EStIssueCommand" );
 		TMMCCommandDesc& cmd = s.Command();
 		// If its an addressed command (rather than a selected command), then
 		// setup the argument with the RCA. (Commands requiring card to be
 		// selected - ACS don't matter since selected cards don't need an RCA now).
 		if ((iConfig.iModes & KMMCModeCardControlled) && cmd.iSpec.iCommandType==ECmdTypeAC )
 			{
 			const TRCA targetRCA = s.CardRCA();
 			if ( targetRCA == 0 )
+			    {
+			    OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT7, this, (TInt) KMMCErrNoCard );
 				SMF_RETURN( KMMCErrNoCard )
+			    }
 			cmd.iArgument.SetRCA(targetRCA);
 			}
 		// Issue the top-level command
 		SMF_INVOKES(IssueCommandCheckResponseSMST,EStCommandIssued)
 	SMF_STATE(EStCommandIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM13, "EStCommandIssued" );
 		// If command was succesful then we've finished.
 		if (!err)
 			SMF_EXIT
 	SMF_STATE(EStErrRecover)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_EXECCOMMANDSM14, "EStErrRecover" );
 		TMMCCommandDesc& cmd = s.Command();
 		const TUint32 modes=iConfig.iModes;
 		SMF_NEXTS(EStRetry)
 		m.ResetTraps();							// no more re-entries via return()
 			s.iBytesTransferred += cmd.iBytesDone;
 			if (cmd.iTotalLength < cmd.BlockLength())
 				{
 				DeselectsToIssue(1);
-				return(err);
+				OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT8, this, (TInt) err );
+				return err;
 				}
 			}
 		if ((modes & KMMCModeEnableRetries) == 0)
-			return( err );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT9, this, (TInt) err );
+			return err;
+		    }
 		const TUint32 toMask = (KMMCErrResponseTimeOut|KMMCErrDataTimeOut);
 		const TUint32 crcMask = (KMMCErrResponseCRC|KMMCErrDataCRC|KMMCErrCommandCRC);
 		if( (err & ~(toMask|crcMask)) == KMMCErrNone ) // time-outs/CRC errors
 			if( cmd.iSpec.iCommandType == ECmdTypeADTCS )	// for data transfer commands
 				{
 				DeselectsToIssue( 1 );						// enforce deselect before any retries
 				if( (modes & KMMCModeCardControlled) == 0 )
-					return( err );		// we wouldn't know what to select - no retries
+				    {
+					OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT10, this, (TInt) err );
+					return err;		// we wouldn't know what to select - no retries
+				    }
 				}
 			TUint32 gapEnabled = 0;
 			if( err & toMask )
 				cmd.iTimeOutRetries++;
 				gapEnabled |= KMMCModeTimeOutRetryGap;
 				if( (modes & KMMCModeEnableTimeOutRetry) == 0 ||
 					cmd.iTimeOutRetries > iConfig.iTimeOutRetries )
-					return( err );
+				    {
+					OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT11, this, (TInt) err );
+					return err;
+				    }
 				}
 			if( err & crcMask )
 				{
 				cmd.iCRCRetries++;
 				gapEnabled |= KMMCModeCRCRetryGap;
 				if( (modes & KMMCModeEnableCRCRetry) == 0	||
 					cmd.iCRCRetries > iConfig.iCRCRetries		||
 					((err & KMMCErrDataCRC) != 0 && (modes & KMMCModeDataCRCRetry) == 0) )
-					return( err );
+				    {
+					OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT12, this, (TInt) err );
+					return err;
+				    }
 				}
 			if( (modes & gapEnabled) == gapEnabled )
 				{
 				if( modes & KMMCModeCardControlled )
 //			ReportInconsistentBusState();	// ASSP layer should have it done
 			s.iGlobalRetries++;
 			if( s.iGlobalRetries > KMMCMaxGlobalRetries )
-				return( err );
+			    {
+				OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT13, this, (TInt) err );
+				return err;
+			    }
 			s.SwapMe();		// To prevent the initialiser from aborting this session
 			SMF_WAIT		// Initialiser will take over here
 			}
 			cmd.iPollAttempts++;
 			if( (modes & KMMCModeEnableBusyPoll) == 0 ||
 				((modes & KMMCModeCardControlled) == 0 && cmd.iCommand != ECmdSelectCard) ||
 				cmd.iPollAttempts > iConfig.iPollAttempts )
-				return( err );
+			    {
+				OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT14, this, (TInt) err );
+				return err;
+			    }
 			if( modes & KMMCModeBusyPollGap )
 				{
 				s.iState |= KMMCSessStateSafeInGaps;	// preemption allowed
 				SMF_CALL( PollGapTimerSMST )
 			// No preemption, just repeat the Deselect/Select sequence
 			SMF_GOTONEXTS
 			}
-		return( err );
+		OstTraceFunctionExitExt( DMMCSTACK_EXECCOMMANDSM_EXIT15, this, (TInt) err );
+		return err;
 	SMF_END
 	}
 TMMCErr DMMCStack::IssueCommandCheckResponseSM()
 		EStEnd
 		};
 		DMMCSession& s=Session();
 		TMMCCommandDesc& cmd = Command();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM2, "EStBegin" );
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:Issue %d %x",TUint(cmd.iCommand),TUint(cmd.iArgument)));
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM3, "CMD%02d(0x%08x)", TUint(cmd.iCommand), TUint(cmd.iArgument) );
 		// Stop the Controller from powering down the card due to bus inactivity
 		iSocket->ResetInactivity(0);
 	SMF_STATE(EStIssueCommand)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM4, "EStIssueCommand" );
 		// If command is directed at a specific card then save this command in card object
 		if (iConfig.iModes & KMMCModeCardControlled)
 			{
 			s.iCardP->iLastCommand = cmd.iCommand;
 		m.SetTraps(KMMCErrAll);
 		SMF_INVOKES(IssueMMCCommandSMST,EStCommandIssued)
 	SMF_STATE(EStCommandIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM5, "EStCommandIssued" );
 #ifdef ENABLE_DETAILED_SD_COMMAND_TRACE
 		cmd.Dump(s.ResponseP(), err);
 #endif
+		OstTraceDefExt2( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM6, "MMC Protocol: CMD%02d(0x%08x)", (TInt) cmd.iCommand, (TUint) cmd.iArgument );
+		OstTraceDefExt4( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM7, "MMC Protocol: RSP%d - LEN 0x%08x - ERR 0x%08x - STAT 0x%08x", (TUint) cmd.iSpec.iResponseType, (TUint) cmd.iSpec.iResponseLength, (TUint) err, (TUint) TMMC::BigEndian32(s.ResponseP()) );
 		TMMCErr exitCode=err;
 		// If we have just de-selected all cards in the stack, RCA(0) then ignore response timeout.
 		if ( cmd.iCommand==ECmdSelectCard && TRCA(cmd.iArgument)==0 )
 			exitCode &= ~KMMCErrResponseTimeOut;
 		else
 				  (cmd.iSpec.iResponseType==ERespTypeR1 || cmd.iSpec.iResponseType==ERespTypeR1B)) )
 				{
 				TMMCStatus status=s.ResponseP();
 				s.iLastStatus=status;
 				__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:ec:st=%08x", TUint32(status)));
+				OstTrace1( TRACE_INTERNALS, DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM8, "status=0x%08x", TUint32(status) );
 				if (iConfig.iModes & KMMCModeCardControlled)
 					s.iCardP->iStatus=status;
 				// Update exit code if card status is reporting an error (in case not done already)
 		// If we've just selected a card and the command was succesful then
 		// remember which one so we don't need to do it twice.
 		if (cmd.iCommand==ECmdSelectCard && exitCode==KMMCErrNone)
 			iSelectedCard=TRCA(cmd.iArgument);
+		OstTraceFunctionExitExt( DMMCSTACK_ISSUECOMMANDCHECKRESPONSESM_EXIT, this, ( TInt ) exitCode );
 		SMF_RETURN(exitCode)
 	SMF_END
 	}
 			EStFinish,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_NAKEDSESSIONSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_NAKEDSESSIONSM2, "EStBegin" );
 		s.iState |= KMMCSessStateInProgress;
 		if( (iConfig.iModes & KMMCModeCardControlled) != 0 )
 			SMF_INVOKES( AttachCardSMST, EStAttached )
 	SMF_BPOINT(EStAttached)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_NAKEDSESSIONSM3, "EStAttached" );
 		SMF_INVOKES( ExecCommandSMST, EStFinish )
 	SMF_STATE(EStFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_NAKEDSESSIONSM4, "EStFinish" );
 		s.iState &= ~KMMCSessStateInProgress;
 	SMF_END
 	}
 inline TMMCErr DMMCStack::CIMSetupCardSM()
 			EStGotCSD,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_CIMSETUPCARDSM1, "Current session=0x%x; Last status=0x%x", (TUint) &s, (TUint) s.iLastStatus );
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:SetupCardSM %x",TUint(s.iLastStatus)));
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMSETUPCARDSM2, "EStBegin" );
 		s.iState |= KMMCSessStateInProgress;
 		SMF_INVOKES( AttachCardSMST, EStAttached )	// attachment is mandatory here
 	SMF_BPOINT(EStAttached)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMSETUPCARDSM3, "EStAttached" );
 		s.FillCommandDesc( ECmdSelectCard, 0 );
 		SMF_INVOKES( ExecCommandSMST, EStSelected )
 	SMF_STATE(EStSelected)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMSETUPCARDSM4, "EStSelected" );
 		if( !s.iCardP->IsReady() )
-			return( KMMCErrNoCard );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_CIMSETUPCARDSM_EXIT, this, (TInt) KMMCErrNoCard );
+			return KMMCErrNoCard;
+		    }
 		s.FillCommandDesc( ECmdSendCSD, Command().iArgument ); // NB: the card will be deselected to execute this command
 		SMF_INVOKES( ExecCommandSMST, EStGotCSD )
 	SMF_STATE(EStGotCSD)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMSETUPCARDSM5, "EStGotCSD" );
 		s.iCardP->iCSD = s.ResponseP();
 		s.iState &= ~KMMCSessStateInProgress;
 	SMF_END
 	}
 			EStRWFinish,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM1, "Current session=0x%x; Last status=0x%x", (TUint) &s, (TUint) s.iLastStatus );
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:RWBlocksSM %x",TUint(s.iLastStatus)));
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM2, "EStBegin" );
 		if(s.iSessionID == ECIMWriteBlock || s.iSessionID == ECIMWriteMBlock)
 			{
 			// Check that the card supports class 4 (Write) commands
 			const TUint ccc = s.iCardP->CSD().CCC();
 			if(!(ccc & KMMCCmdClassBlockWrite))
-				return( KMMCErrNotSupported );
+			    {
+				OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT1, this, (TInt) KMMCErrNotSupported );
+				return KMMCErrNotSupported;
+			    }
 			}
 		s.iState |= KMMCSessStateInProgress;
 		m.SetTraps(KMMCErrInitContext);
 	SMF_STATE(EStRestart)		// NB: ErrBypass is not processed here
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM3, "EStRestart" );
 		SMF_CALLMEWR(EStRestart) // Create a recursive call entry to recover from the errors trapped
 		m.SetTraps(KMMCErrStatus);
 		if (s.Command().iSpec.iCommandClass!=KMMCCmdClassApplication || s.Command().iCommand==ECmdAppCmd)
 			{
 			s.ResetCommandStack();
 			SMF_INVOKES( AttachCardSMST, EStAttached )	// attachment is mandatory here
 			}
 	SMF_BPOINT(EStAttached)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM4, "EStAttached" );
 		TMMCCommandDesc& cmd = s.Command();
 		const TUint32 blockLength = cmd.BlockLength();
 		if(blockLength == 0)
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT2, this, (TInt) KMMCErrArgument );
 			return KMMCErrArgument;
+		    }
 		if(s.iSessionID == ECIMReadBlock	||
 		   s.iSessionID == ECIMWriteBlock	||
 		   s.iSessionID == ECIMReadMBlock	||
 		   s.iSessionID == ECIMWriteMBlock)
 			{
 			// read/write operation
 			if(!cmd.AdjustForBlockOrByteAccess(s))
 				{
 				// unable to convert command arguments to suit the underlying block/byte access mode
+				OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT3, this, (TInt) KMMCErrArgument );
 				return KMMCErrArgument;
 				}
 			}
 		// Set the block length if it has changed. Always set for ECIMLockUnlock.
 		s.FillCommandDesc( ECmdSetBlockLen, blockLength );
 		SMF_INVOKES( ExecCommandSMST, EStLength1 )
 	SMF_STATE(EStLength1)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM5, "EStAttached" );
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 		if (status.Error())
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT4, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus)
+		    }
 		s.iCardP->iSetBlockLen = s.Command().BlockLength();
 	SMF_STATE(EStLengthSet)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM6, "EStLengthSet" );
 		TMMCCommandDesc& cmd = s.Command();
 		TUint opType = 0;
 		const TUint kTypeWrite =	KBit0;
 		const TUint kTypeMultiple =	KBit1;
 		const TUint kTypeSpecial =	KBit2;
 				// data transmission, then it may return KMMCErrNotSupported to force
 				// the 'Stop Transmission' mode to be used instead.
 				//
 				if(s.iCardP->CSD().SpecVers() >= 3)
 					{
+					OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM7, "CMD12 (STOP_TRANSMISSION) not used" );
 					cmd.iSpec.iUseStopTransmission = EFalse;
 					SMF_NEXTS(EStIssueBlockCount)
 					}
 				else
 					{
 			}
 		SMF_GOTONEXTS
 	SMF_STATE(EStIssueBlockCount)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM8, "EStIssueBlockCount" );
 		//
 		// Issues SET_BLOCK_COUNT (CMD23) for MB R/W data transfers.
 		// This is only issued if MMC version >= 3.1 and the PSL
 		// supports this mode of operation.
 		//
 		s.FillCommandDesc( ECmdSetBlockCount, args );
 		SMF_INVOKES( ExecCommandSMST, EStBlockCountCmdIssued )
 	SMF_STATE(EStBlockCountCmdIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM9, "EStBlockCountCmdIssued" );
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 		if (status.Error())
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT5, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus)
+		    }
 		if(err & KMMCErrNotSupported)
 			{
 			// Not supported by the PSL, so use standard Stop Transmission mode
 			s.Command().iSpec.iUseStopTransmission = ETrue;
 		SMF_GOTOS(EStBpoint1)
 	SMF_STATE(EStAppCmdIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM10, "EStAppCmdIssued" );
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 		if (status.Error())
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT6, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus)
+		    }
 	SMF_BPOINT(EStBpoint1)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM11, "EStBpoint1" );
 		// NB We need to trap KMMCErrStatus errors, because if one occurs,
 		// we still need to wait to exit PRG/RCV/DATA state
 		m.SetTraps(KMMCErrStatus);
 		SMF_INVOKES( ExecCommandSMST, EStIssued )
 	SMF_STATE(EStIssued)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM12, "EStIssued" );
 		// check state of card after data transfer with CMD13.
 		if (s.Command().Direction() != 0)
 			{
 			SMF_GOTOS(EStWaitFinish)
 			}
 		SMF_GOTOS(EStRWFinish);
 	SMF_STATE(EStWaitFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM13, "EStWaitFinish" );
 		// Save the status and examine it after issuing CMD13...
 		// NB We don't know where in the command stack the last response is stored (e.g. there may
 		// have bee a Deselect/Select issued), but we do know last response is stored in iLastStatus
 		TMMC::BigEndian4Bytes(s.ResponseP(), s.iLastStatus);
 		s.PushCommandStack();
 		s.FillCommandDesc(ECmdSendStatus, 0);
 		SMF_INVOKES(ExecCommandSMST, EStWaitFinish1)
 	SMF_STATE(EStWaitFinish1)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM14, "EStWaitFinish1" );
 		const TMMCStatus status(s.ResponseP());
 		s.PopCommandStack();
 #ifdef __WINS__
 		SMF_GOTOS(EStRWFinish);
 		if (st1 == ECardStatePrg || st1 == ECardStateRcv || st1 == ECardStateData)
 			{
 			SMF_INVOKES(ProgramTimerSMST, EStWaitFinish);
 			}
 		if (status.Error())
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT7, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus)
+		    }
 #endif
 		// Fall through if CURRENT_STATE is not PGM or DATA
 	SMF_STATE(EStRWFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEBLOCKSSM15, "EStRWFinish" );
 		if (TMMCStatus(s.ResponseP()).Error() != 0)
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT8, this, (TInt) KMMCErrStatus );
 			SMF_RETURN(KMMCErrStatus);
+		    }
 		s.iState &= ~KMMCSessStateInProgress;
 		// skip over recursive entry or throw error and catch in CIMLockUnlockSM()
-		return (s.Command().iCommand == ECmdLockUnlock) ? KMMCErrUpdPswd : KMMCErrBypass;
+		TMMCErr ret = (s.Command().iCommand == ECmdLockUnlock) ? KMMCErrUpdPswd : KMMCErrBypass;
+		OstTraceFunctionExitExt( DMMCSTACK_CIMREADWRITEBLOCKSSM_EXIT9, this, (TInt) ret );
+		return ret;
 	SMF_END
 	}
 inline TMMCErr DMMCStack::CIMEraseSM()
 			EStEraseFinish,
 			EStEnd
 			};
 		DMMCSession& s=Session();
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_CIMERASESM1, "Current session=0x%x; Last status=0x%x", (TUint) &s, (TUint) s.iLastStatus );
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:EraseSM %x",TUint(s.iLastStatus)));
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM2, "EStBegin" );
 		// Check that the card supports class 4 (Write) commands
 		const TUint ccc = s.iCardP->CSD().CCC();
 		if(!(ccc & KMMCCmdClassErase))
-			return( KMMCErrNotSupported );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT1, this, (TInt) KMMCErrNotSupported );
+			return KMMCErrNotSupported;
+		    }
 		s.iState |= KMMCSessStateInProgress;
 		m.SetTraps( KMMCErrInitContext );
 	SMF_STATE(EStRestart)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM3, "EStRestart" );
 		SMF_CALLMEWR(EStRestart) // Create a recursive call entry to recover from Init
 		s.ResetCommandStack();
 		SMF_INVOKES( AttachCardSMST, EStAttached )		// attachment is mandatory
 	SMF_BPOINT(EStAttached)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM4, "EStAttached" );
 		TMMCCommandDesc& cmd = s.Command();
 		if(cmd.iTotalLength == 0)
-			return( KMMCErrArgument );
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT2, this, (TInt) KMMCErrArgument );
+			return KMMCErrArgument;
+		    }
 		switch( s.iSessionID )
 			{
 			case ECIMEraseSector:
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM5, "ECIMEraseSector" );
 				TMMCEraseInfo eraseInfo;
 				s.iCardP->GetEraseInfo(eraseInfo);
 				cmd.iBlockLength = eraseInfo.iMinEraseSectorSize;
 				cmd.iCommand = ECmdTagSectorStart;
 				break;
 			case ECIMEraseGroup:
+				OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM6, "ECIMEraseGroup" );
 				cmd.iBlockLength = s.iCardP->iCSD.EraseGroupSize();
 				if(cmd.iBlockLength == 0 || cmd.iTotalLength % cmd.iBlockLength != 0)
+				    {
+					OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT3, this, (TInt) KMMCErrArgument );
 					return KMMCErrArgument;
+				    }
 				cmd.iCommand = ECmdTagEraseGroupStart;
 				break;
 			default:
 				DMMCSocket::Panic(DMMCSocket::EMMCEraseSessionID);
 			}
 		if(!cmd.AdjustForBlockOrByteAccess(s))
+		    {
+			OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT4, this, (TInt) KMMCErrArgument );
 			return KMMCErrArgument;
+		    }
 		iConfig.RemoveMode( KMMCModeEnablePreemption );	// erase sequence must not be pre-empted
 		const TUint flags = cmd.iFlags;
 		s.FillCommandDesc();
 		cmd.iFlags = flags;
 		SMF_INVOKES( ExecCommandSMST, EStStartTagged )
 	SMF_STATE(EStStartTagged)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM7, "EStStartTagged" );
 		const TMMCCommandDesc& cmd = s.Command();
 		TMMCCommandEnum command;
 		TUint endAddr = cmd.iArgument;
 		if(s.iSessionID == ECIMEraseSector)
 		s.FillCommandDesc( command, endAddr );
 		SMF_INVOKES( ExecCommandSMST, EStEndTagged )
 	SMF_STATE(EStEndTagged)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM8, "EStEndTagged" );
 		// Increase the inactivity timeout as an erase operation can potentially take a long time
 		// At the moment this is a somewhat arbitrary 30 seconds. This could be calculated more accurately
 		// using TAAC,NSAC, R2W_FACTOR etc. but that seems to yield very large values (?)
 		const TInt KMaxEraseTimeoutInSeconds = 30;
 		iBody->SetInactivityTimeout(KMaxEraseTimeoutInSeconds);
 		m.SetTraps(KMMCErrAll);
 		s.FillCommandDesc( ECmdErase, 0 );
 		SMF_INVOKES( ExecCommandSMST, EStErased )
 	SMF_STATE(EStErased)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM9, "EStErased" );
 		m.SetTraps( KMMCErrInitContext );
 		iBody->RestoreInactivityTimeout();
 		if (err != KMMCErrNone)
+		    {
+		    OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT5, this, (TInt) err );
 			SMF_RETURN(err);
+		    }
 	SMF_STATE(EStWaitFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM10, "EStWaitFinish" );
 		s.PushCommandStack();
 		s.FillCommandDesc(ECmdSendStatus, 0);
 		SMF_INVOKES(ExecCommandSMST, EStWaitFinish1)
 	SMF_STATE(EStWaitFinish1)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM11, "EStWaitFinish1" );
 		const TMMCStatus st(s.ResponseP());
 		s.PopCommandStack();
 #ifdef __WINS__
 		SMF_GOTOS(EStEraseFinish);
 #endif
 		// Fall through if CURRENT_STATE is not PGM or DATA
 	SMF_STATE(EStEraseFinish)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMERASESM12, "EStEraseFinish" );
 		s.iState &= ~KMMCSessStateInProgress;
-		return( KMMCErrBypass );		// to skip over the recursive entry
+		OstTraceFunctionExitExt( DMMCSTACK_CIMERASESM_EXIT6, this, (TInt) KMMCErrBypass );
+		return KMMCErrBypass;		// to skip over the recursive entry
 	SMF_END
 	}
 inline TMMCErr DMMCStack::CIMReadWriteIOSM()
 			EStEnd
 			};
 		DMMCSession& s=Session();
 		TMMCCommandDesc& cmd = s.Command();
+		OstTraceExt2( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEIOSM1, "Current session=0x%x; Last status=0x%x", (TUint) &s, (TUint) s.iLastStatus );
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:IOSM %x",TUint(s.iLastStatus)));
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEIOSM2, "EStBegin" );
 		s.iState |= KMMCSessStateInProgress;
 		TUint argument = (TUint(cmd.iArgument)&0x7F) << 8; // shift reg addr into a proper position
 		switch( s.iSessionID )
 			{
 		SMF_INVOKES( AttachCardSMST, EStIOLoop )	// attachment's mandatory
 	SMF_STATE(EStReadIO)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEIOSM3, "EStReadIO" );
 		*(cmd.iDataMemoryP)++ = s.ResponseP()[3];
 		cmd.iTotalLength--;
 	SMF_BPOINT(EStIOLoop)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMREADWRITEIOSM4, "EStIOLoop" );
 		s.iBytesTransferred++;
 		if( cmd.iTotalLength == 0 )
 			{
 			s.iState &= ~KMMCSessStateInProgress;
 			EStEnd
 			};
 		DMMCSession& s=Session();
 		TMMCCommandDesc& cmd = Command();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM1, "Current session=0x%x", &s );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:clusm"));
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM2, "EStBegin" );
 		m.SetTraps(KMMCErrStatus | KMMCErrUpdPswd);
 		cmd.iUnlockRetries = 0;					// attempt counter
 		iCMD42CmdByte = cmd.iDataMemoryP[0];
 	SMF_STATE(EStRetry)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM3, "EStRetry" );
 		__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:clusm:%x/%x", cmd.iUnlockRetries, (iSessionP == &iAutoUnlockSession) ? KMMCMaxAutoUnlockRetries : iConfig.iUnlockRetries));
 	if (iCMD42CmdByte == KMMCLockUnlockErase)
 		{
 		// Section 4.6.2 of version 4.2 of the the MMC specification states that
 		SMF_INVOKES(CIMReadWriteBlocksSMST, EStTestR1);
 	SMF_STATE(EStTestR1)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM4, "EStTestR1" );
 		if (iCMD42CmdByte == KMMCLockUnlockErase)
 			{
 			m.SetTraps(KMMCErrStatus | KMMCErrUpdPswd);
 			iBody->RestoreInactivityTimeout();
 			}
 			const TMMCStatus st = s.LastStatus();	// set in ExecCommandSM() / EStCommandIssued
 			TMMCCommandDesc& cmd0 = Command();
 			__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:clusm:EStTestR1 [err: %08x, st:%08x] : RETRY [%d]",
 											  err, (TInt)s.LastStatus(), cmd0.iUnlockRetries));
+			OstTraceExt3( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM5, "err=%08x; Last status=%d; Unlock retries=%d", (TUint) err, (TInt) s.LastStatus(), (TUint) cmd0.iUnlockRetries );
 			const TInt KMaxRetries = (iSessionP == &iAutoUnlockSession) ? KMMCMaxAutoUnlockRetries : iConfig.iUnlockRetries;
 			// retry if LOCK_UNLOCK_FAIL only error bit
 			if (!(	iCMD42CmdByte == 0	// LOCK_UNLOCK = 0; SET_PWD = 0
 				&&	err == KMMCErrStatus && st.Error() == KMMCStatErrLockUnlock
 				&&	(iConfig.iModes & KMMCModeEnableUnlockRetry) != 0
 				&&	++cmd0.iUnlockRetries < KMaxRetries ))
 				{
 				__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:clusm:abt"));
+OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM6, "LockUnlock abort" );
+OstTraceFunctionExitExt( DMMCSTACK_CIMLOCKUNLOCKSM_EXIT, this, (TInt) err );
 				SMF_RETURN(err);
 				}
 			__KTRACE_OPT(KPBUS1, Kern::Printf("mmc:clusm:retry"));
+			OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMLOCKUNLOCKSM7, "LockUnlock retry" );
 #ifdef __EPOC32__
 			s.SynchBlock(KMMCBlockOnRetryTimer);
 			s.iRetryTimer.OneShot(KMMCUnlockRetryGapInMilliseconds,EFalse);
 			SMF_WAITS(EStRetry)
 			SMF_EXIT;
 			}
 		else if (err != KMMCErrNone)
 			{
+			OstTraceFunctionExitExt( DMMCSTACK_CIMLOCKUNLOCKSM_EXIT2, this, (TInt) err );
 			SMF_RETURN(err);
 			}
 	SMF_END
 			};
 		__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:CIMAutoUnlockSM"));
 		DMMCSession& s=Session();
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM1, "Current session=0x%x", &s );
 	SMF_BEGIN
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM2, "EStBegin" );
 		iAutoUnlockIndex = -1;
 		m.SetTraps(KMMCErrAll);	// Trap (and ignore) all errors during auto-unlock
 	SMF_STATE(EStNextIndex)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM3, "EStNextIndex" );
 		if(err)
 			{
 			iSocket->PasswordControlEnd(&Session(), err);
 			}
 		//
 		// Upon completion, test the next card before performing further initialisation.
 		//
 		TMMCard &cd = *(iCardArray->CardP(iAutoUnlockIndex++));
+		OstTrace1( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM4, "Attempting to unlock card %d", cd.Number() );
 		s.SetCard(&cd);
 		const TInt kPWD_LEN = mp->iPWD.Length();
 		iPSLBuf[0] = 0;				// LOCK_UNLOCK = 0; unlock
 		iPSLBuf[1] = static_cast<TUint8>(kPWD_LEN);
 		SMF_INVOKES( CIMLockUnlockSMST, EStNextIndex )
 	SMF_STATE(EStInitStackAfterUnlock)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM5, "EStInitStackAfterUnlock" );
 		//
 		// We've attempted to unlock all cards (successfully or not)
 		//  - Now perform second-stage initialisation that can only be performed
 		//    on unlocked cards (such as setting bus width, high speed etc..)
 		//
 		m.ResetTraps();
 		SMF_INVOKES( InitStackAfterUnlockSMST, EStDone )
 	SMF_STATE(EStDone)
+		OstTrace0( TRACE_INTERNALS, DMMCSTACK_CIMAUTOUNLOCKSM6, "EStDone" );
 	SMF_END
 	}
 inline TMMCErr DMMCStack::NoSessionSM()
 * controllers can override this to generate more specific objects.
 * @param aCallBack Callback function to notify the client that a session has completed
 * @return A pointer to the new session
 */
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_ALLOCSESSION_ENTRY, this );
 	return new DMMCSession(aCallBack);
 	}
 EXPORT_C void DMMCStack::Dummy1() {}
 * Calls the PSL-implemented function SetBusWidth() if the bus width has changed
 *
 */
 void DMMCStack::DoSetBusWidth(TUint32 aBusWidth)
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_DOSETBUSWIDTH_ENTRY, this );
 	if (iBody->iCurrentSelectedBusWidth != aBusWidth)
 		{
 		iBody->iCurrentSelectedBusWidth = aBusWidth;
 		SetBusWidth(aBusWidth);
 		}
+	OstTraceFunctionExit1( DMMCSTACK_DOSETBUSWIDTH_EXIT, this );
 	}
 /**
 * Sets iConfig.iBusConfig.iBusClock - which the PSL SHOULD use to set the clock before every command.
 *
 *
 * @param aClock The requested clock frequency in Kilohertz
 */
 void DMMCStack::DoSetClock(TUint32 aClock)
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_DOSETCLOCK_ENTRY, this );
 	iConfig.iBusConfig.iBusClock = aClock;
 	if (iPoweredUp&&(iBody->iCurrentSelectedClock != aClock))
 		{
 		iBody->iCurrentSelectedClock = aClock;
 		SetBusConfigDefaults(iConfig.iBusConfig, aClock);
 		}
+	OstTraceFunctionExit1( DMMCSTACK_DOSETCLOCK_EXIT, this );
 	}
 TUint DMMCStack::MaxTranSpeedInKilohertz(const TMMCard& aCard) const
 	{
+	OstTraceFunctionEntry1( DMMCSTACK_MAXTRANSPEEDINKILOHERTZ_ENTRY, this );
 	TUint32 highSpeedClock = aCard.HighSpeedClock();
-	return highSpeedClock ? highSpeedClock : aCard.MaxTranSpeedInKilohertz();
+	TUint ret = highSpeedClock ? highSpeedClock : aCard.MaxTranSpeedInKilohertz();
+	OstTraceFunctionExitExt( DMMCSTACK_MAXTRANSPEEDINKILOHERTZ_EXIT, this, ret );
+	return ret;
 	}
 EXPORT_C void DMMCStack::SetBusWidth(TUint32 /*aBusWidth*/)
 * Returns the bus width as a TBusWidth given a card's bus width
 * expressed as an integer (1,4 or 8)
 * @return the bus width encoded as a TBusWidth
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSTACK_BUSWIDTHENCODING_ENTRY, this );
 	TBusWidth busWidth = EBusWidth1;
 	switch(aBusWidth)
 		{
 		case 8:
 			break;
 		default:
 			DMMCSocket::Panic(DMMCSocket::EMMCBadBusWidth);
 		}
+	OstTraceFunctionExitExt( DMMCSTACK_BUSWIDTHENCODING_EXIT, this, ( TUint )&( busWidth ) );
 	return busWidth;
 	}
 /**
 * class DMMCSocket
 * @param aPasswordStore pointer to the password store
 */
 	:DPBusSocket(aSocketNumber),
 	iPasswordStore(aPasswordStore)
 	{
+	OstTraceFunctionEntryExt( DMMCSOCKET_DMMCSOCKET_ENTRY, this );
 	}
 TInt DMMCSocket::TotalSupportedCards()
 /**
 * Returns the total number of MMC slots supported by the socket.
 * @return The number of MMC slots supported by the socket
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_TOTALSUPPORTEDCARDS_ENTRY, this );
+	OstTraceFunctionExitExt( DMMCSOCKET_TOTALSUPPORTEDCARDS_EXIT, this, iMachineInfo.iTotalSockets );
 	return iMachineInfo.iTotalSockets;
 	}
 // -------- Password store management --------
 * @return KErrAccessDenied An attempt to lock or clear was made with a NULL password.
 * @return KErrLocked An an attempt to unlock was made with a NULL password.
 * @return KErrNone on success
 */
 	{
+	OstTraceExt3(TRACE_FLOW, DMMCSOCKET_PREPARESTORE_ENTRY, "DMMCSocket::PrepareStore;aBus=%d;aFunc=%d;this=%x", aBus, aFunc, (TUint) this);
 	TInt r = 0;
 	TMMCard *card=iStack->CardP(aBus);
 	__ASSERT_ALWAYS(card, Panic(EMMCSessionNoPswdCard));
 	const TCID &cid = card->CID();
 	default:
 		Panic(EMMCSessionPswdCmd);
 		break;
 		}
+	OstTraceFunctionExitExt( DMMCSOCKET_PREPARESTORE_EXIT, this, r );
 	return r;
 	}
 TInt DMMCSocket::PasswordControlStart(const TCID &aCID, const TMediaPassword *aPWD)
 * trying to unlock a card with the wrong password.
 *
 * See PasswordControlEnd() for recovery policy.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_PASSWORDCONTROLSTART_ENTRY, this );
 	TInt r = KErrNone;							// error code
 	TBool changed = EFalse;						// compress store if changed
 	TBuf8<KMMCCIDLength> cid;					// convert to TBuf8<> for comparison
 		if (!s)
 			{
 			TMediaPassword mp;					// empty, to indicate !s
 			if ((r = iPasswordStore->InsertMapping(aCID, mp, TMapping::EStPending)) != KErrNone)
+			    {
+				OstTraceFunctionExitExt( DMMCSOCKET_PASSWORDCONTROLSTART_EXIT1, this, r );
 				return r;
+			    }
 			changed = ETrue;
 			}
 		}
 	if (changed)
 		iPasswordStore->iStore->Compress();
+	OstTraceFunctionExitExt( DMMCSOCKET_PASSWORDCONTROLSTART_EXIT2, this, r );
 	return r;
 	}
 * 	I	invalidate	R	restore
 * '
 * See PasswordControlStart() for details of how store set up.
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSOCKET_PASSWORDCONTROLEND_ENTRY, this );
 	// autounlock is a special case because the PasswordControlStart() will
 	// not have been called (the CID is not known in ks context.)  The mapping
 	// for this specific card is removed on failure, because it is the current
 	// mapping that is definitely wrong.
 		TMapping mp, *pmp;						// get mapping to mutate
 		mp.iCID = cid;
 		TInt psn = iPasswordStore->iStore->Find(mp, iPasswordStore->iIdentityRelation);
 		if (psn == KErrNotFound)
 			{
+			OstTraceFunctionExit1( DMMCSOCKET_PASSWORDCONTROLEND_EXIT1, this );
 			return;
 			}
 		else
 			{
 			pmp = &(*iPasswordStore->iStore)[psn];
 				if (s)	// s & ~t & ~f
 					pmp->iState = TMapping::EStInvalid;	// wipe
 				}
 			}	// else (f)
 		}	// else if (aSessP == &iStack->iAutoUnlockSession)
+	OstTraceFunctionExit1( DMMCSOCKET_PASSWORDCONTROLEND_EXIT2, this );
 	}
 TMMCPasswordStore::TMMCPasswordStore()
 /**
 * Contructor
 */
 	: iIdentityRelation(TMMCPasswordStore::CompareCID)
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_TMMCPASSWORDSTORE_ENTRY, this );
 	}
 TInt TMMCPasswordStore::Init()
 /**
 * Initialises the password store and allocates resources.
 * @return KErrNone if successful, standard error code otherwise.
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_INIT_ENTRY, this );
 	// We don't have a destructor yet as this object lasts forever
 	iStore = new RArray<TMapping>(4, _FOFF(TMapping, iCID));
 	if(!iStore)
+	    {
+		OstTraceFunctionExitExt( TMMCPASSWORDSTORE_INIT_EXIT1, this, KErrNoMemory );
 		return KErrNoMemory;
+	    }
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_INIT_EXIT2, this, KErrNone );
 	return KErrNone;
 	}
 EXPORT_C TBool TMMCPasswordStore::IsMappingIncorrect(const TCID& aCID, const TMediaPassword& aPWD)
 /**
 * Returns true if the password is definitely incorrect, i.e. if a valid entry with a
 * different password exists.  Returns false if correct (because the mapping matches,)
 * or if cannot tell (because no valid mapping.)
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_ISMAPPINGINCORRECT_ENTRY, this );
 	TMapping* pmp = FindMappingInStore(aCID);
-	return (pmp != 0 && pmp->iState == TMapping::EStValid && pmp->iPWD.Compare(aPWD) != 0);
+	TBool ret = pmp != 0 && pmp->iState == TMapping::EStValid && pmp->iPWD.Compare(aPWD) != 0;
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_ISMAPPINGINCORRECT_EXIT, this, ret );
+	return ret;
 	}
 TMapping *TMMCPasswordStore::FindMappingInStore(const TCID &aCID)
 /**
 * return pointer to aCID mapping in store or NULL if not found
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_FINDMAPPINGINSTORE_ENTRY, this );
 	TMapping *pmp = NULL;
 	TMapping mp;								// 8 + 16 + 8 + 16 + 4 bytes
 	mp.iCID.SetLength(KMMCCIDLength);
 	aCID.Copy(&mp.iCID[0]);
 	TInt psn=iStore->Find(mp, iIdentityRelation);
 	if(psn!=KErrNotFound)
 		{
 		pmp = &(*iStore)[psn];
 		}
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_FINDMAPPINGINSTORE_EXIT, this, ( TUint )( pmp ) );
 	return pmp;
 	}
 TInt TMMCPasswordStore::InsertMapping(const TCID &aCID, const TMediaPassword &aPWD, TMapping::TState aState)
 /**
 *
 * If the CID is already bound to something in the store, then this operation
 * is a binary search, otherwise it may involve kernel heap allocation.
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_INSERTMAPPING_ENTRY, this );
 	TInt r = KErrNone;
 	TMapping mpN;
 	mpN.iCID.SetLength(KMMCCIDLength);
 	aCID.Copy(&mpN.iCID[0]);					// copies from aCID into buffer.
 		mpE.iPWD.Copy(aPWD);
 		mpE.iState = aState;
 		r = KErrNone;
 		}
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_INSERTMAPPING_EXIT, this, r );
 	return r;
 	}
 TInt TMMCPasswordStore::PasswordStoreLengthInBytes()
 /**
 * virtual from DPeriphBusController, kern exec
 * return number of bytes needed for persistent file representation
 * of the password store
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_PASSWORDSTORELENGTHINBYTES_ENTRY, this );
 	TInt sz = 0;
 	for (TInt i = 0; i < iStore->Count(); ++i)
 		{
 		const TMapping &mp = (*iStore)[i];
 		if (mp.iState == TMapping::EStValid)
 			sz += KMMCCIDLength + sizeof(TInt32) + mp.iPWD.Length();
 		}
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_PASSWORDSTORELENGTHINBYTES_EXIT, this, sz );
 	return sz;
 	}
 TBool TMMCPasswordStore::ReadPasswordData(TDes8 &aBuf)
 /**
 * data.  aBuf is resized to contain exactly the password data from
 * the store.  If its maximum length is not enough then KErrOverflow
 * is returned and aBuf is not mutated.
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_READPASSWORDDATA_ENTRY, this );
 	TInt r=KErrNone;										// error code
 	if (PasswordStoreLengthInBytes() > aBuf.MaxLength())
 		r = KErrOverflow;
 	else
 			}
 		r = KErrNone;
 		}
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_READPASSWORDDATA_EXIT, this, r );
 	return r;
 	}
 TInt TMMCPasswordStore::WritePasswordData(TDesC8 &aBuf)
 /**
 * virtual from DPeriphBusController, kern server
 * replace current store with data from persistent representation in aBuf.
 */
 	{
+	OstTraceFunctionEntry1( TMMCPASSWORDSTORE_WRITEPASSWORDDATA_ENTRY, this );
 	// should only be called at boot up, but remove chance of duplicate entries
 	iStore->Reset();
 	TInt iBIdx;									// buffer index
 		// skip over PWD_LEN and PWD to next entry
 		iBIdx += sizeof(TInt32) + pwd_len;
 		}
 	if (corrupt)
+	    {
+		OstTraceFunctionExitExt( TMMCPASSWORDSTORE_WRITEPASSWORDDATA_EXIT1, this, KErrCorrupt );
 		return KErrCorrupt;
+	    }
 	// Build the store from the entries in the buffer.
 	TInt r = KErrNone;							// error code
 	for (iBIdx = 0; r == KErrNone && iBIdx < aBuf.Length(); )
 		{
 	// atomic from the startup thread's point of view.
 	if (r != KErrNone)
 		iStore->Reset();
+	OstTraceFunctionExitExt( TMMCPASSWORDSTORE_WRITEPASSWORDDATA_EXIT2, this, r );
 	return r;
 	}
 TInt TMMCPasswordStore::CompareCID(const TMapping& aLeft, const TMapping& aRight)
 /**
 * CID Comparason Functions for RArray::Find
 */
 	{
+	OstTraceFunctionEntry0( TMMCPASSWORDSTORE_COMPARECID_ENTRY );
 	return(aLeft.iCID == aRight.iCID);
 	}
 void DMMCSocket::InitiatePowerUpSequence()
 /**
 * Initiates a power up sequence on the stack
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_INITIATEPOWERUPSEQUENCE_ENTRY, this );
 	iStack->PowerUpStack();
+	OstTraceFunctionExit1( DMMCSOCKET_INITIATEPOWERUPSEQUENCE_EXIT, this );
 	}
 TBool DMMCSocket::CardIsPresent()
 /**
 * Indicates the presence of a card.
 * @return ETrue if a card is present, EFalse otherwise
 */
 	{
-	return(iStack->HasCardsPresent());
+	OstTraceFunctionEntry1( DMMCSOCKET_CARDISPRESENT_ENTRY, this );
+	TInt r = iStack->HasCardsPresent();
+	OstTraceFunctionExitExt( DMMCSOCKET_CARDISPRESENT_EXIT, this, r );
+	return r;
 	}
 void DMMCSocket::AdjustPartialRead(const TMMCard* aCard, TUint32 aStart, TUint32 aEnd, TUint32* aPhysStart, TUint32* aPhysEnd) const
 /**
 * Calculates the minimum range that must be read off a card, an optimisation that takes advantage
 * @param aEnd The required end position
 * @param aPhysStart The adjusted start position
 * @param aPhysEnd The adjusted end position
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSOCKET_ADJUSTPARTIALREAD_ENTRY, this );
 	iStack->AdjustPartialRead(aCard, aStart, aEnd, aPhysStart, aPhysEnd);
+	OstTraceFunctionExit1( DMMCSOCKET_ADJUSTPARTIALREAD_EXIT, this );
 	}
 void DMMCSocket::GetBufferInfo(TUint8** aMDBuf, TInt* aMDBufLen)
 /**
 * Returns the details of the buffer allocated by the socket for data transfer operations.  The buffer
 * allocated for DMA transfers.
 * @param aMDBuf A pointer to the allocated buffer
 * @param aMDBufLen The length of the allocated buffer
 */
 	{
+	OstTraceFunctionEntryExt( DMMCSOCKET_GETBUFFERINFO_ENTRY, this );
 	iStack->GetBufferInfo(aMDBuf, aMDBufLen);
+	OstTraceFunctionExit1( DMMCSOCKET_GETBUFFERINFO_EXIT, this );
 	}
 void DMMCSocket::Reset1()
 /**
 * Resets the socket by powering down the stack.
 * If there are operations in progress (inCritical), this call will be deferred
 * until the operation is complete.  In the case of an emergency power down,
 * this will occur immediately.
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_RESET1_ENTRY, this );
 	if (iState == EPBusCardAbsent)
 	    {
 	    // Reset is result of card eject!
 	    iStack->iStackState |= KMMCStackStateCardRemoved;
 	    }
 	iStack->PowerDownStack();
+	OstTraceFunctionExit1( DMMCSOCKET_RESET1_EXIT, this );
 	}
 void DMMCSocket::Reset2()
 /**
 * Resets the socket in response to a PSU fault or media change.
 /**
 * Allocates resources and initialises the MMC socket and associated stack object.
 * @return KErrNotReady if no stack has been allocated, standard error code otherwise
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_INIT_ENTRY, this );
 	__KTRACE_OPT(KPBUS1,Kern::Printf(">MMC:Init"));
 	GetMachineInfo();
 	// We need to make sure the stack is initialised,
 	// as DPBusSocket::Init() will initiate a power up sequence
 	if(iStack == NULL)
+	    {
+		OstTraceFunctionExitExt( DMMCSOCKET_INIT_EXIT1, this, KErrNotReady );
 		return KErrNotReady;
+	    }
 	TInt r = iStack->Init();
 	if (r!=KErrNone)
+	    {
+		OstTraceFunctionExitExt( DMMCSOCKET_INIT_EXIT2, this, r );
 		return r;
+	    }
 	r = DPBusSocket::Init();
 	if (r!=KErrNone)
+	    {
+		OstTraceFunctionExitExt( DMMCSOCKET_INIT_EXIT3, this, r );
 		return r;
+	    }
+	OstTraceFunctionExitExt( DMMCSOCKET_INIT_EXIT4, this, KErrNone );
 	return KErrNone;
 	}
 void DMMCSocket::GetMachineInfo()
 /**
 * Gets the platform specific configuration information.
 * @see TMMCMachineInfo
 */
 	{
+	OstTraceFunctionEntry1( DMMCSOCKET_GETMACHINEINFO_ENTRY, this );
 	// Get machine info from the stack
 	iStack->MachineInfo(iMachineInfo);
 	__KTRACE_OPT(KPBUS1, Kern::Printf(">GetMI : iTotalSockets %u", iMachineInfo.iTotalSockets));
 	__KTRACE_OPT(KPBUS1, Kern::Printf(">GetMI : iTotalMediaChanges %u", iMachineInfo.iTotalMediaChanges));
 	__KTRACE_OPT(KPBUS1, Kern::Printf(">GetMI : iTotalPrimarySupplies %u", iMachineInfo.iTotalPrimarySupplies));
 	__KTRACE_OPT(KPBUS1, Kern::Printf(">GetMI : iSPIMode %u", iMachineInfo.iSPIMode));
 	__KTRACE_OPT(KPBUS1, Kern::Printf(">GetMI : iBaseBusNumber %u", iMachineInfo.iBaseBusNumber));
+	OstTraceDefExt5( OST_TRACE_CATEGORY_RND, TRACE_MMCDEBUG, DMMCSOCKET_GETMACHINEINFO, "iTotalSockets=%d; iTotalMediaChanges=%d; iTotalPrimarySupplies=%d; iSPIMode=%d; iBaseBusNumber=%d", iMachineInfo.iTotalSockets, iMachineInfo.iTotalMediaChanges, iMachineInfo.iTotalPrimarySupplies, iMachineInfo.iSPIMode, iMachineInfo.iBaseBusNumber );
+	OstTraceFunctionExit1( DMMCSOCKET_GETMACHINEINFO_EXIT, this );
 	}
 // MMC specific functions
 /**
 * Panic the MMC Controller
 * @param aPanic The panic code
 */
 	{
+	OstTraceFunctionEntry0( DMMCSOCKET_PANIC_ENTRY );
 	_LIT(KPncNm,"PBUS-MMC");
 	Kern::PanicCurrentThread(KPncNm,aPanic);
 	}
 EXPORT_C DMMCPsu::DMMCPsu(TInt aPsuNum, TInt aMediaChangedNum)
 * @param aPsuNum The power supply number
 * @param aMediaChangedNum The associated media change number
 */
 	: DPBusPsuBase(aPsuNum, aMediaChangedNum)
 	{
+	OstTraceFunctionEntryExt( DMMCPSU_DMMCPSU_ENTRY, this );
 	iVoltageSetting=0x00ffc000; // Default voltage range - 2.6V to 3.6V (OCR reg. format).
+	OstTraceFunctionExit1( DMMCPSU_DMMCPSU_EXIT, this );
 	}
 EXPORT_C TInt DMMCPsu::DoCreate()
 /**
 * Create a DMMCPsu object.
 * and therefore if VccQ supply can be turned off.
 *
 * @Param aPtr reference to DMMCPsu Object to be acted upon.
 */
 	{
+	OstTraceFunctionEntry0( DMMCPSU_SLEEPCHECK_ENTRY );
 	DMMCPsu& self = *static_cast<DMMCPsu*>(aPtr);
 	if (
 		(self.iNotLockedTimeout&&!self.IsLocked()&&++self.iNotLockedCount>self.iNotLockedTimeout) ||
 		(self.iInactivityTimeout&&++self.iInactivityCount>self.iInactivityTimeout)
 	   )
 		{
 		DMMCSocket* socket = static_cast<DMMCSocket*>(self.iSocket);
 		socket->iStack->QSleepStack();
 		}
+	OstTraceFunctionExit0( DMMCPSU_SLEEPCHECK_EXIT );
 	}
 EXPORT_C DMMCMediaChange::DMMCMediaChange(TInt aMediaChangeNum)
 /**
 * Constructor for a DMMCMediaChange object
 * @param aMediaChangeNum The media change number
 */
 	: DMediaChangeBase(aMediaChangeNum)
-	{}
+	{
+	OstTraceFunctionEntryExt( DMMCMEDIACHANGE_DMMCMEDIACHANGE_ENTRY, this );
+	}
 EXPORT_C TInt DMMCMediaChange::Create()
 /**
 * Create a DMMCMediaChange object.
 * This should be overridden at the variant layer to allow interrupts and
 * other variant-specific parameters to be initialised.  The base class implementation
 * should be called prior to any variant-specific initialisation.
 * @return Standard Symbian OS error code.
 */
 	{
-	return DMediaChangeBase::Create();
+	OstTraceFunctionEntry1( DMMCMEDIACHANGE_CREATE_ENTRY, this );
-	}
+	TInt r = DMediaChangeBase::Create();
+	OstTraceFunctionExitExt( DMMCMEDIACHANGE_CREATE_EXIT, this, r );
+	return r;
+	}

changeset 13	46fffbe7b5a7
parent 9	96e5fb8b040d
child 19	4a8fed1c0ef6