fs2open.github.com/code/tracing/FrameProfiler.cpp

//
//

#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<profile_sample>& 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<profile_sample>& 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<trace_event>& events, SCP_vector<uint64_t>& self_time_by_id) {
	self_time_by_id.assign(Category::getCount(), 0);

	if (events.empty()) {
		return 0;
	}

	uint64_t total = 0;
	SCP_vector<int> 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<size_t>(open_stack.back())] += delta;
			total += delta;
		}
		last_ts = evt.timestamp;

		if (evt.category_id < 0 || evt.category_id >= static_cast<int>(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<std::mutex> 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<profile_sample>& 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<uint64_t>& 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<std::pair<int, uint64_t>> 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<int>(id), self_time_by_id[id]);
		}
	}
	std::sort(sorted.begin(), sorted.end(),
		[](const std::pair<int, uint64_t>& a, const std::pair<int, uint64_t>& 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<std::mutex> 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<profile_sample> 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();
}

}