From: James Benton Date: Thu, 16 Aug 2012 12:44:19 +0000 (+0100) Subject: Improve profiling. X-Git-Url: https://git.cworth.org/git?p=apitrace;a=commitdiff_plain;h=56ad11c7849c7e6ca0ad66558cb1a99c58d4cd3d Improve profiling. Remove frame_begin from profile output. Change frame_end to no longer record times. Profile non-draw calls for CPU only. Resynchronise gpu time every frame to account for drift. Improve performance of profile gui. Add seperate CPU view to timeline widget. --- diff --git a/common/trace_profiler.cpp b/common/trace_profiler.cpp index 403c260..642ba6e 100644 --- a/common/trace_profiler.cpp +++ b/common/trace_profiler.cpp @@ -24,16 +24,16 @@ **************************************************************************/ #include "trace_profiler.hpp" +#include "os_time.hpp" #include #include -#include #include -#include "os_time.hpp" namespace trace { Profiler::Profiler() : baseGpuTime(0), baseCpuTime(0), + minCpuTime(1000), cpuTimes(false), gpuTimes(true), pixelsDrawn(false) @@ -50,14 +50,26 @@ void Profiler::setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_) gpuTimes = gpuTimes_; pixelsDrawn = pixelsDrawn_; - std::cout << "# frame_begin no gpu_start cpu_start" << std::endl; - std::cout << "# frame_end no gpu_end gpu_dura cpu_end cpu_dura" << std::endl; std::cout << "# call no gpu_start gpu_dura cpu_start cpu_dura pixels program name" << std::endl; } -void Profiler::setBaseTimes(int64_t gpuStart, int64_t cpuStart) +int64_t Profiler::getBaseCpuTime() +{ + return baseCpuTime; +} + +int64_t Profiler::getBaseGpuTime() +{ + return baseGpuTime; +} + +void Profiler::setBaseCpuTime(int64_t cpuStart) { baseCpuTime = cpuStart; +} + +void Profiler::setBaseGpuTime(int64_t gpuStart) +{ baseGpuTime = gpuStart; } @@ -84,6 +96,10 @@ void Profiler::addCall(unsigned no, double cpuTimeScale = 1.0E9 / os::timeFrequency; cpuStart = (cpuStart - baseCpuTime) * cpuTimeScale; cpuDuration = cpuDuration * cpuTimeScale; + + if (cpuDuration < minCpuTime) { + return; + } } else { cpuStart = 0; cpuDuration = 0; @@ -105,108 +121,81 @@ void Profiler::addCall(unsigned no, << std::endl; } -void Profiler::addFrameStart(unsigned no, int64_t gpuStart, int64_t cpuStart) -{ - lastFrame.no = no; - lastFrame.gpuStart = gpuStart; - lastFrame.cpuStart = cpuStart; - - if (gpuTimes) { - gpuStart = gpuStart - baseGpuTime; - } else { - gpuStart = 0; - } - - if (cpuTimes) { - double cpuTimeScale = 1.0E9 / os::timeFrequency; - cpuStart = (cpuStart - baseCpuTime) * cpuTimeScale; - } else { - cpuStart = 0; - } - - std::cout << "frame_begin" - << " " << no - << " " << gpuStart - << " " << cpuStart - << std::endl; -} - -void Profiler::addFrameEnd(int64_t gpuEnd, int64_t cpuEnd) +void Profiler::addFrameEnd() { - int64_t gpuDuration, cpuDuration; - - if (gpuTimes) { - gpuDuration = gpuEnd - lastFrame.gpuStart; - gpuEnd = gpuEnd - baseGpuTime; - } else { - gpuEnd = 0; - gpuDuration = 0; - } - - if (cpuTimes) { - double cpuTimeScale = 1.0E9 / os::timeFrequency; - cpuDuration = (cpuEnd - lastFrame.cpuStart) * cpuTimeScale; - cpuEnd = (cpuEnd - baseCpuTime) * cpuTimeScale; - } else { - cpuEnd = 0; - cpuDuration = 0; - } - - std::cout << "frame_end" - << " " << lastFrame.no - << " " << gpuEnd - << " " << gpuDuration - << " " << cpuEnd - << " " << cpuDuration - << std::endl; + std::cout << "frame_end" << std::endl; } void Profiler::parseLine(const char* in, Profile* profile) { std::stringstream line(in, std::ios_base::in); std::string type; + static int64_t lastGpuTime; + static int64_t lastCpuTime; - if (in[0] == '#' || strlen(in) < 12) + if (in[0] == '#' || strlen(in) < 4) return; + if (profile->programs.size() == 0 && profile->cpuCalls.size() == 0 && profile->frames.size() == 0) { + lastGpuTime = 0; + lastCpuTime = 0; + } + line >> type; if (type.compare("call") == 0) { - assert(profile->frames.size()); - Profile::Call call; - - line >> call.no - >> call.gpuStart - >> call.gpuDuration - >> call.cpuStart - >> call.cpuDuration - >> call.pixels - >> call.program - >> call.name; - - if (call.pixels >= 0) { - profile->frames.back().calls.push_back(call); + Profile::DrawCall draw; + unsigned program; + + line >> draw.no + >> draw.gpuStart + >> draw.gpuDuration + >> draw.cpuStart + >> draw.cpuDuration + >> draw.pixels + >> program + >> draw.name; + + if (lastGpuTime < draw.gpuStart + draw.gpuDuration) { + lastGpuTime = draw.gpuStart + draw.gpuDuration; } - } else if (type.compare("frame_begin") == 0) { - Profile::Frame frame; - frame.gpuDuration = 0; - frame.cpuDuration = 0; - line >> frame.no - >> frame.gpuStart - >> frame.cpuStart; + if (lastCpuTime < draw.cpuStart + draw.cpuDuration) { + lastCpuTime = draw.cpuStart + draw.cpuDuration; + } - profile->frames.push_back(frame); + if (draw.pixels >= 0) { + if (profile->programs.size() <= program) { + profile->programs.resize(program + 1); + } + + profile->programs[program].cpuTotal += draw.cpuDuration; + profile->programs[program].gpuTotal += draw.gpuDuration; + profile->programs[program].pixelTotal += draw.pixels; + profile->programs[program].drawCalls.push_back(draw); + } + + Profile::CpuCall call; + call.no = draw.no; + call.name = draw.name; + call.cpuStart = draw.cpuStart; + call.cpuDuration = draw.cpuDuration; + profile->cpuCalls.push_back(call); } else if (type.compare("frame_end") == 0) { - assert(profile->frames.size()); - Profile::Frame& frame = profile->frames.back(); - int64_t skipi64; - - line >> frame.no - >> skipi64 - >> frame.gpuDuration - >> skipi64 - >> frame.cpuDuration; + Profile::Frame frame; + frame.no = profile->frames.size(); + + if (frame.no == 0) { + frame.gpuStart = 0; + frame.cpuStart = 0; + } else { + frame.gpuStart = profile->frames.back().gpuStart + profile->frames.back().gpuDuration; + frame.cpuStart = profile->frames.back().cpuStart + profile->frames.back().cpuDuration; + } + + frame.gpuDuration = lastGpuTime - frame.gpuStart; + frame.cpuDuration = lastCpuTime - frame.cpuStart; + profile->frames.push_back(frame); } } } diff --git a/common/trace_profiler.hpp b/common/trace_profiler.hpp index dc3c4be..42fd032 100644 --- a/common/trace_profiler.hpp +++ b/common/trace_profiler.hpp @@ -34,34 +34,51 @@ namespace trace { struct Profile { - struct Call { + struct CpuCall { unsigned no; + + int64_t cpuStart; + int64_t cpuDuration; + + std::string name; + }; + + struct DrawCall { + unsigned no; + int64_t gpuStart; int64_t gpuDuration; + int64_t cpuStart; int64_t cpuDuration; + int64_t pixels; - unsigned program; - std::string name; - typedef std::vector::iterator iterator; - typedef std::vector::const_iterator const_iterator; + std::string name; }; struct Frame { unsigned no; + int64_t gpuStart; int64_t gpuDuration; + int64_t cpuStart; int64_t cpuDuration; + }; - std::vector calls; + struct Program { + Program() : gpuTotal(0), cpuTotal(0), pixelTotal(0) {} - typedef std::vector::iterator iterator; - typedef std::vector::const_iterator const_iterator; + uint64_t gpuTotal; + uint64_t cpuTotal; + uint64_t pixelTotal; + std::vector drawCalls; }; std::vector frames; + std::vector programs; + std::vector cpuCalls; }; class Profiler @@ -71,11 +88,6 @@ public: ~Profiler(); void setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_); - void setBaseTimes(int64_t gpuStart, int64_t cpuStart); - bool hasBaseTimes(); - - void addFrameStart(unsigned no, int64_t gpuStart, int64_t cpuStart); - void addFrameEnd(int64_t gpuEnd, int64_t cpuEnd); void addCall(unsigned no, const char* name, @@ -84,21 +96,26 @@ public: int64_t gpuStart, int64_t gpuDuration, int64_t cpuStart, int64_t cpuDuration); + void addFrameEnd(); + + bool hasBaseTimes(); + + void setBaseCpuTime(int64_t cpuStart); + void setBaseGpuTime(int64_t gpuStart); + + int64_t getBaseCpuTime(); + int64_t getBaseGpuTime(); + static void parseLine(const char* line, Profile* profile); private: int64_t baseGpuTime; int64_t baseCpuTime; + int64_t minCpuTime; bool cpuTimes; bool gpuTimes; bool pixelsDrawn; - - struct { - unsigned no; - int64_t gpuStart; - int64_t cpuStart; - } lastFrame; }; } diff --git a/gui/profiledialog.cpp b/gui/profiledialog.cpp index 5568b54..d0a55a3 100644 --- a/gui/profiledialog.cpp +++ b/gui/profiledialog.cpp @@ -22,7 +22,7 @@ ProfileDialog::~ProfileDialog() void ProfileDialog::tableDoubleClicked(const QModelIndex& index) { ProfileTableModel* model = (ProfileTableModel*)m_table->model(); - const trace::Profile::Call* call = model->getJumpCall(index); + const trace::Profile::DrawCall* call = model->getJumpCall(index); if (call) { emit jumpToCall(call->no); diff --git a/gui/profiletablemodel.cpp b/gui/profiletablemodel.cpp index 8da07e0..649dae0 100644 --- a/gui/profiletablemodel.cpp +++ b/gui/profiletablemodel.cpp @@ -1,7 +1,9 @@ #include "profiletablemodel.h" -typedef trace::Profile::Call Call; typedef trace::Profile::Frame Frame; +typedef trace::Profile::Program Program; +typedef trace::Profile::CpuCall CpuCall; +typedef trace::Profile::DrawCall DrawCall; enum { COLUMN_PROGRAM, @@ -38,8 +40,8 @@ ProfileTableModel::ProfileTableModel(QObject *parent) void ProfileTableModel::setProfile(trace::Profile* profile) { m_profile = profile; - m_timeMin = m_profile->frames.front().gpuStart; - m_timeMax = m_profile->frames.back().gpuStart + m_profile->frames.back().gpuDuration; + m_timeMin = m_profile->frames.front().cpuStart; + m_timeMax = m_profile->frames.back().cpuStart + m_profile->frames.back().cpuDuration; updateModel(); } @@ -59,8 +61,8 @@ void ProfileTableModel::setTimeSelection(int64_t start, int64_t end) void ProfileTableModel::updateModel() { if (m_timeMin == m_timeMax) { - m_timeMin = m_profile->frames.front().gpuStart; - m_timeMax = m_profile->frames.back().gpuStart + m_profile->frames.back().gpuDuration; + m_timeMin = m_profile->frames.front().cpuStart; + m_timeMax = m_profile->frames.back().cpuStart + m_profile->frames.back().cpuDuration; } for (QList::iterator itr = m_rowData.begin(); itr != m_rowData.end(); ++itr) { @@ -75,39 +77,25 @@ void ProfileTableModel::updateModel() row.longestPixel = NULL; } - for (Frame::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { - const Frame& frame = *itr; + for (std::vector::const_iterator itr = m_profile->programs.begin(); itr != m_profile->programs.end(); ++itr) { + ProfileTableRow* row = getRow(itr - m_profile->programs.begin()); + const Program& program = *itr; - if (frame.gpuStart > m_timeMax) { - break; - } - - if ((frame.gpuStart + frame.gpuDuration) < m_timeMin) { - continue; - } - - for (Call::const_iterator jtr = frame.calls.begin(); jtr != frame.calls.end(); ++jtr) { - const Call& call = *jtr; + for (std::vector::const_iterator jtr = program.drawCalls.begin(); jtr != program.drawCalls.end(); ++jtr) { + const DrawCall& call = *jtr; - if (call.gpuStart > m_timeMax) { + if (call.cpuStart > m_timeMax) { break; } - if ((call.gpuStart + call.gpuDuration) < m_timeMin) { + if (call.cpuStart + call.cpuDuration < m_timeMin) { continue; } - ProfileTableRow* row = getRow(call.program); - if (!row) { - m_rowData.append(ProfileTableRow()); - row = &m_rowData.back(); - } - row->uses++; - row->program = call.program; + row->pixels += call.pixels; row->gpuTime += call.gpuDuration; row->cpuTime += call.cpuDuration; - row->pixels += call.pixels; if (!row->longestGpu || row->longestGpu->gpuDuration < call.gpuDuration) { row->longestGpu = &call; @@ -128,7 +116,7 @@ void ProfileTableModel::updateModel() /** * Get the appropriate call associated with an item in the table */ -const Call* ProfileTableModel::getJumpCall(const QModelIndex & index) const { +const DrawCall* ProfileTableModel::getJumpCall(const QModelIndex & index) const { const ProfileTableRow& row = m_rowData[index.row()]; switch(index.column()) { @@ -153,7 +141,8 @@ ProfileTableRow* ProfileTableModel::getRow(unsigned program) { return &*itr; } - return NULL; + m_rowData.append(ProfileTableRow(program)); + return &m_rowData.back(); } diff --git a/gui/profiletablemodel.h b/gui/profiletablemodel.h index fe7979a..6cca74d 100644 --- a/gui/profiletablemodel.h +++ b/gui/profiletablemodel.h @@ -6,8 +6,8 @@ struct ProfileTableRow { - ProfileTableRow() - : program(0), + ProfileTableRow(unsigned no) + : program(no), uses(0), gpuTime(0), cpuTime(0), @@ -24,9 +24,9 @@ struct ProfileTableRow qulonglong cpuTime; qulonglong pixels; - const trace::Profile::Call* longestGpu; - const trace::Profile::Call* longestCpu; - const trace::Profile::Call* longestPixel; + const trace::Profile::DrawCall* longestGpu; + const trace::Profile::DrawCall* longestCpu; + const trace::Profile::DrawCall* longestPixel; }; class ProfileTableModel : public QAbstractTableModel @@ -39,7 +39,7 @@ public: void setProfile(trace::Profile* profile); void setTimeSelection(int64_t start, int64_t end); - const trace::Profile::Call* getJumpCall(const QModelIndex & index) const; + const trace::Profile::DrawCall* getJumpCall(const QModelIndex & index) const; virtual int rowCount(const QModelIndex & parent) const; virtual int columnCount(const QModelIndex & parent) const; diff --git a/gui/timelinewidget.cpp b/gui/timelinewidget.cpp index 92c971f..d9f1b58 100644 --- a/gui/timelinewidget.cpp +++ b/gui/timelinewidget.cpp @@ -9,8 +9,10 @@ #include #include -typedef trace::Profile::Call Call; typedef trace::Profile::Frame Frame; +typedef trace::Profile::Program Program; +typedef trace::Profile::CpuCall CpuCall; +typedef trace::Profile::DrawCall DrawCall; TimelineWidget::TimelineWidget(QWidget *parent) : QWidget(parent), @@ -19,16 +21,18 @@ TimelineWidget::TimelineWidget(QWidget *parent) m_timeSelectionEnd(0), m_rowHeight(20), m_axisWidth(50), - m_axisHeight(20), + m_axisHeight(30), + m_axisLine(QColor(240, 240, 240)), m_axisBorder(Qt::black), - m_axisBackground(Qt::lightGray), + m_axisForeground(Qt::black), + m_axisBackground(QColor(210, 210, 210)), m_itemBorder(Qt::red), m_itemForeground(Qt::cyan), m_itemBackground(Qt::red), - m_selectionBorder(QColor(50, 50, 255)), - m_selectionBackground(QColor(245, 245, 255)), - m_zoomBorder(Qt::green), - m_zoomBackground(QColor(100, 255, 100, 80)) + m_selectionBorder(Qt::green), + m_selectionBackground(QColor(100, 255, 100, 8)), + m_zoomBorder(QColor(255, 0, 255)), + m_zoomBackground(QColor(255, 0, 255, 30)) { setBackgroundRole(QPalette::Base); setAutoFillBackground(true); @@ -111,18 +115,54 @@ int64_t TimelineWidget::positionToTime(int pos) /** - * Return the item at position + * Binary Search for a time in start+durations */ -const VisibleItem* TimelineWidget::itemAtPosition(const QPoint& pos) +template +typename std::vector::const_iterator binarySearchTimespan( + typename std::vector::const_iterator begin, + typename std::vector::const_iterator end, + int64_t time) { - foreach (const VisibleItem& item, m_visibleItems) { - if (pos.x() < item.rect.left() || pos.y() < item.rect.top()) - continue; + int lower = 0; + int upper = end - begin; + int pos = (lower + upper) / 2; + typename std::vector::const_iterator itr = begin + pos; + + while (!((*itr).*mem_ptr_start <= time && (*itr).*mem_ptr_start + (*itr).*mem_ptr_dura > time) && (lower <= upper)) { + if ((*itr).*mem_ptr_start > time) { + upper = pos - 1; + } else { + lower = pos + 1; + } - if (pos.x() > item.rect.right() || pos.y() > item.rect.bottom()) - continue; + pos = (lower + upper) / 2; + itr = begin + pos; + } + + if (lower <= upper) + return itr; + else + return end; +} + + +/** + * Find the frame at time + */ +const Frame* TimelineWidget::frameAtTime(int64_t time) { + if (!m_profile) { + return NULL; + } + + std::vector::const_iterator res + = binarySearchTimespan( + m_profile->frames.begin(), + m_profile->frames.end(), + time); - return &item; + if (res != m_profile->frames.end()) { + const Frame& frame = *res; + return &frame; } return NULL; @@ -130,45 +170,82 @@ const VisibleItem* TimelineWidget::itemAtPosition(const QPoint& pos) /** - * Calculate the row order by total gpu time per shader + * Find the CPU call at time */ -void TimelineWidget::calculateRows() -{ - typedef QPair HeatProgram; - QList heats; - int idx; +const CpuCall* TimelineWidget::cpuCallAtTime(int64_t time) { + if (!m_profile) { + return NULL; + } - m_programRowMap.clear(); - m_rowCount = 0; + std::vector::const_iterator res + = binarySearchTimespan( + m_profile->cpuCalls.begin(), + m_profile->cpuCalls.end(), + time); - for (Frame::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { - const Frame& frame = *itr; + if (res != m_profile->cpuCalls.end()) { + const CpuCall& call = *res; + return &call; + } - for (Call::const_iterator jtr = frame.calls.begin(); jtr != frame.calls.end(); ++jtr) { - const Call& call = *jtr; + return NULL; +} - while (call.program >= heats.size()) { - heats.append(HeatProgram(0, heats.size())); - m_programRowMap.append(m_programRowMap.size()); - } - heats[call.program].first += call.gpuDuration; - } +/** + * Find the draw call at time + */ +const DrawCall* TimelineWidget::drawCallAtTime(int program, int64_t time) { + if (!m_profile) { + return NULL; } - qSort(heats); - idx = heats.size() - 1; + std::vector& drawCalls = m_profile->programs[program].drawCalls; - for (QList::iterator itr = heats.begin(); itr != heats.end(); ++itr, --idx) { - HeatProgram& pair = *itr; + std::vector::const_iterator res + = binarySearchTimespan( + drawCalls.begin(), + drawCalls.end(), + time); - if (pair.first == 0) { - m_programRowMap[pair.second] = -1; - } else { - m_programRowMap[pair.second] = idx; - m_rowCount++; + if (res != drawCalls.end()) { + const DrawCall& call = *res; + return &call; + } + + return NULL; +} + + +/** + * Calculate the row order by total gpu time per shader + */ +void TimelineWidget::calculateRows() +{ + typedef QPair Pair; + std::vector gpu; + + /* Map shader to visible row */ + for (std::vector::const_iterator itr = m_profile->programs.begin(); itr != m_profile->programs.end(); ++itr) { + const Program& program = *itr; + unsigned no = itr - m_profile->programs.begin(); + + if (program.gpuTotal > 0) { + gpu.push_back(Pair(program.gpuTotal, no)); } } + + /* Sort the shaders by most used gpu */ + qSort(gpu); + + /* Create row order */ + m_rowPrograms.clear(); + + for (std::vector::const_reverse_iterator itr = gpu.rbegin(); itr != gpu.rend(); ++itr) { + m_rowPrograms.push_back(itr->second); + } + + m_rowCount = m_rowPrograms.size(); } @@ -183,8 +260,8 @@ void TimelineWidget::setProfile(trace::Profile* profile) m_profile = profile; calculateRows(); - m_timeMin = m_profile->frames.front().gpuStart; - m_timeMax = m_profile->frames.back().gpuStart + m_profile->frames.back().gpuDuration; + m_timeMin = m_profile->frames.front().cpuStart; + m_timeMax = m_profile->frames.back().cpuStart + m_profile->frames.back().cpuDuration; m_time = m_timeMin; m_timeWidth = m_timeMax - m_timeMin; @@ -253,8 +330,8 @@ void TimelineWidget::setRowScroll(int position, bool notify) void TimelineWidget::resizeEvent(QResizeEvent *e) { /* Update viewport size */ - m_viewWidth = width() - m_axisWidth; - m_viewHeight = height() - m_axisHeight; + m_viewWidth = qMax(0, width() - m_axisWidth); + m_viewHeight = qMax(0, height() - m_axisHeight - m_rowHeight); /* Update vertical scroll bar */ if (m_profile) { @@ -267,33 +344,56 @@ void TimelineWidget::resizeEvent(QResizeEvent *e) void TimelineWidget::mouseMoveEvent(QMouseEvent *e) { + bool tooltip = false; + m_mousePosition = e->pos(); + if (!m_profile) { return; } /* Display tooltip if necessary */ if (e->buttons() == Qt::NoButton) { - const VisibleItem* item = itemAtPosition(e->pos()); - - if (item) { - const trace::Profile::Call* call = item->call; - - QString text; - text = QString::fromStdString(call->name); - text += QString("\nCall: %1").arg(call->no); - text += QString("\nGPU Time: %1").arg(call->gpuDuration); - text += QString("\nCPU Time: %1").arg(call->cpuDuration); - text += QString("\nPixels Drawn: %1").arg(call->pixels); - - QToolTip::showText(e->globalPos(), text); + if (m_mousePosition.x() > m_axisWidth && m_mousePosition.y() > m_axisHeight) { + int64_t time = positionToTime(m_mousePosition.x() - m_axisWidth); + int y = m_mousePosition.y() - m_axisHeight; + + if (y < m_rowHeight) { + const CpuCall* call = cpuCallAtTime(time); + + if (call) { + QString text; + text = QString::fromStdString(call->name); + text += QString("\nCall: %1").arg(call->no); + text += QString("\nCPU Start: %1").arg(call->cpuStart); + text += QString("\nCPU Duration: %1").arg(call->cpuDuration); + + QToolTip::showText(e->globalPos(), text); + tooltip = true; + } + } else { + int row = (y - m_rowHeight + m_scrollY) / m_rowHeight; + + if (row < m_rowPrograms.size()) { + int program = m_rowPrograms[row]; + const DrawCall* call = drawCallAtTime(program, time); + + if (call) { + QString text; + text = QString::fromStdString(call->name); + text += QString("\nCall: %1").arg(call->no); + text += QString("\nGPU Start: %1").arg(call->gpuStart); + text += QString("\nCPU Start: %1").arg(call->cpuStart); + text += QString("\nGPU Duration: %1").arg(call->gpuDuration); + text += QString("\nCPU Duration: %1").arg(call->cpuDuration); + text += QString("\nPixels Drawn: %1").arg(call->pixels); + + QToolTip::showText(e->globalPos(), text); + tooltip = true; + } + } + } } - } - - m_mousePosition = e->pos(); - - if (e->buttons().testFlag(Qt::LeftButton)) { - QToolTip::hideText(); - + } else if (e->buttons().testFlag(Qt::LeftButton)) { if (m_mousePressMode == DragView) { /* Horizontal scroll */ double dt = m_timeWidth; @@ -305,21 +405,26 @@ void TimelineWidget::mouseMoveEvent(QMouseEvent *e) int dy = m_mousePressPosition.y() - e->pos().y(); setRowScroll(m_mousePressRow + dy); } else if (m_mousePressMode == RulerSelect) { + /* Horizontal selection */ int64_t down = positionToTime(m_mousePressPosition.x() - m_axisWidth); - int64_t up = positionToTime(e->pos().x() - m_axisWidth); + int64_t up = positionToTime(qMax(e->pos().x() - m_axisWidth, 0)); setSelection(qMin(down, up), qMax(down, up)); } update(); } + + if (!tooltip) { + QToolTip::hideText(); + } } void TimelineWidget::mousePressEvent(QMouseEvent *e) { if (e->buttons() & Qt::LeftButton) { - if (e->pos().y() < m_axisHeight) { + if (e->pos().y() < m_axisHeight && e->pos().x() >= m_axisWidth) { if (QApplication::keyboardModifiers() & Qt::ControlModifier) { m_mousePressMode = RulerZoom; } else { @@ -350,7 +455,7 @@ void TimelineWidget::mouseReleaseEvent(QMouseEvent *e) /* Calculate new time view based on selected area */ int64_t down = positionToTime(m_mousePressPosition.x() - m_axisWidth); - int64_t up = positionToTime(e->pos().x() - m_axisWidth); + int64_t up = positionToTime(qMax(e->pos().x() - m_axisWidth, 0)); int64_t left = qMin(down, up); int64_t right = qMax(down, up); @@ -371,26 +476,38 @@ void TimelineWidget::mouseDoubleClickEvent(QMouseEvent *e) { int64_t time = positionToTime(e->pos().x() - m_axisWidth); - if (e->pos().y() < m_axisHeight) { - int64_t time = positionToTime(e->pos().x() - m_axisWidth); - - for (Frame::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { - const Frame& frame = *itr; + if (e->pos().x() > m_axisWidth) { + int row = (e->pos().y() - m_axisHeight) / m_rowHeight; - if (frame.gpuStart + frame.gpuDuration < time) - continue; + if (e->pos().y() < m_axisHeight) { + /* Horizontal axis */ + const Frame* frame = frameAtTime(time); - if (frame.gpuStart > time) - break; + if (frame) { + setSelection(frame->cpuStart, frame->cpuStart + frame->cpuDuration, true); + return; + } + } else if (row == 0) { + /* CPU Calls */ + const CpuCall* call = cpuCallAtTime(time); - setSelection(frame.gpuStart, frame.gpuStart + frame.gpuDuration, true); - return; + if (call) { + emit jumpToCall(call->no); + return; + } + } else if (row > 0) { + /* Draw Calls */ + int program = m_rowPrograms[row - 1 + m_row]; + const DrawCall* call = drawCallAtTime(program, time); + + if (call) { + emit jumpToCall(call->no); + return; + } } } - if (const VisibleItem* item = itemAtPosition(e->pos())) { - emit jumpToCall(item->call->no); - } else if (time < m_timeSelectionStart || time > m_timeSelectionEnd) { + if (time < m_timeSelectionStart || time > m_timeSelectionEnd) { setSelection(0, 0, true); } } @@ -404,6 +521,7 @@ void TimelineWidget::wheelEvent(QWheelEvent *e) int zoomPercent = 10; + /* If holding Ctrl key then zoom 2x faster */ if (QApplication::keyboardModifiers() & Qt::ControlModifier) { zoomPercent = 20; } @@ -432,27 +550,25 @@ void TimelineWidget::wheelEvent(QWheelEvent *e) /** * Paints a single pixel column of the heat map */ -void TimelineWidget::paintHeatmapColumn(int x, QPainter& painter, QVector& rows) +void TimelineWidget::drawHeat(QPainter& painter, int x, int64_t heat, bool isCpu) { + if (heat == 0) { + return; + } + double timePerPixel = m_timeWidth; timePerPixel /= m_viewWidth; - for(int i = 0, y = 0; i < rows.size(); ++i, y += m_rowHeight) { - if (rows[i] == 0) - continue; - - if (y > m_viewHeight) - continue; - - double heat = rows[i] / timePerPixel; - heat = qBound(0.0, heat, 1.0); - heat *= 255.0; + double colour = heat / timePerPixel; + colour = qBound(0.0, colour * 255.0, 255.0); - painter.setPen(QColor(255, 255 - heat, 255 - heat)); - painter.drawLine(x, y, x, y + m_rowHeight); - - rows[i] = 0; + if (isCpu) { + painter.setPen(QColor(255 - colour, 255 - colour, 255)); + } else { + painter.setPen(QColor(255, 255 - colour, 255 - colour)); } + + painter.drawLine(x, 0, x, m_rowHeight - 1); } @@ -464,230 +580,303 @@ void TimelineWidget::paintEvent(QPaintEvent *e) if (!m_profile) return; - QVector heatMap(m_programRowMap.size(), 0); QPainter painter(this); - int64_t timeEnd; - int selectionRight; - int selectionLeft; - int rowEnd; - int lastX; - - - /* - * Draw the active selection background - */ - if (m_timeSelectionStart != m_timeSelectionEnd) { - selectionLeft = timeToPosition(m_timeSelectionStart) + m_axisWidth; - selectionRight = (timeToPosition(m_timeSelectionEnd) + 0.5) + m_axisWidth; - - selectionLeft = qBound(-1, selectionLeft, width() + 1); - selectionRight = qBound(-1, selectionRight, width() + 1); - - painter.setPen(Qt::NoPen); - painter.setBrush(m_selectionBackground); - painter.drawRect(selectionLeft, m_axisHeight, selectionRight - selectionLeft, m_viewHeight); - } + int rowEnd = qMin(m_row + (m_viewHeight / m_rowHeight) + 1, m_rowCount); + int64_t timeEnd = m_time + m_timeWidth; + int64_t heat = 0; + int lastX = 0; + int widgetHeight = height(); + int widgetWidth = width(); - /* - * Draw profile heatmap - */ - rowEnd = m_row + (m_viewHeight / m_rowHeight) + 1; - timeEnd = m_time + m_timeWidth; - m_visibleItems.clear(); - lastX = 0; + /* Draw GPU rows */ + painter.translate(m_axisWidth, m_axisHeight + m_rowHeight - (m_scrollY % m_rowHeight)); - painter.translate(m_axisWidth + 1, m_axisHeight + 1 - (m_scrollY % m_rowHeight)); - painter.setBrush(m_itemBackground); - painter.setPen(m_itemBorder); + for (int row = m_row; row < rowEnd; ++row) { + Program& program = m_profile->programs[m_rowPrograms[row]]; + lastX = 0; + heat = 0; - for (Frame::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { - const Frame& frame = *itr; + for (std::vector::const_iterator itr = program.drawCalls.begin(); itr != program.drawCalls.end(); ++itr) { + const DrawCall& call = *itr; + int64_t gpuEnd = call.gpuStart + call.gpuDuration; - if (frame.gpuStart > timeEnd) - break; - - if (frame.gpuStart + frame.gpuDuration < m_time) - continue; - - for (Call::const_iterator jtr = frame.calls.begin(); jtr != frame.calls.end(); ++jtr) { - const Call& call = *jtr; - int row = m_programRowMap[call.program]; - - if (call.gpuStart + call.gpuDuration < m_time || call.gpuStart > timeEnd) - continue; + if (call.gpuStart > timeEnd) { + break; + } - if (row < m_row || row > rowEnd) + if (gpuEnd < m_time) { continue; + } - double left = qMax(0.0, timeToPosition(call.gpuStart)); - double right = timeToPosition(call.gpuStart + call.gpuDuration); + double left = timeToPosition(call.gpuStart); + double right = timeToPosition(gpuEnd); - int leftX = left; + int leftX = left; int rightX = right; - if (lastX != leftX) { - paintHeatmapColumn(lastX, painter, heatMap); + /* Draw last heat if needed */ + if (leftX != lastX) { + drawHeat(painter, lastX, heat, false); lastX = leftX; + heat = 0; } - row -= m_row; - - if (rightX <= lastX + 1) { - if (lastX == rightX) { + if (rightX <= leftX + 1) { + if (rightX == lastX) { /* Fully contained in this X */ - heatMap[row] += call.gpuDuration; + heat += call.gpuDuration; } else { /* Split call time between the two pixels it occupies */ int64_t time = positionToTime(rightX); - heatMap[row] += time - call.gpuStart; - paintHeatmapColumn(lastX, painter, heatMap); + heat += time - call.gpuStart; + drawHeat(painter, lastX, heat, false); - heatMap[row] += (call.gpuDuration + call.gpuStart) - time; + heat = gpuEnd - time; lastX = rightX; } } else { - leftX = (left + 0.5); - rightX = (right + 0.5); - QRect rect; - rect.setLeft(leftX); - rect.setWidth(rightX - leftX); - rect.setTop(row * m_rowHeight); + rect.setLeft(left + 0.5); + rect.setWidth(right - left); + rect.setTop(0); rect.setHeight(m_rowHeight); - VisibleItem vis; - vis.rect = painter.transform().mapRect(rect); - vis.frame = &frame; - vis.call = &call; - m_visibleItems.push_back(vis); - - painter.drawRect(rect); + painter.fillRect(rect, m_itemBackground); if (rect.width() > 6) { - rect.adjust(1, 0, -1, 0); + rect.adjust(1, 0, -1, -2); painter.setPen(m_itemForeground); - painter.drawText(rect, Qt::AlignLeft | Qt::AlignVCenter, QString::fromStdString(call.name)); - painter.setPen(m_itemBorder); + + painter.drawText(rect, + Qt::AlignLeft | Qt::AlignVCenter, + painter.fontMetrics().elidedText(QString::fromStdString(call.name), Qt::ElideRight, rect.width())); } } } - } - - /* Paint the last column if needed */ - paintHeatmapColumn(lastX, painter, heatMap); + painter.translate(0, m_rowHeight); + } - /* - * Draw the axis border and background - */ + /* Draw CPU row */ painter.resetTransform(); - painter.setPen(Qt::NoPen); - painter.setBrush(m_axisBackground); - painter.drawRect(0, 0, m_viewWidth + m_axisWidth, m_axisHeight); - painter.drawRect(0, m_axisHeight, m_axisWidth, m_viewHeight); + painter.translate(m_axisWidth, m_axisHeight); + painter.fillRect(0, 0, m_viewWidth, m_rowHeight, Qt::white); - painter.setPen(m_axisBorder); - painter.drawLine(0, m_axisHeight, m_axisWidth + m_viewWidth, m_axisHeight); - painter.drawLine(m_axisWidth, 0, m_axisWidth, m_viewHeight + m_axisHeight); + for (std::vector::const_iterator itr = m_profile->cpuCalls.begin(); itr != m_profile->cpuCalls.end(); ++itr) { + const CpuCall& call = *itr; + int64_t cpuEnd = call.cpuStart + call.cpuDuration; + if (call.cpuStart > timeEnd) { + continue; + } - /* - * Draw horizontal axis - */ - for (Frame::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { - const Frame& frame = *itr; - int left, right, width; - bool drawText = true; - QString text; + if (cpuEnd < m_time) { + continue; + } - if (frame.gpuStart > timeEnd) - break; + double left = timeToPosition(call.cpuStart); + double right = timeToPosition(cpuEnd); - if (frame.gpuStart + frame.gpuDuration < m_time) - continue; + int leftX = left; + int rightX = right; - left = timeToPosition(frame.gpuStart); - right = timeToPosition(frame.gpuStart + frame.gpuDuration) + 0.5; + /* Draw last heat if needed */ + if (leftX != lastX) { + drawHeat(painter, lastX, heat, true); + lastX = leftX; + heat = 0; + } - left = qBound(0, left, m_viewWidth) + m_axisWidth; - right = qBound(0, right, m_viewWidth) + m_axisWidth; + if (rightX <= leftX + 1) { + if (rightX == lastX) { + /* Fully contained in this X */ + heat += call.cpuDuration; + } else { + /* Split call time between the two pixels it occupies */ + int64_t time = positionToTime(rightX); - width = right - left; + heat += time - call.cpuStart; + drawHeat(painter, lastX, heat, true); - text = QString("Frame %1").arg(frame.no); + heat = cpuEnd - time; + lastX = rightX; + } + } else { + QRect rect; + rect.setLeft(left + 0.5); + rect.setWidth(right - left); + rect.setTop(0); + rect.setHeight(m_rowHeight); + + painter.fillRect(rect, QColor(0, 0, 255)); - if (painter.fontMetrics().width(text) > width) { - text = QString("%1").arg(frame.no); + if (rect.width() > 6) { + rect.adjust(1, 0, -1, -2); + painter.setPen(QColor(255, 255, 0)); - if (painter.fontMetrics().width(text) > width) { - drawText = false; + painter.drawText(rect, + Qt::AlignLeft | Qt::AlignVCenter, + painter.fontMetrics().elidedText(QString::fromStdString(call.name), Qt::ElideRight, rect.width())); } } + } + + /* Draw axis */ + painter.resetTransform(); + painter.setPen(m_axisBorder); + + /* Top Rect */ + painter.fillRect(m_axisWidth - 1, 0, widgetWidth, m_axisHeight - 1, m_axisBackground); + painter.drawLine(0, m_axisHeight - 1, widgetWidth, m_axisHeight - 1); + + /* Left Rect */ + painter.fillRect(0, m_axisHeight - 1, m_axisWidth - 1, widgetHeight, m_axisBackground); + painter.drawLine(m_axisWidth - 1, 0, m_axisWidth - 1, widgetHeight); + + /* Draw the program numbers */ + painter.translate(0, m_axisHeight + m_rowHeight); + + for (int row = m_row; row < rowEnd; ++row) { + int y = (row - m_row) * m_rowHeight - (m_scrollY % m_rowHeight); - if (drawText) { - painter.drawText(left, 0, width, m_axisHeight, Qt::AlignHCenter | Qt::AlignVCenter, text); + painter.setPen(m_axisForeground); + painter.drawText(0, y, m_axisWidth, m_rowHeight, Qt::AlignHCenter | Qt::AlignVCenter, QString("%1").arg(m_rowPrograms[row])); + + painter.setPen(m_axisBorder); + painter.drawLine(0, y + m_rowHeight - 1, m_axisWidth - 1, y + m_rowHeight - 1); + + painter.setPen(m_axisLine); + painter.drawLine(m_axisWidth, y + m_rowHeight - 1, widgetWidth, y + m_rowHeight - 1); + } + + /* Draw the "CPU" axis label */ + painter.resetTransform(); + painter.translate(0, m_axisHeight); + + painter.setPen(m_axisBorder); + painter.setBrush(m_axisBackground); + painter.drawRect(-1, -1, m_axisWidth, m_rowHeight); + + painter.setPen(m_axisForeground); + painter.drawText(0, 0, m_axisWidth - 1, m_rowHeight - 1, Qt::AlignHCenter | Qt::AlignVCenter, "CPU"); + + painter.setPen(m_axisBorder); + painter.drawLine(m_axisWidth, m_rowHeight - 1, widgetWidth, m_rowHeight - 1); + + + /* Draw the frame numbers */ + painter.resetTransform(); + + painter.setPen(m_axisForeground); + painter.translate(m_axisWidth, 0); + + int lastLabel = -9999; + + double scroll = m_time; + scroll /= m_timeWidth; + scroll *= m_viewWidth; + + for (std::vector::const_iterator itr = m_profile->frames.begin(); itr != m_profile->frames.end(); ++itr) { + static const int padding = 4; + const Frame& frame = *itr; + bool draw = true; + int width; + + if (frame.cpuStart > timeEnd) { + break; } - if (width > 5) { - painter.drawLine(left, 0, left, m_axisHeight); - painter.drawLine(right, 0, right, m_axisHeight); + if (frame.cpuStart + frame.cpuDuration < m_time) { + draw = false; } - } + double left = frame.cpuStart; + left /= m_timeWidth; + left *= m_viewWidth; - /* - * Draw vertical axis - */ - painter.translate(0, -(m_scrollY % m_rowHeight)); + double right = frame.cpuStart + frame.cpuDuration; + right /= m_timeWidth; + right *= m_viewWidth; - for (int i = 0; i < m_programRowMap.size(); ++i) { - int y = (m_programRowMap[i] - m_row) * m_rowHeight; + QString text = QString("%1").arg(frame.no); - if (m_programRowMap[i] < 0 || y < -m_rowHeight || y > m_viewHeight) - continue; + width = painter.fontMetrics().width(text) + padding * 2; + + if (left + width > scroll) + draw = true; - y += m_axisHeight + 1; - painter.drawText(0, y, m_axisWidth, m_rowHeight, Qt::AlignHCenter | Qt::AlignVCenter, QString("%1").arg(i)); - painter.drawLine(0, y + m_rowHeight, m_axisWidth, y + m_rowHeight); + /* Draw a frame number if we have space since the last one */ + if (left - lastLabel > width) { + lastLabel = left + width; + + if (draw) { + int textX; + painter.setPen(m_axisForeground); + + if (left < scroll && right - left > width) { + if (right - scroll > width) { + textX = 0; + } else { + textX = right - scroll - width; + } + } else { + textX = left - scroll; + } + + /* Draw frame number and major ruler marking */ + painter.drawText(textX + padding, 0, width - padding, m_axisHeight - 5, Qt::AlignLeft | Qt::AlignVCenter, text); + painter.drawLine(left - scroll, m_axisHeight / 2, left - scroll, m_axisHeight - 1); + } + } else if (draw) { + /* Draw a minor ruler marking */ + painter.drawLine(left - scroll, m_axisHeight - (m_axisHeight / 4), left - scroll, m_axisHeight - 1); + } } - /* Draw the top left square again to cover up any hanging over text */ + /* Draw "Frame" axis label */ painter.resetTransform(); - painter.setPen(Qt::NoPen); + + painter.setPen(m_axisBorder); painter.setBrush(m_axisBackground); - painter.drawRect(0, 0, m_axisWidth, m_axisHeight); + painter.drawRect(-1, -1, m_axisWidth, m_axisHeight); + painter.setPen(m_axisForeground); + painter.drawText(0, 0, m_axisWidth - 1, m_axisHeight - 1, Qt::AlignHCenter | Qt::AlignVCenter, "Frame"); - /* - * Draw the active selection border - */ + /* Draw the active selection border */ if (m_timeSelectionStart != m_timeSelectionEnd) { + int selectionLeft = timeToPosition(m_timeSelectionStart) + m_axisWidth; + int selectionRight = (timeToPosition(m_timeSelectionEnd) + 0.5) + m_axisWidth; + painter.setPen(m_selectionBorder); - painter.drawLine(selectionLeft, 0, selectionLeft, m_viewHeight + m_axisHeight); - painter.drawLine(selectionRight, 0, selectionRight, m_viewHeight + m_axisHeight); - painter.drawLine(selectionLeft, m_axisHeight, selectionRight, m_axisHeight); - } + if (selectionLeft >= m_axisWidth && selectionLeft < widgetWidth) { + painter.drawLine(selectionLeft, 0, selectionLeft, widgetHeight); + } + + if (selectionRight >= m_axisWidth && selectionRight < widgetWidth) { + painter.drawLine(selectionRight, 0, selectionRight, widgetHeight); + } + + selectionLeft = qBound(m_axisWidth, selectionLeft, widgetWidth); + selectionRight = qBound(m_axisWidth, selectionRight, widgetWidth); - /* - * Draw the ruler zoom - */ + painter.drawLine(selectionLeft, m_axisHeight - 1, selectionRight, m_axisHeight - 1); + painter.fillRect(selectionLeft, 0, selectionRight - selectionLeft, widgetHeight, m_selectionBackground); + } + + /* Draw the ruler zoom */ if (m_mousePressMode == RulerZoom) { int x1 = m_mousePressPosition.x(); - int x2 = m_mousePosition.x(); - int y1 = m_axisHeight; - int y2 = height(); + int x2 = qMax(m_mousePosition.x(), m_axisWidth); painter.setPen(m_zoomBorder); - painter.drawLine(x1, 0, x1, y2); - painter.drawLine(x2, 0, x2, y2); - painter.drawLine(x1, y1, x2, y1); - - painter.setPen(Qt::NoPen); - painter.setBrush(m_zoomBackground); - painter.drawRect(x1, y1, x2 - x1, y2); + painter.drawLine(x1, 0, x1, widgetHeight); + painter.drawLine(x2, 0, x2, widgetHeight); + painter.drawLine(x1, m_axisHeight - 1, x2, m_axisHeight - 1); + painter.fillRect(x1, m_axisHeight, x2 - x1, widgetHeight, m_zoomBackground); } } diff --git a/gui/timelinewidget.h b/gui/timelinewidget.h index be8f92a..472ffa1 100644 --- a/gui/timelinewidget.h +++ b/gui/timelinewidget.h @@ -6,12 +6,6 @@ #include #include "trace_profiler.hpp" -struct VisibleItem { - QRect rect; - const trace::Profile::Frame* frame; - const trace::Profile::Call* call; -}; - class TimelineWidget : public QWidget { Q_OBJECT @@ -58,20 +52,21 @@ private: void setRowScroll(int position, bool notify = true); void setTimeScroll(int64_t time, bool notify = true); - void paintHeatmapColumn(int x, QPainter& painter, QVector& rows); + void drawHeat(QPainter& painter, int x, int64_t heat, bool isCpu); double timeToPosition(int64_t time); int64_t positionToTime(int pos); - const VisibleItem* itemAtPosition(const QPoint& pos); - void calculateRows(); + const trace::Profile::Frame* frameAtTime(int64_t time); + const trace::Profile::CpuCall* cpuCallAtTime(int64_t time); + const trace::Profile::DrawCall* drawCallAtTime(int program, int64_t time); + private: /* Data */ trace::Profile* m_profile; - QList m_programRowMap; - QList m_visibleItems; + std::vector m_rowPrograms; /* Scrollbars */ int m_scrollX; @@ -108,7 +103,9 @@ private: int m_rowHeight; int m_axisWidth; int m_axisHeight; + QPen m_axisLine; QPen m_axisBorder; + QPen m_axisForeground; QBrush m_axisBackground; QPen m_itemBorder; QPen m_itemForeground; diff --git a/retrace/glretrace.hpp b/retrace/glretrace.hpp index 568049e..11f4d27 100644 --- a/retrace/glretrace.hpp +++ b/retrace/glretrace.hpp @@ -82,7 +82,6 @@ extern const retrace::Entry glx_callbacks[]; extern const retrace::Entry wgl_callbacks[]; extern const retrace::Entry egl_callbacks[]; -void frame_start(); void frame_complete(trace::Call &call); void initContext(); diff --git a/retrace/glretrace_main.cpp b/retrace/glretrace_main.cpp index c01b67d..44b278f 100755 --- a/retrace/glretrace_main.cpp +++ b/retrace/glretrace_main.cpp @@ -47,6 +47,7 @@ struct CallQuery { GLuint ids[3]; unsigned call; + bool isDraw; GLuint program; const trace::FunctionSig *sig; int64_t cpuStart; @@ -58,7 +59,6 @@ static bool supportsTimestamp = true; static bool supportsOcclusion = true; static bool supportsDebugOutput = true; -static bool firstFrame = true; static std::list callQueries; static void APIENTRY @@ -109,55 +109,58 @@ checkGlError(trace::Call &call) { os << "\n"; } -static inline GLint64 -getGpuTimestamp() { - GLuint query = 0; - GLint64 timestamp = 0; +static void +getCurrentTimes(int64_t& cpuTime, int64_t& gpuTime) { + GLuint query; if (retrace::profilingGpuTimes && supportsTimestamp) { glGenQueries(1, &query); glQueryCounter(query, GL_TIMESTAMP); - glGetQueryObjecti64vEXT(query, GL_QUERY_RESULT, ×tamp); - glDeleteQueries(1, &query); + glGetQueryObjecti64vEXT(query, GL_QUERY_RESULT, &gpuTime); + } else { + gpuTime = 0; } - return timestamp; -} - -static inline GLint64 -getCpuTimestamp() { if (retrace::profilingCpuTimes) { - return os::getTime(); + cpuTime = os::getTime(); } else { - return 0; + cpuTime = 0; + } + + if (retrace::profilingGpuTimes && supportsTimestamp) { + glDeleteQueries(1, &query); } } static void completeCallQuery(CallQuery& query) { /* Get call start and duration */ - GLint64 gpuStart = 0, gpuDuration = 0, cpuDuration = 0, samples = 0; + int64_t gpuStart = 0, gpuDuration = 0, cpuDuration = 0, pixels = 0; - if (retrace::profilingGpuTimes) { - if (supportsTimestamp) { - glGetQueryObjecti64vEXT(query.ids[0], GL_QUERY_RESULT, &gpuStart); + if (query.isDraw) { + if (retrace::profilingGpuTimes) { + if (supportsTimestamp) { + glGetQueryObjecti64vEXT(query.ids[0], GL_QUERY_RESULT, &gpuStart); + } + + glGetQueryObjecti64vEXT(query.ids[1], GL_QUERY_RESULT, &gpuDuration); + } + + if (retrace::profilingPixelsDrawn) { + glGetQueryObjecti64vEXT(query.ids[2], GL_QUERY_RESULT, &pixels); } - glGetQueryObjecti64vEXT(query.ids[1], GL_QUERY_RESULT, &gpuDuration); + glDeleteQueries(3, query.ids); + } else { + pixels = -1; } if (retrace::profilingCpuTimes) { cpuDuration = query.cpuEnd - query.cpuStart; } - if (retrace::profilingPixelsDrawn) { - glGetQueryObjecti64vEXT(query.ids[2], GL_QUERY_RESULT, &samples); - } - - glDeleteQueries(3, query.ids); - /* Add call to profile */ - retrace::profiler.addCall(query.call, query.sig->name, query.program, samples, gpuStart, gpuDuration, query.cpuStart, cpuDuration); + retrace::profiler.addCall(query.call, query.sig->name, query.program, pixels, gpuStart, gpuDuration, query.cpuStart, cpuDuration); } void @@ -171,16 +174,14 @@ flushQueries() { void beginProfile(trace::Call &call, bool isDraw) { - if (firstFrame) { - frame_start(); - } - /* Create call query */ CallQuery query; + query.isDraw = isDraw; query.call = call.no; query.sig = call.sig; query.program = glretrace::currentContext ? glretrace::currentContext->activeProgram : 0; + /* GPU profiling only for draw calls */ if (isDraw) { glGenQueries(3, query.ids); @@ -197,25 +198,25 @@ beginProfile(trace::Call &call, bool isDraw) { } } + callQueries.push_back(query); + + /* CPU profiling for all calls */ if (retrace::profilingCpuTimes) { - query.cpuStart = getCpuTimestamp(); + callQueries.back().cpuStart = os::getTime(); } - - callQueries.push_back(query); } void endProfile(trace::Call &call, bool isDraw) { + GLint64 time = os::getTime(); + + /* CPU profiling for all calls */ if (retrace::profilingCpuTimes) { CallQuery& query = callQueries.back(); - query.cpuEnd = getCpuTimestamp(); - - if (!isDraw) { - retrace::profiler.addCall(query.call, query.sig->name, query.program, -1, 0, 0, query.cpuStart, query.cpuEnd - query.cpuStart); - callQueries.pop_back(); - } + query.cpuEnd = time; } + /* GPU profiling only for draw calls */ if (isDraw) { if (retrace::profilingGpuTimes) { glEndQuery(GL_TIME_ELAPSED); @@ -229,10 +230,7 @@ endProfile(trace::Call &call, bool isDraw) { void initContext() { - GLint64 gpuTime = 0, cpuTime = 0; - const char* extensions; - - extensions = (const char*)glGetString(GL_EXTENSIONS); + const char* extensions = (const char*)glGetString(GL_EXTENSIONS); /* Ensure we have adequate extension support */ supportsTimestamp = glws::checkExtension("GL_ARB_timer_query", extensions); @@ -240,6 +238,7 @@ initContext() { supportsOcclusion = glws::checkExtension("GL_ARB_occlusion_query", extensions); supportsDebugOutput = glws::checkExtension("GL_ARB_debug_output", extensions); + /* Check for timer query support */ if (retrace::profilingGpuTimes) { if (!supportsTimestamp && !supportsElapsed) { std::cout << "Error: Cannot run profile, GL_EXT_timer_query extension is not supported." << std::endl; @@ -255,11 +254,13 @@ initContext() { } } + /* Check for occlusion query support */ if (retrace::profilingPixelsDrawn && !supportsOcclusion) { std::cout << "Error: Cannot run profile, GL_ARB_occlusion_query extension is not supported." << std::endl; exit(-1); } + /* Setup debug message call back */ if (retrace::debug && supportsDebugOutput) { glDebugMessageCallbackARB(&debugOutputCallback, currentContext); @@ -269,27 +270,14 @@ initContext() { } /* Sync the gpu and cpu start times */ - if (!retrace::profiler.hasBaseTimes()) { - if (retrace::profilingGpuTimes) { - gpuTime = getGpuTimestamp(); - } + if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { + if (!retrace::profiler.hasBaseTimes()) { + GLint64 gpuTime, cpuTime; - if (retrace::profilingCpuTimes) { - cpuTime = getCpuTimestamp(); + getCurrentTimes(cpuTime, gpuTime); + retrace::profiler.setBaseCpuTime(cpuTime); + retrace::profiler.setBaseGpuTime(gpuTime); } - - retrace::profiler.setBaseTimes(gpuTime, cpuTime); - } -} - -void -frame_start() { - firstFrame = false; - - if (retrace::profiling) { - int64_t gpuStart = getGpuTimestamp(); - int64_t cpuStart = getCpuTimestamp(); - retrace::profiler.addFrameStart(retrace::frameNo, gpuStart, cpuStart); } } @@ -299,17 +287,29 @@ frame_complete(trace::Call &call) { /* Complete any remaining queries */ flushQueries(); + /* GPU time drifts due to being relative times, not absolute and can be + * affected by the gpu switch between processes. + * + * To attempt to compensate we resynchronise on frame end however there is + * still noticeable drift within a single frame which we do not account for. + */ + if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { + int64_t cpuTime, gpuTime, error; + + getCurrentTimes(cpuTime, gpuTime); + cpuTime = cpuTime - retrace::profiler.getBaseCpuTime(); + gpuTime = gpuTime - retrace::profiler.getBaseGpuTime(); + error = gpuTime - cpuTime; + + retrace::profiler.setBaseGpuTime(retrace::profiler.getBaseGpuTime() + error); + } + /* Indicate end of current frame */ - int64_t gpuEnd = getGpuTimestamp(); - int64_t cpuEnd = getCpuTimestamp(); - retrace::profiler.addFrameEnd(gpuEnd, cpuEnd); + retrace::profiler.addFrameEnd(); } retrace::frameComplete(call); - /* Indicate start of next frame */ - frame_start(); - if (!currentDrawable) { return; } diff --git a/scripts/profileshader.py b/scripts/profileshader.py index bcb661c..d31130e 100755 --- a/scripts/profileshader.py +++ b/scripts/profileshader.py @@ -31,8 +31,6 @@ import sys def process(stream): times = {} - # frame_begin no gpu_start cpu_start - # frame_end no gpu_end gpu_dura cpu_end cpu_dura # call no gpu_start gpu_dura cpu_start cpu_dura pixels program name for line in stream: