// // #include "FrameProfiler.h" #include "cmdline/cmdline.h" #include "globalincs/systemvars.h" using namespace tracing; namespace { bool event_sorter(const trace_event& left, const trace_event& right) { return left.event_id < right.event_id; } void process_begin(SCP_vector& samples, const trace_event& evt) { // Read the name through the id, not evt.category: the Category it names may already be dead // (see trace_event::category_id). const SCP_string category_name = Category::getNameById(evt.category_id); int parent = -1; for (int i = 0; i < (int) samples.size(); i++) { if (!samples[i].open_profiles) { continue; } samples[i].num_children++; if (samples[i].num_children == 1) { // this is our direct parent for this new sample parent = i; } } for (int i = 0; i < (int) samples.size(); i++) { if (samples[i].name == category_name && samples[i].parent == parent) { // found the profile sample samples[i].open_profiles++; samples[i].profile_instances++; samples[i].start_time = evt.timestamp; Assert(samples[i].open_profiles == 1); // max 1 open at once return; } } // create a new profile sample profile_sample new_sample; new_sample.name = category_name; new_sample.open_profiles = 1; new_sample.profile_instances = 1; new_sample.accumulator = 0; new_sample.start_time = evt.timestamp; new_sample.children_sample_time = 0; new_sample.num_children = 0; new_sample.parent = parent; new_sample.num_parents = (parent >= 0) ? 1 : 0; samples.push_back(std::move(new_sample)); } void process_end(SCP_vector& samples, const trace_event& evt) { // Read the name through the id, not evt.category: the Category it names may already be dead // (see trace_event::category_id). const SCP_string category_name = Category::getNameById(evt.category_id); uint num_parents = 0; int child_of = -1; for (int i = 0; i < (int) samples.size(); i++) { if (samples[i].open_profiles) { if (samples[i].num_children == 1) { child_of = i; } } } for (int i = 0; i < (int) samples.size(); i++) { if (samples[i].name == category_name && samples[i].parent == child_of) { int inner = 0; int parent = -1; uint64_t end_time = evt.timestamp; samples[i].open_profiles--; // count all parents and find the immediate parent while (inner < (int) samples.size()) { if (samples[inner].open_profiles > 0) { // found a parent (any open profiles are parents) num_parents++; if (parent < 0) { // replace invalid parent (index) parent = inner; } else if (samples[inner].start_time >= samples[parent].start_time) { // replace with more immediate parent parent = inner; } } inner++; } // remember the current number of parents of the sample samples[i].num_parents = num_parents; if (parent >= 0) { // record this time in children_sample_time (add it in) samples[parent].children_sample_time += end_time - samples[i].start_time; } // save sample time in accumulator samples[i].accumulator += end_time - samples[i].start_time; break; } } for (int i = 0; i < (int) samples.size(); i++) { if (samples[i].open_profiles) { samples[i].num_children--; samples[i].num_children = MAX(samples[i].num_children, 0u); } } } } namespace tracing { uint64_t accumulate_self_times(const SCP_vector& events, SCP_vector& self_time_by_id) { self_time_by_id.assign(Category::getCount(), 0); if (events.empty()) { return 0; } uint64_t total = 0; SCP_vector open_stack; // category ids of currently-open scopes open_stack.reserve(32); uint64_t last_ts = events.front().timestamp; for (const auto& evt : events) { if (!open_stack.empty()) { const uint64_t delta = evt.timestamp - last_ts; self_time_by_id[static_cast(open_stack.back())] += delta; total += delta; } last_ts = evt.timestamp; if (evt.category_id < 0 || evt.category_id >= static_cast(self_time_by_id.size())) { // Can't happen today (processEvent filters out null-category events, and every // recorded id is in range at record time), but the category this id names may have // been destroyed since (see trace_event::category_id) -- never trust it blindly, and // keep last_ts advanced above so a stray event could never cause the next delta to // span it. continue; } if (evt.type == EventType::Begin) { open_stack.push_back(evt.category_id); } else if (evt.type == EventType::End) { if (!open_stack.empty()) { open_stack.pop_back(); } } } return total; } FrameProfiler::FrameProfiler(std::int64_t mainThreadID) : _mainThreadID(mainThreadID) { } FrameProfiler::~FrameProfiler() { } void FrameProfiler::processEvent(const trace_event* event) { if (event->type != EventType::Complete) { // Only process complete events return; } if (event->pid == GPU_PID) { // Ignore GPU events since we can't display them properly return; } if (event->tid != _mainThreadID) { // Multithreaded events don't have a deterministic sequence and that confuses the old profiling system return; } if (event->duration == 0) { // Discard events with no duration return; } if (event->category == &MainFrame) { // The main frame category doesn't work right since the output is generated while we are still in that category return; } trace_event begin = *event; begin.type = EventType::Begin; begin.event_id = event->event_id; begin.duration = event->duration; trace_event end = *event; end.type = EventType::End; end.event_id = event->end_event_id; end.timestamp = event->timestamp + event->duration; end.duration = event->duration; std::lock_guard vectorGuard(_eventsMutex); _bufferedEvents.push_back(begin); _bufferedEvents.push_back(end); } void FrameProfiler::get_profile_from_history(SCP_string& name, uint64_t* avg_micro_sec, uint64_t* min_micro_sec, uint64_t* max_micro_sec) { for (int i = 0; i < (int) history.size(); i++) { if (history[i].name == name) { *avg_micro_sec = history[i].avg_micro_sec; *min_micro_sec = history[i].min_micro_sec; *max_micro_sec = history[i].max_micro_sec; return; } } } void FrameProfiler::store_profile_in_history(SCP_string& name, uint64_t time) { float old_ratio; float new_ratio = 0.8f * f2fl(Frametime); if (new_ratio > 1.0f) { new_ratio = 1.0f; } old_ratio = 1.0f - new_ratio; for (int i = 0; i < (int) history.size(); i++) { if (history[i].valid && history[i].name == name) { // found the sample history[i].avg_micro_sec = (uint64_t)((history[i].avg_micro_sec * old_ratio) + (time * new_ratio)); if (time < history[i].min_micro_sec) { history[i].min_micro_sec = time; } else { history[i].min_micro_sec = (uint64_t)((history[i].min_micro_sec * old_ratio) + (time * new_ratio)); } if (time > history[i].max_micro_sec) { history[i].max_micro_sec = time; } else { history[i].max_micro_sec = (uint64_t)((history[i].max_micro_sec * old_ratio) + (time * new_ratio)); } return; } } // add to history profile_sample_history new_history; new_history.name = name; new_history.valid = true; new_history.avg_micro_sec = new_history.min_micro_sec = new_history.max_micro_sec = time; history.push_back(std::move(new_history)); } void FrameProfiler::dump_output(SCP_stringstream& out, uint64_t /*start_profile_time*/, uint64_t /*end_profile_time*/, SCP_vector& samples) { out << " Avg : Min : Max : # : Profile Name\n"; out << "----------------------------------------\n"; for (int i = 0; i < (int) samples.size(); i++) { uint64_t sample_time; uint64_t avg_micro_seconds, min_micro_seconds, max_micro_seconds; Assert(samples[i].open_profiles == 0); sample_time = samples[i].accumulator - samples[i].children_sample_time; avg_micro_seconds = min_micro_seconds = max_micro_seconds = sample_time; // add new measurement into the history and get avg, min, and max store_profile_in_history(samples[i].name, sample_time); get_profile_from_history(samples[i].name, &avg_micro_seconds, &min_micro_seconds, &max_micro_seconds); // format the data char avg[64], min[64], max[64], num[64]; sprintf(avg, "%3.1fms", i2fl(avg_micro_seconds) * 0.000001f); sprintf(min, "%3.1fms", i2fl(min_micro_seconds) * 0.000001f); sprintf(max, "%3.1fms", i2fl(max_micro_seconds) * 0.000001f); sprintf(num, "%3d", samples[i].profile_instances); SCP_string indented_name; for (uint indent = 0; indent < samples[i].num_parents; indent++) { indented_name += ">"; } indented_name += samples[i].name; char line[256]; sprintf_safe(line, "%5s : %5s : %5s : %3s : ", avg, min, max, num); out << line + indented_name + "\n"; } } SCP_string FrameProfiler::getContent() { return content; } void FrameProfiler::build_overlay_snapshot(const SCP_vector& self_time_by_id, uint64_t total) { // Keep the id, not a Category pointer: a category that a script made through the Lua API // tracing_category can be gone by now, but its name stays available through getNameById(). SCP_vector> sorted; for (size_t id = 0; id < self_time_by_id.size(); id++) { if (self_time_by_id[id] > 0) { sorted.emplace_back(static_cast(id), self_time_by_id[id]); } } std::sort(sorted.begin(), sorted.end(), [](const std::pair& a, const std::pair& b) { return a.second > b.second; }); overlaySnapshot.valid = true; overlaySnapshot.total_nanosec = total; overlaySnapshot.top_contributors.clear(); overlaySnapshot.other_nanosec = 0; for (size_t i = 0; i < sorted.size(); i++) { if (i < FRAME_OVERLAY_MAX_CONTRIBUTORS) { overlaySnapshot.top_contributors.push_back({Category::getNameById(sorted[i].first), sorted[i].second}); } else { overlaySnapshot.other_nanosec += sorted[i].second; } } } void FrameProfiler::processFrame() { std::lock_guard vectorGuard(_eventsMutex); std::sort(_bufferedEvents.begin(), _bufferedEvents.end(), event_sorter); // Overlay fast path: per-category self-time via a single stack walk (see accumulate_self_times). // _selfTimeScratch is a member so the per-frame run reuses its allocation. const uint64_t total = accumulate_self_times(_bufferedEvents, _selfTimeScratch); build_overlay_snapshot(_selfTimeScratch, total); // Legacy on-screen text dump (-profile_frame_time). This still builds the full parent/child // sample tree (process_begin/process_end) and the min/avg/max history, both O(n^2); only pay for // it when that output is actually consumed, not for the overlay. if (Cmdline_frame_profile) { SCP_stringstream stream; SCP_vector samples; for (auto& event : _bufferedEvents) { switch (event.type) { case EventType::Begin: process_begin(samples, event); break; case EventType::End: process_end(samples, event); break; default: break; } } dump_output(stream, 0, 0, samples); content = stream.str(); } _bufferedEvents.clear(); } }