From f3cf30089b92aaa7345a81707064497b67572539 Mon Sep 17 00:00:00 2001 From: rdb Date: Fri, 2 Dec 2022 20:47:25 +0100 Subject: [PATCH] pstats: Improvements and fixees to Timeline view: - Properly display and stack bars overlapping frame boundaries - Ignore "App:Show code:General" collector (already disabled on master, but to support 1.10 clients) - it's an "inverted" collector that doesn't nest properly so it messes up the stacking - Better handling / display of dropped frames - Better handling of clock skew due to `PStatClient::resume_after_pause()` (but please don't use it, because it's not possible to fully handle it properly) - Vertical scrolling (Windows only) --- pandatool/src/pstatserver/pStatTimeline.I | 12 + pandatool/src/pstatserver/pStatTimeline.cxx | 239 +++++++++++++++---- pandatool/src/pstatserver/pStatTimeline.h | 4 + pandatool/src/win-stats/winStatsTimeline.cxx | 23 +- pandatool/src/win-stats/winStatsTimeline.h | 5 +- 5 files changed, 230 insertions(+), 53 deletions(-) diff --git a/pandatool/src/pstatserver/pStatTimeline.I b/pandatool/src/pstatserver/pStatTimeline.I index 610078b566..e3daa44a18 100644 --- a/pandatool/src/pstatserver/pStatTimeline.I +++ b/pandatool/src/pstatserver/pStatTimeline.I @@ -137,3 +137,15 @@ INLINE double PStatTimeline:: pixel_to_height(int x) const { return _time_scale * (double)x; } + +/** + * Returns the total number of rows. + */ +INLINE int PStatTimeline:: +get_num_rows() const { + if (_threads.empty()) { + return 0; + } else { + return _threads.back()._row_offset + _threads.back()._rows.size(); + } +} diff --git a/pandatool/src/pstatserver/pStatTimeline.cxx b/pandatool/src/pstatserver/pStatTimeline.cxx index a5e3733158..dd49584ff0 100644 --- a/pandatool/src/pstatserver/pStatTimeline.cxx +++ b/pandatool/src/pstatserver/pStatTimeline.cxx @@ -39,6 +39,9 @@ PStatTimeline(PStatMonitor *monitor, int xsize, int ysize) : if (client_data != nullptr) { size_t row_offset = 0; + // Ignore this nasty "inverted" collector, which messes up everything. + _app_collector_index = client_data->find_collector("App:Show code:General"); + for (int thread_index = 0; thread_index < client_data->get_num_threads(); ++thread_index) { _threads.emplace_back(); ThreadRow &thread_row = _threads.back(); @@ -62,10 +65,12 @@ PStatTimeline(PStatMonitor *monitor, int xsize, int ysize) : else { _lowest_start_time = std::min(_lowest_start_time, oldest_start_time); } - _highest_end_time = std::max(_highest_end_time, latest_end_time); + _highest_end_time = std::max(_highest_end_time, latest_end_time + _clock_skew); for (int frame = oldest_frame; frame <= latest_frame; ++frame) { - update_bars(thread_index, frame); + if (thread_data->has_frame(frame)) { + update_bars(thread_index, frame); + } } } } @@ -102,10 +107,14 @@ new_data(int thread_index, int frame_number) { const PStatThreadData *thread_data = client_data->get_thread_data(thread_index); - if (thread_data != nullptr && !thread_data->is_empty()) { + if (thread_data != nullptr && thread_data->has_frame(frame_number)) { const PStatFrameData &frame_data = thread_data->get_frame(frame_number); - double frame_start = frame_data.get_start(); - double frame_end = frame_data.get_end(); + double frame_start = frame_data.get_start() + _clock_skew; + double frame_end = frame_data.get_end() + _clock_skew; + + if (thread_index == 0 && _app_collector_index == -1) { + _app_collector_index = client_data->find_collector("App:Show code:General"); + } if (!_have_start_time) { _start_time = frame_start; @@ -173,70 +182,185 @@ update_bars(int thread_index, int frame_number) { // pair pvector > stack; - size_t num_events = frame_data.get_num_events(); - for (size_t i = 0; i < num_events; ++i) { - int collector_index = frame_data.get_time_collector(i); - double time = frame_data.get_time(i); + double frame_start = frame_data.get_start() + _clock_skew; + double prev = frame_start; - if (frame_data.is_start(i)) { - stack.push_back(std::make_pair(collector_index, std::max(time, _start_time))); - if (stack.size() > thread_row._rows.size()) { - thread_row._rows.resize(stack.size()); - changed_num_rows = true; - } - } - else if (!stack.empty()) { - if (stack.back().first == collector_index) { - // Most likely case, ending the most recent collector that is still - // open. - double start_time = stack.back().second; - stack.pop_back(); - thread_row._rows[stack.size()].push_back({ - start_time, time, collector_index, thread_index, frame_number}); + // There may still be open collectors from the previous frame. Rebuild the + // stack based on that so we can close them properly. + for (size_t i = 0; i < thread_row._rows.size(); ++i) { + Row &row = thread_row._rows[i]; - while (!stack.empty() && stack.back().first < 0) { - stack.pop_back(); - } - } - else { - // Unlikely case: ending a collector before a "child" has ended. - // Go back and clear the row where this collector started. - // Don't decrement the row index. - for (size_t i = 0; i < stack.size(); ++i) { - auto &item = stack[stack.size() - 1 - i]; - - if (item.first == collector_index) { - thread_row._rows[stack.size() - 1 - i].push_back({ - item.second, time, collector_index, thread_index, frame_number}); - item.first = -1; - break; + // Keep iterating from the back until we get to the previous frame. + for (size_t j = 0; j < row.size(); ++j) { + ColorBar &bar = row[row.size() - j - 1]; + if (bar._frame_number < frame_number) { + // Was this collector left unstopped at the end of the last frame? + if (bar._open_end && bar._frame_number == frame_number - 1) { + if (i >= stack.size()) { + stack.resize(i + 1, std::make_pair(-1, 0.0)); } + stack[i] = std::make_pair(bar._collector_index, bar._start); + + // Remove this bar for now, we'll recreate it when we close it. + row.erase(row.begin() + (row.size() - j - 1)); } + break; } } - else { - // Somehow, we got an end event for a collector we didn't start. - // This shouldn't really happen, so we just ignore it. - } } - // Add all unclosed bars. + size_t num_events = frame_data.get_num_events(); + for (size_t i = 0; i < num_events; ++i) { + int collector_index = frame_data.get_time_collector(i); + double time = frame_data.get_time(i) + _clock_skew; + + if (time < prev) { + // Apparently, it is too hard to ask for monotonically increasing time + // values! Don't be tempted to sort the values, or think this is a bug, + // the client can arbitrarily move back the clock if it feels like it! + // I had some fancy mechanism that handled clock skew properly for + // multiple out-of-order frames, but I gave up when I realised it's not + // possible to solve this problem for multiple threads, so we just assume + // this is done just once at startup before the other threads exist. + double delta = prev - time; + _clock_skew += delta; + _highest_end_time += delta; + time = prev; + nout << "Correcting for clock skew of " + << format_number(delta, GBU_show_units | GBU_ms) + << " in frame " << frame_number << " of thread " + << thread_index << "\n"; + } + prev = time; + + if (collector_index == _app_collector_index) { + continue; + } + + if (frame_data.is_start(i)) { + if (collector_index == 0 && !stack.empty()) { + // Collector 0 always goes at the top, no matter what. + stack[0].first = 0; + stack[0].second = std::max(time, _start_time); + } else { + stack.push_back(std::make_pair(collector_index, std::max(time, _start_time))); + if (stack.size() > thread_row._rows.size()) { + thread_row._rows.resize(stack.size()); + changed_num_rows = true; + } + } + } + else if (!stack.empty() && stack.back().first == collector_index) { + // Most likely case, ending the most recent collector that is still open. + double start_time = stack.back().second; + stack.pop_back(); + thread_row._rows[stack.size()].push_back({ + start_time, time, collector_index, thread_index, frame_number, false, false}); + + // Pop off stack levels for prematurely ended collectors (see below). + while (!stack.empty() && stack.back().first < 0) { + stack.pop_back(); + } + } + else { + // Unlikely case: ending a collector before a "child" has ended. + // Go back and clear the row where this collector started. + // Don't decrement the row index. + size_t i; + for (i = 0; i < stack.size(); ++i) { + auto &item = stack[stack.size() - 1 - i]; + + if (item.first == collector_index) { + thread_row._rows[stack.size() - 1 - i].push_back({ + item.second, time, collector_index, thread_index, frame_number, false, false}); + item.first = -1; + break; + } + } + if (i == stack.size()) { + // We stopped a collector that wasn't started at all. That means it + // must have already been running when this frame started, which we + // normally handle by pre-populating the stack with the open collectors + // from last frame, but maybe we didn't get the last frame (yet). + // Unfortunately we need to add it above any bars we've already started + // and stopped, which means we need to shift everything down belonging + // to this frame, except for the top-level Frame collector. This is + // probably pretty inefficient, but it should be pretty rare for frames + // to arrive out-of-order in this manner. + nassertd(!stack.empty()) continue; + stack.insert(stack.begin() + 1, std::make_pair(-1, 0.0)); + + const size_t num_rows = thread_row._rows.size(); + for (size_t j = num_rows - 1; j >= 1; --j) { + size_t row_size = thread_row._rows[j].size(); + for (size_t k = row_size; k > 0; --k) { + Row &row = thread_row._rows[j]; + ColorBar bar = row[k - 1]; + if (bar._frame_number == frame_number) { + row.erase(row.begin() + (k - 1)); + if (j + 1 >= thread_row._rows.size()) { + thread_row._rows.resize(j + 2); + changed_num_rows = true; + } + + // Insert it into the row below while retaining sorting. + Row &row2 = thread_row._rows[j + 1]; + row2.insert(std::upper_bound(row2.begin(), row2.end(), bar), bar); + } + else if (bar._frame_number < frame_number) { + break; + } + } + } + + // Now insert the bar, just below Frame level. + if (thread_row._rows.size() < 2) { + thread_row._rows.resize(2); + changed_num_rows = true; + } + thread_row._rows[1].push_back({ + frame_start, time, collector_index, thread_index, + frame_number, true, false}); + } + } + } + + // Add all unclosed bars, marking them as open-ended, for later gluing. while (!stack.empty()) { int collector_index = stack.back().first; if (collector_index >= 0) { double start_time = stack.back().second; thread_row._rows[stack.size() - 1].push_back({ - start_time, frame_data.get_end(), - collector_index, thread_index, frame_number, + start_time, frame_data.get_end() + _clock_skew, + collector_index, thread_index, frame_number, false, true, }); } stack.pop_back(); } if (thread_row._last_frame >= 0 && frame_number < thread_row._last_frame) { - // Added a frame out of order. Resort the rows. + // Added a frame out of order. for (Row &row : thread_row._rows) { + // Sort by end time. std::sort(row.begin(), row.end()); + + // Glue together open ends and beginnings that match up. + size_t end = row.size() - 1; + for (size_t i = 0; i < end;) { + ColorBar &left = row[i]; + ColorBar &right = row[i + 1]; + if (left._collector_index == right._collector_index && + left._frame_number + 1 == right._frame_number && + left._open_end && right._open_begin) { + // Erase the left one, to maintain the sorting by end time. + right._open_begin = false; + right._start = left._start; + row.erase(row.begin() + i); + --end; + } else { + ++i; + } + } } } else { thread_row._last_frame = frame_number; @@ -413,6 +537,8 @@ normal_guide_bars() { while (it != row.end() && it->_start <= end_time) { double frame_start = it->_start; + double frame_end = it->_end; + int frame_number = it->_frame_number; if (frame_start > start_time) { if (!_guide_bars.empty() && height_to_pixel(frame_start - _guide_bars.back()._height) < 30) { @@ -420,7 +546,7 @@ normal_guide_bars() { _guide_bars.back()._label.clear(); } std::string label = "#"; - label += format_string(it->_frame_number); + label += format_string(frame_number); _guide_bars.push_back(GuideBar(frame_start, label, GBS_frame)); if (++num_frames > max_frames) { @@ -439,7 +565,7 @@ normal_guide_bars() { if (it != row.end()) { // Only go up to the start of the next frame, limiting to however much // fits in the graph. - frame_width = std::min(it->_start - frame_start, end_time - frame_start); + frame_width = std::min(frame_end - frame_start, end_time - frame_start); } else { // Reached the end; just continue to the end of the graph. frame_width = end_time - frame_start; @@ -456,6 +582,19 @@ normal_guide_bars() { _guide_bars.push_back(GuideBar(frame_start + offset, label, GBS_normal)); } } + + // If there's a gap between frames, add another line. + if (it->_start > frame_end && it->_frame_number > frame_number + 1) { + std::string label; + if (it->_start - frame_end >= interval) { + label = "#" + format_string(frame_number + 1); + if (it->_frame_number > frame_number + 2) { + label += "-" + format_string(it->_frame_number - 1); + } + label += " (dropped)"; + } + _guide_bars.push_back(GuideBar(frame_end, label, GBS_frame)); + } } } diff --git a/pandatool/src/pstatserver/pStatTimeline.h b/pandatool/src/pstatserver/pStatTimeline.h index 3cb23af559..18c9e916d1 100644 --- a/pandatool/src/pstatserver/pStatTimeline.h +++ b/pandatool/src/pstatserver/pStatTimeline.h @@ -53,6 +53,7 @@ public: INLINE double pixel_to_timestamp(int x) const; INLINE int height_to_pixel(double value) const; INLINE double pixel_to_height(int y) const; + INLINE int get_num_rows() const; std::string get_bar_tooltip(int row, int x) const; @@ -84,6 +85,7 @@ protected: int _collector_index; int _thread_index; int _frame_number; + bool _open_begin : 8, _open_end : 8; bool operator < (const ColorBar &other) const { return _end < other._end; @@ -104,6 +106,8 @@ protected: typedef pvector ThreadRows; ThreadRows _threads; bool _threads_changed = true; + double _clock_skew = 0.0; + int _app_collector_index = -1; enum KeyFlag { F_left = 1, diff --git a/pandatool/src/win-stats/winStatsTimeline.cxx b/pandatool/src/win-stats/winStatsTimeline.cxx index 246d6d0f9f..d38e2ceb8e 100644 --- a/pandatool/src/win-stats/winStatsTimeline.cxx +++ b/pandatool/src/win-stats/winStatsTimeline.cxx @@ -490,6 +490,22 @@ graph_window_proc(HWND hwnd, UINT msg, WPARAM wparam, LPARAM lparam) { zoom_by(delta / 120.0, pixel_to_timestamp(point.x)); start_animation(); } + } else { + int delta = GET_WHEEL_DELTA_WPARAM(wparam); + delta = (delta * _pixel_scale * 5) / 120; + int new_scroll = _scroll - delta; + if (_threads.empty()) { + new_scroll = 0; + } else { + new_scroll = (std::min)(new_scroll, get_num_rows() * _pixel_scale * 5 + _pixel_scale * 2 - get_ysize()); + new_scroll = (std::max)(new_scroll, 0); + } + delta = new_scroll - _scroll; + if (delta != 0) { + _scroll = new_scroll; + _threads_changed = true; + PStatTimeline::force_redraw(); + } } return 0; } @@ -650,6 +666,7 @@ draw_guide_label(HDC hdc, int y, const PStatGraph::GuideBar &bar) { return; } + bool center = true; switch (bar._style) { case GBS_target: SetTextColor(hdc, _light_color); @@ -665,6 +682,7 @@ draw_guide_label(HDC hdc, int y, const PStatGraph::GuideBar &bar) { case GBS_frame: SetTextColor(hdc, _dark_color); + center = false; break; } @@ -672,7 +690,10 @@ draw_guide_label(HDC hdc, int y, const PStatGraph::GuideBar &bar) { SIZE size; GetTextExtentPoint32(hdc, label.data(), label.length(), &size); - int this_x = _graph_left + x - size.cx / 2; + int this_x = _graph_left + x; + if (center) { + this_x -= size.cx / 2; + } if (x >= 0 && x < get_xsize()) { TextOut(hdc, this_x, y, label.data(), label.length()); diff --git a/pandatool/src/win-stats/winStatsTimeline.h b/pandatool/src/win-stats/winStatsTimeline.h index 3152a7118b..8c66b2b106 100644 --- a/pandatool/src/win-stats/winStatsTimeline.h +++ b/pandatool/src/win-stats/winStatsTimeline.h @@ -75,10 +75,10 @@ private: static LONG WINAPI static_window_proc(HWND hwnd, UINT msg, WPARAM wparam, LPARAM lparam); int row_to_pixel(int y) const { - return y * _pixel_scale * 5 + _pixel_scale; + return y * _pixel_scale * 5 + _pixel_scale - _scroll; } int pixel_to_row(int y) const { - return (y - _pixel_scale) / (_pixel_scale * 5); + return (y + _scroll - _pixel_scale) / (_pixel_scale * 5); } static bool _window_class_registered; @@ -88,6 +88,7 @@ private: int _highlighted_row = -1; int _highlighted_x = 0; + int _scroll = 0; ColorBar _popup_bar; };