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