/*---------------------------------------------------------------------------* Project: Horizon File: dbg_Instrument.cpp Copyright (C)2009-2012 Nintendo Co., Ltd. All rights reserved. These coded instructions, statements, and computer programs contain proprietary information of Nintendo of America Inc. and/or Nintendo Company Ltd., and are protected by Federal copyright law. They may not be disclosed to third parties or copied or duplicated in any form, in whole or in part, without the prior written consent of Nintendo. $Rev: 46347 $ *---------------------------------------------------------------------------*/ #include #include #include #include #include namespace { #define NN_DBG_INS_PRINTF_BUFFER_LENGTH 1024 void ins_VPrintf(const char* fmt, va_list arg) { char buf[NN_DBG_INS_PRINTF_BUFFER_LENGTH]; int length = ::std::vsnprintf(buf, sizeof(buf), fmt, arg); if (length >= NN_DBG_INS_PRINTF_BUFFER_LENGTH) { length = NN_DBG_INS_PRINTF_BUFFER_LENGTH - 1; // need not count \0 of tail end } NN_PUT(buf, length); } void ins_Printf(const char* fmt, ...) { va_list vlist; va_start(vlist, fmt); ins_VPrintf(fmt, vlist); va_end(vlist); } // Critical section for process exclusion nn::os::CriticalSection sCriticalSection = nn::WithInitialize(); // Measurement: List nn::dbg::CTR::Instrument* sListHead = NULL; // Measurement: function for output void (*sLogFuncForInstrument)( const char*, ... ) = ins_Printf; // Statistic: function for output void (*sLogFuncForStatistics)( const char*, ... ) = ins_Printf; } namespace nn { namespace dbg { namespace CTR { //================================================================ // Measurement //================================================================ // Add to list void Instrument::AddToList( Instrument* pInfo ) { if ( ! sListHead ) { sListHead = pInfo; } else { Instrument* p = sListHead; while( p->mNext ) { p = p->mNext; } p->mNext = pInfo; } pInfo->mNext = NULL; } // Delete from the list void Instrument::DeleteFromList( Instrument* pInfo ) { Instrument* p = sListHead; Instrument* prev = NULL; while(p) { if ( p == pInfo ) { if ( prev ) { prev->mNext = p->mNext; } else { sListHead = p->mNext; } break; } prev = p; p++; } } // Search by thread ID Instrument* Instrument::SearchInfo( bit32 threadId ) { Instrument* p = sListHead; while( p && p->mThreadId != threadId ) { p = p->mNext; } return p; } // Pointer operation function: in final position? bool Instrument::IsBottom_BufferPtr( void* p ) { p = reinterpret_cast(p) + GetRecordSize(); return ( p >= mBufferBottom )? true: false; } // Pointer operation function: advance one void* Instrument::Inc_BufferPtr( void* p ) { p = reinterpret_cast(p) + GetRecordSize(); if ( p >= mBufferBottom ) { p = mBufferTop; } return p; } // Pointer operation function: go back one void* Instrument::Dec_BufferPtr( void* p ) { p = reinterpret_cast(p) - GetRecordSize(); if ( p < mBufferTop ) { p = reinterpret_cast(mBufferBottom) - GetRecordSize(); } return p; } // Initialization void Instrument::Initialize( void* pBuffer, size_t bufferSize, s32 type ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); bit32 id = nn::os::Thread::GetCurrentId(); // Check if already registered if ( SearchInfo( id ) ) { return; } mThreadId = id; mCount = 0; mType = type; // Ring mode and stack mode are not possible if ( IsRingBuffer() && ! IsTraceLog() ) { return; } u32 size1 = GetRecordSize(); mBufferSize = (bufferSize / size1) * size1; mBufferTop = (bufferSize>0)? pBuffer: NULL; mBufferBottom = (bufferSize>0)? (reinterpret_cast(mBufferTop) + mBufferSize): NULL; // Clear Clear(); // Add to the list AddToList( this ); } // End processing void Instrument::Finalize(void) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); // Delete from the list DeleteFromList( this ); } // Clear buffer void Instrument::Clear(void) { mBufferOrigin = mBufferTop; mBufferPtr = mBufferTop; mBufferCount = 0; } // Enable measurement void Instrument::Enable( void ) { mIsAvailable = true; } // Disable measurement void Instrument::Disable( void ) { mIsAvailable = false; } // Measurement Entry void Instrument::EntryFunc( void *func_address, void *call_site ) { if ( ! mIsAvailable ) { return; } // Number of times called mCount++; mBufferCount++; // No buffer set if ( ! mBufferTop || ! mBufferPtr ) { return; } // Record with system tick if ( IsRecordTick() ) { RecordForLogWithTick* p = reinterpret_cast(mBufferPtr); p->mAddress = reinterpret_cast(func_address) & 0xfffffffe; p->mCall = reinterpret_cast(call_site); p->mTick = nn::os::Tick::GetSystemCurrent(); } // Record without system tick else { RecordForLog* p = reinterpret_cast(mBufferPtr); p->mAddress = reinterpret_cast(func_address); p->mCall = reinterpret_cast(call_site); } // Next pointer mBufferPtr = Inc_BufferPtr( mBufferPtr ); if ( mBufferPtr == mBufferOrigin ) { if ( IsRingBuffer() ) { mBufferOrigin = Inc_BufferPtr( mBufferOrigin ); } else { mBufferPtr = NULL; } } } // Measurement Exit void Instrument::ExitFunc( void *func_address, void *call_site ) { NN_UNUSED_VAR( func_address ); NN_UNUSED_VAR( call_site ); if ( ! mIsAvailable ) { return; } // No buffer set if ( ! mBufferTop || ! mBufferPtr ) { return; } // Log mode if ( IsTraceLog() ) { // Only when recording with system tick if ( IsRecordTick() ) { RecordForLogWithTick* p = reinterpret_cast(mBufferPtr); p->mAddress = (reinterpret_cast(func_address) & 0xfffffffe) | 0x1; p->mCall = reinterpret_cast(call_site); p->mTick = nn::os::Tick::GetSystemCurrent(); // Next pointer mBufferPtr = Inc_BufferPtr( mBufferPtr ); if ( mBufferPtr == mBufferOrigin ) { if ( IsRingBuffer() ) { mBufferOrigin = Inc_BufferPtr( mBufferOrigin ); } else { mBufferPtr = NULL; } } } } // Stack mode else { if ( mBufferPtr != mBufferOrigin ) { mBufferPtr = reinterpret_cast(mBufferPtr) - GetRecordSize(); } } } // Output function configuration void Instrument::SetLogFunction( void (*logFunc)( const char*, ... ) ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); sLogFuncForInstrument = logFunc; } // Result output void Instrument::Dump( void ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); // No buffer set if ( ! mBufferTop ) { return; } sLogFuncForInstrument("count: %d\n", mCount ); // Record with system tick if ( IsRecordTick() ) { RecordForLogWithTick* p = reinterpret_cast(mBufferOrigin); while( p != mBufferPtr ) { if ( p->mAddress & 1 ) { sLogFuncForInstrument("func: %08x out tick: %llx\n", p->mAddress & 0xfffffffe, p->mTick); } else { sLogFuncForInstrument("func: %08x in caller: %08x tick: %llx\n", p->mAddress & 0xfffffffe, p->mCall, p->mTick); } if ( ! IsRingBuffer() && IsBottom_BufferPtr(p) ) { break; } p = reinterpret_cast(Inc_BufferPtr(p)); } } // Record without system tick else { RecordForLog* p = reinterpret_cast(mBufferOrigin); while( p != mBufferPtr ) { sLogFuncForInstrument("func: %08x caller: %08x\n", p->mAddress, p->mCall); if ( ! IsRingBuffer() && IsBottom_BufferPtr(p) ) { break; } p = reinterpret_cast(Inc_BufferPtr(p)); } } sLogFuncForInstrument("\n"); } //================================================================ // Statistic //================================================================ // Subroutine for output: align digits static f32 arrangeTick( f32 tick ) { return ( tick > 1000000.f ) ? (tick / 1000000.f) : ( tick > 1000.f ) ? (tick / 1000.f) : tick; } // Subroutine for output: units when aligning digits static const char* arrangeTickUnit( f32 tick ) { return ( tick > 1000000.f ) ? "s " : ( tick > 1000.f ) ? "ms" : "us"; } // Initialization void Statistics::Initialize( void* buffer, size_t bufferSize ) { size_t size1 = sizeof(StatisticsRecord); // Buffer information mBuffer = reinterpret_cast(buffer); mBufferSize = (bufferSize / size1) * size1; mBufferBottom = (mBuffer && bufferSize>0)? (reinterpret_cast(mBuffer) + mBufferSize): NULL; Clear(); } // Totals void Statistics::Collect( Instrument* pInfo, bool isClear ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); if ( ! mBuffer ) { return; } // Check each item of the measurement buffer RecordForLogWithTick* pRecord = reinterpret_cast(pInfo->mBufferOrigin); while( pRecord != pInfo->mBufferPtr ) { //NN_LOG("pRecord=%x pInfo->mBufferPtr=%x ring=%d bottom=%x\n", pRecord, pInfo->mBufferPtr, pInfo->IsRingBuffer(), pInfo->mBufferBottom ); // exit line when there is time measurement if ( pInfo->IsRecordTick() && (pRecord->mAddress & 1) ) { StatisticsRecord* p = mBuffer; while( pmAddress & 0xfffffffe) == p->mAddress ) { // When there is entry if ( p->mTickStart ) { p->mTickSum += (pRecord->mTick - p->mTickStart); p->mTickStart = 0; p->mTickCount++; break; } } p++; } } // entry line with time measurement or entry line without time measurement else { // Search if already exists bool isFound = false; StatisticsRecord* pBlank = NULL; StatisticsRecord* p = mBuffer; while( pmAddress && ! pBlank ) { pBlank = p; } // Update record since the address of the record in question exists else if ( pRecord->mAddress == p->mAddress ) { p->mEntryCount++; p->mTickStart = pRecord->mTick; isFound = true; break; } p++; } // Did not find if ( ! isFound ) { //Register new since there is a space if ( pBlank ) { pBlank->mAddress = pRecord->mAddress; pBlank->mEntryCount = 1; pBlank->mTickCount = 0; pBlank->mTickStart = pRecord->mTick; pBlank->mTickSum = 0; } //Since there is no space, record that there was an ignored line else { mIgnoredLines++; } } } // Did it scan to the end for a normal buffer? if ( ! pInfo->IsRingBuffer() && ( reinterpret_cast(pRecord) + pInfo->GetRecordSize() >= pInfo->mBufferBottom ) ) { break; } // Next record pRecord = reinterpret_cast(pInfo->Inc_BufferPtr( pRecord )); } // Clear measurement buffer content if ( isClear ) { pInfo->Clear(); } } // information display void Statistics::Dump( bool isArrangeTick ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); StatisticsRecord* p = mBuffer; if ( ! p ) { return; } while( pmAddress ) { f32 sumMicroSec = p->mTickSum / (nn::os::Tick::TICKS_PER_SECOND / (1000.f * 1000.f)); u32 ave = p->mTickSum / p->mTickCount; f32 aveMicroSec = ave / (nn::os::Tick::TICKS_PER_SECOND / (1000.f * 1000.f)); if ( isArrangeTick ) { sLogFuncForStatistics( "func: %08x count:%8d (%8d) sum: %10.2f %s (ave: %10.2f %s)\n", p->mAddress, p->mEntryCount, p->mTickCount, arrangeTick(sumMicroSec), arrangeTickUnit(sumMicroSec), arrangeTick(aveMicroSec), arrangeTickUnit(aveMicroSec) ); } else { sLogFuncForStatistics( "func: %08x count:%8d (%8d) sum: %10.2f us (ave: %10.2f us)\n", p->mAddress, p->mEntryCount, p->mTickCount, sumMicroSec, aveMicroSec ); } } p++; } sLogFuncForStatistics("\n"); } // Discard information void Statistics::Clear(void) { StatisticsRecord* p = mBuffer; if ( ! p ) { return; } while( pmAddress = NULL; p->mEntryCount = 0; p->mTickCount = 0; p->mTickSum = 0; p->mTickStart = 0; p++; } mIgnoredLines = 0; } // Output function setting void Statistics::SetLogFunction( void (*logFunc)( const char*, ... ) ) { nn::os::CriticalSection::ScopedLock lock(sCriticalSection); sLogFuncForStatistics = logFunc; } } //================================================================================ // Call function for GCC format measurements //================================================================================ extern "C"{ #ifdef NN_BUILD_VERBOSE NN_WEAK_SYMBOL void __cyg_profile_func_enter( void *func_address, void *call_site ) { nn::dbg::CTR::Instrument* pInfo = nn::dbg::CTR::Instrument::SearchInfo( nn::os::Thread::GetCurrentId() ); if ( pInfo ) { pInfo->EntryFunc( func_address, call_site ); } } NN_WEAK_SYMBOL void __cyg_profile_func_exit ( void *func_address, void *call_site ) { nn::dbg::CTR::Instrument* pInfo = nn::dbg::CTR::Instrument::SearchInfo( nn::os::Thread::GetCurrentId() ); if ( pInfo ) { pInfo->ExitFunc( func_address, call_site ); } } #else NN_WEAK_SYMBOL void __cyg_profile_func_enter( void *func_address, void *call_site ) { NN_UNUSED_VAR( func_address ); NN_UNUSED_VAR( call_site ); // Do nothing } NN_WEAK_SYMBOL void __cyg_profile_func_exit ( void *func_address, void *call_site ) { NN_UNUSED_VAR( func_address ); NN_UNUSED_VAR( call_site ); // Do nothing } #endif } // namespace CTR } // namespace dbg } // namespace nn