sl@0: // Copyright (c) 2005-2009 Nokia Corporation and/or its subsidiary(-ies). sl@0: // All rights reserved. sl@0: // This component and the accompanying materials are made available sl@0: // under the terms of the License "Eclipse Public License v1.0" sl@0: // which accompanies this distribution, and is available sl@0: // at the URL "http://www.eclipse.org/legal/epl-v10.html". sl@0: // sl@0: // Initial Contributors: sl@0: // Nokia Corporation - initial contribution. sl@0: // sl@0: // Contributors: sl@0: // sl@0: // Description: sl@0: // Kernel Performance Logger test sl@0: // Uses helper LDD for performing actual logging from the kernel side. sl@0: // See sl@0: // sl@0: // sl@0: sl@0: /** sl@0: @file sl@0: */ sl@0: sl@0: sl@0: #include sl@0: #include sl@0: #include sl@0: #include sl@0: #include sl@0: sl@0: sl@0: #include "t_perflogger.h" sl@0: #include "t_perflogger_drv.h" sl@0: sl@0: sl@0: //------------------------------------------------------------------------------------- sl@0: sl@0: //-- logging subcategoty test tags sl@0: const TUint8 KLogSubCat_UserThread = 0x11; sl@0: const TUint8 KLogSubCat_KernelThread = 0x12; sl@0: const TUint8 KLogSubCat_ISR = 0x13; sl@0: const TUint8 KLogSubCat_IDFC = 0x14; sl@0: sl@0: sl@0: //------------------------------------------------------------------------------------- sl@0: sl@0: RTest test(_L("T_PerfLogger")); sl@0: TInt64 rndSeed; sl@0: sl@0: //------------------------------------------------------------------------------------- sl@0: sl@0: /** sl@0: Print out the logging record. sl@0: @param aTraceLayout unrolled trace record structure sl@0: */ sl@0: void PrintTraceRecord(const TTraceLayout& aTraceLayout) sl@0: { sl@0: TBuf<256> printBuf; sl@0: sl@0: printBuf.Format(_L("Record: Size:%d, Flags:0x%02x, Cat:%d, SubCat:%d "), aTraceLayout.iSize, aTraceLayout.iFlags, aTraceLayout.iCategory, aTraceLayout.iSubCategory); sl@0: sl@0: TUint flags = aTraceLayout.iFlags; sl@0: sl@0: if(flags&(BTrace::EHeader2Present)) sl@0: printBuf.AppendFormat(_L("Header2:0x%08x "), aTraceLayout.iHeader2); sl@0: sl@0: if(flags & (BTrace::ETimestampPresent)) sl@0: printBuf.AppendFormat(_L("Timestamp:0x%x "), aTraceLayout.iTimestamp); sl@0: sl@0: if(flags & (BTrace::ETimestamp2Present)) sl@0: printBuf.AppendFormat(_L("Timestamp2:0x%x "), aTraceLayout.iTimestamp2); sl@0: sl@0: if(flags & (BTrace::EContextIdPresent)) sl@0: printBuf.AppendFormat(_L("Context:0x%08x "), aTraceLayout.iContext); sl@0: sl@0: if(flags & (BTrace::EPcPresent)) sl@0: printBuf.AppendFormat(_L("PC: 0x%08x "), aTraceLayout.iPC); sl@0: sl@0: if(flags & (BTrace::EExtraPresent)) sl@0: printBuf.AppendFormat(_L("Extra: 0x%08x "), aTraceLayout.iExtra); sl@0: sl@0: printBuf.Append(_L("| ")); sl@0: for(TInt i=0; i< aTraceLayout.iDataWords; ++i) sl@0: { sl@0: printBuf.AppendFormat(_L(" 0x%08x"), aTraceLayout.ipData[i]); sl@0: } sl@0: sl@0: printBuf.Append(_L("\n")); sl@0: test.Printf(printBuf); sl@0: sl@0: } sl@0: sl@0: //------------------------------------------------------------------------------------- sl@0: sl@0: /** sl@0: Get logging trace from the kernel trace engine and optionally check if it corresponds to the sl@0: TTestLogCtrl structure fields. Actually, the logging trace in our case shall be the result of the sl@0: test helper LDD worr, that in turn, is controlled by the data in TTestLogCtrl structure. sl@0: sl@0: @param aTrace ref. to the kernel trace engine LDD. sl@0: @param apControlStruct if not NULL obtained trace fields checked against fields of this structure. sl@0: sl@0: */ sl@0: void GetParseRecordData(RBTrace& aTrace, const TTestLogCtrl* apControlStruct = NULL) sl@0: { sl@0: TUint8* record; sl@0: TTraceLayout traceLayout; sl@0: sl@0: for(TInt i=0; ;++i) sl@0: { sl@0: //-- get raw trace record sl@0: TInt dataSize = aTrace.GetData(record); sl@0: sl@0: if(i != 0 && !dataSize) sl@0: break; //-- no more data sl@0: sl@0: //-- check if we get log data at all at the very beginning sl@0: if(i == 0 && !dataSize) sl@0: { sl@0: if(!apControlStruct) sl@0: {//-- it's ok, no check sl@0: break; sl@0: } sl@0: else sl@0: {//-- panic if there is no log data, but we are required to get some. sl@0: if(apControlStruct->iLogsNum > 0) sl@0: { sl@0: test.Printf(_L("GetParseRecordData() No trace data found!\n")); sl@0: test(0); sl@0: } sl@0: } sl@0: } sl@0: sl@0: sl@0: TUint8* end = record+dataSize; sl@0: TUint8* currPos = record; sl@0: TInt nRecords = 0; sl@0: TUint nBytes = 0; sl@0: sl@0: //-- parser the record, print out fields and optionally check the correspondence to the fields of the control structure. sl@0: for(; currPos0 ); sl@0: sl@0: //-- skip possible loggings that we didn't make sl@0: if(traceLayout.iCategory != BTrace::EKernPerfLog) sl@0: continue; sl@0: sl@0: ++nRecords; sl@0: sl@0: //-- print the record out sl@0: PrintTraceRecord(traceLayout); sl@0: sl@0: //-- check the obtained record structure sl@0: if(apControlStruct) sl@0: { sl@0: test(traceLayout.iCategory == apControlStruct->iCategory); sl@0: test(traceLayout.iSubCategory == apControlStruct->iSubCategory); sl@0: sl@0: if(traceLayout.iDataWords > 1) //-- we have at least 1 word of user data (1 is for TickCount) sl@0: test(traceLayout.ipData[0] == apControlStruct->iUserData); sl@0: sl@0: if(traceLayout.iDataWords > 2) //-- we have 2 words of user data (1 is for TickCount) sl@0: test(traceLayout.ipData[1] == apControlStruct->iUserData2); sl@0: sl@0: } sl@0: sl@0: } sl@0: sl@0: //-- check number of trace records obtained sl@0: if(apControlStruct) sl@0: { sl@0: test(nRecords == apControlStruct->iLogsNum); sl@0: } sl@0: sl@0: //-- release data buffer. sl@0: aTrace.DataUsed(); sl@0: } sl@0: } sl@0: sl@0: sl@0: //--------------------------------------------------------------------------------- sl@0: sl@0: /** sl@0: Parse logging record, converting it from the raw representation to the unrolled data sl@0: structure. sl@0: sl@0: @param apRecord points to the buffer with the raw trace record sl@0: @param aTraceLayout here parsed record will bre returned sl@0: sl@0: @return sise of the record, bytes sl@0: */ sl@0: TUint ParseTraceRecord(const TUint8* apRecord, TTraceLayout& aTraceLayout) sl@0: { sl@0: aTraceLayout.iSize = apRecord[BTrace::ESizeIndex]; sl@0: aTraceLayout.iFlags = apRecord[BTrace::EFlagsIndex]; sl@0: aTraceLayout.iCategory = apRecord[BTrace::ECategoryIndex]; sl@0: aTraceLayout.iSubCategory = apRecord[BTrace::ESubCategoryIndex]; sl@0: sl@0: const TUint flags= aTraceLayout.iFlags; sl@0: TInt size = aTraceLayout.iSize; sl@0: const TUint32* pData = (const TUint32*)(apRecord+4); sl@0: sl@0: size -= 4; //-- count header sl@0: sl@0: //-- process header flags and appropriate fields of the record sl@0: if(flags&(BTrace::EHeader2Present)) sl@0: { sl@0: aTraceLayout.iHeader2 = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: if(flags & (BTrace::ETimestampPresent)) sl@0: { sl@0: aTraceLayout.iTimestamp = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: if(flags & (BTrace::ETimestamp2Present)) sl@0: { sl@0: aTraceLayout.iTimestamp2 = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: if(flags & (BTrace::EContextIdPresent)) sl@0: { sl@0: aTraceLayout.iContext = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: if(flags & (BTrace::EPcPresent)) sl@0: { sl@0: aTraceLayout.iPC = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: if(flags & (BTrace::EExtraPresent)) sl@0: { sl@0: aTraceLayout.iExtra = *pData++; sl@0: size -= sizeof(TUint32); sl@0: test(size >= 0); sl@0: } sl@0: sl@0: //-- process user data if present sl@0: test(size >= 0); sl@0: test(size % sizeof(TUint32) == 0); sl@0: sl@0: aTraceLayout.iDataWords = size / sizeof(TUint32); sl@0: aTraceLayout.ipData = (aTraceLayout.iDataWords!=0) ? pData : NULL; sl@0: sl@0: return aTraceLayout.iSize; sl@0: } sl@0: sl@0: //--------------------------------------------------------------------------------- sl@0: //! @SYMTestCaseID KBASE-T_PERFLOGGER-0055 sl@0: //! @SYMTestType UT sl@0: //! @SYMPREQ PREQ1030 sl@0: //! @SYMTestCaseDesc Tests logging from different contexts: user thread, ISR, Kernel thread and IDFC. sl@0: //! The main functionality is performed by test heller LDD, "d_perflogger_test" that acually calls the logging function from different contexts sl@0: //! following the commands from user application. sl@0: //! sl@0: //! @SYMTestActions 0 setup the data structures that specify the logging parameters. sl@0: //! 1 call RKPLoggerTestHelper::MakeLogFromUserThread() this is a synchronous operation. Performs logging from the user thread context. sl@0: //! 1.1 Parse the log record data and ensure that the logged information matches the data we passed to the helper LDD. sl@0: //! sl@0: //! 2 call RKPLoggerTestHelper::MakeLogFromISR() this is asynchronous operation. Performs logging from the ISR context. sl@0: //! 2.1 Wait for operation to complete, validate the completion status. sl@0: //! 2.2 Parse the log record data and ensure that the logged information matches the data we passed to the helper LDD. sl@0: //! sl@0: //! sl@0: //! 3 call RKPLoggerTestHelper::MakeLogFromDFC() this is asynchronous operation. Performs logging from the Kernel thread context (DFC). sl@0: //! 3.1 Wait for operation to complete, validate the completion status. sl@0: //! 3.2 Parse the log record data and ensure that the logged information matches the data we passed to the helper LDD. sl@0: //! sl@0: //! 4 call RKPLoggerTestHelper::MakeLogFromIDFC() this is asynchronous operation. Performs logging from the IDFC. sl@0: //! 4.1 Wait for operation to complete, validate the completion status. sl@0: //! 4.2 Parse the log record data and ensure that the logged information matches the data we passed to the helper LDD. sl@0: //! sl@0: //! 5. Make scattered overlapped logging from ISR, DFC & IDFC simultaneously, ensure that this work. sl@0: //! sl@0: //! @SYMTestExpectedResults return if the performace logger behaves as expected, panic otherwise sl@0: //! @SYMTestPriority High sl@0: //! @SYMTestStatus Implemented sl@0: //--------------------------------------------------------------------------------- sl@0: void TestPerfLogger(RBTrace &aTrace) sl@0: { sl@0: TInt nRes; sl@0: sl@0: const TUint32 KLogUserData = 0xBAAABEEF; //-- just for testing sl@0: const TUint32 KLogUserData2 = 0x11FFDDCC; //-- just for testing sl@0: sl@0: sl@0: test.Next(_L("testing kernel performance logger functionality\n")); sl@0: sl@0: RKPLoggerTestHelper testHelperLDD; //-- helper test driver sl@0: CleanupClosePushL(testHelperLDD); sl@0: sl@0: nRes = testHelperLDD.Open(TVersion(1,0,1)); //-- open test helper ldd for a logger sl@0: test(nRes == KErrNone); sl@0: sl@0: //--- sl@0: TTestLogCtrl logCtrl_UserThread; sl@0: TTestLogCtrl logCtrl_ISR; sl@0: TTestLogCtrl logCtrl_DFC; sl@0: TTestLogCtrl logCtrl_IDFC; sl@0: sl@0: sl@0: TRequestStatus rqStatLogFromISR; sl@0: TRequestStatus rqStatLogFromDFC; sl@0: TRequestStatus rqStatLogFromIDFC; sl@0: sl@0: sl@0: //-- setup log control structures sl@0: logCtrl_UserThread.iLogsNum = 3; sl@0: logCtrl_UserThread.iCategory = BTrace::EKernPerfLog; sl@0: logCtrl_UserThread.iSubCategory = KLogSubCat_UserThread; sl@0: logCtrl_UserThread.iUserData = KLogUserData; sl@0: logCtrl_UserThread.iUserData2 = KLogUserData2; sl@0: sl@0: sl@0: logCtrl_ISR.iLogsNum = 3; sl@0: logCtrl_ISR.iCategory = BTrace::EKernPerfLog; sl@0: logCtrl_ISR.iSubCategory = KLogSubCat_ISR; sl@0: logCtrl_ISR.iUserData = KLogUserData; sl@0: logCtrl_ISR.iUserData2 = KLogUserData2; sl@0: sl@0: sl@0: logCtrl_DFC.iLogsNum = 3; sl@0: logCtrl_DFC.iCategory = BTrace::EKernPerfLog; sl@0: logCtrl_DFC.iSubCategory = KLogSubCat_KernelThread; sl@0: logCtrl_DFC.iUserData = KLogUserData; sl@0: logCtrl_DFC.iUserData2 = KLogUserData2; sl@0: sl@0: sl@0: logCtrl_IDFC.iLogsNum = 3; sl@0: logCtrl_IDFC.iCategory = BTrace::EKernPerfLog; sl@0: logCtrl_IDFC.iSubCategory = KLogSubCat_IDFC; sl@0: logCtrl_IDFC.iUserData = KLogUserData; sl@0: logCtrl_IDFC.iUserData2 = KLogUserData2; sl@0: sl@0: sl@0: sl@0: test.Printf(_L("Testing logging from user thread\n")); sl@0: //============================================================ sl@0: //-- 1. make logging from user thread, this is a synchronous operation sl@0: nRes = testHelperLDD.MakeLogFromUserThread(logCtrl_UserThread); sl@0: test(nRes == KErrNone); sl@0: sl@0: //-- 1.1 check the results sl@0: GetParseRecordData(aTrace, &logCtrl_UserThread); sl@0: sl@0: sl@0: test.Printf(_L("Testing logging from ISR\n")); sl@0: //============================================================ sl@0: //-- 2. make logging from ISR, this is asynchronous operation sl@0: testHelperLDD.MakeLogFromISR(rqStatLogFromISR, logCtrl_ISR); sl@0: User::WaitForRequest(rqStatLogFromISR); sl@0: test(rqStatLogFromISR.Int() == KErrNone); sl@0: sl@0: //-- 2.1 check the results sl@0: GetParseRecordData(aTrace, &logCtrl_ISR); sl@0: sl@0: test.Printf(_L("Testing logging from DFC\n")); sl@0: //============================================================ sl@0: //-- 3. make logging from DFC kennel thread, this is asynchronous operation sl@0: testHelperLDD.MakeLogFromDFC(rqStatLogFromDFC, logCtrl_DFC); sl@0: User::WaitForRequest(rqStatLogFromDFC); sl@0: test(rqStatLogFromDFC.Int() == KErrNone); sl@0: sl@0: //-- 3.1 check the results sl@0: GetParseRecordData(aTrace, &logCtrl_DFC); sl@0: sl@0: test.Printf(_L("Testing logging from IDFC\n")); sl@0: //============================================================ sl@0: //-- 4. make logging from IDFC, this is asynchronous operation sl@0: testHelperLDD.MakeLogFromIDFC(rqStatLogFromIDFC, logCtrl_IDFC); sl@0: User::WaitForRequest(rqStatLogFromIDFC); sl@0: test(rqStatLogFromIDFC.Int() == KErrNone); sl@0: sl@0: //-- 4.1 check the results sl@0: GetParseRecordData(aTrace, &logCtrl_IDFC); sl@0: sl@0: sl@0: test.Printf(_L("Testing overlapped logging from ISR, DFC & IDFC\n")); sl@0: //============================================================ sl@0: //-- 5. make logging from ISR, DFC and IDFC simultaneously sl@0: sl@0: //-- use random numbers for number and period of loggings sl@0: logCtrl_ISR.iLogsNum = URnd(16)+1; sl@0: logCtrl_ISR.iLogPeriodTick = URnd(20)+1; sl@0: sl@0: logCtrl_DFC.iLogsNum = URnd(16)+1; sl@0: logCtrl_DFC.iLogPeriodTick = URnd(20)+1; sl@0: sl@0: logCtrl_IDFC.iLogsNum = URnd(16)+1; sl@0: logCtrl_IDFC.iLogPeriodTick = URnd(20)+1; sl@0: sl@0: //-- start logging sl@0: testHelperLDD.MakeLogFromISR(rqStatLogFromISR, logCtrl_ISR); sl@0: testHelperLDD.MakeLogFromDFC(rqStatLogFromDFC, logCtrl_DFC); sl@0: testHelperLDD.MakeLogFromIDFC(rqStatLogFromIDFC, logCtrl_IDFC); sl@0: sl@0: //-- wait for logging to finish sl@0: User::WaitForRequest(rqStatLogFromISR); sl@0: User::WaitForRequest(rqStatLogFromDFC); sl@0: User::WaitForRequest(rqStatLogFromIDFC); sl@0: sl@0: GetParseRecordData(aTrace); sl@0: sl@0: sl@0: CleanupStack::PopAndDestroy(1); //-- testHelperLDD sl@0: sl@0: } sl@0: sl@0: sl@0: //--------------------------------------------------------------------------------- sl@0: //! @SYMTestCaseID KBASE-T_PERFLOGGER-0056 sl@0: //! @SYMTestType UT sl@0: //! @SYMPREQ PREQ1030 sl@0: //! @SYMTestCaseDesc Test of PERF_LOG0, PERF_LOG1, PERF_LOG macros performed by helper LDD sl@0: //! @SYMTestActions Calls helper LDD API that in turn implies using PERF_LOG0, PERF_LOG1, PERF_LOG macros by helper LDD sl@0: //! @SYMTestExpectedResults return if the performace logger behaves as expected, panic otherwise sl@0: //! @SYMTestPriority High sl@0: //! @SYMTestStatus Implemented sl@0: //--------------------------------------------------------------------------------- sl@0: void TestMacros(RBTrace &aTrace) sl@0: { sl@0: TInt nRes; sl@0: sl@0: const TUint32 KLogUserData = 0xBAAABEEF; //-- just for testing sl@0: const TUint32 KLogUserData2 = 0x11FFDDCC; //-- just for testing sl@0: sl@0: sl@0: test.Next(_L("Unit test for different macros\n")); sl@0: sl@0: RKPLoggerTestHelper testHelperLDD; //-- helper test driver sl@0: CleanupClosePushL(testHelperLDD); sl@0: sl@0: nRes = testHelperLDD.Open(TVersion(1,0,1)); //-- open test helper ldd for a logger sl@0: test(nRes == KErrNone); sl@0: sl@0: //--- sl@0: TTestLogCtrl logCtrl; sl@0: sl@0: //-- setup log control structures sl@0: logCtrl.iLogsNum = 1; sl@0: logCtrl.iCategory = BTrace::EKernPerfLog; sl@0: logCtrl.iSubCategory = KLogSubCat_UserThread; sl@0: logCtrl.iUserData = KLogUserData; sl@0: logCtrl.iUserData2 = KLogUserData2; sl@0: sl@0: //-- make logging from user thread using different macros, PERF_LOG0, PERF_LOG1, PERF_LOG sl@0: //-- see the helper driver sl@0: nRes = testHelperLDD.TestDifferentMacros(logCtrl); sl@0: test(nRes == KErrNone); sl@0: sl@0: //-- print out the results sl@0: GetParseRecordData(aTrace); sl@0: sl@0: sl@0: CleanupStack::PopAndDestroy(1); //-- testHelperLDD sl@0: sl@0: } sl@0: sl@0: //--------------------------------------------------------------------------------- sl@0: void MainL(void) sl@0: { sl@0: test.Start(_L("Kern Perf Logger tests")); sl@0: Initialise(); sl@0: sl@0: sl@0: RBTrace trace; sl@0: TInt error = trace.Open(); sl@0: test(error == KErrNone); sl@0: sl@0: trace.Empty(); sl@0: trace.SetFilter(BTrace::EThreadIdentification,0); sl@0: sl@0: sl@0: sl@0: //-- actually, for hardware platforms, the testing category and trace enabling sl@0: //-- may be set up in appropriate "header.iby" file sl@0: trace.SetMode(RBTrace::EEnable); sl@0: trace.SetFilter(BTrace::EKernPerfLog, ETrue); sl@0: sl@0: //-- unit-test for PERF_LOG macros sl@0: TestMacros(trace); sl@0: sl@0: //-- functionality test sl@0: TestPerfLogger(trace); sl@0: sl@0: trace.Close(); sl@0: sl@0: Finalise(); sl@0: test.End(); sl@0: } sl@0: sl@0: sl@0: //--------------------------------------------------------------------------------- sl@0: //! @SYMTestCaseID KBASE-T_PERFLOGGER-0162 sl@0: //! @SYMTestType UT sl@0: //! @SYMPREQ PREQ1030 sl@0: //! @SYMTestCaseDesc Load test helper LDD and check the result sl@0: //! @SYMTestActions load specified LDD by calling User::LoadLogicalDevice() sl@0: //! @SYMTestExpectedResults return if helper LDD is loaded OK, panic otherwise sl@0: //! @SYMTestPriority High sl@0: //! @SYMTestStatus Implemented sl@0: //--------------------------------------------------------------------------------- sl@0: void Initialise() sl@0: { sl@0: rndSeed = Math::Random(); sl@0: sl@0: //-- load device drivers sl@0: TInt nRes; sl@0: sl@0: test.Printf(_L("Loading test helper LDD...\n")); sl@0: nRes = User::LoadLogicalDevice(KPLoggerHelperTestDrv); sl@0: test(nRes == KErrNone || nRes == KErrAlreadyExists); sl@0: } sl@0: sl@0: /** Finalise environment */ sl@0: void Finalise(void) sl@0: { sl@0: } sl@0: sl@0: sl@0: sl@0: /** sl@0: Main sl@0: */ sl@0: GLDEF_C TInt E32Main() sl@0: { sl@0: CTrapCleanup* cleanup=CTrapCleanup::New() ; // get clean-up stack sl@0: sl@0: TRAPD(r,MainL()); sl@0: sl@0: delete cleanup ; // destroy clean-up stack sl@0: sl@0: return r; sl@0: sl@0: } sl@0: sl@0: //------------------------------------------------------------------------------------- sl@0: sl@0: TUint URnd(TUint aMin, TUint aMax) sl@0: { sl@0: test(aMin < aMax); sl@0: TUint uRes; sl@0: sl@0: do sl@0: { sl@0: uRes = Math::Rand(rndSeed) % aMax; sl@0: }while(uRes < aMin); sl@0: sl@0: return uRes; sl@0: } sl@0: sl@0: TUint URnd(TUint aMax) sl@0: { sl@0: return Math::Rand(rndSeed) % aMax; sl@0: } sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: sl@0: