performance 改成多行
This commit is contained in:
@@ -23,7 +23,7 @@
|
||||
|
||||
namespace renderive {
|
||||
namespace {
|
||||
constexpr int Log_Schema_Version = 1;
|
||||
constexpr int Log_Schema_Version = 2;
|
||||
|
||||
std::uint64_t process_id() {
|
||||
#ifdef _WIN32
|
||||
@@ -51,7 +51,7 @@ std::string session_id_for(const Performance_Log_Options& options) {
|
||||
return out.str();
|
||||
}
|
||||
|
||||
std::string csv_bool(bool value) {
|
||||
std::string log_bool(bool value) {
|
||||
return value ? "1" : "0";
|
||||
}
|
||||
|
||||
@@ -172,57 +172,107 @@ std::string dirty_reason_text(std::uint32_t mask) {
|
||||
return result.empty() ? "none" : result;
|
||||
}
|
||||
|
||||
std::string renderable_cache_stats_text(const Frame_Lifecycle_Record& frame) {
|
||||
std::ostringstream stream;
|
||||
bool first = true;
|
||||
for (const auto& stat : frame.renderable_cache_stats) {
|
||||
if (!first)
|
||||
stream << '|';
|
||||
first = false;
|
||||
stream << stat.object_name
|
||||
<< ":parent=" << stat.parent_object_name
|
||||
<< ";depth=" << stat.tree_depth
|
||||
<< ";hit=" << stat.hit_count
|
||||
<< ";miss=" << stat.miss_count
|
||||
<< ";rebuild=" << stat.rebuild_count
|
||||
<< ";rebuild_ns=" << stat.rebuild_time_ns
|
||||
<< ";compose_ns=" << stat.compose_time_ns
|
||||
<< ";subtree_compose_ns=" << renderable_cache_subtree_compose_time(frame.renderable_cache_stats, stat)
|
||||
<< ";last_rebuild_ns=" << stat.last_rebuild_time_ns
|
||||
<< ";last_compose_ns=" << stat.last_compose_time_ns
|
||||
<< ";image_bytes=" << stat.last_image_bytes
|
||||
<< ";image_area=" << stat.last_image_area
|
||||
<< ";version=" << stat.last_edit_version << '/' << stat.last_ready_version;
|
||||
std::string log_escape(const std::string& value) {
|
||||
std::string escaped;
|
||||
escaped.reserve(value.size());
|
||||
for (char ch : value) {
|
||||
switch (ch) {
|
||||
case '\\': escaped += "\\\\"; break;
|
||||
case '\r': escaped += "\\r"; break;
|
||||
case '\n': escaped += "\\n"; break;
|
||||
case '\t': escaped += "\\t"; break;
|
||||
default: escaped.push_back(ch); break;
|
||||
}
|
||||
}
|
||||
return stream.str();
|
||||
return escaped;
|
||||
}
|
||||
|
||||
std::string renderable_stats_text(const Frame_Lifecycle_Record& frame) {
|
||||
std::ostringstream stream;
|
||||
bool first = true;
|
||||
for (const auto& stat : frame.renderable_stats) {
|
||||
if (!first)
|
||||
stream << '|';
|
||||
first = false;
|
||||
stream << stat.object_name
|
||||
<< ":parent=" << stat.parent_object_name
|
||||
<< ";depth=" << stat.tree_depth
|
||||
<< ";cache=" << (stat.cache_enabled ? 1 : 0)
|
||||
<< ";render=" << stat.render_count
|
||||
<< ";self_draw=" << stat.self_draw_count
|
||||
<< ";render_ns=" << stat.total_render_time_ns
|
||||
<< ";self_draw_ns=" << stat.self_draw_time_ns
|
||||
<< ";last_render_ns=" << stat.last_total_render_time_ns
|
||||
<< ";last_self_draw_ns=" << stat.last_self_draw_time_ns;
|
||||
std::string json_escape(const std::string& value) {
|
||||
std::string escaped;
|
||||
escaped.reserve(value.size() + 2);
|
||||
escaped.push_back('"');
|
||||
for (char ch : value) {
|
||||
switch (ch) {
|
||||
case '\\': escaped += "\\\\"; break;
|
||||
case '"': escaped += "\\\""; break;
|
||||
case '\r': escaped += "\\r"; break;
|
||||
case '\n': escaped += "\\n"; break;
|
||||
case '\t': escaped += "\\t"; break;
|
||||
default: escaped.push_back(ch); break;
|
||||
}
|
||||
}
|
||||
escaped.push_back('"');
|
||||
return escaped;
|
||||
}
|
||||
|
||||
class Log_Record_Builder {
|
||||
public:
|
||||
explicit Log_Record_Builder(std::string kind)
|
||||
: kind_(std::move(kind)) {
|
||||
out_ << '[' << kind_ << ']';
|
||||
}
|
||||
|
||||
template<typename T>
|
||||
void add(const std::string& key, const T& value) {
|
||||
out_ << '\n' << key << '=' << value;
|
||||
}
|
||||
|
||||
std::string finish() {
|
||||
out_ << "\n[/" << kind_ << ']';
|
||||
return out_.str();
|
||||
}
|
||||
|
||||
private:
|
||||
std::string kind_;
|
||||
std::ostringstream out_;
|
||||
};
|
||||
|
||||
void append_renderable_stats(Log_Record_Builder& out, const Frame_Lifecycle_Record& frame) {
|
||||
out.add("renderable_stats.count", frame.renderable_stats.size());
|
||||
for (std::size_t i = 0; i < frame.renderable_stats.size(); ++i) {
|
||||
const auto& stat = frame.renderable_stats[i];
|
||||
const std::string prefix = "renderable_stats." + std::to_string(i) + '.';
|
||||
out.add(prefix + "object_name", log_escape(stat.object_name));
|
||||
out.add(prefix + "parent_object_name", log_escape(stat.parent_object_name));
|
||||
out.add(prefix + "tree_depth", stat.tree_depth);
|
||||
out.add(prefix + "cache_enabled", log_bool(stat.cache_enabled));
|
||||
out.add(prefix + "render_count", stat.render_count);
|
||||
out.add(prefix + "self_draw_count", stat.self_draw_count);
|
||||
out.add(prefix + "total_render_time_ns", stat.total_render_time_ns);
|
||||
out.add(prefix + "self_draw_time_ns", stat.self_draw_time_ns);
|
||||
out.add(prefix + "last_total_render_time_ns", stat.last_total_render_time_ns);
|
||||
out.add(prefix + "last_self_draw_time_ns", stat.last_self_draw_time_ns);
|
||||
}
|
||||
}
|
||||
|
||||
void append_renderable_cache_stats(Log_Record_Builder& out, const Frame_Lifecycle_Record& frame) {
|
||||
out.add("renderable_cache_stats.count", frame.renderable_cache_stats.size());
|
||||
for (std::size_t i = 0; i < frame.renderable_cache_stats.size(); ++i) {
|
||||
const auto& stat = frame.renderable_cache_stats[i];
|
||||
const std::string prefix = "renderable_cache_stats." + std::to_string(i) + '.';
|
||||
out.add(prefix + "object_name", log_escape(stat.object_name));
|
||||
out.add(prefix + "parent_object_name", log_escape(stat.parent_object_name));
|
||||
out.add(prefix + "tree_depth", stat.tree_depth);
|
||||
out.add(prefix + "hit_count", stat.hit_count);
|
||||
out.add(prefix + "miss_count", stat.miss_count);
|
||||
out.add(prefix + "rebuild_count", stat.rebuild_count);
|
||||
out.add(prefix + "rebuild_time_ns", stat.rebuild_time_ns);
|
||||
out.add(prefix + "compose_time_ns", stat.compose_time_ns);
|
||||
out.add(prefix + "subtree_compose_time_ns", renderable_cache_subtree_compose_time(frame.renderable_cache_stats, stat));
|
||||
out.add(prefix + "last_rebuild_time_ns", stat.last_rebuild_time_ns);
|
||||
out.add(prefix + "last_compose_time_ns", stat.last_compose_time_ns);
|
||||
out.add(prefix + "last_image_bytes", stat.last_image_bytes);
|
||||
out.add(prefix + "last_image_area", stat.last_image_area);
|
||||
out.add(prefix + "last_edit_version", stat.last_edit_version);
|
||||
out.add(prefix + "last_ready_version", stat.last_ready_version);
|
||||
}
|
||||
return stream.str();
|
||||
}
|
||||
|
||||
std::string logger_name(const std::string& session_id, const char* suffix) {
|
||||
return session_id + "_" + suffix;
|
||||
}
|
||||
|
||||
std::shared_ptr<spdlog::logger> make_csv_logger(const std::filesystem::path& path, std::size_t max_file_size, std::size_t max_files, const std::string& name) {
|
||||
std::shared_ptr<spdlog::logger> make_log_logger(const std::filesystem::path& path, std::size_t max_file_size, std::size_t max_files, const std::string& name) {
|
||||
std::ofstream(path, std::ios::trunc).close();
|
||||
auto sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(
|
||||
path.string(),
|
||||
@@ -249,8 +299,8 @@ void write_meta_json(const std::filesystem::path& path, const Performance_Log_Op
|
||||
std::ofstream out(path, std::ios::trunc);
|
||||
out << "{\n"
|
||||
<< " \"schema_version\": " << Log_Schema_Version << ",\n"
|
||||
<< " \"session_id\": " << performance_csv_escape(session_id) << ",\n"
|
||||
<< " \"session_name\": " << performance_csv_escape(options.session_name) << ",\n"
|
||||
<< " \"session_id\": " << json_escape(session_id) << ",\n"
|
||||
<< " \"session_name\": " << json_escape(options.session_name) << ",\n"
|
||||
<< " \"start_time_ns\": " << clock_ns() << ",\n"
|
||||
<< " \"process_id\": " << process_id() << ",\n"
|
||||
#ifdef NDEBUG
|
||||
@@ -269,52 +319,6 @@ void write_meta_json(const std::filesystem::path& path, const Performance_Log_Op
|
||||
}
|
||||
} // namespace
|
||||
|
||||
std::string performance_csv_escape(const std::string& value) {
|
||||
std::string escaped;
|
||||
escaped.reserve(value.size() + 2);
|
||||
escaped.push_back('"');
|
||||
for (char ch : value) {
|
||||
if (ch == '"')
|
||||
escaped.push_back('"');
|
||||
escaped.push_back(ch);
|
||||
}
|
||||
escaped.push_back('"');
|
||||
return escaped;
|
||||
}
|
||||
|
||||
std::string performance_frame_csv_header() {
|
||||
return "schema_version,session_id,plot_id,plot_name,process_id,thread_id,timestamp_ns,frame_id,input_version,outcome,dirty_reason,"
|
||||
"production_mode,limit_reason,stable_bottleneck,candidate_bottleneck,consumer_confidence,last_consumer_sample_result,last_decision,decision_reason,decision_timestamp_ns,"
|
||||
"input_interval_current_ns,input_interval_srtt_ns,input_interval_jitter_ns,"
|
||||
"producer_interval_current_ns,producer_interval_srtt_ns,producer_interval_jitter_ns,"
|
||||
"render_service_current_ns,render_service_srtt_ns,render_service_jitter_ns,"
|
||||
"request_to_update_post_current_ns,request_to_update_post_srtt_ns,request_to_update_post_jitter_ns,"
|
||||
"update_post_to_paint_current_ns,update_post_to_paint_srtt_ns,update_post_to_paint_jitter_ns,"
|
||||
"paint_service_current_ns,paint_service_srtt_ns,paint_service_jitter_ns,"
|
||||
"raw_display_interval_current_ns,raw_display_interval_srtt_ns,raw_display_interval_jitter_ns,"
|
||||
"accepted_consumer_interval_current_ns,accepted_consumer_interval_srtt_ns,accepted_consumer_interval_jitter_ns,"
|
||||
"user_period_ns,target_period_ns,effective_interval_ns,next_render_time_ns,admission_deadline_wait_ns,executor_queue_wait_ns,present_queue_wait_ns,paint_return_wait_ns,"
|
||||
"consumer_window_size,consumer_window_accepted,consumer_window_rejected_no_backlog,consumer_window_rejected_starved,consumer_window_rejected_no_new_frame,consumer_window_rejected_invalid,consumer_window_accepted_ratio,"
|
||||
"consumer_accepted_total,consumer_rejected_no_backlog_total,consumer_rejected_starved_total,consumer_rejected_no_new_frame_total,consumer_rejected_invalid_total,"
|
||||
"producer_starvation_total,producer_starvation_epoch_id,producer_starvation_active,mode_enter_total,mode_exit_total,"
|
||||
"update_posted,update_coalesced,update_ack,update_repost,paint_without_core_post,"
|
||||
"rendered,middle_published,middle_superseded,painting_advanced,painting_repeated,underrun,display_efficiency,logger_dropped,"
|
||||
"executor_workers,executor_active_workers,executor_queued_frames,executor_active_frames,executor_submitted_frames,executor_started_tasks,executor_completed_tasks,executor_rejected_frames,"
|
||||
"frame_task_count,frame_peak_parallelism,frame_task_wait_max_ns,frame_task_run_total_ns,"
|
||||
"request_wait_ns,prepare_ns,draw_ns,render_total_ns,ready_to_paint_ns,paint_ns,input_to_display_age_ns,e2e_total_ns,"
|
||||
"renderable_stats,renderable_cache_stats";
|
||||
}
|
||||
|
||||
std::string performance_feedback_csv_header() {
|
||||
return "schema_version,session_id,plot_id,plot_name,process_id,thread_id,timestamp_ns,event,frame_id,"
|
||||
"mode_before,mode_after,decision,reason,"
|
||||
"dirty,render_active,middle_has_new_frame,paint_active,paint_update_posted,backlog_epoch_active,continuously_backlogged,producer_starved,"
|
||||
"backlog_epoch_id,backlog_rendered_frames,backlog_superseded_frames,"
|
||||
"consumer_sample_result,raw_display_sample_ns,accepted_consumer_sample_ns,"
|
||||
"window_accepted,window_rejected,window_ratio,"
|
||||
"user_period_ns,consumer_capacity_ns,target_period_ns,effective_interval_before_ns,effective_interval_after_ns,next_render_time_ns";
|
||||
}
|
||||
|
||||
struct Performance_Log_Service::Private {
|
||||
mutable std::mutex mutex;
|
||||
std::condition_variable cv;
|
||||
@@ -422,16 +426,14 @@ void Performance_Log_Service::configure(Performance_Log_Options options) {
|
||||
std::filesystem::create_directories(d->options.directory);
|
||||
d->session.session_id = session_id_for(d->options);
|
||||
std::filesystem::path directory = d->options.directory;
|
||||
std::filesystem::path frame_path = directory / (d->options.session_name + "_frames.csv");
|
||||
std::filesystem::path feedback_path = directory / (d->options.session_name + "_feedback.csv");
|
||||
std::filesystem::path frame_path = directory / (d->options.session_name + "_frames.log");
|
||||
std::filesystem::path feedback_path = directory / (d->options.session_name + "_feedback.log");
|
||||
std::filesystem::path meta_path = directory / (d->options.session_name + "_meta.json");
|
||||
d->session.frame_log_path = frame_path.string();
|
||||
d->session.feedback_log_path = feedback_path.string();
|
||||
d->session.meta_path = meta_path.string();
|
||||
d->frame_logger = make_csv_logger(frame_path, d->options.max_file_size, d->options.max_files, logger_name(d->session.session_id, "frames"));
|
||||
d->feedback_logger = make_csv_logger(feedback_path, d->options.max_file_size, d->options.max_files, logger_name(d->session.session_id, "feedback"));
|
||||
d->frame_logger->info("{}", performance_frame_csv_header());
|
||||
d->feedback_logger->info("{}", performance_feedback_csv_header());
|
||||
d->frame_logger = make_log_logger(frame_path, d->options.max_file_size, d->options.max_files, logger_name(d->session.session_id, "frames"));
|
||||
d->feedback_logger = make_log_logger(feedback_path, d->options.max_file_size, d->options.max_files, logger_name(d->session.session_id, "feedback"));
|
||||
write_meta_json(meta_path, d->options, d->session.session_id);
|
||||
d->queue = std::make_unique<rigtorp::MPMCQueue<Performance_Log_Record>>(d->options.queue_capacity);
|
||||
d->running.store(true, std::memory_order_release);
|
||||
@@ -481,55 +483,112 @@ bool Performance_Log_Service::enqueue_frame(Performance_Log_Plot_Identity identi
|
||||
record.kind = Performance_Log_Record_Kind::Frame;
|
||||
const Refresh_Control_Snapshot& r = frame->refresh;
|
||||
const auto& e = frame->worker.executor_at_finish;
|
||||
std::ostringstream out;
|
||||
out << Log_Schema_Version << ','
|
||||
<< performance_csv_escape(d->session.session_id) << ','
|
||||
<< identity.plot_id << ','
|
||||
<< performance_csv_escape(identity.plot_name) << ','
|
||||
<< process_id() << ','
|
||||
<< thread_id_hash() << ','
|
||||
<< timestamp_for(*frame) << ','
|
||||
<< frame->frame_id << ','
|
||||
<< frame->input_version << ','
|
||||
<< outcome_text(frame->outcome) << ','
|
||||
<< dirty_reason_text(frame->dirty_reason_mask) << ','
|
||||
<< production_mode_text(r.production_mode) << ','
|
||||
<< limit_reason_text(r.limit_reason) << ','
|
||||
<< bottleneck_text(r.stable_bottleneck) << ','
|
||||
<< bottleneck_text(r.candidate_bottleneck) << ','
|
||||
<< consumer_confidence_text(r.consumer_confidence) << ','
|
||||
<< consumer_sample_result_text(r.last_consumer_sample_result) << ','
|
||||
<< feedback_decision_text(r.last_decision) << ','
|
||||
<< performance_csv_escape(r.decision_reason) << ','
|
||||
<< r.decision_timestamp_ns << ','
|
||||
<< r.input_interval_current_ns << ',' << r.input_interval_srtt_ns << ',' << r.input_jitter_ns << ','
|
||||
<< r.producer_interval_current_ns << ',' << r.producer_interval_srtt_ns << ',' << r.producer_interval_jitter_ns << ','
|
||||
<< r.render_service_current_ns << ',' << r.render_service_srtt_ns << ',' << r.render_jitter_ns << ','
|
||||
<< r.request_to_update_post_current_ns << ',' << r.request_to_update_post_srtt_ns << ',' << r.request_to_update_post_jitter_ns << ','
|
||||
<< r.update_post_to_paint_current_ns << ',' << r.update_post_to_paint_srtt_ns << ',' << r.update_to_paint_jitter_ns << ','
|
||||
<< r.paint_service_current_ns << ',' << r.paint_service_srtt_ns << ',' << r.paint_service_jitter_ns << ','
|
||||
<< r.raw_display_interval_current_ns << ',' << r.raw_display_interval_srtt_ns << ',' << r.raw_display_interval_jitter_ns << ','
|
||||
<< r.accepted_consumer_interval_current_ns << ',' << r.accepted_consumer_interval_srtt_ns << ',' << r.accepted_consumer_interval_jitter_ns << ','
|
||||
<< r.user_period_ns << ',' << r.target_period_ns << ',' << r.effective_min_render_interval_ns << ',' << r.next_render_time_ns << ','
|
||||
<< r.admission_deadline_wait_ns << ',' << r.executor_queue_wait_ns << ',' << r.present_wait_ns << ',' << frame->paint_return_wait_ns << ','
|
||||
<< r.consumer_window_size << ',' << r.consumer_window_accepted << ',' << r.consumer_window_rejected_no_backlog << ',' << r.consumer_window_rejected_starved << ',' << r.consumer_window_rejected_no_new_frame << ',' << r.consumer_window_rejected_invalid << ',' << r.consumer_window_accepted_ratio << ','
|
||||
<< r.consumer_sample_accepted_count << ',' << r.consumer_sample_rejected_no_backlog_count << ',' << r.consumer_sample_rejected_starved_count << ',' << r.consumer_sample_rejected_no_new_frame_count << ',' << r.consumer_sample_rejected_invalid_timestamp_count << ','
|
||||
<< r.producer_starvation_count << ',' << r.producer_starvation_epoch_id << ',' << csv_bool(r.producer_starvation_active) << ',' << r.mode_enter_count << ',' << r.mode_exit_count << ','
|
||||
<< r.update_posted_count << ',' << r.update_coalesced_count << ',' << r.update_ack_count << ',' << r.update_repost_count << ',' << r.paint_without_posted_update_count << ','
|
||||
<< csv_bool(frame->render_end_ns != 0) << ',' << r.middle_published_count << ',' << r.middle_superseded_count << ',' << r.painting_advanced_count << ',' << r.repeated_frame_count << ',' << r.underrun_count << ',' << r.display_efficiency << ',' << dropped_record_count() << ','
|
||||
<< e.worker_count << ',' << e.active_workers << ',' << e.queued_frame_jobs << ',' << e.active_frame_jobs << ',' << e.submitted_jobs << ',' << e.started_task_nodes << ',' << e.completed_task_nodes << ',' << e.rejected_frame_jobs << ','
|
||||
<< frame->worker.task_count << ',' << frame->worker.peak_parallelism << ',' << frame->worker.queue_wait_max_ns << ',' << frame->worker.worker_run_total_ns << ','
|
||||
<< duration_ns(frame->render_request_ns, frame->render_begin_ns) << ','
|
||||
<< duration_ns(frame->prepare_begin_ns, frame->prepare_end_ns) << ','
|
||||
<< duration_ns(frame->draw_begin_ns, frame->draw_end_ns) << ','
|
||||
<< duration_ns(frame->render_begin_ns, frame->render_end_ns) << ','
|
||||
<< duration_ns(frame->transition_12_ns, frame->paint_begin_ns ? frame->paint_begin_ns : frame->superseded_time_ns) << ','
|
||||
<< duration_ns(frame->paint_begin_ns, frame->paint_end_ns) << ','
|
||||
<< duration_ns(frame->core_data_time_ns, frame->paint_end_ns) << ','
|
||||
<< duration_ns(frame->render_request_ns, frame->transition_32_ns ? frame->transition_32_ns : frame->superseded_time_ns) << ','
|
||||
<< performance_csv_escape(renderable_stats_text(*frame)) << ','
|
||||
<< performance_csv_escape(renderable_cache_stats_text(*frame));
|
||||
record.line = out.str();
|
||||
Log_Record_Builder out("frame");
|
||||
out.add("schema_version", Log_Schema_Version);
|
||||
out.add("session_id", log_escape(d->session.session_id));
|
||||
out.add("plot_id", identity.plot_id);
|
||||
out.add("plot_name", log_escape(identity.plot_name));
|
||||
out.add("process_id", process_id());
|
||||
out.add("thread_id", thread_id_hash());
|
||||
out.add("timestamp_ns", timestamp_for(*frame));
|
||||
out.add("frame_id", frame->frame_id);
|
||||
out.add("input_version", frame->input_version);
|
||||
out.add("outcome", outcome_text(frame->outcome));
|
||||
out.add("dirty_reason", dirty_reason_text(frame->dirty_reason_mask));
|
||||
out.add("production_mode", production_mode_text(r.production_mode));
|
||||
out.add("limit_reason", limit_reason_text(r.limit_reason));
|
||||
out.add("stable_bottleneck", bottleneck_text(r.stable_bottleneck));
|
||||
out.add("candidate_bottleneck", bottleneck_text(r.candidate_bottleneck));
|
||||
out.add("consumer_confidence", consumer_confidence_text(r.consumer_confidence));
|
||||
out.add("last_consumer_sample_result", consumer_sample_result_text(r.last_consumer_sample_result));
|
||||
out.add("last_decision", feedback_decision_text(r.last_decision));
|
||||
out.add("decision_reason", log_escape(r.decision_reason));
|
||||
out.add("decision_timestamp_ns", r.decision_timestamp_ns);
|
||||
out.add("input_interval_current_ns", r.input_interval_current_ns);
|
||||
out.add("input_interval_srtt_ns", r.input_interval_srtt_ns);
|
||||
out.add("input_interval_jitter_ns", r.input_jitter_ns);
|
||||
out.add("producer_interval_current_ns", r.producer_interval_current_ns);
|
||||
out.add("producer_interval_srtt_ns", r.producer_interval_srtt_ns);
|
||||
out.add("producer_interval_jitter_ns", r.producer_interval_jitter_ns);
|
||||
out.add("render_service_current_ns", r.render_service_current_ns);
|
||||
out.add("render_service_srtt_ns", r.render_service_srtt_ns);
|
||||
out.add("render_service_jitter_ns", r.render_jitter_ns);
|
||||
out.add("request_to_update_post_current_ns", r.request_to_update_post_current_ns);
|
||||
out.add("request_to_update_post_srtt_ns", r.request_to_update_post_srtt_ns);
|
||||
out.add("request_to_update_post_jitter_ns", r.request_to_update_post_jitter_ns);
|
||||
out.add("update_post_to_paint_current_ns", r.update_post_to_paint_current_ns);
|
||||
out.add("update_post_to_paint_srtt_ns", r.update_post_to_paint_srtt_ns);
|
||||
out.add("update_post_to_paint_jitter_ns", r.update_to_paint_jitter_ns);
|
||||
out.add("paint_service_current_ns", r.paint_service_current_ns);
|
||||
out.add("paint_service_srtt_ns", r.paint_service_srtt_ns);
|
||||
out.add("paint_service_jitter_ns", r.paint_service_jitter_ns);
|
||||
out.add("raw_display_interval_current_ns", r.raw_display_interval_current_ns);
|
||||
out.add("raw_display_interval_srtt_ns", r.raw_display_interval_srtt_ns);
|
||||
out.add("raw_display_interval_jitter_ns", r.raw_display_interval_jitter_ns);
|
||||
out.add("accepted_consumer_interval_current_ns", r.accepted_consumer_interval_current_ns);
|
||||
out.add("accepted_consumer_interval_srtt_ns", r.accepted_consumer_interval_srtt_ns);
|
||||
out.add("accepted_consumer_interval_jitter_ns", r.accepted_consumer_interval_jitter_ns);
|
||||
out.add("user_period_ns", r.user_period_ns);
|
||||
out.add("target_period_ns", r.target_period_ns);
|
||||
out.add("effective_interval_ns", r.effective_min_render_interval_ns);
|
||||
out.add("next_render_time_ns", r.next_render_time_ns);
|
||||
out.add("admission_deadline_wait_ns", r.admission_deadline_wait_ns);
|
||||
out.add("executor_queue_wait_ns", r.executor_queue_wait_ns);
|
||||
out.add("present_queue_wait_ns", r.present_wait_ns);
|
||||
out.add("paint_return_wait_ns", frame->paint_return_wait_ns);
|
||||
out.add("consumer_window_size", r.consumer_window_size);
|
||||
out.add("consumer_window_accepted", r.consumer_window_accepted);
|
||||
out.add("consumer_window_rejected_no_backlog", r.consumer_window_rejected_no_backlog);
|
||||
out.add("consumer_window_rejected_starved", r.consumer_window_rejected_starved);
|
||||
out.add("consumer_window_rejected_no_new_frame", r.consumer_window_rejected_no_new_frame);
|
||||
out.add("consumer_window_rejected_invalid", r.consumer_window_rejected_invalid);
|
||||
out.add("consumer_window_accepted_ratio", r.consumer_window_accepted_ratio);
|
||||
out.add("consumer_accepted_total", r.consumer_sample_accepted_count);
|
||||
out.add("consumer_rejected_no_backlog_total", r.consumer_sample_rejected_no_backlog_count);
|
||||
out.add("consumer_rejected_starved_total", r.consumer_sample_rejected_starved_count);
|
||||
out.add("consumer_rejected_no_new_frame_total", r.consumer_sample_rejected_no_new_frame_count);
|
||||
out.add("consumer_rejected_invalid_total", r.consumer_sample_rejected_invalid_timestamp_count);
|
||||
out.add("producer_starvation_total", r.producer_starvation_count);
|
||||
out.add("producer_starvation_epoch_id", r.producer_starvation_epoch_id);
|
||||
out.add("producer_starvation_active", log_bool(r.producer_starvation_active));
|
||||
out.add("mode_enter_total", r.mode_enter_count);
|
||||
out.add("mode_exit_total", r.mode_exit_count);
|
||||
out.add("update_posted", r.update_posted_count);
|
||||
out.add("update_coalesced", r.update_coalesced_count);
|
||||
out.add("update_ack", r.update_ack_count);
|
||||
out.add("update_repost", r.update_repost_count);
|
||||
out.add("paint_without_core_post", r.paint_without_posted_update_count);
|
||||
out.add("rendered", log_bool(frame->render_end_ns != 0));
|
||||
out.add("middle_published", r.middle_published_count);
|
||||
out.add("middle_superseded", r.middle_superseded_count);
|
||||
out.add("painting_advanced", r.painting_advanced_count);
|
||||
out.add("painting_repeated", r.repeated_frame_count);
|
||||
out.add("underrun", r.underrun_count);
|
||||
out.add("display_efficiency", r.display_efficiency);
|
||||
out.add("logger_dropped", dropped_record_count());
|
||||
out.add("executor_workers", e.worker_count);
|
||||
out.add("executor_active_workers", e.active_workers);
|
||||
out.add("executor_queued_frames", e.queued_frame_jobs);
|
||||
out.add("executor_active_frames", e.active_frame_jobs);
|
||||
out.add("executor_submitted_frames", e.submitted_jobs);
|
||||
out.add("executor_started_tasks", e.started_task_nodes);
|
||||
out.add("executor_completed_tasks", e.completed_task_nodes);
|
||||
out.add("executor_rejected_frames", e.rejected_frame_jobs);
|
||||
out.add("frame_task_count", frame->worker.task_count);
|
||||
out.add("frame_peak_parallelism", frame->worker.peak_parallelism);
|
||||
out.add("frame_task_wait_max_ns", frame->worker.queue_wait_max_ns);
|
||||
out.add("frame_task_run_total_ns", frame->worker.worker_run_total_ns);
|
||||
out.add("request_wait_ns", duration_ns(frame->render_request_ns, frame->render_begin_ns));
|
||||
out.add("prepare_ns", duration_ns(frame->prepare_begin_ns, frame->prepare_end_ns));
|
||||
out.add("draw_ns", duration_ns(frame->draw_begin_ns, frame->draw_end_ns));
|
||||
out.add("render_total_ns", duration_ns(frame->render_begin_ns, frame->render_end_ns));
|
||||
out.add("ready_to_paint_ns", duration_ns(frame->transition_12_ns, frame->paint_begin_ns ? frame->paint_begin_ns : frame->superseded_time_ns));
|
||||
out.add("paint_ns", duration_ns(frame->paint_begin_ns, frame->paint_end_ns));
|
||||
out.add("input_to_display_age_ns", duration_ns(frame->core_data_time_ns, frame->paint_end_ns));
|
||||
out.add("e2e_total_ns", duration_ns(frame->render_request_ns, frame->transition_32_ns ? frame->transition_32_ns : frame->superseded_time_ns));
|
||||
append_renderable_stats(out, *frame);
|
||||
append_renderable_cache_stats(out, *frame);
|
||||
record.line = out.finish();
|
||||
record.flush = frame->outcome != Frame_Outcome::Presented || r.last_decision == Low_Latency_Feedback_Decision::Enter_Consumer_Paced || r.last_decision == Low_Latency_Feedback_Decision::Exit_Consumer_Paced;
|
||||
return enqueue(std::move(record));
|
||||
}
|
||||
@@ -544,44 +603,44 @@ bool Performance_Log_Service::enqueue_feedback_event(Performance_Log_Plot_Identi
|
||||
+ r.consumer_window_rejected_starved
|
||||
+ r.consumer_window_rejected_no_new_frame
|
||||
+ r.consumer_window_rejected_invalid;
|
||||
std::ostringstream out;
|
||||
out << Log_Schema_Version << ','
|
||||
<< performance_csv_escape(d->session.session_id) << ','
|
||||
<< identity.plot_id << ','
|
||||
<< performance_csv_escape(identity.plot_name) << ','
|
||||
<< process_id() << ','
|
||||
<< thread_id_hash() << ','
|
||||
<< (event_record.timestamp_ns ? event_record.timestamp_ns : timestamp_for(frame)) << ','
|
||||
<< event_record.event << ','
|
||||
<< frame.frame_id << ','
|
||||
<< production_mode_text(event_record.mode_before) << ','
|
||||
<< production_mode_text(event_record.mode_after) << ','
|
||||
<< feedback_decision_text(r.last_decision) << ','
|
||||
<< performance_csv_escape(r.decision_reason) << ','
|
||||
<< csv_bool(event_record.dirty) << ','
|
||||
<< csv_bool(event_record.render_active) << ','
|
||||
<< csv_bool(event_record.middle_has_new_frame) << ','
|
||||
<< csv_bool(event_record.paint_active) << ','
|
||||
<< csv_bool(event_record.paint_update_posted) << ','
|
||||
<< csv_bool(event_record.backlog_epoch_active) << ','
|
||||
<< csv_bool(event_record.continuously_backlogged) << ','
|
||||
<< csv_bool(event_record.producer_starved) << ','
|
||||
<< event_record.backlog_epoch_id << ','
|
||||
<< event_record.backlog_rendered_frames << ','
|
||||
<< event_record.backlog_superseded_frames << ','
|
||||
<< consumer_sample_result_text(r.last_consumer_sample_result) << ','
|
||||
<< r.raw_display_interval_current_ns << ','
|
||||
<< r.accepted_consumer_interval_current_ns << ','
|
||||
<< r.consumer_window_accepted << ','
|
||||
<< window_rejected << ','
|
||||
<< r.consumer_window_accepted_ratio << ','
|
||||
<< r.user_period_ns << ','
|
||||
<< r.accepted_consumer_interval_srtt_ns << ','
|
||||
<< r.target_period_ns << ','
|
||||
<< event_record.effective_interval_before_ns << ','
|
||||
<< event_record.effective_interval_after_ns << ','
|
||||
<< r.next_render_time_ns;
|
||||
record.line = out.str();
|
||||
Log_Record_Builder out("feedback");
|
||||
out.add("schema_version", Log_Schema_Version);
|
||||
out.add("session_id", log_escape(d->session.session_id));
|
||||
out.add("plot_id", identity.plot_id);
|
||||
out.add("plot_name", log_escape(identity.plot_name));
|
||||
out.add("process_id", process_id());
|
||||
out.add("thread_id", thread_id_hash());
|
||||
out.add("timestamp_ns", event_record.timestamp_ns ? event_record.timestamp_ns : timestamp_for(frame));
|
||||
out.add("event", log_escape(event_record.event));
|
||||
out.add("frame_id", frame.frame_id);
|
||||
out.add("mode_before", production_mode_text(event_record.mode_before));
|
||||
out.add("mode_after", production_mode_text(event_record.mode_after));
|
||||
out.add("decision", feedback_decision_text(r.last_decision));
|
||||
out.add("reason", log_escape(r.decision_reason));
|
||||
out.add("dirty", log_bool(event_record.dirty));
|
||||
out.add("render_active", log_bool(event_record.render_active));
|
||||
out.add("middle_has_new_frame", log_bool(event_record.middle_has_new_frame));
|
||||
out.add("paint_active", log_bool(event_record.paint_active));
|
||||
out.add("paint_update_posted", log_bool(event_record.paint_update_posted));
|
||||
out.add("backlog_epoch_active", log_bool(event_record.backlog_epoch_active));
|
||||
out.add("continuously_backlogged", log_bool(event_record.continuously_backlogged));
|
||||
out.add("producer_starved", log_bool(event_record.producer_starved));
|
||||
out.add("backlog_epoch_id", event_record.backlog_epoch_id);
|
||||
out.add("backlog_rendered_frames", event_record.backlog_rendered_frames);
|
||||
out.add("backlog_superseded_frames", event_record.backlog_superseded_frames);
|
||||
out.add("consumer_sample_result", consumer_sample_result_text(r.last_consumer_sample_result));
|
||||
out.add("raw_display_sample_ns", r.raw_display_interval_current_ns);
|
||||
out.add("accepted_consumer_sample_ns", r.accepted_consumer_interval_current_ns);
|
||||
out.add("window_accepted", r.consumer_window_accepted);
|
||||
out.add("window_rejected", window_rejected);
|
||||
out.add("window_ratio", r.consumer_window_accepted_ratio);
|
||||
out.add("user_period_ns", r.user_period_ns);
|
||||
out.add("consumer_capacity_ns", r.accepted_consumer_interval_srtt_ns);
|
||||
out.add("target_period_ns", r.target_period_ns);
|
||||
out.add("effective_interval_before_ns", event_record.effective_interval_before_ns);
|
||||
out.add("effective_interval_after_ns", event_record.effective_interval_after_ns);
|
||||
out.add("next_render_time_ns", r.next_render_time_ns);
|
||||
record.line = out.finish();
|
||||
return enqueue(std::move(record));
|
||||
}
|
||||
|
||||
|
||||
@@ -30,8 +30,4 @@ private:
|
||||
|
||||
Performance_Log_Service& performance_log_service();
|
||||
|
||||
std::string performance_frame_csv_header();
|
||||
std::string performance_feedback_csv_header();
|
||||
std::string performance_csv_escape(const std::string& value);
|
||||
|
||||
} // namespace renderive
|
||||
|
||||
@@ -972,16 +972,13 @@ struct Performance_Layout_Builder {
|
||||
result.push_back(render_line_text(line));
|
||||
return result;
|
||||
}
|
||||
static int resolve_column_count(double available_width) {
|
||||
return std::clamp(static_cast<int>(available_width / 320.0), 1, 4);
|
||||
}
|
||||
static bool warning_line(std::string_view line) {
|
||||
return (contains(line, "underrun:") && !contains(line, "underrun:0"))
|
||||
|| (contains(line, "dropped:") && !contains(line, "dropped:0"))
|
||||
|| (contains(line, "starvation_active:1"))
|
||||
|| (contains(line, "confidence:low") && contains(line, "consumer_paced"));
|
||||
}
|
||||
std::vector<Performance_Text_Span> plain_line_runs(const std::string& text, Canvas& canvas, int column_index, double x_offset) {
|
||||
std::vector<Performance_Text_Span> plain_line_runs(const std::string& text, Canvas& canvas) {
|
||||
std::vector<Performance_Text_Span> runs;
|
||||
auto append = [&](std::string value, Performance_Text_Role role, double offset) {
|
||||
if (value.empty())
|
||||
@@ -989,8 +986,8 @@ struct Performance_Layout_Builder {
|
||||
Performance_Text_Span run;
|
||||
run.text = std::move(value);
|
||||
run.role = role;
|
||||
run.column_index = column_index;
|
||||
run.x_offset = x_offset + offset;
|
||||
run.column_index = 0;
|
||||
run.x_offset = offset;
|
||||
measure_run(canvas, run);
|
||||
runs.push_back(std::move(run));
|
||||
};
|
||||
@@ -1015,24 +1012,18 @@ struct Performance_Layout_Builder {
|
||||
append(text, Performance_Text_Role::Value, 0.0);
|
||||
return runs;
|
||||
}
|
||||
void build_render_lines(Canvas& canvas, double available_width) {
|
||||
void build_render_lines(Canvas& canvas) {
|
||||
render_lines.clear();
|
||||
text_runs.clear();
|
||||
available_width = std::max(1.0, available_width);
|
||||
int column_count = resolve_column_count(available_width);
|
||||
double column_gap = column_count > 1 ? 18.0 : 0.0;
|
||||
double column_width = (available_width - column_gap * static_cast<double>(column_count - 1)) / static_cast<double>(column_count);
|
||||
std::size_t row_count = (lines.size() + static_cast<std::size_t>(column_count) - 1) / static_cast<std::size_t>(column_count);
|
||||
render_lines.resize(std::max<std::size_t>(1, row_count));
|
||||
for (std::size_t i = 0; i < lines.size(); ++i) {
|
||||
int column = static_cast<int>(i % static_cast<std::size_t>(column_count));
|
||||
std::size_t row = i / static_cast<std::size_t>(column_count);
|
||||
double x_offset = static_cast<double>(column) * (column_width + column_gap);
|
||||
std::vector<Performance_Text_Span> runs = plain_line_runs(lines[i], canvas, column, x_offset);
|
||||
for (const auto& text : lines) {
|
||||
Performance_Line_Layout line;
|
||||
std::vector<Performance_Text_Span> runs = plain_line_runs(text, canvas);
|
||||
for (auto& run : runs) {
|
||||
render_lines[row].width = std::max(render_lines[row].width, run.x_offset + run.measured_width);
|
||||
render_lines[row].runs.push_back(run);
|
||||
line.width = std::max(line.width, run.x_offset + run.measured_width);
|
||||
line.runs.push_back(std::move(run));
|
||||
}
|
||||
if (!line.runs.empty())
|
||||
render_lines.push_back(std::move(line));
|
||||
}
|
||||
if (render_lines.empty()) {
|
||||
Performance_Line_Layout line;
|
||||
@@ -1344,8 +1335,7 @@ struct Performance_Overlay_Private {
|
||||
if (metrics.line_height() <= 0.0)
|
||||
metrics = measure_canvas.measure_text("M");
|
||||
layout.seed_static_field_widths(measure_canvas);
|
||||
int available_text_width = viewport.width - state.left_margin - state.right_margin - state.scroll_bar_width - state.scroll_bar_margin * 2;
|
||||
layout.build_render_lines(measure_canvas, static_cast<double>(std::max(1, available_text_width)));
|
||||
layout.build_render_lines(measure_canvas);
|
||||
}
|
||||
worker_state.field_layout_states = layout.field_layout_states;
|
||||
snapshot->lines = layout.display_lines();
|
||||
|
||||
Reference in New Issue
Block a user