From 43bbe54b72dc64d164e1b8f49830e8229cfaf9c8 Mon Sep 17 00:00:00 2001 From: wyc <1104749580@qq.com> Date: Mon, 3 Aug 2026 08:56:29 +0800 Subject: [PATCH] =?UTF-8?q?performance=20=E6=94=B9=E6=88=90=E5=A4=9A?= =?UTF-8?q?=E8=A1=8C?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- Core/performance/Performance_Log_Service.cpp | 427 +++++++++++-------- Core/performance/Performance_Log_Service.h | 4 - Core/plottable/Performance_Overlay_p.h | 34 +- 3 files changed, 255 insertions(+), 210 deletions(-) diff --git a/Core/performance/Performance_Log_Service.cpp b/Core/performance/Performance_Log_Service.cpp index fa599ca..b7bcee1 100644 --- a/Core/performance/Performance_Log_Service.cpp +++ b/Core/performance/Performance_Log_Service.cpp @@ -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 + 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 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 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( 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>(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)); } diff --git a/Core/performance/Performance_Log_Service.h b/Core/performance/Performance_Log_Service.h index ace8e85..dfa2ba5 100644 --- a/Core/performance/Performance_Log_Service.h +++ b/Core/performance/Performance_Log_Service.h @@ -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 diff --git a/Core/plottable/Performance_Overlay_p.h b/Core/plottable/Performance_Overlay_p.h index a4e5753..e14cad7 100644 --- a/Core/plottable/Performance_Overlay_p.h +++ b/Core/plottable/Performance_Overlay_p.h @@ -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(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 plain_line_runs(const std::string& text, Canvas& canvas, int column_index, double x_offset) { + std::vector plain_line_runs(const std::string& text, Canvas& canvas) { std::vector 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(column_count - 1)) / static_cast(column_count); - std::size_t row_count = (lines.size() + static_cast(column_count) - 1) / static_cast(column_count); - render_lines.resize(std::max(1, row_count)); - for (std::size_t i = 0; i < lines.size(); ++i) { - int column = static_cast(i % static_cast(column_count)); - std::size_t row = i / static_cast(column_count); - double x_offset = static_cast(column) * (column_width + column_gap); - std::vector runs = plain_line_runs(lines[i], canvas, column, x_offset); + for (const auto& text : lines) { + Performance_Line_Layout line; + std::vector 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(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();