#include "munga.h" #pragma hdrstop #include "trace.h" #include "filestrm.h" #if defined(TRACE_ON) //########################################################################## //############################ Trace ################################# //########################################################################## Byte Trace::NextTraceID = 0; //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Trace::Trace( const char* name, Type type ) { traceNumber = NextTraceID++; traceType = (Byte)type; traceName = name; lastFrameActivity = 0; lastFractionActivity = 0.0f; trace_manager.Add(this); } #if defined(USE_TIME_ANALYSIS) //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void Trace::PrintUsage(Scalar usage) { Check(this); DEBUG_STREAM << usage << std::flush; } #endif //########################################################################## //########################### BitTrace ############################### //########################################################################## Byte BitTrace::NextActiveLine = 0; //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // BitTrace::BitTrace(const char* name): Trace(name, BitType) { activeLine = NextActiveLine++; #if defined(USE_ACTIVE_PROFILE) DEBUG_STREAM << name << " used trace line " << (int)activeLine << "!\n"; if (!IsLineValidImplementation(activeLine)) { Fail("Invalid active trace line!"); } #endif BitTrace::ResetTrace(); } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::DumpTraceStatus() { Check(this); DEBUG_STREAM << (int)activeLine << ((traceUp) ? " is On" : " is Off") << std::flush; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::ResetTrace() { #if defined(USE_TIME_ANALYSIS) traceUp = False; lastUpTime = 0.0; totalUpTime = 0.0; #endif #if defined(USE_ACTIVE_PROFILE) ClearLineImplementation(activeLine); #endif } #if defined(USE_TIME_ANALYSIS) //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::StartTiming() { Check(this); totalUpTime = 0.0; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Scalar BitTrace::CalculateUsage( long frame, Scalar fraction, double sample_time ) { if (traceUp) { totalUpTime += frame - lastFrameActivity; totalUpTime += fraction - lastFractionActivity; } Scalar result = totalUpTime / sample_time; Check_Fpu(); DEBUG_STREAM << setprecision(4) << totalUpTime / GetTicksPerSecond() << "s, "; return result; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::PrintUsage(Scalar usage) { Check(this); DEBUG_STREAM << setprecision(4) << (usage*100.0f) << "% CPU" << std::flush; #if defined(USE_ACTIVE_PROFILE) DEBUG_STREAM << " (active on line " << (int)activeLine << ')' << std::flush; #endif } #endif //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::Set() { Check(this); if (!traceUp) { #if defined(USE_ACTIVE_PROFILE) SetLineImplementation(activeLine); #endif traceUp = True; #if defined(USE_TIME_ANALYSIS) || defined(USE_TRACE_LOG) long frame = Now().ticks; Scalar fraction = Get_Frame_Percent_Used(); #endif #if defined(USE_TIME_ANALYSIS) lastFrameActivity = frame; lastFractionActivity = fraction; #endif #if defined(USE_TRACE_LOG) // Check(traceManager); IncrementSampleCount(); MemoryStream *log = GetTraceLog(); if (log) { Check(log); TraceSample *sample = (TraceSample*)log->GetPointer(); sample->sampleType = TraceSample::GoingUp; sample->traceNumber = traceNumber; sample->sampleFrame = (Word)frame; sample->sampleFraction = fraction; log->AdvancePointer(sizeof(*sample)); } #endif } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void BitTrace::Clear() { Check(this); if (traceUp) { traceUp = False; #if defined(USE_TIME_ANALYSIS) || defined(USE_TRACE_LOG) long frame = Now().ticks; Scalar fraction = Get_Frame_Percent_Used(); #endif #if defined(USE_TIME_ANALYSIS) if (frame == lastFrameActivity && fraction < lastFractionActivity) { ++frame; } lastUpTime = frame - lastFrameActivity; lastUpTime += fraction - lastFractionActivity; Verify(lastUpTime >= 0.0f) totalUpTime += lastUpTime; Check_Fpu(); #endif #if defined(USE_TRACE_LOG) //Check(traceManager); IncrementSampleCount(); MemoryStream *log = GetTraceLog(); if (log) { Check(log); TraceSample *sample = (TraceSample*)log->GetPointer(); sample->sampleType = TraceSample::GoingDown; sample->traceNumber = traceNumber; sample->sampleFrame = (Word)frame; sample->sampleFraction = fraction; log->AdvancePointer(sizeof(*sample)); } #endif #if defined(USE_ACTIVE_PROFILE) ClearLineImplementation(activeLine); #endif } } //########################################################################## //######################## TraceManager ############################## //########################################################################## TraceManager trace_manager; //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // TraceManager::TraceManager(): traceChain(NULL) { sampleStartFrame = 0; sampleStartFraction = 0.0f; actualSampleCount = 0; ignoredSampleCount = 0; traceCount = 0; activeTraceLog = NULL; allocatedTraceLog = NULL; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // TraceManager::~TraceManager() { Check(this); if (allocatedTraceLog) { Check(allocatedTraceLog); allocatedTraceLog->Rewind(); TraceSample *samples = (TraceSample*)allocatedTraceLog->GetPointer(); Unregister_Object(allocatedTraceLog); delete allocatedTraceLog; activeTraceLog = allocatedTraceLog = NULL; Unregister_Pointer(samples); delete[] samples; } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Logical TraceManager::TestInstance() const { return True; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::Add(Trace *trace) { Check(this); traceCount = (Byte)(traceCount + 1); traceChain.Add(trace); } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::DumpTracesStatus() { ChainIteratorOf traces(traceChain); Trace *trace; while ((trace = traces.ReadAndNext()) != NULL) { Check(trace); DEBUG_STREAM << trace->traceName << ": " << std::flush; trace->DumpTraceStatus(); DEBUG_STREAM << endl << std::flush; } DEBUG_STREAM << endl << std::flush; } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::ResetTraces() { ChainIteratorOf traces(traceChain); Trace *trace; while ((trace = traces.ReadAndNext()) != NULL) { Check(trace); trace->ResetTrace(); } #if defined(USE_TRACE_LOG) actualSampleCount = 0; ignoredSampleCount = 0; if (allocatedTraceLog) { allocatedTraceLog->Rewind(); } #endif } #if defined(USE_TIME_ANALYSIS) //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::StartTimingAnalysis() { sampleStartFrame = Now().ticks; sampleStartFraction = Get_Frame_Percent_Used(); ChainIteratorOf traces(traceChain); Trace *trace; while ((trace = traces.ReadAndNext()) != NULL) { Check(trace); trace->StartTiming(); trace->lastFrameActivity = sampleStartFrame; trace->lastFractionActivity = sampleStartFraction; } #if defined(USE_TRACE_LOG) actualSampleCount = 0; ignoredSampleCount = 0; if (allocatedTraceLog) { allocatedTraceLog->Rewind(); } #endif } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // int TraceManager::SnapshotTimingAnalysis(Logical print) { long now = Now().ticks; float fraction = Get_Frame_Percent_Used(); double time = now - sampleStartFrame; time += fraction - sampleStartFraction; if (time < SMALL) { return False; } ChainIteratorOf traces(traceChain); Trace *trace; DEBUG_STREAM << "Sample length: " << setprecision(4) << time/GetTicksPerSecond() << "s\n"; while ((trace = traces.ReadAndNext()) != NULL) { Check(trace); if (print) { DEBUG_STREAM << trace->traceName << ": " << std::flush; Scalar usage = trace->CalculateUsage(now, fraction, time); trace->PrintUsage(usage); DEBUG_STREAM << endl << std::flush; } trace->StartTiming(); trace->lastFrameActivity = now; trace->lastFractionActivity = fraction; } sampleStartFrame = now; sampleStartFraction = fraction; return True; } #endif #if defined(USE_TRACE_LOG) //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::CreateTraceLog( size_t max_trace_count, Logical start_logging ) { Check(this); Verify(!allocatedTraceLog); TraceSample *samples = new TraceSample[max_trace_count]; Register_Pointer(samples); allocatedTraceLog = new MemoryStream(samples, max_trace_count*sizeof(TraceSample)); Register_Object(allocatedTraceLog); if (start_logging) { activeTraceLog = allocatedTraceLog; } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::SaveTraceLog(const char* filename) { Check(this); if (allocatedTraceLog) { Check(allocatedTraceLog); // //-------------------------------------------------------- // Rewind the memory stream and save it out in a disk file //-------------------------------------------------------- // FileStream output(filename, True); size_t size = allocatedTraceLog->GetBytesUsed(); DEBUG_STREAM << ignoredSampleCount << " samples were ignored\n" << std::flush; if (size > 0) { DEBUG_STREAM << "Writing " << actualSampleCount << " samples to trace log..."; Byte trace_count = GetTraceCount(); output << trace_count; ChainIteratorOf traces(traceChain); Trace *trace; while ((trace = traces.ReadAndNext()) != NULL) { output << trace->traceType; const char* p = trace->traceName; do { output << *p; } while (*p++); } output << size; allocatedTraceLog->Rewind(); output.WriteBytes(allocatedTraceLog->GetPointer(), size); DEBUG_STREAM << "trace log written\n" << std::flush; } // //------------------- // Release the memory //------------------- // TraceSample *samples = (TraceSample*)allocatedTraceLog->GetPointer(); Unregister_Object(allocatedTraceLog); delete allocatedTraceLog; activeTraceLog = allocatedTraceLog = NULL; Unregister_Pointer(samples); delete[] samples; } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::MarkTraceLog() { Check(this); if (activeTraceLog) { Check(activeTraceLog); long now = Now().ticks; float fraction = Get_Frame_Percent_Used(); TraceSample *sample = (TraceSample*)activeTraceLog->GetPointer(); sample->sampleType = TraceSample::Marker; sample->sampleFrame = (Word)now; sample->sampleFraction = fraction; sample->traceNumber = 0; activeTraceLog->AdvancePointer(sizeof(*sample)); } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::SuspendTraceLogging() { Check(this); if (activeTraceLog) { Check(activeTraceLog); long now = Now().ticks; float fraction = Get_Frame_Percent_Used(); TraceSample *sample = (TraceSample*)activeTraceLog->GetPointer(); sample->sampleType = TraceSample::SuspendSampling; sample->sampleFrame = (Word)now; sample->sampleFraction = fraction; sample->traceNumber = 0; activeTraceLog->AdvancePointer(sizeof(*sample)); activeTraceLog = NULL; } } //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // void TraceManager::ResumeTraceLogging() { Check(this); if (allocatedTraceLog && !activeTraceLog) { Check(allocatedTraceLog); activeTraceLog = allocatedTraceLog; long now = Now().ticks; float fraction = Get_Frame_Percent_Used(); TraceSample *sample = (TraceSample*)activeTraceLog->GetPointer(); sample->sampleType = TraceSample::ResumeSampling; sample->sampleFrame = (Word)now; sample->sampleFraction = fraction; sample->traceNumber = 0; activeTraceLog->AdvancePointer(sizeof(*sample)); } } #endif #endif