From 7883371166263af2d9a02a761c1046fcbd7f5f3a Mon Sep 17 00:00:00 2001 From: Victor Zarubkin Date: Wed, 14 Dec 2016 22:16:14 +0300 Subject: [PATCH] (GUI) Added calculation of thread wait time (sum of all context switches) --- easy_profiler_core/include/easy/reader.h | 56 +++--------------------- easy_profiler_core/reader.cpp | 5 ++- profiler_gui/blocks_graphics_view.cpp | 8 ++-- profiler_gui/easy_graphics_scrollbar.cpp | 21 +++++---- profiler_gui/easy_graphics_scrollbar.h | 3 +- profiler_gui/tree_widget_loader.cpp | 8 ++-- 6 files changed, 33 insertions(+), 68 deletions(-) diff --git a/easy_profiler_core/include/easy/reader.h b/easy_profiler_core/include/easy/reader.h index 93c2f0c..9f06469 100644 --- a/easy_profiler_core/include/easy/reader.h +++ b/easy_profiler_core/include/easy/reader.h @@ -194,12 +194,13 @@ namespace profiler { BlocksTree::children_t sync; ///< List of context-switch events BlocksTree::children_t events; ///< List of events indexes std::string thread_name; ///< Name of this thread - ::profiler::timestamp_t active_time; ///< Active time of this thread (sum of all children duration) + ::profiler::timestamp_t profiled_time; ///< Profiled time of this thread (sum of all children duration) + ::profiler::timestamp_t wait_time; ///< Wait time of this thread (sum of all context switches) ::profiler::thread_id_t thread_id; ///< System Id of this thread ::profiler::block_index_t blocks_number; ///< Total blocks number including their children uint16_t depth; ///< Maximum stack depth (number of levels) - BlocksTreeRoot() : active_time(0), thread_id(0), blocks_number(0), depth(0) + BlocksTreeRoot() : profiled_time(0), wait_time(0), thread_id(0), blocks_number(0), depth(0) { } @@ -208,7 +209,8 @@ namespace profiler { , sync(::std::move(that.sync)) , events(::std::move(that.events)) , thread_name(::std::move(that.thread_name)) - , active_time(that.active_time) + , profiled_time(that.profiled_time) + , wait_time(that.wait_time) , thread_id(that.thread_id) , blocks_number(that.blocks_number) , depth(that.depth) @@ -221,7 +223,8 @@ namespace profiler { sync = ::std::move(that.sync); events = ::std::move(that.events); thread_name = ::std::move(that.thread_name); - active_time = that.active_time; + profiled_time = that.profiled_time; + wait_time = that.wait_time; thread_id = that.thread_id; blocks_number = that.blocks_number; depth = that.depth; @@ -346,51 +349,6 @@ namespace profiler { ////////////////////////////////////////////////////////////////////////// - struct FileData - { - ::profiler::SerializedData serialized_blocks; - ::profiler::SerializedData serialized_descriptors; - ::std::vector<::profiler::thread_id_t> threads_order; - ::profiler::timestamp_t begin_time = 0ULL; - ::profiler::timestamp_t end_time = 0ULL; - int64_t cpu_frequency = 0LL; - uint32_t total_blocks_number = 0; - uint32_t total_descriptors_number = 0; - - FileData() = default; - FileData(FileData&& _other) - : serialized_blocks(::std::move(_other.serialized_blocks)) - , serialized_descriptors(::std::move(_other.serialized_descriptors)) - , threads_order(::std::move(_other.threads_order)) - , begin_time(_other.begin_time) - , end_time(_other.end_time) - , cpu_frequency(_other.cpu_frequency) - , total_blocks_number(_other.total_blocks_number) - , total_descriptors_number(_other.total_descriptors_number) - { - } - - FileData& operator = (FileData&& _other) - { - serialized_blocks = ::std::move(_other.serialized_blocks); - serialized_descriptors = ::std::move(_other.serialized_descriptors); - threads_order = ::std::move(_other.threads_order); - begin_time = _other.begin_time; - end_time = _other.end_time; - cpu_frequency = _other.cpu_frequency; - total_blocks_number = _other.total_blocks_number; - total_descriptors_number = _other.total_descriptors_number; - return *this; - } - - private: - - FileData(const FileData&) = delete; - FileData& operator = (const FileData&) = delete; - }; - - ////////////////////////////////////////////////////////////////////////// - typedef ::std::vector descriptors_list_t; } // END of namespace profiler. diff --git a/easy_profiler_core/reader.cpp b/easy_profiler_core/reader.cpp index 497bb8c..ba4000b 100644 --- a/easy_profiler_core/reader.cpp +++ b/easy_profiler_core/reader.cpp @@ -532,6 +532,7 @@ extern "C" { tree.node = baseData; const auto block_index = blocks_counter++; + root.wait_time += baseData->duration(); root.sync.emplace_back(block_index); } @@ -741,7 +742,7 @@ extern "C" { if (root.depth < frame.depth) root.depth = frame.depth; - root.active_time += frame.node->duration(); + root.profiled_time += frame.node->duration(); } ++root.depth; @@ -774,7 +775,7 @@ extern "C" { auto& frame = blocks[i]; if (root.depth < frame.depth) root.depth = frame.depth; - root.active_time += frame.node->duration(); + root.profiled_time += frame.node->duration(); } ++root.depth; diff --git a/profiler_gui/blocks_graphics_view.cpp b/profiler_gui/blocks_graphics_view.cpp index 097fe69..78789db 100644 --- a/profiler_gui/blocks_graphics_view.cpp +++ b/profiler_gui/blocks_graphics_view.cpp @@ -427,8 +427,8 @@ void EasyGraphicsView::setTree(const ::profiler::thread_blocks_tree_t& _blocksTr if (finish < timefinish) finish = timefinish; - if (t.active_time > busyTime) { - busyTime = t.active_time; + if (t.profiled_time > busyTime) { + busyTime = t.profiled_time; longestTree = threadTree.first; } @@ -1442,10 +1442,10 @@ void EasyGraphicsView::onIdleTimeout() lay->addWidget(new QLabel("Thread", widget), row + 1, 1, Qt::AlignHCenter); - auto percent = ::profiler_gui::percentReal(duration, item->root()->active_time); + auto percent = ::profiler_gui::percentReal(duration, item->root()->profiled_time); lay->addWidget(new QLabel(0.005 < percent && percent < 0.5001 ? QString::number(percent, 'f', 2) : QString::number(static_cast(0.5 + percent)), widget), row + 2, 1, Qt::AlignHCenter); - lay->addWidget(new QLabel(QString::number(::profiler_gui::percent(itemBlock.per_thread_stats->total_duration, item->root()->active_time)), widget), row + 3, 1, Qt::AlignHCenter); + lay->addWidget(new QLabel(QString::number(::profiler_gui::percent(itemBlock.per_thread_stats->total_duration, item->root()->profiled_time)), widget), row + 3, 1, Qt::AlignHCenter); lay->addWidget(new QLabel(QString::number(itemBlock.per_thread_stats->calls_number), widget), row + 4, 1, Qt::AlignHCenter); diff --git a/profiler_gui/easy_graphics_scrollbar.cpp b/profiler_gui/easy_graphics_scrollbar.cpp index 327369d..12ce854 100644 --- a/profiler_gui/easy_graphics_scrollbar.cpp +++ b/profiler_gui/easy_graphics_scrollbar.cpp @@ -228,7 +228,8 @@ void EasyGraphicsSliderItem::setColor(const QColor& _color) EasyHystogramItem::EasyHystogramItem() : Parent(nullptr) , m_threadDuration(0) - , m_threadActiveTime(0) + , m_threadProfiledTime(0) + , m_threadWaitTime(0) , m_pSource(nullptr) , m_temporaryImage(nullptr) , m_maxDuration(0) @@ -451,10 +452,12 @@ void EasyHystogramItem::paintByPtr(QPainter* _painter) _painter->setPen(Qt::black); rect.setRect(0, bottom + 2, width, widget->defaultFontHeight()); - _painter->drawText(rect, Qt::AlignHCenter | Qt::TextDontClip, QString("%1 | duration: %2 | active time: %3 (%4%) | %5 blocks (%6 events)").arg(m_threadName) + _painter->drawText(rect, Qt::AlignHCenter | Qt::TextDontClip, QString("%1 | duration: %2 | profiled time: %3 (%4%) | wait time: %5 (%6%) | %7 blocks (%8 events)").arg(m_threadName) .arg(::profiler_gui::timeStringRealNs(EASY_GLOBALS.time_units, m_threadDuration)) - .arg(::profiler_gui::timeStringRealNs(EASY_GLOBALS.time_units, m_threadActiveTime)) - .arg(m_threadDuration ? QString::number(100. * (double)m_threadActiveTime / (double)m_threadDuration, 'f', 2) : QString("0")) + .arg(::profiler_gui::timeStringRealNs(EASY_GLOBALS.time_units, m_threadProfiledTime)) + .arg(m_threadDuration ? QString::number(100. * (double)m_threadProfiledTime / (double)m_threadDuration, 'f', 2) : QString("0")) + .arg(::profiler_gui::timeStringRealNs(EASY_GLOBALS.time_units, m_threadWaitTime)) + .arg(m_threadDuration ? QString::number(100. * (double)m_threadWaitTime / (double)m_threadDuration, 'f', 2) : QString("0")) .arg(m_pProfilerThread->blocks_number) .arg(m_pProfilerThread->events.size())); @@ -670,9 +673,9 @@ void EasyHystogramItem::paintById(QPainter* _painter) const auto name = *item->tree.node->name() != 0 ? item->tree.node->name() : easyDescriptor(item->tree.node->id()).name(); if (item->tree.per_thread_stats != nullptr) { - _painter->drawText(rect, Qt::AlignHCenter | Qt::TextDontClip, QString("%1 | %2 | %3 calls | %4% of thread active time").arg(m_threadName).arg(name) + _painter->drawText(rect, Qt::AlignHCenter | Qt::TextDontClip, QString("%1 | %2 | %3 calls | %4% of thread profiled time").arg(m_threadName).arg(name) .arg(item->tree.per_thread_stats->calls_number) - .arg(m_threadActiveTime ? QString::number(100. * (double)item->tree.per_thread_stats->total_duration / (double)m_threadActiveTime, 'f', 2) : QString("100"))); + .arg(m_threadProfiledTime ? QString::number(100. * (double)item->tree.per_thread_stats->total_duration / (double)m_threadProfiledTime, 'f', 2) : QString("100"))); } else { @@ -768,7 +771,8 @@ void EasyHystogramItem::setSource(::profiler::thread_id_t _thread_id, const ::pr m_threadDuration = 0; else m_threadDuration = easyBlock(root.children.back()).tree.node->end() - easyBlock(root.children.front()).tree.node->begin(); - m_threadActiveTime = root.active_time; + m_threadProfiledTime = root.profiled_time; + m_threadWaitTime = root.wait_time; m_pProfilerThread = &root; @@ -816,7 +820,8 @@ void EasyHystogramItem::setSource(::profiler::thread_id_t _thread_id, ::profiler m_threadDuration = 0; else m_threadDuration = easyBlock(root.children.back()).tree.node->end() - easyBlock(root.children.front()).tree.node->begin(); - m_threadActiveTime = root.active_time; + m_threadProfiledTime = root.profiled_time; + m_threadWaitTime = root.wait_time; m_pProfilerThread = &root; diff --git a/profiler_gui/easy_graphics_scrollbar.h b/profiler_gui/easy_graphics_scrollbar.h index 75d2b5c..9a8a459 100644 --- a/profiler_gui/easy_graphics_scrollbar.h +++ b/profiler_gui/easy_graphics_scrollbar.h @@ -144,7 +144,8 @@ class EasyHystogramItem : public QGraphicsItem EasyQTimer m_timer; ::std::thread m_workerThread; ::profiler::timestamp_t m_threadDuration; - ::profiler::timestamp_t m_threadActiveTime; + ::profiler::timestamp_t m_threadProfiledTime; + ::profiler::timestamp_t m_threadWaitTime; const ::profiler_gui::EasyItems* m_pSource; QImage* m_temporaryImage; const ::profiler::BlocksTreeRoot* m_pProfilerThread; diff --git a/profiler_gui/tree_widget_loader.cpp b/profiler_gui/tree_widget_loader.cpp index c3b0a58..d763857 100644 --- a/profiler_gui/tree_widget_loader.cpp +++ b/profiler_gui/tree_widget_loader.cpp @@ -208,7 +208,7 @@ void FillTreeClass::setTreeInternal1(T& _safelocker, Items& _items, ThreadedI //_items.push_back(item); - item->setTimeSmart(COL_SELF_DURATION, _units, root.active_time); + item->setTimeSmart(COL_SELF_DURATION, _units, root.profiled_time); ::profiler::timestamp_t children_duration = 0; const auto children_items_number = FillTreeClass::setTreeInternal(_safelocker, _items, _beginTime, root.children, item, nullptr, item, _beginTime, finishtime + 1000000000ULL, false, children_duration, _colorizeRows, _addZeroBlocks, _units); @@ -291,7 +291,7 @@ void FillTreeClass::setTreeInternal2(T& _safelocker, Items& _items, ThreadedI thread_item->setTextColor(::profiler_gui::SELECTED_THREAD_FOREGROUND); // Sum of all children durations: - thread_item->setTimeSmart(COL_SELF_DURATION, _units, block.root->active_time); + thread_item->setTimeSmart(COL_SELF_DURATION, _units, block.root->profiled_time); threadsMap.insert(::std::make_pair(block.root->thread_id, thread_item)); } @@ -307,7 +307,7 @@ void FillTreeClass::setTreeInternal2(T& _safelocker, Items& _items, ThreadedI item->setData(COL_PERCENT_PER_FRAME, Qt::UserRole, 0); - auto percentage_per_thread = ::profiler_gui::percent(duration, block.root->active_time); + auto percentage_per_thread = ::profiler_gui::percent(duration, block.root->profiled_time); item->setData(COL_PERCENT_PER_PARENT, Qt::UserRole, percentage_per_thread); item->setText(COL_PERCENT_PER_PARENT, QString::number(percentage_per_thread)); @@ -329,7 +329,7 @@ void FillTreeClass::setTreeInternal2(T& _safelocker, Items& _items, ThreadedI item->setData(COL_NCALLS_PER_THREAD, Qt::UserRole, per_thread_stats->calls_number); item->setText(COL_NCALLS_PER_THREAD, QString::number(per_thread_stats->calls_number)); - percentage_per_thread = ::profiler_gui::percent(per_thread_stats->total_duration, block.root->active_time); + percentage_per_thread = ::profiler_gui::percent(per_thread_stats->total_duration, block.root->profiled_time); item->setData(COL_PERCENT_SUM_PER_THREAD, Qt::UserRole, percentage_per_thread); item->setText(COL_PERCENT_SUM_PER_THREAD, QString::number(percentage_per_thread));