kerneltest/e32test/debug/t_perflogger.cpp
author Dremov Kirill (Nokia-D-MSW/Tampere) <kirill.dremov@nokia.com>
Fri, 14 May 2010 17:13:29 +0300
changeset 109 b3a1d9898418
parent 90 947f0dc9f7a8
permissions -rw-r--r--
Revision: 201019 Kit: 201019

// 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 <e32std.h>
#include <e32std_private.h>
#include <e32cons.h>
#include <e32test.h>
#include <e32math.h>


#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;
	TInt    		nRecords = 0;
	
	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;
		TUint nBytes = 0;
		
        //-- parser the record, print out fields and optionally check the correspondence to the fields of the control structure.
        for(; currPos<end; currPos+=nBytes)
			{
            
            nBytes = ParseTraceRecord(currPos ,traceLayout);
            test(nBytes >0 );
            
            //-- 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);
				
				}
            
			}
				
		//-- release data buffer.
		aTrace.DataUsed();
		}
		
	//-- check number of trace records obtained
	if(apControlStruct)
		{
		test(nRecords == apControlStruct->iLogsNum);
		}

	}


//---------------------------------------------------------------------------------

/**
	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;
	}