diff -r 000000000000 -r a41df078684a kerneltest/e32utils/trace/btrace_analyse.cpp --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/kerneltest/e32utils/trace/btrace_analyse.cpp Mon Oct 19 15:55:17 2009 +0100 @@ -0,0 +1,3110 @@ +// Copyright (c) 2007-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: +// + +#if defined(__EPOC32__) || defined(__WINS__) +// compiling for Symbian OS... +#include +#include +#include +#include +#include +#include +#include "e32btrace.h" + +inline void* malloc(TInt aSize) { return User::Alloc(aSize); } +inline void* realloc(void* aPtr,TInt aSize) { return User::ReAlloc(aPtr,aSize); } +inline void free(void* aPtr) { User::Free(aPtr); } + +TUint8 PrintfBuffer[256]; +TUint PrintfBufferWidth = 0; + +static void printf(const char* aFormat,...) + { + VA_LIST list; + VA_START(list,aFormat); + TPtrC8 format((const TUint8*)aFormat); + TPtr8 buf(PrintfBuffer+PrintfBufferWidth,sizeof(PrintfBuffer)-PrintfBufferWidth); + buf.AppendFormatList(format,list); + PrintfBufferWidth += buf.Size(); + for(;;) + { + TUint width = 0; + for(;;) + { + if(width>=PrintfBufferWidth) + return; + if(PrintfBuffer[width]=='\n') + break; + ++width; + } + TPtrC8 line(PrintfBuffer,width); + ++width; + RDebug::RawPrint(line); + _LIT(KLineEnd,"\r\n"); + RDebug::RawPrint(KLineEnd); + memcpy(PrintfBuffer,PrintfBuffer+width,PrintfBufferWidth-width); + PrintfBufferWidth -= width; + } + } + +typedef TUint uintptr_t; + +#ifndef ASSERT +#define ASSERT(c) (void)((c)||(AssertFailed(__LINE__))) +TInt AssertFailed(TInt aLine) + { + _LIT(KPanicCategory,"BTRACE-ANALYSE"); + User::Panic(KPanicCategory,aLine); + return 0; + } +#endif // ASSERT + + +// +// Trace buffer helper functions - for use on target only +// +RBTrace Trace; +TUint8* AnalyseData; +TUint AnalyseDataRemain = 0; + +void RePrime() + { + for(TInt i=0; i<256; ++i) + { + if(Trace.Filter(i)) + { + // toggle filter to force a prime + Trace.SetFilter(i,0); + Trace.SetFilter(i,1); + } + } + } + +TUint AnalyseStream(TAny* aBuffer, TUint aMaxSize) + { + TUint size = AnalyseDataRemain; + if(!size) + { + Trace.DataUsed(); + AnalyseDataRemain = Trace.GetData(AnalyseData); + size = AnalyseDataRemain; + } + if(size>aMaxSize) + size = aMaxSize; + memcpy(aBuffer,AnalyseData,size); + AnalyseData += size; + AnalyseDataRemain -= size; + return size; + } + +void ProcessAllTrace(TUint (*aInput)(TAny* aBuffer, TUint aMaxSize),TInt aReportLevel); + +void DoAnalyse(TInt aAnalysisLevel) + { + AnalyseDataRemain = 0; + TUint oldMode = Trace.Mode(); + Trace.SetMode(0); // turn off trace capture while we dump + ProcessAllTrace(AnalyseStream, aAnalysisLevel); + Trace.SetMode(oldMode); + RePrime(); + } + +TInt BTraceAnalyseSetup() + { + TInt r = Trace.Open(); + if (r != KErrNone) + { + return r; + } + // Stop tracing + TUint oldMode = Trace.Mode(); + Trace.SetMode(0); + + // empty btrace buffer and reprime it + Trace.Empty(); + Trace.SetMode(oldMode); + RePrime(); + return KErrNone; + } + +void BTraceAnalyseEnd() + { + Trace.Close(); + } + +void BTraceAnalyse(TInt aAnalysisLevel) + { + // Stop tracing + TUint oldMode = Trace.Mode(); + Trace.SetMode(0); + + AnalyseDataRemain = 0; + ProcessAllTrace(AnalyseStream, aAnalysisLevel); + + // empty btrace buffer and reprime it + Trace.Empty(); + Trace.SetMode(oldMode); + RePrime(); + } + +#else +// compiling for host... + +#include +#include +#include + +#if defined(_MSC_VER) +typedef __int64 longlong; +typedef unsigned __int64 ulonglong; +#define BREAKPOINT { _asm int 3 } /**< Invoke debugger */ +#else +typedef long long longlong; +typedef long long ulonglong; +#define BREAKPOINT +#endif + +typedef signed char TInt8; +typedef unsigned char TUint8; +typedef unsigned short TUint16; +typedef unsigned int TUint32; +typedef ulonglong TUint64; +typedef unsigned int uintptr_t; +typedef int TInt; +typedef unsigned TUint; +typedef int TBool; +typedef void TAny; +typedef float TReal; +#define IMPORT_C +#include "e32btrace.h" + +#define ASSERT(c) (void)((c)||(AssertFailed(__LINE__))) +extern "C" void exit(int); +TInt AssertFailed(TInt aLine) + { + fprintf(stderr,"Panic: BTRACE-ANALYSE %d",aLine); + BREAKPOINT; + exit(2); + return 0; + } + +#define __UHEAP_MARK +#define __UHEAP_MARKEND + +TAny* operator new(size_t, TAny* p) {return p;} + +#endif // SYMBIAN_OS + + + +// +// Global data +// + +TInt ReportLevel = 0; +TUint8 TraceBuffer[0x10000]; +TUint TraceBufferSize = 0; +TUint64 Timestamp = 0; +TUint64 TimestampBase = 0; +TUint32 TraceRecordId = 0; +TUint32 TimestampPeriod = 0; +TUint32 Timestamp2Period = 0; +TBool Timestamp64Bit = 0; +TUint TraceFormatErrors = 0; +TBool TraceBufferFilled = false; +TBool SMP = true; +TBool ErrorOnThisTrace = false; + +const TUint8 KJunkTraceSubcategory = 255; // Dummy sub-category for EMetaTrace + +const TInt KMaxCpus = 8; + +// +// Utilities +// + +void ToHex(TUint8* aString,TUint32 aValue) + { + TUint i=32; + do + { + i -= 4; + TUint8 c = (TUint8)((aValue>>i)&0xf); + if(c>=10) + c += 'a'-10; + else + c += '0'; + *aString++ = c; + } + while(i); + } + + +TUint MakeName(TUint8* aString,const char* aName,TUint32 aHexValue) + { + TUint8* start = aString; + for(;;) + { + TUint8 c = *aName++; + if(!c) + break; + *aString++ = c; + } + ToHex(aString,aHexValue); + aString[8] = 0; + return aString-start+8; + } + + +/** +Convert a timestamp into real time units (micro-seconds) +*/ +TUint32 Time(TUint64 aTimestamp) + { + if(!TimestampPeriod) + return (TUint32)aTimestamp; + TInt exponent = (TInt8)(TimestampPeriod>>24); + TUint64 mantissa = TimestampPeriod&0xffffff; + aTimestamp *= mantissa; + exponent += 32; + if(exponent<0) + aTimestamp >>= -exponent; + else + aTimestamp <<= exponent; + TUint64 timeLo = (aTimestamp&0xffffffffu)*1000000; + TUint64 timeHi = (aTimestamp>>32)*1000000; + TUint64 us = timeHi+(timeLo>>32)+((timeLo>>31)&1); + return TUint32(us); + } + + +void ReportTimeUnits() + { + if(!TimestampPeriod) + printf("\nAll times are given in BTrace Timestamp1 units.\n\n"); + else + { + TInt exponent = (TInt8)(TimestampPeriod>>24); + TUint64 mantissa = TimestampPeriod&0xffffff; + TUint64 period = 1000000; + period *= mantissa; + exponent += 32; + if(exponent<0) + period >>= -exponent; + else + period <<= exponent; + printf("\nAll times are given in microseconds, resolution %d.%03dus\n\n",(int)TUint32(period>>32),(int)TUint32((((period&0xffffffffu)*1000)+0x80000000u)>>32)); + } + } + + +TUint SetBits(TUint8* aData, TUint aOffset, TUint aSize) + { + TUint mask = 1<<(aOffset&7); + TUint8* data = aData+(aOffset>>3); + TUint errors = 0; + while(aSize) + { + if(*data&mask) + ++errors; + *data |= (TUint8)mask; + mask <<= 1; + if(mask>0xFF) + { + mask = 0x01; + ++data; + } + --aSize; + } + return errors; + } + + +TUint ClearBits(TUint8* aData, TUint aOffset, TUint aSize) + { + TUint mask = 1<<(aOffset&7); + TUint8* data = aData+(aOffset>>3); + TUint errors = 0; + while(aSize) + { + if(!(*data&mask)) + ++errors; + *data &= (TUint8)~mask; + mask <<= 1; + if(mask>0xFF) + { + mask = 0x01; + ++data; + } + --aSize; + } + return errors; + } + + +void WarnIfError(TUint aErrorCount) + { + if (TraceBufferFilled) + printf("WARNING - BTRACE BUFFER IS FULL SO TRACE DATA MAY BE INCOMPLETE\n"); + + if(aErrorCount==0 && TraceFormatErrors==0) + return; + printf("CONSISTENCY ERRORS FOUND DURING TRACE ANALYSIS, RESULTS ARE UNRELIABLE!\n"); + } + + +#define CHECK_TRACE_DATA_WORDS(numWords) \ + if(aTrace.iDataSizeiOwner) + { + memcpy(aName+length,iOwner->iOwner->iName,iOwner->iOwner->iNameLength); + length += iOwner->iOwner->iNameLength; + aName[length++] = ':'; + aName[length++] = ':'; + } + memcpy(aName+length,iOwner->iName,iOwner->iNameLength); + length += iOwner->iNameLength; + aName[length++] = ':'; + aName[length++] = ':'; + } + memcpy(aName+length,iName,iNameLength); + length += iNameLength; + aName[length] = 0; + return length; + } + + TUint TraceName(TraceNameBuf& aName) + { + TInt i = 0; + const TUint KNumDigits = KMaxTraceNameLength-4; + aName[i++] = '<'; + const char* prefix = iTraceNamePrefix; + if(prefix[0]) + aName[i++] = *prefix++; + if(prefix[0]) + aName[i++] = *prefix++; + TUint n = iIndex; + for(TUint d=KNumDigits; d>0; --d) + { + aName[i+d-1] = TUint8('0'+(n%10)); + n /= 10; + } + i += KNumDigits; + aName[i++] = '>'; + aName[i] = 0; + return i; + } + + TUint FullTraceName(FullTraceNameBuf& aName) + { + TUint l1 = TraceName(*(TraceNameBuf*)aName); + aName[l1++] = '\''; + TUint l2 = FullName(*(FullNameBuf*)(aName+l1)); + aName[l1+l2++] = '\''; + aName[l1+l2] = 0; + return l1+l2; + } + +public: + TUint32 iTraceId; ///< ID for object as found in raw trace data. + TUint iIndex; ///< Index into container for this object. + Object* iOwner; ///< Object which 'owns' this one, e.g. process which owns a thread. + TUint32 iOwnerTraceId; ///< Trace ID for owner if owner object as yet unknown + TUint8 iAlive; ///< True if object destroyed trace not yet parsed. + TUint8 iNameSet; ///< True if name has been set. + TUint8 iNameLength; + TUint8 iName[KMaxBTraceDataArray+1]; + const char* iTraceNamePrefix; +public: + static TUint32 UnknownOwners; + }; +TUint32 Object::UnknownOwners = 0; + + +class ObjectContainer + { +public: + ObjectContainer() + : iNumEntries(0), iEntriesLength(0) , iEntries(0) + { + iLink = iAllContainers; + iAllContainers = this; + } + + static void Reset() + { + ObjectContainer* container = iAllContainers; + while(container) + { + TUint i = container->iNumEntries; + while(i--) + free(container->iEntries[i].iItem); + free(container->iEntries); + container->iEntries = 0; + container->iNumEntries = 0; + container->iEntriesLength = 0; + container = container->iLink; + } + } + + void Add(Object* aObject) + { + if(iNumEntries>=iEntriesLength) + { + iEntriesLength += 128; + iEntries = (Entry*)realloc(iEntries,iEntriesLength*sizeof(Entry)); + ASSERT(iEntries); + } + aObject->iIndex = iNumEntries; + Entry& entry = iEntries[iNumEntries++]; + entry.iTraceId = aObject->iTraceId; + entry.iItem = aObject; + } + + TUint Count() + { + return iNumEntries; + } + + Object* operator[](TInt aIndex) + { + if(TUint(aIndex)end) + { + --ptr; + if(ptr->iTraceId==aTraceId) + { + if(ptr->iItem->iAlive) + return ptr->iItem; + else + break; + } + } + return 0; + } +private: + struct Entry + { + TUint32 iTraceId; + Object* iItem; + }; + TUint iNumEntries; + TUint iEntriesLength; + Entry* iEntries; + ObjectContainer* iLink; + + static ObjectContainer* iAllContainers; + }; +ObjectContainer* ObjectContainer::iAllContainers = 0; + + +#define GENERIC_OBJECT_DEFINITIONS(C) \ + \ + static C* Find(TUint32 aTraceId) \ + { \ + return (C*)iContainer.Find(aTraceId); \ + } \ + \ + static C* Create(TraceRecord& aTrace, TUint aIndex) \ + { \ + TUint32 traceId = aTrace.iData[aIndex]; \ + C* object = new C(traceId); \ + aTrace.iDataTypes[aIndex] = EDataTypeObject; \ + aTrace.iData[aIndex] = (uintptr_t)object; \ + return object; \ + } \ + \ + static C* Find(TraceRecord& aTrace, TUint aIndex) \ + { \ + TUint32 traceId = aTrace.iData[aIndex]; \ + C* object = Find(traceId); \ + if(!object) \ + return 0; \ + aTrace.iDataTypes[aIndex] = EDataTypeObject; \ + aTrace.iData[aIndex] = (uintptr_t)object; \ + return object; \ + } \ + \ + static C* FindOrCreate(TraceRecord& aTrace, TUint aIndex) \ + { \ + C* object = Find(aTrace,aIndex); \ + if(!object) \ + object = Create(aTrace,aIndex); \ + return object; \ + } + + + +// +// Process +// + +class Process : public Object + { +public: + Process(TUint32 aTraceId) + : Object(aTraceId,"P"), iThreadCount(0), iMaxThreadCount(0) + { + iContainer.Add(this); + } + + GENERIC_OBJECT_DEFINITIONS(Process); + +public: + TUint iThreadCount; + TUint iMaxThreadCount; + + static ObjectContainer iContainer; + }; +ObjectContainer Process::iContainer; + + + +// +// Thread +// +class FastMutex; +class Thread : public Object + { +public: + Thread(TUint32 aTraceId) + : Object(aTraceId,"T"), iId(~0u), iCpuTime(0), iSamples(0) + { + iContainer.Add(this); + iNameLength = (TUint8)MakeName(iName,"NThread-",aTraceId); + } + + TUint64 CpuTime() + { + if(!iLastCpu || !iLastCpu->iBaseTimestamp) + return 0; + if(iLastCpu->iCurrentThread==this) + return iCpuTime + Timestamp - iLastCpu->iBaseTimestamp; + return iCpuTime; + } + + void Sampled() + { + if( iSamples+1 != 0xFFFFFFFF) + { + iSamples++; + } + } + + GENERIC_OBJECT_DEFINITIONS(Thread); + + static Object* FindThreadOrProcess(TraceRecord& aTrace, TUint aIndex) + { + if (!aTrace.iData[aIndex]) + return 0; + Object* p = Find(aTrace, aIndex); + if (!p) + p = Process::Find(aTrace, aIndex); + return p; + } +public: + TUint32 iId; + Cpu* iLastCpu; + TUint64 iCpuTime; + TUint64 iFMBlockStartTime; + FastMutex* iWaitFastMutex; + + // Number of profiling samples + TUint32 iSamples; + + static ObjectContainer iContainer; + }; + +ObjectContainer Thread::iContainer; + + + +// +// Chunk +// + +TUint ChunkErrors = 0; + +const TUint KPageShift = 12; // chunk memory is allocated in 4kB pages + +class Chunk : public Object + { +public: + Chunk(TUint32 aTraceId) + : Object(aTraceId,"C"), iCurrentSize(0), iPeakSize(0), iMaxSize(0), iPageMap(0), iTraceErrors(0) + { + iContainer.Add(this); + } + + ~Chunk() + { + free(iPageMap); + } + + void SetMaxSize(TUint32 aMaxSize) + { + ASSERT(!iMaxSize); + iMaxSize = aMaxSize; + TUint mapSize = ((aMaxSize>>KPageShift)+7)>>3; + iPageMap = (TUint8*)malloc(mapSize); + ASSERT(iPageMap); + memset(iPageMap,0,mapSize); + iCurrentSize = 0; + } + + void Commit(TUint32 aStart,TUint32 aSize) + { + if(!iPageMap) // we havent been intialised yet + return; + + if(aStart+aSizeiMaxSize) + { + ++iTraceErrors; + ++ChunkErrors; + return; + } + if(SetBits(iPageMap,aStart>>KPageShift,aSize>>KPageShift)) + { + ++iTraceErrors; + ++ChunkErrors; + ErrorOnThisTrace = true; + } + } + + void Decommit(TUint32 aStart,TUint32 aSize) + { + if(!iPageMap) // we havent been intialised yet + return; + + // Decommit is complicated by the fact that aSize is the number of pages + // actually decommited, which may be less than the region of the original + // chunk decommit operation. E.g. if pages 1 and 3 were originally decommited + // and the decommit operation was for pages 0-3, then the trace has a size of + // 2 pages, even though the operation was on 4 pages. + // We handle this, repeatedly decommiting from our iPageMap, until we have + // freed aSize bytes worth of pages... + while(aSize) + { + if(aStart+aSizeiMaxSize) + { + // we haven't found enough memory to decommit + ++iTraceErrors; + ++ChunkErrors; + ErrorOnThisTrace = true; + return; + } + TUint notDecommitted = ClearBits(iPageMap,aStart>>KPageShift,aSize>>KPageShift); + aStart += aSize; + aSize = notDecommitted<CpuTime(); + if (aThread->iWaitFastMutex == this) + { + time = (TUint32)(Timestamp - aThread->iFMBlockStartTime); + } + aThread->iWaitFastMutex = 0; + return time; + } + + void Block(Thread* aThread) + { + if (aThread->iWaitFastMutex != this) + { + aThread->iFMBlockStartTime = Timestamp; + aThread->iWaitFastMutex = this; + ++iBlockCount; + } + }; + + TUint32 Signal(Thread* aThread, TUint32 aPc) + { + if (!iHoldingThread) // First record for this mutex so ignore it as don't + return 0; // have waiting thread details + + if(iHoldingThread!=aThread) + { + ++FastMutexNestErrors; + ErrorOnThisTrace = true; + iHoldingThread = 0; + return 0; + } + iHoldingThread = 0; + TUint64 time = aThread->CpuTime()-iWaitCpuTimeBase; + ++iHeldCount; + iTotalHeldTime += time; + if(time>iMaxHeldTime) + { + iMaxHeldTime = time; + iMaxHeldPc = aPc; + iMaxHeldTimestamp = Timestamp; + } + return (TUint32)time; + } + + GENERIC_OBJECT_DEFINITIONS(FastMutex); + +public: + Thread* iHoldingThread; + TUint32 iHeldCount; // number of times mutex acquired + TUint64 iTotalHeldTime; + TUint64 iWaitCpuTimeBase; + TUint64 iMaxHeldTime; + TUint64 iMaxHeldTimestamp; + TUint32 iMaxHeldPc; + TUint32 iBlockCount; // number of times mutex caused a thread to wait + + static ObjectContainer iContainer; + }; +ObjectContainer FastMutex::iContainer; + + + + +// +// ProfilingSample +// + +TUint ProfilingSampleErrors = 0; + +class ProfilingSample : public Object + { +public: + ProfilingSample(TUint32 aTraceId) + : Object(aTraceId,"PS") + { + iContainer.Add(this); + iNameLength = (TUint8)MakeName(iName,"ProfilingSample-",aTraceId); + } + + void SetPC( TUint32 aPC ) + { + iPC = aPC; + } + + void SetThread( TUint32 aThread ) + { + if( 0 != aThread ) + iThread = aThread; + } + + void SetType(const BTrace::TProfiling aType) + { + iType = aType; + } + + GENERIC_OBJECT_DEFINITIONS(ProfilingSample); + + +public: + + static ObjectContainer iContainer; + static Thread* iTopTen[10]; + static TUint32 iSamples; + static TUint32 iLastThread; + + TUint32 iPC; + TUint32 iThread; + BTrace::TProfiling iType; + + }; + +TUint32 ProfilingSample::iSamples = 0; +TUint32 ProfilingSample::iLastThread = 0; + +ObjectContainer ProfilingSample::iContainer; + + +// +// EThreadIdentification traces +// + +void PreProcessThreadIdentification(TraceRecord& aTrace) + { + Thread* thread; + Process* process; + + switch((BTrace::TThreadIdentification)aTrace.iSubCategory) + { + case BTrace::ENanoThreadCreate: + CHECK_TRACE_DATA_WORDS(1); + thread = Thread::FindOrCreate(aTrace,0); + break; + + case BTrace::ENanoThreadDestroy: + CHECK_TRACE_DATA_WORDS(1); + thread = Thread::Find(aTrace,0); + if(thread) + thread->Destroy(); + break; + + case BTrace::EThreadCreate: + case BTrace::EThreadName: + CHECK_TRACE_DATA_WORDS(2); + thread = Thread::FindOrCreate(aTrace,0); + if(aTrace.iSubCategory==BTrace::EThreadCreate) + ++thread->iAlive; // thread needs destroying twice (ENanoThreadDestroy+EThreadDestroy) + process = Process::FindOrCreate(aTrace,1); + thread->iOwner = process; + ++process->iThreadCount; + if(process->iThreadCount>process->iMaxThreadCount) + process->iMaxThreadCount = process->iThreadCount; + thread->SetName(aTrace,2); + break; + + case BTrace::EThreadDestroy: + CHECK_TRACE_DATA_WORDS(1); + thread = Thread::Find(aTrace,0); + if(thread) + { + thread->Destroy(); + process = (Process*)thread->iOwner; + if(process && process->iThreadCount) + --process->iThreadCount; + } + break; + + case BTrace::EProcessName: + CHECK_TRACE_DATA_WORDS(2); + if(aTrace.iData[0]) + { + thread = Thread::FindOrCreate(aTrace,0); + process = Process::Find(aTrace.iData[1]); + if(!process || (process->iNameLength && !process->IsName(aTrace.iData+2,aTrace.iDataSize-2*4))) + { + if(process) + process->Destroy(); + process = Process::Create(aTrace,1); // no existing process, or name different + } + else + process = Process::Find(aTrace,1); // find again (this will update trace data[1]) + } + else + process = Process::Find(aTrace,1); + if(process) + process->SetName(aTrace,2); + break; + + case BTrace::EThreadId: + CHECK_TRACE_DATA_WORDS(2); + thread = Thread::FindOrCreate(aTrace,0); + process = Process::FindOrCreate(aTrace,1); + thread->iId = aTrace.iData[2]; + break; + + case BTrace::EProcessCreate: + CHECK_TRACE_DATA_WORDS(1); + process = Process::FindOrCreate(aTrace,0); + break; + + case BTrace::EProcessDestroy: + CHECK_TRACE_DATA_WORDS(1); + process = Process::FindOrCreate(aTrace,0); + if(process) + process->Destroy(); + break; + + default: + break; + } + } + + +// +// ECpuUsage traces +// + +Cpu TheCpus[KMaxCpus]; +TUint InterruptNestErrors = 0; +TUint CpuUsagePresent = 0; + +Cpu::Cpu() + : iCurrentContext(EContextUnknown), + iFiqNest(0), + iIrqNest(0), + iIDFCNest(0), + iFiqTime(0), + iIrqTime(0), + iIDFCTime(0), + iCurrentThread(0), + iBaseTimestamp(0) + { + } + +void Cpu::Reset() + { + iCurrentContext = EContextUnknown; + iFiqNest = 0; + iIrqNest = 0; + iIDFCNest = 0; + iCurrentThread = 0; + iBaseTimestamp = 0; + } + +void ResetCpuUsage() + { + TInt i; + for (i=0; iiCpuTime += delta; + break; + case EContextFiq: + iFiqTime += delta; + break; + case EContextIrq: + iIrqTime += delta; + break; + case EContextIDFC: + iIDFCTime += delta; + break; + default: + break; + } + + if(aType==EContextUnknown) + { + if(iFiqNest) + aType = EContextFiq; + else if(iIrqNest) + aType = EContextIrq; + else if(iIDFCNest) + aType = EContextIDFC; + else + { + aType = EContextThread; + aThread = iCurrentThread; + } + } + + if(aType==EContextThread && !aThread) + { + iCurrentContext = EContextUnknown; + iBaseTimestamp = 0; + return; + } + + iCurrentContext = aType; + if(aType==EContextThread) + { + iCurrentThread = aThread; + aThread->iLastCpu = this; + } + + iBaseTimestamp = Timestamp; + } + + +void PreProcessCpuUsage(TraceRecord& aTrace) + { + CpuUsagePresent = true; + Cpu& cpu = *aTrace.iCpu; + + switch((BTrace::TCpuUsage)aTrace.iSubCategory) + { + case BTrace::EIrqStart: + ++cpu.iIrqNest; + cpu.ChangeContext(EContextIrq); + break; + + case BTrace::EFiqStart: + ++cpu.iFiqNest; + cpu.ChangeContext(EContextFiq); + break; + + case BTrace::EIDFCStart: + if(cpu.iIrqNest+cpu.iFiqNest>1 || cpu.iIDFCNest!=0) + { + ++InterruptNestErrors; + ErrorOnThisTrace = true; + } + cpu.iIrqNest = 0; + cpu.iFiqNest = 0; + cpu.iIDFCNest = 1; + cpu.ChangeContext(EContextIDFC); + break; + + case BTrace::EIrqEnd: + if(cpu.iIrqNest) + --cpu.iIrqNest; + else + { + ++InterruptNestErrors; + ErrorOnThisTrace = true; + } + cpu.ChangeContext(EContextUnknown); + break; + + case BTrace::EFiqEnd: + if(cpu.iFiqNest) + --cpu.iFiqNest; + else + { + ++InterruptNestErrors; + ErrorOnThisTrace = true; + } + cpu.ChangeContext(EContextUnknown); + break; + + case BTrace::EIDFCEnd: + if(cpu.iIDFCNest!=1) + { + ++InterruptNestErrors; + ErrorOnThisTrace = true; + } + cpu.iIDFCNest = 0; + cpu.ChangeContext(EContextUnknown); + break; + + case BTrace::ENewThreadContext: + if(cpu.iIrqNest+cpu.iFiqNest>1 || cpu.iIDFCNest!=0) + { + ++InterruptNestErrors; + ErrorOnThisTrace = true; + } + cpu.iIrqNest = 0; + cpu.iFiqNest = 0; + cpu.iIDFCNest = 0; + cpu.ChangeContext(EContextThread,aTrace.iContextID); + break; + } + } + + +void ReportThreads() + { + TUint numThreads = Thread::iContainer.Count(); + if(!numThreads) + return; + + TUint64 totalTime = 0; + printf("\nREPORT: Threads\n\n"); + WarnIfError(0); + printf("%-10s %5s %10s %8s %s\n","","State","CPUTime","TraceId","Name"); + TUint i; + for(i=0; iFullName(fullName); + Object::TraceNameBuf name; + thread->TraceName(name); + printf("%-10s %5s %10d %08x '%s'\n",name, + thread->iAlive?(const char*)"Alive":(const char*)"Dead", + (int)Time(thread->iCpuTime),(int)thread->iTraceId,fullName); + totalTime += thread->iCpuTime; + } + for (i=0; i<(TUint)KMaxCpus; ++i) + { + printf("CPU %1d\n", i); + Cpu& cpu = TheCpus[i]; + printf("%-10s %5s %10d %s\n","FIQ","",(int)Time(cpu.iFiqTime),""); + printf("%-10s %5s %10d %s\n","IRQ","",(int)Time(cpu.iIrqTime),""); + printf("%-10s %5s %10d %s\n","IDFC","",(int)Time(cpu.iIDFCTime),""); + totalTime += cpu.iFiqTime + cpu.iIrqTime + cpu.iIDFCTime; + } + printf("%-10s %5s ----------\n","",""); + printf("%-10s %5s %10d\n","","",(int)Time(totalTime)); + printf("\n"); + } + + +void ReportProcesses() + { + TUint numProcesses = Process::iContainer.Count(); + if(!numProcesses) + return; + + printf("\nREPORT: Processes\n\n"); + WarnIfError(0); + printf("%-10s %5s %7s %8s %s\n","","State","Threads","TraceId","Name"); + TUint i; + for(i=0; iFullName(fullName); + Object::TraceNameBuf name; + process->TraceName(name); + printf("%-10s %5s %3u/%-3u %08x '%s'\n",name, + process->iAlive?(const char*)"Alive":(const char*)"Dead", + (unsigned int)process->iThreadCount,(unsigned int)process->iMaxThreadCount, + (unsigned int)process->iTraceId,fullName); + } + printf("\n"); + } + + +void EndCpuUsage() + { + TInt i; + for (i=0; iSetName(aTrace,2); + chunk->SetMaxSize(aTrace.iData[1]); + // start by assuming thread is 'owned' by the thread which created it... + chunk->iOwner = aTrace.iContextID; + break; + + case BTrace::EChunkInfo: + CHECK_TRACE_DATA_WORDS(3); + break; // ignore + + case BTrace::EChunkDestroyed: + chunk->Destroy(); + break; + + case BTrace::EChunkMemoryAllocated: + { + CHECK_TRACE_DATA_WORDS(3); + chunk->Commit(aTrace.iData[1],aTrace.iData[2]); + TUint32 size = chunk->iCurrentSize+aTrace.iData[2]; + if(sizeiCurrentSize || size>chunk->iMaxSize) + size = chunk->iMaxSize; + chunk->iCurrentSize = size; + if(size>chunk->iPeakSize) + chunk->iPeakSize = size; + aTrace.iCalculatedData[0] = size/1024; + } + break; + + case BTrace::EChunkMemoryDeallocated: + { + CHECK_TRACE_DATA_WORDS(3); + chunk->Decommit(aTrace.iData[1],aTrace.iData[2]); + TUint32 size = chunk->iCurrentSize-aTrace.iData[2]; + if(size>chunk->iCurrentSize) + size = 0; + chunk->iCurrentSize = size; + aTrace.iCalculatedData[0] = size/1024; + } + break; + + case BTrace::EChunkMemoryAdded: + CHECK_TRACE_DATA_WORDS(3); + chunk->Commit(aTrace.iData[1],aTrace.iData[2]); + break; + + case BTrace::EChunkMemoryRemoved: + CHECK_TRACE_DATA_WORDS(3); + chunk->Decommit(aTrace.iData[1],aTrace.iData[2]); + break; + + case BTrace::EChunkOwner: + { + CHECK_TRACE_DATA_WORDS(2); + Process* process = Process::FindOrCreate(aTrace,1); + // set owner, unless current owner is owned by the same process + // (this preserves creating thread names in ownership list which is more useful) + if(!chunk->iOwner || chunk->iOwner->iOwner!=process) + chunk->iOwner = process; + } + break; + + } + } + + +void ReportChunks() + { + TUint numChunks = Chunk::iContainer.Count(); + if(!numChunks) + return; + + if(!ReportLevel) + printf("\nREPORT: Chunks (Named objects only)\n\n"); + else + printf("\nREPORT: Chunks\n\n"); + WarnIfError(ChunkErrors); + printf("%-10s %5s %8s %8s %8s %8s %s\n", + "","State","Size","Peak","Max","TraceId","Name"); + TUint totalSize = 0; + TUint i; + for(i=0; iiNameSet) + continue; // only report explicitly named mutexes at report level 0 + Object::FullNameBuf fullName; + chunk->FullName(fullName); + Object::TraceNameBuf name; + chunk->TraceName(name); + printf("%-10s %5s %7uk %7uk %7uk %08x '%s'\n", + name,chunk->iAlive?(const char*)"Alive":(const char*)"Dead", + (unsigned int)chunk->iCurrentSize/1024,(unsigned int)chunk->iPeakSize/1024,(unsigned int)chunk->iMaxSize/1024, + (unsigned int)chunk->iTraceId,fullName); + totalSize += chunk->iCurrentSize/1024; + } + printf("%-10s %5s --------\n","",""); + printf("%-10s %5s %7uk\n","","",totalSize); + printf("\n"); + } + + + +// +// CodeSeg +// + +void StartCodeSegs() + { + CodeSegErrors = 0; + } + + +void PreProcessCodeSegs(TraceRecord& aTrace) + { + CHECK_TRACE_DATA_WORDS(1); + CodeSeg* codeseg; + + switch((BTrace::TCodeSegs)aTrace.iSubCategory) + { + case BTrace::ECodeSegCreated: + codeseg = CodeSeg::FindOrCreate(aTrace,0); + codeseg->SetName(aTrace,1); + break; + + case BTrace::ECodeSegInfo: + CHECK_TRACE_DATA_WORDS(10); + CodeSeg::FindOrCreate(aTrace,0); +/* - 4 bytes containing the attributes. + - 4 bytes containing the code base address (.text). + - 4 bytes containing the size of the code section (.text). + - 4 bytes containing the base address of the constant data section (.radata). + - 4 bytes containing the size of the constant data section (.radata). + - 4 bytes containing the base address of the initialised data section (.data). + - 4 bytes containing the size of the initialised data section (.data). + - 4 bytes containing the base address of the uninitialised data section (.bss). + - 4 bytes containing the size of the uninitialised data section (.bss). +*/ break; + + case BTrace::ECodeSegDestroyed: + codeseg = CodeSeg::FindOrCreate(aTrace,0); + codeseg->Destroy(); + codeseg->iAllocatedMemory = 0; // clear this now because ECodeSegMemoryDeallocated comes after codeseg destroy + break; + + case BTrace::ECodeSegMapped: + CHECK_TRACE_DATA_WORDS(2); + codeseg = CodeSeg::FindOrCreate(aTrace,0); + Process::FindOrCreate(aTrace,1); + break; + + case BTrace::ECodeSegUnmapped: + CHECK_TRACE_DATA_WORDS(2); + CodeSeg::FindOrCreate(aTrace,0); + Process::FindOrCreate(aTrace,1); + break; + + case BTrace::ECodeSegMemoryAllocated: + CHECK_TRACE_DATA_WORDS(2); + codeseg = CodeSeg::FindOrCreate(aTrace,0); + codeseg->iAllocatedMemory += aTrace.iData[1]; + if(codeseg->iAllocatedMemoryiAllocatedMemory = ~0u; // overflowed! + ++CodeSegErrors; + ErrorOnThisTrace = true; + } + break; + + case BTrace::ECodeSegMemoryDeallocated: + { + CHECK_TRACE_DATA_WORDS(2); + codeseg = CodeSeg::Find(aTrace,0); + if(codeseg) + { + TUint32 memory = codeseg->iAllocatedMemory-aTrace.iData[1]; + if(memory>codeseg->iAllocatedMemory) + { + memory = 0; // underflowed + ++CodeSegErrors; + ErrorOnThisTrace = true; + } + codeseg->iAllocatedMemory = memory; + } + } + break; + + } + } + + +void ReportCodeSegs() + { + TUint numCodeSegs = CodeSeg::iContainer.Count(); + if(!numCodeSegs) + return; + + if(!ReportLevel) + printf("\nREPORT: CodeSegs (Named objects only)\n\n"); + else + printf("\nREPORT: CodeSegs\n\n"); + WarnIfError(CodeSegErrors); + printf("%-10s %5s %8s %8s %s\n", + "","State","Memory","TraceId","Name"); + TUint totalSize = 0; + TUint i; + for(i=0; iiNameSet) + continue; // only report explicitly named mutexes at report level 0 + Object::FullNameBuf fullName; + codeseg->FullName(fullName); + Object::TraceNameBuf name; + codeseg->TraceName(name); + printf("%-10s %5s %7uk %08x '%s'\n", + name,codeseg->iAlive?(const char*)"Alive":(const char*)"Dead", + (unsigned int)codeseg->iAllocatedMemory/1024,(unsigned int)codeseg->iTraceId,fullName); + totalSize += codeseg->iAllocatedMemory/1024; + } + printf("%-10s %5s --------\n","",""); + printf("%-10s %5s %7uk\n","","",totalSize); + printf("\n"); + } + + + +// +// MetaTrace +// + +TUint KernelMemoryInitialFree = 0; +TUint KernelMemoryCurrentFree = 0; +TUint KernelMemoryMisc = 0; +TUint KernelMemoryDrvPhys = 0; +TUint KernelMemoryDemandPagingCache = 0; +TUint KernelMemoryErrors = 0; +TBool KernelMemoryTracesPresent = false; + +void StartKernelMemory() + { + KernelMemoryInitialFree = 0; + KernelMemoryCurrentFree = 0; + KernelMemoryMisc = 0; + KernelMemoryDrvPhys = 0; + KernelMemoryErrors = 0; + KernelMemoryTracesPresent = false; + } + + +void PreProcessKernelMemory(TraceRecord& aTrace) + { + CHECK_TRACE_DATA_WORDS(1); + KernelMemoryTracesPresent = true; + switch((BTrace::TKernelMemory)aTrace.iSubCategory) + { + case BTrace::EKernelMemoryInitialFree: + KernelMemoryInitialFree = aTrace.iData[0]; + aTrace.iCalculatedData[0] = KernelMemoryInitialFree/1024; + break; + + case BTrace::EKernelMemoryCurrentFree: + KernelMemoryCurrentFree = aTrace.iData[0]; + aTrace.iCalculatedData[0] = KernelMemoryCurrentFree/1024; + break; + + case BTrace::EKernelMemoryMiscAlloc: + KernelMemoryMisc += aTrace.iData[0]; + if(KernelMemoryMisc < aTrace.iData[0]) + { + KernelMemoryMisc = 0xffffffffu; + ++KernelMemoryErrors; + ErrorOnThisTrace = true; + } + aTrace.iCalculatedData[0] = KernelMemoryMisc/1024; + break; + + case BTrace::EKernelMemoryMiscFree: + if(KernelMemoryMisc >= aTrace.iData[0]) + KernelMemoryMisc -= aTrace.iData[0]; + else + { + KernelMemoryMisc = 0; + ++KernelMemoryErrors; + ErrorOnThisTrace = true; + } + aTrace.iCalculatedData[0] = KernelMemoryMisc/1024; + break; + + case BTrace::EKernelMemoryDemandPagingCache: + KernelMemoryDemandPagingCache = aTrace.iData[0]; + break; + + case BTrace::EKernelMemoryDrvPhysAlloc: + KernelMemoryDrvPhys += aTrace.iData[0]; + if(KernelMemoryDrvPhys < aTrace.iData[0]) + { + KernelMemoryDrvPhys = 0xffffffffu; + ++KernelMemoryErrors; + ErrorOnThisTrace = true; + } + aTrace.iCalculatedData[0] = KernelMemoryDrvPhys/1024; + break; + + case BTrace::EKernelMemoryDrvPhysFree: + if(KernelMemoryDrvPhys >= aTrace.iData[0]) + KernelMemoryDrvPhys -= aTrace.iData[0]; + else + { + KernelMemoryDrvPhys = 0; + ++KernelMemoryErrors; + ErrorOnThisTrace = true; + } + aTrace.iCalculatedData[0] = KernelMemoryDrvPhys/1024; + break; + } + } + +void ReportKernelMemory() + { + if(!KernelMemoryTracesPresent) + return; + + printf("\nREPORT: Kernel Memory\n\n"); + WarnIfError(KernelMemoryErrors); + printf("Total RAM size............................. %dk\n",KernelMemoryInitialFree/1024); + printf("Miscelaneous RAM used by kernel............ %dk\n",KernelMemoryMisc/1024); + printf("Physical RAM allocated by device drivers... %dk\n",KernelMemoryDrvPhys/1024); + printf("Demand paging cache reserve................ %dk\n",KernelMemoryDemandPagingCache/1024); + if(ReportLevel>1) + printf("Last 'current free RAM' value seen......... %dk\n",KernelMemoryCurrentFree/1024); + + printf("\n"); + } + +// +// MetaTrace +// + +void StartMetaTrace() + { + TimestampPeriod = 0; + Timestamp2Period = 0; + } + + +void PreProcessMetaTrace(TraceRecord& aTrace) + { + switch((BTrace::TMetaTrace)aTrace.iSubCategory) + { + case BTrace::EMetaTraceTimestampsInfo: + CHECK_TRACE_DATA_WORDS(3); + TimestampPeriod = aTrace.iData[0]; + Timestamp2Period = aTrace.iData[1]; + Timestamp64Bit = aTrace.iData[2]&1; + break; + + case BTrace::EMetaTraceMeasurementStart: + case BTrace::EMetaTraceMeasurementEnd: + CHECK_TRACE_DATA_WORDS(2); + aTrace.iDataTypes[2] = EDataTypeText; + break; + + case BTrace::EMetaTraceFilterChange: + CHECK_TRACE_DATA_WORDS(1); + break; + } + } + +// +// EFastMutex traces +// + +void StartFastMutex() + { + FastMutexNestErrors = 0; + } + + +void PreProcessFastMutex(TraceRecord& aTrace) + { + CHECK_TRACE_DATA_WORDS(1); + FastMutex* mutex = FastMutex::FindOrCreate(aTrace,0); + Thread* thread = aTrace.iContextID; + + switch((BTrace::TFastMutex)aTrace.iSubCategory) + { + case BTrace::EFastMutexWait: + aTrace.iCalculatedData[0] = Time(mutex->Wait(thread)); + break; + + case BTrace::EFastMutexSignal: + aTrace.iCalculatedData[0] = Time(mutex->Signal(thread,aTrace.iPC)); + break; + + case BTrace::EFastMutexFlash: + aTrace.iCalculatedData[0] = Time(mutex->Signal(thread,aTrace.iPC)); + mutex->Wait(thread); + break; + + case BTrace::EFastMutexName: + CHECK_TRACE_DATA_WORDS(2); + mutex->SetName(aTrace,2); + break; + + case BTrace::EFastMutexBlock: + mutex->Block(thread); + break; + + } + } + + +void PreProcessSymbianKernelSync(TraceRecord& aTrace) + { + switch((BTrace::TSymbianKernelSync)aTrace.iSubCategory) + { + case BTrace::ESemaphoreCreate: + { + CHECK_TRACE_DATA_WORDS(2); + TUint32 ownerid = aTrace.iData[1]; + Semaphore* sem = Semaphore::FindOrCreate(aTrace,0); + Object* owner = Thread::FindThreadOrProcess(aTrace,1); + sem->iOwner = owner; + if (!owner && ownerid) + sem->iOwnerTraceId = ownerid, ++Object::UnknownOwners; + sem->SetName(aTrace,2); + break; + } + + case BTrace::ESemaphoreDestroy: + { + CHECK_TRACE_DATA_WORDS(1); + Semaphore* sem = Semaphore::Find(aTrace,0); + if (sem) + sem->Destroy(); + break; + } + + case BTrace::ESemaphoreAcquire: + case BTrace::ESemaphoreRelease: + case BTrace::ESemaphoreBlock: + { + CHECK_TRACE_DATA_WORDS(1); + Semaphore::FindOrCreate(aTrace,0); + break; + } + + + case BTrace::EMutexCreate: + { + CHECK_TRACE_DATA_WORDS(2); + TUint32 ownerid = aTrace.iData[1]; + Mutex* m = Mutex::FindOrCreate(aTrace,0); + Object* owner = Thread::FindThreadOrProcess(aTrace,1); + m->iOwner = owner; + if (!owner && ownerid) + m->iOwnerTraceId = ownerid, ++Object::UnknownOwners; + m->SetName(aTrace,2); + break; + } + + case BTrace::EMutexDestroy: + { + CHECK_TRACE_DATA_WORDS(1); + Mutex* m = Mutex::Find(aTrace,0); + if (m) + m->Destroy(); + break; + } + + case BTrace::EMutexAcquire: + case BTrace::EMutexRelease: + case BTrace::EMutexBlock: + { + CHECK_TRACE_DATA_WORDS(1); + Mutex::FindOrCreate(aTrace,0); + break; + } + + + case BTrace::ECondVarCreate: + { + CHECK_TRACE_DATA_WORDS(2); + TUint32 ownerid = aTrace.iData[1]; + CondVar* cv = CondVar::FindOrCreate(aTrace,0); + Object* owner = Thread::FindThreadOrProcess(aTrace,1); + cv->iOwner = owner; + if (!owner && ownerid) + cv->iOwnerTraceId = ownerid, ++Object::UnknownOwners; + cv->SetName(aTrace,2); + break; + } + + case BTrace::ECondVarDestroy: + { + CHECK_TRACE_DATA_WORDS(1); + CondVar* cv = CondVar::Find(aTrace,0); + if (cv) + cv->Destroy(); + break; + } + + case BTrace::ECondVarBlock: + case BTrace::ECondVarWakeUp: + case BTrace::ECondVarSignal: + case BTrace::ECondVarBroadcast: + { + CHECK_TRACE_DATA_WORDS(1); + CondVar::FindOrCreate(aTrace,0); + break; + } + + + default: + break; + } + } + + +void ReportFastMutex() + { + TUint numMutexes = FastMutex::iContainer.Count(); + if(!numMutexes) + return; + + if(!ReportLevel) + printf("\nREPORT: FastMutexes (Named objects only)\n\n"); + else + printf("\nREPORT: FastMutexes\n\n"); + WarnIfError(0); + printf("%-10s %8s %8s %10s %10s %-8s %12s %8s %s\n", + "","MaxTime","AveTime","HeldCount","BlockCount","MaxPC","MaxTimestamp","TraceId","Name"); + TUint i; + for(i=0; iiNameSet) + continue; // only report explicitly named mutexes at report level 0 + Object::FullNameBuf fullName; + mutex->FullName(fullName); + Object::TraceNameBuf name; + mutex->TraceName(name); + TUint32 averageHeldTime = mutex->iHeldCount ? Time(mutex->iTotalHeldTime/mutex->iHeldCount) : 0; + printf("%-10s %8u %8u %10u %10u %08x %12u %08x '%s'\n", + name,(unsigned int)Time(mutex->iMaxHeldTime),(unsigned int)averageHeldTime,(unsigned int)mutex->iHeldCount,(unsigned int)mutex->iBlockCount, + (unsigned int)mutex->iMaxHeldPc,(unsigned int)Time(mutex->iMaxHeldTimestamp-TimestampBase),(unsigned int)mutex->iTraceId,fullName); + } + printf("\n"); + } + + +// +// ProfilingSample +// + +void StartProfilingSample() + { + ProfilingSampleErrors = 0; + } + + +/** + Index 0 of TraceRecord is the program counter + The only one not having it are ECpuNonSymbianThreadSample samples. + Index 1 of TraceRecord is the NThread pointer. + The only one that has it is ECpuFullSample. + The samples are identified by their index, which is maintained by + ProfilingSample::iSamples. Thus to create a ProfilingSample object we + need to put this value in the data at index 0 after copying the PC + and Thread id (if present). + The reasoning is that all samples need to be represented and thus we + need to create a ProfilingSample object, even when they are on the same + PC and or thread. Each sample important and should not be discarded. +*/ +void PreProcessProfiling(TraceRecord& aTrace) + { + + ProfilingSample* sample; + Thread* thread; + + switch((BTrace::TProfiling)aTrace.iSubCategory) + { + + case BTrace::ECpuFullSample: + { + CHECK_TRACE_DATA_WORDS(2); + + TUint32 aThread = aTrace.iData[1]; + // The thread id is aTrace.iData[1], so find or create it + // This action can modify aTrace.iData[1], that is why we took a copy above + thread = Thread::FindOrCreate(aTrace,1); + if( thread ) + thread->Sampled(); + + TUint32 aPC = aTrace.iData[0]; + + // Always create a sample identified by the running counter ProfilingSample::iSamples + aTrace.iData[0] = ProfilingSample::iSamples; + sample = ProfilingSample::Create(aTrace,0); + if( sample ) + { + sample->SetPC( aPC ); + sample->SetThread( aThread ); + sample->SetType(BTrace::ECpuFullSample); + } + + ProfilingSample::iLastThread = aThread; + } + break; + + case BTrace::ECpuOptimisedSample: + { + CHECK_TRACE_DATA_WORDS(1); + TUint32 aPC = aTrace.iData[0]; + + aTrace.iData[0] = ProfilingSample::iSamples; + sample = ProfilingSample::Create(aTrace,0); + if( sample ) + { + sample->SetPC( aPC ); + sample->SetType( BTrace::ECpuOptimisedSample ); + sample->SetThread(ProfilingSample::iLastThread); + } + + if( 0 != ProfilingSample::iLastThread ) + { + thread = Thread::Find(ProfilingSample::iLastThread); + if( thread ) + { + thread->Sampled(); + } + } + + } + break; + + case BTrace::ECpuIdfcSample: + { + CHECK_TRACE_DATA_WORDS(1); + TUint32 aPC = aTrace.iData[0]; + + aTrace.iData[0] = ProfilingSample::iSamples; + sample = ProfilingSample::Create(aTrace,0); + + sample->SetPC( aPC ); + sample->SetType(BTrace::ECpuIdfcSample); + + } + break; + + case BTrace::ECpuNonSymbianThreadSample: + { + // No data + aTrace.iData[0] = ProfilingSample::iSamples; + sample = ProfilingSample::Create(aTrace,0); + sample->SetType(BTrace::ECpuNonSymbianThreadSample); + + } + break; + + default: + ProfilingSampleErrors++; + ErrorOnThisTrace = true; + } + + ProfilingSample::iSamples++; + + } + + +void ReportSampleProfiling() + { + printf("\nREPORT: Profiling\n\n"); + + TUint numSamples = ProfilingSample::iContainer.Count(); + if(!numSamples) + { + printf("\n No Samples\n\n"); + return; + } + + WarnIfError(0); + + + // Print thread samples + TUint numThreads = Thread::iContainer.Count(); + if(numThreads) + { + printf(" Samples by Thread\n\n"); + printf("%-11s %-8s %-8s\t%-12s\t%s\n\n", "", "TraceId", "Samples", "%", "Name"); + TUint i; + TReal threadPercentage; + for(i=0; iiSamples ) + { + Object::FullNameBuf fullName; + thread->FullName(fullName); + Object::TraceNameBuf name; + thread->TraceName(name); + + threadPercentage = thread->iSamples*100.0/numSamples; + + printf("%-10s %08x %8d\t%02.2f\t'%s'\n", + name, + (unsigned int)thread->iTraceId, + (unsigned int)(thread->iSamples), + threadPercentage, + fullName ); + + }//if samples + }//for numThreads + }//if threads + + + if(ReportLevel>0) + { + + printf("\nAll samples\n\n%-21s %-8s %-8s\n\n", "Type", "ThreadId", "PC"); + + TUint i; + TUint fullSamples = 0; + TUint optSamples = 0; + TUint dfcSamples = 0; + TUint nonSymbSamples = 0; + + for(i=0; iiType) + { + case BTrace::ECpuFullSample: + { + if( ReportLevel>1) + printf("ECpuFull %08x %08x\n", + (unsigned int)(sample->iThread), (unsigned int)(sample->iPC) ); + + fullSamples++; + } + break; + case BTrace::ECpuOptimisedSample: + { + if( ReportLevel>1) + printf("ECpuOptimised %08x %08x\n", + (unsigned int)(sample->iThread), (unsigned int)(sample->iPC) ); + + optSamples++; + } + break; + case BTrace::ECpuIdfcSample: + { + if( ReportLevel>1) + printf("ECpuIdfc %08x\n", (unsigned int)(sample->iPC) ); + + dfcSamples++; + } + break; + case BTrace::ECpuNonSymbianThreadSample: + { + if( ReportLevel>1) + printf("ECpuNonSymbianThread\n"); + + nonSymbSamples++; + } + break; + }//switch + }//for + + + TReal typePercentage; + + printf("\nSamples by type\n"); + + typePercentage = fullSamples * 100.0 / numSamples; + printf(" Samples of type ECpuFullSample :\t\t%-10d\t%02.2f %%\n", fullSamples, typePercentage ); + + typePercentage = optSamples * 100.0 / numSamples; + printf(" Samples of type ECpuOptimisedSample :\t\t%-10d\t%02.2f %%\n", optSamples, typePercentage ); + + typePercentage = dfcSamples * 100.0 / numSamples; + printf(" Samples of type ECpuIdfcSample :\t\t%-10d\t%02.2f %%\n", dfcSamples, typePercentage ); + + typePercentage = nonSymbSamples * 100.0 / numSamples; + printf(" Samples of type ECpuNonSymbianThreadSample :\t%-10d\t%02.2f %%\n", nonSymbSamples, typePercentage ); + + printf(" Total Samples : \t\t\t\t%d\n", numSamples ); + + }//report level + + printf("\n"); + } + +// +// Trace processing +// + +TraceRecord** TraceIndex = 0; +TUint TraceIndexSize = 0; +TUint32 NextTraceId = 0; +TraceRecord* LastTrace = 0; +TBool Timestamp2Present = 0; +TBool TraceDumpStarted = false; + + +void StartTrace() + { + TraceDumpStarted = false; + TraceFormatErrors = 0; + TraceBufferFilled = false; + Timestamp2Present = false; + } + + +TUint32 ReadTraceWord(const TUint8*& header) + { + TUint32 word; + memcpy(&word, header, sizeof(TUint32)); + header += sizeof(TUint32); + return word; + } + + +TBool PreProcessTrace(TraceRecord& aTrace, const TUint8* aData) + { + ErrorOnThisTrace = false; + aTrace.iError = 0; + + aTrace.iDataSize = 0; // initialise to safe value + + // process aTrace header... + TUint traceSize = aData[BTrace::ESizeIndex]; + if(traceSize<4u || traceSize>(TUint)KMaxBTraceRecordSize) + { + aTrace.iError = 1; + return false; // bad size + } + aTrace.iCpuNum = 0; + + TUint8 flags = aData[BTrace::EFlagsIndex]; + if(!TraceRecordId) // first trace record...? + flags &= ~BTrace::EMissingRecord; // ignore missing traces before log start + aTrace.iFlags = flags; + + TUint8 category = aData[BTrace::ECategoryIndex]; + aTrace.iCategory = category; + + TUint8 subCategory = aData[BTrace::ESubCategoryIndex]; + aTrace.iSubCategory = subCategory; + + const TUint8* header = aData+4; + + TUint32 header2 = 0; + if(flags&BTrace::EHeader2Present) + { + header2 = ReadTraceWord(header); + aTrace.iCpuNum = (TUint8)(header2>>20); + } + aTrace.iHeader2 = header2; + aTrace.iCpu = TheCpus + aTrace.iCpuNum; + + // process timestamp and timestamp2... + TUint32 ts1 = 0; + TUint32 ts2 = 0; + TUint64 timestamp = 0; + if(flags&BTrace::ETimestampPresent) + ts1 = ReadTraceWord(header); + if(flags&BTrace::ETimestamp2Present) + { + Timestamp2Present = true; + ts2 = ReadTraceWord(header); + } + aTrace.iTimestamp2 = ts2; + if(flags&BTrace::ETimestampPresent) + { + if (Timestamp64Bit) + { + timestamp = ts2; + timestamp <<= 32; + timestamp |= ts1; + Timestamp = timestamp; + } + else + { + timestamp = ts1; + if(timestamp<(Timestamp&0xffffffffu)) + Timestamp += TUint64(1)<<32; + Timestamp &= TUint64(0xffffffff)<<32; + Timestamp |= timestamp; + timestamp = Timestamp; + } + if(!TraceRecordId) + TimestampBase = timestamp; // record timestamp of first trace + } + aTrace.iTimestamp = timestamp; + + // process context... + // coverity[assign_zero] + aTrace.iContextID = 0; + if(flags&BTrace::EContextIdPresent) + { + TUint32 contextId = ReadTraceWord(header); + Thread* thread = Thread::Find(contextId); + if(!thread) + thread = new Thread(contextId); + aTrace.iContextID = thread; + } + + // process pc... + TUint32 pc = 0; + if(flags&BTrace::EPcPresent) + pc = ReadTraceWord(header); + aTrace.iPC = pc; + + // process extra... + TUint32 extra = 0; + if(flags&BTrace::EExtraPresent) + extra = ReadTraceWord(header); + aTrace.iExtra = extra; + + // process payload data... + TUint headerSize = header-aData; + aData = (TUint8*)header; + if(headerSize>traceSize) + { + aTrace.iError = 1; + return false; // bad trace record + } + TUint dataSize = traceSize-headerSize; + if(dataSize>sizeof(aTrace.iData)) + { + aTrace.iError = 1; + return false; // bad trace record + } + aTrace.iDataSize = dataSize; + memcpy(&aTrace.iData,aData,dataSize); + + // clear pre-processor specific data... + aTrace.iDataTypes[0] = 0; + aTrace.iDataTypes[1] = 0; + aTrace.iDataTypes[2] = 0; + aTrace.iDataTypes[3] = 0; + aTrace.iCalculatedData[0] = 0; + aTrace.iCalculatedData[1] = 0; + + // check for missing. + if(flags & BTrace::EMissingRecord) + {// Some trace was missing as the btrace buffer must have been filled. + TraceBufferFilled = true; + aTrace.iError = 1; + return false; + } + + // category specific processing... + switch(aTrace.iCategory) + { + case BTrace::ERDebugPrintf: + case BTrace::EKernPrintf: + case BTrace::EPlatsecPrintf: + if((flags&BTrace::EHeader2Present) && (header2&BTrace::EMultipartFlagMask)) + aTrace.iDataTypes[2] = EDataTypeText; + else + aTrace.iDataTypes[1] = EDataTypeText; + break; + case BTrace::EThreadIdentification: + PreProcessThreadIdentification(aTrace); break; + case BTrace::ECpuUsage: + PreProcessCpuUsage(aTrace); break; + case BTrace::EChunks: + PreProcessChunks(aTrace); break; + case BTrace::ECodeSegs: + PreProcessCodeSegs(aTrace); break; + case BTrace::EKernelMemory: + PreProcessKernelMemory(aTrace); break; + case BTrace::EMetaTrace: + PreProcessMetaTrace(aTrace); break; + case BTrace::EFastMutex: + PreProcessFastMutex(aTrace); break; + case BTrace::EProfiling: + PreProcessProfiling(aTrace); break; + case BTrace::ESymbianKernelSync: + PreProcessSymbianKernelSync(aTrace); break; + default: + break; + } + + // update trace ID... + ++TraceRecordId; + if (ErrorOnThisTrace) + aTrace.iError = 1; + return true; + } + + +void DumpTrace(TraceRecord& aTrace) + { + if(!TraceDumpStarted) + { + // print heading... + if(SMP) + printf("C "); + if(Timestamp2Present) + printf("%10s ","TimeStamp2"); + printf("%10s ","Time"); + printf("%-8s ","PC"); + if(ReportLevel>2) + { + printf("%-60s ","Context"); + printf("%18s ","Category"); + printf("%24s ","SubCategory"); + } + else + { + printf("%-10s ","Context"); + printf("%24s ","SubCategory"); + } + printf("Data...\n"); + TraceDumpStarted = true; + } + + if(aTrace.iFlags&BTrace::EMissingRecord) + printf("MISSING TRACE RECORD(S)\n"); + + // print CPU number + if (SMP) + { + printf("%1d ", aTrace.iCpuNum); + } + + // print timestamp... + if(Timestamp2Present) + { + if(aTrace.iFlags&BTrace::ETimestamp2Present) + printf("%10u ",(unsigned int)aTrace.iTimestamp2); + else + printf(" "); + } + + if(aTrace.iFlags&BTrace::ETimestampPresent) + printf("%10u ",(unsigned int)Time(aTrace.iTimestamp-TimestampBase)); + else + printf(" "); + + // print PC... + if(aTrace.iFlags&BTrace::EPcPresent) + printf("%08x ",(unsigned int)aTrace.iPC); + else + printf(" "); + + // print context... + if(ReportLevel>2) + { + Object::FullTraceNameBuf fullName; + fullName[0] = 0; + if(aTrace.iFlags&BTrace::EContextIdPresent) + aTrace.iContextID->FullTraceName(fullName); + printf("%-60s ",fullName); + } + else + { + Object::TraceNameBuf traceName; + traceName[0] = 0; + if(aTrace.iFlags&BTrace::EContextIdPresent) + aTrace.iContextID->TraceName(traceName); + printf("%-10s ",traceName); + } + // print trace categories... + const char* catName = CategoryName(aTrace.iCategory); + const char* subCatName = SubCategoryName(aTrace.iCategory,aTrace.iSubCategory); + if(ReportLevel>2) + printf("%18s %-24s ",catName,subCatName); + else + { + if(subCatName[0]) + printf("%24s ",subCatName); + else + printf("%24s ",catName); + }; + + // print trace data contents... + TUint i; + for(i=0; i2) + { + Object::FullTraceNameBuf name; + object->FullTraceName(name); + printf("%s ",name); + } + else + { + Object::TraceNameBuf name; + object->TraceName(name); + printf("%s ",name); + } + } + continue; + + case EDataTypeText: + { + // rest of trace is text... + TUint8* text = (TUint8*)aTrace.iData+i; + TUint8* textEnd = text+(aTrace.iDataSize-i); + TUint8 buffer[256]; + TUint x=0; + while(textiDataSize); + LastTrace = 0; + } + + +/** +Create a new trace record. +*/ +TraceRecord* NewTrace() + { + if(NextTraceId>=TraceIndexSize) + { + TraceIndexSize += 1024; + TraceIndex = (TraceRecord**)realloc(TraceIndex,TraceIndexSize*sizeof(TraceIndex[0])); + ASSERT(TraceIndex); + } + DoneTrace(); + LastTrace = (TraceRecord*)malloc(sizeof(TraceRecord)); + return LastTrace; + } + + +/** +Delete all processed traces records. +*/ +void ResetTrace() + { + DoneTrace(); + TUint i; + for(i=0; iBTrace::ESizeIndex) + { + TUint traceSize = (data[BTrace::ESizeIndex]+3)&~3; + if(traceSize>sizeRemaining) + break; + + TraceRecord* trace = NewTrace(); + ASSERT(trace); + if(!PreProcessTrace(*trace,data)) + { + if (!TraceBufferFilled) + { + // bad trace, create dummy 1 byte trace record... + memset(trace,0,sizeof(*trace)); + trace->iCategory = BTrace::EMetaTrace; + trace->iSubCategory = KJunkTraceSubcategory; + trace->iDataSize = 4; + trace->iData[0] = *data; + ++TraceFormatErrors; + ErrorOnThisTrace = true; + traceSize = 1; + } + else // The buffer was filled so ignore the rest of the data + break; + } + + data += traceSize; + sizeRemaining -= traceSize; + } + + if (!TraceBufferFilled) + { + memcpy(TraceBuffer,data,sizeRemaining); + TraceBufferSize = sizeRemaining; + } + else + { + // The trace buffer was filled so ignore the rest of the data + // and just read whatever is left to flush it from the btrace buffer. + while ((*aInput)(TraceBuffer, sizeof(TraceBuffer))){}; + TraceBufferSize = 0; // reset here so a format error isn't reported + } + + if(aReportLevel<2) + ResetTrace(); // free up memory as we go along + } + EndTrace(); + EndCpuUsage(); + + if(TraceBufferSize) + { + ++TraceFormatErrors; + ErrorOnThisTrace = true; + } + + ReportTimeUnits(); + ReportErrors(); + if(aReportLevel>=2) + DumpAllTraces(); + if(ReportLevel>=1 || CpuUsagePresent) + { + ReportProcesses(); + ReportThreads(); + } + ReportChunks(); + ReportKernelMemory(); + ReportCodeSegs(); + ReportFastMutex(); + ReportSampleProfiling(); + + ResetTrace(); + ObjectContainer::Reset(); +// __UHEAP_MARKEND; + } + +