/*========================================================================= Program: Visualization Toolkit Module: vtkTimerLog.cxx Copyright (c) Ken Martin, Will Schroeder, Bill Lorensen All rights reserved. See Copyright.txt or http://www.kitware.com/Copyright.htm for details. This software is distributed WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the above copyright notice for more information. =========================================================================*/ // .NAME vtkTimerLog - Maintains timing table for performance analysis // .SECTION Description // vtkTimerLog contains walltime and cputime measurements associated // with a given event. These results can be later analyzed when // "dumping out" the table. // // In addition, vtkTimerLog allows the user to simply get the current // time, and to start/stop a simple timer separate from the timing // table logging. #include "vtkTimerLog.h" #include "vtkMath.h" #include "vtksys/FStream.hxx" #include #include #include #include #include #include #include #include #ifndef _WIN32 #include // for CLK_TCK #include #include #endif #ifndef _WIN32_WCE #include #include #endif #include "vtkObjectFactory.h" //============================================================================== static unsigned int vtkTimerLogCleanupCounter = 0; std::vector* vtkTimerLogEntryVectorPtr = nullptr; vtkTimerLogCleanup::vtkTimerLogCleanup() { ++::vtkTimerLogCleanupCounter; } vtkTimerLogCleanup::~vtkTimerLogCleanup() { if (--::vtkTimerLogCleanupCounter == 0) { delete ::vtkTimerLogEntryVectorPtr; ::vtkTimerLogEntryVectorPtr = nullptr; } } static std::vector& vtkGetTimerLogEntryVector() { if (!vtkTimerLogEntryVectorPtr) { vtkTimerLogEntryVectorPtr = new std::vector(); } return *vtkTimerLogEntryVectorPtr; } //============================================================================== vtkStandardNewMacro(vtkTimerLog); // initialize the class variables int vtkTimerLog::Logging = 1; int vtkTimerLog::Indent = 0; int vtkTimerLog::MaxEntries = 100; int vtkTimerLog::NextEntry = 0; int vtkTimerLog::WrapFlag = 0; #ifdef CLK_TCK int vtkTimerLog::TicksPerSecond = CLK_TCK; #else int vtkTimerLog::TicksPerSecond = 60; #endif #ifndef CLOCKS_PER_SEC #define CLOCKS_PER_SEC (vtkTimerLog::TicksPerSecond) #endif #ifdef _WIN32 #ifndef _WIN32_WCE timeb vtkTimerLog::FirstWallTime; timeb vtkTimerLog::CurrentWallTime; #else FILETIME vtkTimerLog::FirstWallTime; FILETIME vtkTimerLog::CurrentWallTime; #endif #else timeval vtkTimerLog::FirstWallTime; timeval vtkTimerLog::CurrentWallTime; tms vtkTimerLog::FirstCpuTicks; tms vtkTimerLog::CurrentCpuTicks; #endif //------------------------------------------------------------------------------ // Remove timer log. void vtkTimerLog::CleanupLog() { vtkGetTimerLogEntryVector().clear(); } //------------------------------------------------------------------------------ // Clear the timing table. walltime and cputime will also be set // to zero when the first new event is recorded. void vtkTimerLog::ResetLog() { vtkTimerLog::WrapFlag = 0; vtkTimerLog::NextEntry = 0; // may want to free entry_vector to force realloc so // that user can resize the table by changing MaxEntries. } //------------------------------------------------------------------------------ // Record a timing event. The event is represented by a formatted // string. void vtkTimerLog::FormatAndMarkEvent(const char* format, ...) { if (!vtkTimerLog::Logging) { return; } static char event[4096]; va_list var_args; va_start(var_args, format); vsnprintf(event, sizeof(event), format, var_args); va_end(var_args); vtkTimerLog::MarkEventInternal(event, vtkTimerLogEntry::STANDALONE); } //------------------------------------------------------------------------------ // Record a timing event and capture walltime and cputicks. void vtkTimerLog::MarkEvent(const char* event) { vtkTimerLog::MarkEventInternal(event, vtkTimerLogEntry::STANDALONE); } //------------------------------------------------------------------------------ // Record a timing event and capture walltime and cputicks. void vtkTimerLog::MarkEventInternal( const char* event, vtkTimerLogEntry::LogEntryType type, vtkTimerLogEntry* entry) { if (!vtkTimerLog::Logging) { return; } double time_diff; int ticks_diff; auto& global_entries = vtkGetTimerLogEntryVector(); // If this the first event we're recording, allocate the // internal timing table and initialize WallTime and CpuTicks // for this first event to zero. if (vtkTimerLog::NextEntry == 0 && !vtkTimerLog::WrapFlag) { if (global_entries.empty()) { global_entries.resize(vtkTimerLog::MaxEntries); } #ifdef _WIN32 #ifdef _WIN32_WCE SYSTEMTIME st; GetLocalTime(&st); SystemTimeToFileTime(&st, &(vtkTimerLog::FirstWallTime)); #else ::ftime(&(vtkTimerLog::FirstWallTime)); #endif #else gettimeofday(&(vtkTimerLog::FirstWallTime), nullptr); times(&FirstCpuTicks); #endif if (entry) { global_entries[0] = *entry; } else { global_entries[0].Indent = vtkTimerLog::Indent; global_entries[0].WallTime = 0.0; global_entries[0].CpuTicks = 0; if (event) { global_entries[0].Event = event; } global_entries[0].Type = type; vtkTimerLog::NextEntry = 1; } return; } if (entry) { global_entries[vtkTimerLog::NextEntry] = *entry; } else { #ifdef _WIN32 #ifdef _WIN32_WCE SYSTEMTIME st; GetLocalTime(&st); SystemTimeToFileTime(&st, &(vtkTimerLog::CurrentWallTime)); time_diff = (vtkTimerLog::CurrentWallTime.dwHighDateTime - vtkTimerLog::FirstWallTime.dwHighDateTime); time_diff = time_diff * 429.4967296; time_diff = time_diff + ((vtkTimerLog::CurrentWallTime.dwLowDateTime - vtkTimerLog::FirstWallTime.dwLowDateTime) / 10000000.0); #else static double scale = 1.0 / 1000.0; ::ftime(&(vtkTimerLog::CurrentWallTime)); time_diff = vtkTimerLog::CurrentWallTime.time - vtkTimerLog::FirstWallTime.time; time_diff += (vtkTimerLog::CurrentWallTime.millitm - vtkTimerLog::FirstWallTime.millitm) * scale; #endif ticks_diff = 0; #else static double scale = 1.0 / 1000000.0; gettimeofday(&(vtkTimerLog::CurrentWallTime), nullptr); time_diff = vtkTimerLog::CurrentWallTime.tv_sec - vtkTimerLog::FirstWallTime.tv_sec; time_diff += (vtkTimerLog::CurrentWallTime.tv_usec - vtkTimerLog::FirstWallTime.tv_usec) * scale; times(&CurrentCpuTicks); ticks_diff = (CurrentCpuTicks.tms_utime + CurrentCpuTicks.tms_stime) - (FirstCpuTicks.tms_utime + FirstCpuTicks.tms_stime); #endif global_entries[vtkTimerLog::NextEntry].Indent = vtkTimerLog::Indent; global_entries[vtkTimerLog::NextEntry].WallTime = static_cast(time_diff); global_entries[vtkTimerLog::NextEntry].CpuTicks = ticks_diff; if (event) { global_entries[vtkTimerLog::NextEntry].Event = event; } global_entries[vtkTimerLog::NextEntry].Type = type; } vtkTimerLog::NextEntry++; if (vtkTimerLog::NextEntry == vtkTimerLog::MaxEntries) { vtkTimerLog::NextEntry = 0; vtkTimerLog::WrapFlag = 1; } } //------------------------------------------------------------------------------ // Record a timing event and capture walltime and cputicks. // Increments indent after mark. void vtkTimerLog::MarkStartEvent(const char* event) { if (!vtkTimerLog::Logging) { // Maybe we should still change the Indent ... return; } vtkTimerLog::MarkEventInternal(event, vtkTimerLogEntry::START); ++vtkTimerLog::Indent; } //------------------------------------------------------------------------------ // Record a timing event and capture walltime and cputicks. // Decrements indent after mark. void vtkTimerLog::MarkEndEvent(const char* event) { if (!vtkTimerLog::Logging) { // Maybe we should still change the Indent ... return; } vtkTimerLog::MarkEventInternal(event, vtkTimerLogEntry::END); --vtkTimerLog::Indent; } //------------------------------------------------------------------------------ // Record a timing event with known walltime and cputicks. void vtkTimerLog::InsertTimedEvent(const char* event, double time, int cpuTicks) { if (!vtkTimerLog::Logging) { return; } // manually create both the start and end event and then // change the start events values to appear like other events vtkTimerLogEntry entry; entry.WallTime = time; entry.CpuTicks = cpuTicks; if (event) { entry.Event = event; } entry.Type = vtkTimerLogEntry::INSERTED; entry.Indent = vtkTimerLog::Indent; vtkTimerLog::MarkEventInternal(event, vtkTimerLogEntry::INSERTED, &entry); } //------------------------------------------------------------------------------ // Record a timing event and capture walltime and cputicks. int vtkTimerLog::GetNumberOfEvents() { if (vtkTimerLog::WrapFlag) { return vtkTimerLog::MaxEntries; } else { return vtkTimerLog::NextEntry; } } //------------------------------------------------------------------------------ vtkTimerLogEntry* vtkTimerLog::GetEvent(int idx) { int num = vtkTimerLog::GetNumberOfEvents(); int start = 0; if (vtkTimerLog::WrapFlag) { start = vtkTimerLog::NextEntry; } if (idx < 0 || idx >= num) { cerr << "Bad entry index " << idx << endl; return nullptr; } idx = (idx + start) % vtkTimerLog::MaxEntries; return &(vtkGetTimerLogEntryVector()[idx]); } //------------------------------------------------------------------------------ int vtkTimerLog::GetEventIndent(int idx) { if (vtkTimerLogEntry* tmp = vtkTimerLog::GetEvent(idx)) { return tmp->Indent; } return 0; } //------------------------------------------------------------------------------ double vtkTimerLog::GetEventWallTime(int idx) { if (vtkTimerLogEntry* tmp = vtkTimerLog::GetEvent(idx)) { return tmp->WallTime; } return 0.0; } //------------------------------------------------------------------------------ const char* vtkTimerLog::GetEventString(int idx) { if (vtkTimerLogEntry* tmp = vtkTimerLog::GetEvent(idx)) { return tmp->Event.c_str(); } return nullptr; } //------------------------------------------------------------------------------ vtkTimerLogEntry::LogEntryType vtkTimerLog::GetEventType(int idx) { if (vtkTimerLogEntry* tmp = vtkTimerLog::GetEvent(idx)) { return tmp->Type; } return vtkTimerLogEntry::INVALID; } //------------------------------------------------------------------------------ // Write the timing table out to a file. Calculate some helpful // statistics (deltas and percentages) in the process. void vtkTimerLog::DumpLogWithIndents(ostream* os, double threshold) { #ifndef _WIN32_WCE int num = vtkTimerLog::GetNumberOfEvents(); std::vector handledEvents(num, false); for (int w = 0; w < vtkTimerLog::WrapFlag + 1; w++) { int start = 0; int end = vtkTimerLog::NextEntry; if (vtkTimerLog::WrapFlag != 0 && w == 0) { start = vtkTimerLog::NextEntry; end = vtkTimerLog::MaxEntries; } for (int i1 = start; i1 < end; i1++) { int indent1 = vtkTimerLog::GetEventIndent(i1); vtkTimerLogEntry::LogEntryType eventType = vtkTimerLog::GetEventType(i1); int endEvent = -1; // only modified if this is a START event if (eventType == vtkTimerLogEntry::END && handledEvents[i1]) { continue; // this END event is handled by the corresponding START event } if (eventType == vtkTimerLogEntry::START) { // Search for an END event. it may be before the START event if we've wrapped. int counter = 1; while (counter < num && vtkTimerLog::GetEventIndent((i1 + counter) % num) > indent1) { counter++; } if (vtkTimerLog::GetEventIndent((i1 + counter) % num) == indent1) { counter--; endEvent = (i1 + counter) % num; handledEvents[endEvent] = true; } } double dtime = threshold; if (eventType == vtkTimerLogEntry::START) { dtime = vtkTimerLog::GetEventWallTime(endEvent) - vtkTimerLog::GetEventWallTime(i1); } if (dtime >= threshold) { int j = indent1; while (j-- > 0) { *os << " "; } *os << vtkTimerLog::GetEventString(i1); if (endEvent != -1) { // Start event. *os << ", " << dtime << " seconds"; } else if (eventType == vtkTimerLogEntry::INSERTED) { *os << ", " << vtkTimerLog::GetEventWallTime(i1) << " seconds (inserted time)"; } else if (eventType == vtkTimerLogEntry::END) { *os << " (END event without matching START event)"; } *os << endl; } } } #endif } //------------------------------------------------------------------------------ void vtkTimerLog::DumpLogWithIndentsAndPercentages(std::ostream* os) { assert(os); // Use indents to pair start/end events. Indents work like this: // Indent | Event // ------ | ----- // 0 | Event 1 Start // 1 | SubEvent 1 Start // 2 | SubEvent 1 End // 1 | SubEvent 2 Start // 2 | SubSubEvent 1 Start // 3 | SubSubEvent 1 End // 2 | SubEvent 2 End // 1 | Event 1 End // If we've wrapped the entry buffer, the indent information will be // nonsensical. I don't trust the parsing logic below to not do bizarre, // possibly crashy things in this case, so let's just error out and let the // dev know how to fix the issue. if (vtkTimerLog::WrapFlag) { *os << "Error: Event log has exceeded vtkTimerLog::MaxEntries.\n" "Call vtkTimerLog::SetMaxEntries to increase the log buffer size.\n" "Current vtkTimerLog::MaxEntries: " << vtkTimerLog::MaxEntries << ".\n"; return; } // Store previous 'scopes' in a LIFO buffer typedef std::pair IndentTime; std::vector parentInfo; // Find the longest event string: int numEvents = vtkTimerLog::GetNumberOfEvents(); int longestString = 0; for (int i = 0; i < numEvents; ++i) { longestString = std::max(longestString, static_cast(strlen(vtkTimerLog::GetEventString(i)))); } // Loop to numEvents - 1, since the last event must be an end event. for (int startIdx = 0; startIdx < numEvents - 1; ++startIdx) { int curIndent = vtkTimerLog::GetEventIndent(startIdx); vtkTimerLogEntry::LogEntryType logEntryType = vtkTimerLog::GetEventType(startIdx); if (logEntryType == vtkTimerLogEntry::END) { // Skip this event if it is an end event: assert(!parentInfo.empty()); parentInfo.pop_back(); continue; } else if (logEntryType == vtkTimerLogEntry::STANDALONE) { // Skip this event if it is just to mark that an event occurred continue; } // Find the event that follows the end event: int endIdx = startIdx + 1; for (; endIdx < numEvents; ++endIdx) { if (vtkTimerLog::GetEventIndent(endIdx) == curIndent) { break; } } // Move back one event to get our end event (also works when we've reached // the end of the event log). endIdx--; // Get the current event time: double elapsedTime = logEntryType == vtkTimerLogEntry::START ? vtkTimerLog::GetEventWallTime(endIdx) - vtkTimerLog::GetEventWallTime(startIdx) : vtkTimerLog::GetEventWallTime(startIdx); // The total time the parent took to execute. If empty, this is the first // event, and just set to 100%. IndentTime parent = parentInfo.empty() ? IndentTime(-1, elapsedTime) : parentInfo.back(); // Percentage of parent exec time, rounded to a single decimal: double percentage = std::round(elapsedTime / parent.second * 1000.) / 10.; *os << std::setw(12) << std::setprecision(6) << std::fixed << elapsedTime << std::setw(0) << "s" << std::setw(curIndent * 2) << " " << std::setprecision(1) << std::setw(5) << std::right << percentage << std::setw(0) << std::left << "% " << std::setw(longestString) << vtkTimerLog::GetEventString(startIdx); if (logEntryType == vtkTimerLogEntry::INSERTED) { *os << " (inserted time)"; } *os << "\n"; // Add our parent info if this was time with a START and END event: if (logEntryType == vtkTimerLogEntry::START) { parentInfo.emplace_back(curIndent, elapsedTime); } } } //------------------------------------------------------------------------------ // Write the timing table out to a file. This is meant for non-timed events, // i.e. event type = STANDALONE. All other event types besides the first // are ignored. void vtkTimerLog::DumpLog(const char* filename) { #ifndef _WIN32_WCE vtksys::ofstream os_with_warning_C4701(filename); int i; auto& global_entries = vtkGetTimerLogEntryVector(); if (vtkTimerLog::WrapFlag) { vtkTimerLog::DumpEntry(os_with_warning_C4701, 0, global_entries[vtkTimerLog::NextEntry].WallTime, 0, global_entries[vtkTimerLog::NextEntry].CpuTicks, 0, global_entries[vtkTimerLog::NextEntry].Event.c_str()); int previousEvent = vtkTimerLog::NextEntry; for (i = vtkTimerLog::NextEntry + 1; i < vtkTimerLog::MaxEntries; i++) { if (global_entries[i].Type == vtkTimerLogEntry::STANDALONE) { vtkTimerLog::DumpEntry(os_with_warning_C4701, i - vtkTimerLog::NextEntry, global_entries[i].WallTime, global_entries[i].WallTime - global_entries[previousEvent].WallTime, global_entries[i].CpuTicks, global_entries[i].CpuTicks - global_entries[previousEvent].CpuTicks, global_entries[i].Event.c_str()); previousEvent = i; } } for (i = 0; i < vtkTimerLog::NextEntry; i++) { if (global_entries[i].Type == vtkTimerLogEntry::STANDALONE) { vtkTimerLog::DumpEntry(os_with_warning_C4701, vtkTimerLog::MaxEntries - vtkTimerLog::NextEntry + i, global_entries[i].WallTime, global_entries[i].WallTime - global_entries[previousEvent].WallTime, global_entries[i].CpuTicks, global_entries[i].CpuTicks - global_entries[previousEvent].CpuTicks, global_entries[i].Event.c_str()); previousEvent = i; } } } else { vtkTimerLog::DumpEntry(os_with_warning_C4701, 0, global_entries[0].WallTime, 0, global_entries[0].CpuTicks, 0, global_entries[0].Event.c_str()); int previousEvent = 0; for (i = 1; i < vtkTimerLog::NextEntry; i++) { if (global_entries[i].Type == vtkTimerLogEntry::STANDALONE) { vtkTimerLog::DumpEntry(os_with_warning_C4701, i, global_entries[i].WallTime, global_entries[i].WallTime - global_entries[previousEvent].WallTime, global_entries[i].CpuTicks, global_entries[i].CpuTicks - global_entries[previousEvent].CpuTicks, global_entries[i].Event.c_str()); previousEvent = i; } } } os_with_warning_C4701.close(); #endif } //------------------------------------------------------------------------------ // Print method for vtkTimerLog. void vtkTimerLog::PrintSelf(ostream& os, vtkIndent indent) { this->Superclass::PrintSelf(os, indent); os << indent << "MaxEntries: " << vtkTimerLog::MaxEntries << "\n"; os << indent << "NextEntry: " << vtkTimerLog::NextEntry << "\n"; os << indent << "WrapFlag: " << vtkTimerLog::WrapFlag << "\n"; os << indent << "TicksPerSecond: " << vtkTimerLog::TicksPerSecond << "\n"; os << "\n"; os << indent << "Entry \tWall Time\tCpuTicks\tEvent\n"; os << indent << "----------------------------------------------\n"; auto& global_entries = vtkGetTimerLogEntryVector(); if (vtkTimerLog::WrapFlag) { for (int i = vtkTimerLog::NextEntry; i < vtkTimerLog::MaxEntries; i++) { os << indent << i << "\t\t" << global_entries[i].WallTime << "\t\t" << global_entries[i].CpuTicks << "\t\t" << global_entries[i].Event << "\n"; } } for (int i = 0; i < vtkTimerLog::NextEntry; i++) { os << indent << i << "\t\t" << global_entries[i].WallTime << "\t\t" << global_entries[i].CpuTicks << "\t\t" << global_entries[i].Event << "\n"; } os << "\n" << indent << "StartTime: " << this->StartTime << "\n"; } // Methods to support simple timer functionality, separate from // timer table logging. //------------------------------------------------------------------------------ // Returns the elapsed number of seconds since 00:00:00 Coordinated Universal // Time (UTC), Thursday, 1 January 1970. This is also called Unix Time. double vtkTimerLog::GetUniversalTime() { double currentTimeInSeconds; #ifdef _WIN32 #ifdef _WIN32_WCE FILETIME CurrentTime; SYSTEMTIME st; GetLocalTime(&st); SystemTimeToFileTime(&st, &CurrentTime); currentTimeInSeconds = CurrentTime.dwHighDateTime; currentTimeInSeconds *= 429.4967296; currentTimeInSeconds = currentTimeInSeconds + CurrentTime.dwLowDateTime / 10000000.0; #else timeb CurrentTime; static double scale = 1.0 / 1000.0; ::ftime(&CurrentTime); currentTimeInSeconds = CurrentTime.time + scale * CurrentTime.millitm; #endif #else timeval CurrentTime; static double scale = 1.0 / 1000000.0; gettimeofday(&CurrentTime, nullptr); currentTimeInSeconds = CurrentTime.tv_sec + scale * CurrentTime.tv_usec; #endif return currentTimeInSeconds; } //------------------------------------------------------------------------------ double vtkTimerLog::GetCPUTime() { #ifndef _WIN32_WCE return static_cast(clock()) / static_cast(CLOCKS_PER_SEC); #else return 1.0; #endif } //------------------------------------------------------------------------------ // Set the StartTime to the current time. Used with GetElapsedTime(). void vtkTimerLog::StartTimer() { this->StartTime = vtkTimerLog::GetUniversalTime(); } //------------------------------------------------------------------------------ // Sets EndTime to the current time. Used with GetElapsedTime(). void vtkTimerLog::StopTimer() { this->EndTime = vtkTimerLog::GetUniversalTime(); } //------------------------------------------------------------------------------ // Returns the difference between StartTime and EndTime as // a floating point value indicating the elapsed time in seconds. double vtkTimerLog::GetElapsedTime() { return (this->EndTime - this->StartTime); } //------------------------------------------------------------------------------ void vtkTimerLog::DumpEntry(ostream& os, int index, double ttime, double deltatime, int tick, int deltatick, const char* event) { os << index << " " << ttime << " " << deltatime << " " << static_cast(tick) / vtkTimerLog::TicksPerSecond << " " << static_cast(deltatick) / vtkTimerLog::TicksPerSecond << " "; if (deltatime == 0.0) { os << "0.0 "; } else { os << 100.0 * deltatick / vtkTimerLog::TicksPerSecond / deltatime << " "; } os << event << "\n"; } //------------------------------------------------------------------------------ void vtkTimerLog::SetMaxEntries(int a) { if (a == vtkTimerLog::MaxEntries) { return; } auto& global_entries = vtkGetTimerLogEntryVector(); int numEntries = vtkTimerLog::GetNumberOfEvents(); if (vtkTimerLog::WrapFlag) { // if we've wrapped events, reorder them std::vector tmp; tmp.reserve(vtkTimerLog::MaxEntries); std::copy(global_entries.begin() + vtkTimerLog::NextEntry, global_entries.end(), std::back_inserter(tmp)); std::copy(global_entries.begin(), global_entries.begin() + vtkTimerLog::NextEntry, std::back_inserter(tmp)); global_entries = tmp; vtkTimerLog::WrapFlag = 0; } if (numEntries <= a) { global_entries.resize(a); vtkTimerLog::NextEntry = numEntries; vtkTimerLog::WrapFlag = 0; vtkTimerLog::MaxEntries = a; return; } // Reduction so we need to get rid of the first bunch of events int offset = numEntries - a; assert(offset >= 0); global_entries.erase(global_entries.begin(), global_entries.begin() + offset); vtkTimerLog::MaxEntries = a; vtkTimerLog::NextEntry = 0; vtkTimerLog::WrapFlag = 1; } //------------------------------------------------------------------------------ int vtkTimerLog::GetMaxEntries() { return vtkTimerLog::MaxEntries; }