kerneltest/e32test/debug/t_perflogger.cpp
changeset 0 a41df078684a
child 31 56f325a607ea
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/kerneltest/e32test/debug/t_perflogger.cpp	Mon Oct 19 15:55:17 2009 +0100
@@ -0,0 +1,578 @@
+// 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;
+	
+	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(; 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);
+				
+				}
+            
+			}
+		
+        //-- 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();
+	
+    
+    
+    //-- 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;
+	}
+
+
+
+
+
+
+
+
+
+
+