diff --git a/Core/architecture/Frame_Scheduler.h b/Core/architecture/Frame_Scheduler.h index 40d3183..7118713 100644 --- a/Core/architecture/Frame_Scheduler.h +++ b/Core/architecture/Frame_Scheduler.h @@ -79,7 +79,8 @@ struct Refresh_Control_Snapshot { std::uint64_t target_period_ns{}; std::uint64_t effective_min_render_interval_ns{}; std::uint64_t next_render_time_ns{}; - std::uint64_t admission_deadline_wait_ns{}; + std::uint64_t admission_wait_elapsed_ns{}; + std::uint64_t admission_wait_remaining_ns{}; std::uint64_t executor_queue_wait_ns{}; std::uint64_t present_wait_ns{}; std::uint64_t consumer_sample_accepted_count{}; @@ -102,7 +103,7 @@ struct Refresh_Control_Snapshot { std::uint64_t mode_enter_count{}; std::uint64_t mode_exit_count{}; std::uint64_t update_posted_count{}; - std::uint64_t update_coalesced_count{}; + std::uint64_t duplicate_present_request_suppressed_count{}; std::uint64_t update_ack_count{}; std::uint64_t update_repost_count{}; std::uint64_t paint_without_posted_update_count{}; @@ -173,7 +174,8 @@ struct Frame_Lifecycle_Record { std::uint64_t paint_end_ns{}; std::uint64_t presented_frame_id{}; std::uint64_t transition_32_ns{}; - std::uint64_t render_queue_wait_ns{}; + std::uint64_t render_slot_idle_wait_ns{}; + std::uint64_t executor_queue_wait_ns{}; std::uint64_t ready_queue_wait_ns{}; std::uint64_t present_queue_wait_ns{}; std::uint64_t paint_return_wait_ns{}; diff --git a/Core/architecture/Render_Config.h b/Core/architecture/Render_Config.h index b5036bc..23ac7ea 100644 --- a/Core/architecture/Render_Config.h +++ b/Core/architecture/Render_Config.h @@ -25,16 +25,18 @@ struct Render_Executor_Snapshot { std::size_t idle_workers{}; std::size_t active_frame_jobs{}; std::size_t queued_frame_jobs{}; - std::uint64_t submitted_jobs{}; + std::uint64_t submitted_topologies{}; + std::uint64_t started_topologies{}; + std::uint64_t completed_topologies{}; std::uint64_t started_task_nodes{}; std::uint64_t completed_task_nodes{}; std::uint64_t rejected_frame_jobs{}; std::uint64_t dropped_frame_attempts{}; std::uint64_t peak_concurrency{}; - std::uint64_t average_queue_wait_ns{}; - std::uint64_t max_queue_wait_ns{}; - std::uint64_t average_task_duration_ns{}; - std::uint64_t max_task_duration_ns{}; + std::uint64_t average_topology_queue_wait_ns{}; + std::uint64_t max_topology_queue_wait_ns{}; + std::uint64_t average_task_node_duration_ns{}; + std::uint64_t max_task_node_duration_ns{}; std::uint64_t curve_tasks{}; std::uint64_t waterfall_tasks{}; std::uint64_t primitive_tasks{}; @@ -44,13 +46,13 @@ struct Render_Executor_Snapshot { struct Frame_Worker_Stats { Render_Executor_Snapshot executor_at_submit; Render_Executor_Snapshot executor_at_finish; - std::uint32_t task_count{}; - std::uint32_t peak_parallelism{}; - std::uint64_t queue_wait_total_ns{}; - std::uint64_t queue_wait_max_ns{}; - std::uint64_t worker_run_total_ns{}; - std::uint64_t parallel_stage_wall_ns{}; - std::uint64_t rejected_task_count{}; + std::uint32_t business_task_count{}; + std::uint32_t business_task_peak_parallelism{}; + std::uint64_t topology_queue_wait_total_ns{}; + std::uint64_t topology_queue_wait_max_ns{}; + std::uint64_t business_task_run_total_ns{}; + std::uint64_t topology_run_total_ns{}; + std::uint64_t rejected_topology_count{}; }; enum class Refresh_Limit_Source : std::uint8_t { Unknown, @@ -106,7 +108,7 @@ struct Consumer_Backlog_Epoch { }; struct Low_Latency_Performance_Diagnostics { std::uint64_t update_posted_count{}; - std::uint64_t update_coalesced_count{}; + std::uint64_t duplicate_present_request_suppressed_count{}; std::uint64_t update_ack_count{}; std::uint64_t update_repost_count{}; std::uint64_t consumer_sample_accepted_count{}; diff --git a/Core/execution/Render_Executor.cpp b/Core/execution/Render_Executor.cpp index 252b879..adfeae5 100644 --- a/Core/execution/Render_Executor.cpp +++ b/Core/execution/Render_Executor.cpp @@ -11,24 +11,24 @@ namespace renderive { struct Render_Executor_Metrics; -struct Frame_Task_Counters { - std::atomic_uint32_t task_count{0}; - std::atomic_uint32_t active_count{0}; - std::atomic_uint32_t peak_parallelism{0}; - std::atomic_uint64_t task_duration_total_ns{0}; +struct Frame_Business_Task_Counters { + std::atomic_uint32_t business_task_count{0}; + std::atomic_uint32_t active_business_task_count{0}; + std::atomic_uint32_t business_task_peak_parallelism{0}; + std::atomic_uint64_t business_task_duration_total_ns{0}; }; struct Taskflow_Graph_Impl { Taskflow_Graph_Impl( tf::Taskflow& taskflow, std::shared_ptr metrics, - std::shared_ptr frame_counters) + std::shared_ptr frame_counters) : taskflow(taskflow), metrics(std::move(metrics)), frame_counters(std::move(frame_counters)) {} tf::Taskflow& taskflow; std::shared_ptr metrics; - std::shared_ptr frame_counters; + std::shared_ptr frame_counters; std::vector tasks; }; @@ -36,13 +36,13 @@ struct Taskflow_Subflow_Impl { Taskflow_Subflow_Impl( tf::Subflow& subflow, std::shared_ptr metrics, - std::shared_ptr frame_counters) + std::shared_ptr frame_counters) : subflow(subflow), metrics(std::move(metrics)), frame_counters(std::move(frame_counters)) {} tf::Subflow& subflow; std::shared_ptr metrics; - std::shared_ptr frame_counters; + std::shared_ptr frame_counters; std::vector tasks; }; @@ -51,16 +51,18 @@ struct Render_Executor_Metrics { std::atomic active_workers{0}; std::atomic active_frame_jobs{0}; std::atomic queued_frame_jobs{0}; - std::atomic submitted_tasks{0}; - std::atomic started_tasks{0}; - std::atomic completed_tasks{0}; + std::atomic submitted_topologies{0}; + std::atomic started_topologies{0}; + std::atomic completed_topologies{0}; + std::atomic started_task_nodes{0}; + std::atomic completed_task_nodes{0}; std::atomic rejected_frame_jobs{0}; std::atomic dropped_frame_attempts{0}; std::atomic peak_concurrency{0}; - std::atomic queue_wait_total_ns{0}; - std::atomic queue_wait_max_ns{0}; - std::atomic task_duration_total_ns{0}; - std::atomic task_duration_max_ns{0}; + std::atomic topology_queue_wait_total_ns{0}; + std::atomic topology_queue_wait_max_ns{0}; + std::atomic task_node_duration_total_ns{0}; + std::atomic task_node_duration_max_ns{0}; std::atomic curve_tasks{0}; std::atomic waterfall_tasks{0}; std::atomic primitive_tasks{0}; @@ -94,30 +96,30 @@ void add_kind_count(Render_Executor_Metrics& metrics, Render_Task_Kind kind) { } } -void begin_business_task(Render_Executor_Metrics* metrics, Frame_Task_Counters* counters, Render_Task_Kind kind) { +void begin_business_task(Render_Executor_Metrics* metrics, Frame_Business_Task_Counters* counters, Render_Task_Kind kind) { if (metrics) add_kind_count(*metrics, kind); if (!counters) return; - counters->task_count.fetch_add(1, std::memory_order_relaxed); - std::uint32_t active = counters->active_count.fetch_add(1, std::memory_order_acq_rel) + 1; - std::uint32_t peak = counters->peak_parallelism.load(std::memory_order_acquire); - while (peak < active && !counters->peak_parallelism.compare_exchange_weak(peak, active, std::memory_order_acq_rel, std::memory_order_acquire)) {} + counters->business_task_count.fetch_add(1, std::memory_order_relaxed); + std::uint32_t active = counters->active_business_task_count.fetch_add(1, std::memory_order_acq_rel) + 1; + std::uint32_t peak = counters->business_task_peak_parallelism.load(std::memory_order_acquire); + while (peak < active && !counters->business_task_peak_parallelism.compare_exchange_weak(peak, active, std::memory_order_acq_rel, std::memory_order_acquire)) {} } -void end_business_task(Frame_Task_Counters* counters, std::uint64_t begin_ns) { +void end_business_task(Frame_Business_Task_Counters* counters, std::uint64_t begin_ns) { if (!counters) return; std::uint64_t end_ns = steady_now_ns(); - counters->task_duration_total_ns.fetch_add(end_ns > begin_ns ? end_ns - begin_ns : 0, std::memory_order_relaxed); - counters->active_count.fetch_sub(1, std::memory_order_acq_rel); + counters->business_task_duration_total_ns.fetch_add(end_ns > begin_ns ? end_ns - begin_ns : 0, std::memory_order_relaxed); + counters->active_business_task_count.fetch_sub(1, std::memory_order_acq_rel); } Task wrap_business_task( Render_Task_Kind kind, Task work, std::shared_ptr metrics, - std::shared_ptr counters) { + std::shared_ptr counters) { return Task([kind, work = std::move(work), metrics = std::move(metrics), counters = std::move(counters)]() mutable { std::uint64_t begin_ns = steady_now_ns(); begin_business_task(metrics.get(), counters.get(), kind); @@ -221,7 +223,7 @@ public: if (worker_id < worker_entry_ns.size()) worker_entry_ns[worker_id] = steady_now_ns(); std::size_t active = metrics->active_workers.fetch_add(1, std::memory_order_acq_rel) + 1; - metrics->started_tasks.fetch_add(1, std::memory_order_relaxed); + metrics->started_task_nodes.fetch_add(1, std::memory_order_relaxed); update_peak(metrics->peak_concurrency, static_cast(active)); } @@ -233,10 +235,10 @@ public: std::uint64_t begin_ns = worker_entry_ns[worker_id]; std::uint64_t end_ns = steady_now_ns(); std::uint64_t duration_ns = end_ns > begin_ns ? end_ns - begin_ns : 0; - metrics->task_duration_total_ns.fetch_add(duration_ns, std::memory_order_relaxed); - update_peak(metrics->task_duration_max_ns, duration_ns); + metrics->task_node_duration_total_ns.fetch_add(duration_ns, std::memory_order_relaxed); + update_peak(metrics->task_node_duration_max_ns, duration_ns); } - metrics->completed_tasks.fetch_add(1, std::memory_order_relaxed); + metrics->completed_task_nodes.fetch_add(1, std::memory_order_relaxed); metrics->active_workers.fetch_sub(1, std::memory_order_acq_rel); } @@ -246,7 +248,7 @@ private: }; class Render_Executor_Private { - struct Task_Run_Record { + struct Topology_Run_Record { std::uint64_t begin_ns{}; std::uint64_t queue_wait_ns{}; }; @@ -282,11 +284,13 @@ public: } Render_Executor_Snapshot snapshot() const { - std::uint64_t submitted = metrics->submitted_tasks.load(std::memory_order_acquire); - std::uint64_t completed = metrics->completed_tasks.load(std::memory_order_acquire); - std::uint64_t started = metrics->started_tasks.load(std::memory_order_acquire); - std::uint64_t queue_total = metrics->queue_wait_total_ns.load(std::memory_order_acquire); - std::uint64_t duration_total = metrics->task_duration_total_ns.load(std::memory_order_acquire); + std::uint64_t submitted_topologies = metrics->submitted_topologies.load(std::memory_order_acquire); + std::uint64_t started_topologies = metrics->started_topologies.load(std::memory_order_acquire); + std::uint64_t completed_topologies = metrics->completed_topologies.load(std::memory_order_acquire); + std::uint64_t completed_task_nodes = metrics->completed_task_nodes.load(std::memory_order_acquire); + std::uint64_t started_task_nodes = metrics->started_task_nodes.load(std::memory_order_acquire); + std::uint64_t queue_total = metrics->topology_queue_wait_total_ns.load(std::memory_order_acquire); + std::uint64_t duration_total = metrics->task_node_duration_total_ns.load(std::memory_order_acquire); std::size_t active = metrics->active_workers.load(std::memory_order_acquire); std::size_t workers = metrics->worker_count; return { @@ -295,16 +299,18 @@ public: workers > active ? workers - active : 0, metrics->active_frame_jobs.load(std::memory_order_acquire), metrics->queued_frame_jobs.load(std::memory_order_acquire), - submitted, - started, - completed, + submitted_topologies, + started_topologies, + completed_topologies, + started_task_nodes, + completed_task_nodes, metrics->rejected_frame_jobs.load(std::memory_order_acquire), metrics->dropped_frame_attempts.load(std::memory_order_acquire), metrics->peak_concurrency.load(std::memory_order_acquire), - submitted ? queue_total / submitted : 0, - metrics->queue_wait_max_ns.load(std::memory_order_acquire), - completed ? duration_total / completed : 0, - metrics->task_duration_max_ns.load(std::memory_order_acquire), + started_topologies ? queue_total / started_topologies : 0, + metrics->topology_queue_wait_max_ns.load(std::memory_order_acquire), + completed_task_nodes ? duration_total / completed_task_nodes : 0, + metrics->task_node_duration_max_ns.load(std::memory_order_acquire), metrics->curve_tasks.load(std::memory_order_acquire), metrics->waterfall_tasks.load(std::memory_order_acquire), metrics->primitive_tasks.load(std::memory_order_acquire), @@ -319,7 +325,7 @@ public: private: void record_submission(Render_Executor_Task& task) { - metrics->submitted_tasks.fetch_add(1, std::memory_order_relaxed); + metrics->submitted_topologies.fetch_add(1, std::memory_order_relaxed); if (task.frame_job) metrics->queued_frame_jobs.fetch_add(1, std::memory_order_relaxed); if (task.frame_stat) @@ -329,8 +335,8 @@ private: void submit_to_executor(Render_Executor_Task task, std::uint64_t enqueue_ns) { auto task_ptr = std::make_shared(std::move(task)); auto completion = std::make_shared(std::move(task_ptr->completion)); - auto run_record = std::make_shared(); - auto frame_counters = std::make_shared(); + auto run_record = std::make_shared(); + auto frame_counters = std::make_shared(); auto topology = std::make_shared(); auto entry = topology->emplace([this, enqueue_ns, task_ptr, run_record]() mutable { Render_Executor_Task& task = *task_ptr; @@ -338,8 +344,9 @@ private: run_record->begin_ns = begin_ns; std::uint64_t queue_wait_ns = begin_ns > enqueue_ns ? begin_ns - enqueue_ns : 0; run_record->queue_wait_ns = queue_wait_ns; - metrics->queue_wait_total_ns.fetch_add(queue_wait_ns, std::memory_order_relaxed); - update_peak(metrics->queue_wait_max_ns, queue_wait_ns); + metrics->started_topologies.fetch_add(1, std::memory_order_relaxed); + metrics->topology_queue_wait_total_ns.fetch_add(queue_wait_ns, std::memory_order_relaxed); + update_peak(metrics->topology_queue_wait_max_ns, queue_wait_ns); if (task.frame_job) { metrics->queued_frame_jobs.fetch_sub(1, std::memory_order_relaxed); metrics->active_frame_jobs.fetch_add(1, std::memory_order_relaxed); @@ -353,19 +360,19 @@ private: std::uint64_t run_ns = end_ns > begin_ns ? end_ns - begin_ns : 0; if (task.frame_stat) { Frame_Worker_Stats& stat = *task.frame_stat; - std::uint32_t task_count = frame_counters ? frame_counters->task_count.load(std::memory_order_acquire) : 0; - std::uint32_t peak_parallelism = frame_counters ? frame_counters->peak_parallelism.load(std::memory_order_acquire) : 0; - std::uint64_t task_duration_total_ns = frame_counters ? frame_counters->task_duration_total_ns.load(std::memory_order_acquire) : 0; - stat.task_count += task_count; - stat.peak_parallelism = std::max(stat.peak_parallelism, peak_parallelism); - stat.queue_wait_total_ns += queue_wait_ns; - stat.queue_wait_max_ns = std::max(stat.queue_wait_max_ns, queue_wait_ns); - stat.worker_run_total_ns += task_duration_total_ns; - stat.parallel_stage_wall_ns += run_ns; - stat.executor_at_finish = snapshot(); + std::uint32_t business_task_count = frame_counters ? frame_counters->business_task_count.load(std::memory_order_acquire) : 0; + std::uint32_t business_task_peak_parallelism = frame_counters ? frame_counters->business_task_peak_parallelism.load(std::memory_order_acquire) : 0; + std::uint64_t business_task_duration_total_ns = frame_counters ? frame_counters->business_task_duration_total_ns.load(std::memory_order_acquire) : 0; + stat.business_task_count += business_task_count; + stat.business_task_peak_parallelism = std::max(stat.business_task_peak_parallelism, business_task_peak_parallelism); + stat.topology_queue_wait_total_ns += queue_wait_ns; + stat.topology_queue_wait_max_ns = std::max(stat.topology_queue_wait_max_ns, queue_wait_ns); + stat.business_task_run_total_ns += business_task_duration_total_ns; + stat.topology_run_total_ns += run_ns; } if (task.frame_job) metrics->active_frame_jobs.fetch_sub(1, std::memory_order_relaxed); + metrics->completed_topologies.fetch_add(1, std::memory_order_relaxed); }); if (task_ptr->build_graph) { Taskflow_Graph_Impl graph_impl(*topology, metrics, frame_counters); @@ -384,7 +391,8 @@ private: work.precede(exit); } executor.run(*topology, [this, topology, completion, task_ptr]() mutable { - (void)this; + if (task_ptr->frame_stat) + task_ptr->frame_stat->executor_at_finish = snapshot(); if (completion && *completion) (*completion)(); }); @@ -396,7 +404,7 @@ private: else metrics->dropped_frame_attempts.fetch_add(1, std::memory_order_relaxed); if (task.frame_stat) - task.frame_stat->rejected_task_count++; + task.frame_stat->rejected_topology_count++; } std::shared_ptr metrics; diff --git a/Core/flow/low_latency/Low_Latency_Feedback_Controller.cpp b/Core/flow/low_latency/Low_Latency_Feedback_Controller.cpp index f6a9fc3..0e765fb 100644 --- a/Core/flow/low_latency/Low_Latency_Feedback_Controller.cpp +++ b/Core/flow/low_latency/Low_Latency_Feedback_Controller.cpp @@ -161,22 +161,24 @@ void Low_Latency_Feedback_Controller::on_input_changed(std::uint64_t now_ns, std void Low_Latency_Feedback_Controller::on_render_started(Frame_Lifecycle_Record& frame, std::uint64_t now_ns) { exit_producer_starvation(now_ns, "render_started"); - if (last_render_admission_ns && now_ns > last_render_admission_ns) - producer_interval.update(static_cast(now_ns - last_render_admission_ns) / 1000000.0); - last_render_admission_ns = now_ns; + if (last_render_start_ns && now_ns > last_render_start_ns) + producer_interval.update(static_cast(now_ns - last_render_start_ns) / 1000000.0); + last_render_start_ns = now_ns; last_render_begin_ns = now_ns; - frame.render_begin_ns = now_ns; - frame.render_queue_wait_ns = now_ns > frame.render_role_enter_ns ? now_ns - frame.render_role_enter_ns : 0; + if (!frame.render_begin_ns) + frame.render_begin_ns = now_ns; refresh_control_snapshot(now_ns); write_state(frame); } void Low_Latency_Feedback_Controller::on_render_completed(Frame_Lifecycle_Record& frame) { + if (frame.render_begin_ns && frame.render_begin_ns != last_render_start_ns) + on_render_started(frame, frame.render_begin_ns); exit_producer_starvation(frame.render_end_ns, "render_completed"); std::uint64_t render_duration_ns = frame.render_end_ns > frame.render_begin_ns ? frame.render_end_ns - frame.render_begin_ns : 0; last_render_begin_ns = frame.render_begin_ns; render_service_period.update(static_cast(render_duration_ns) / 1000000.0); - executor_queue_period.update_wait(static_cast(frame.render_queue_wait_ns) / 1000000.0); + executor_queue_period.update_wait(static_cast(frame.executor_queue_wait_ns) / 1000000.0); if (consumer_epoch_active) ++consumer_epoch.rendered_frames; refresh_control_snapshot(frame.render_end_ns); @@ -306,21 +308,42 @@ void Low_Latency_Feedback_Controller::observe_runtime(std::uint64_t now_ns, bool refresh_control_snapshot(now_ns); } -void Low_Latency_Feedback_Controller::note_admission_deadline_wait(std::uint64_t wait_ns, std::uint64_t now_ns) { - admission_deadline_wait_ns = wait_ns; +void Low_Latency_Feedback_Controller::note_admission_wait(std::uint64_t remaining_ns, std::uint64_t now_ns) { + if (!admission_wait_begin_ns) + admission_wait_begin_ns = now_ns; + admission_wait_elapsed_ns = now_ns > admission_wait_begin_ns ? now_ns - admission_wait_begin_ns : 0; + admission_wait_remaining_ns = remaining_ns; last_decision = Low_Latency_Feedback_Decision::Hold_User_Period; - decision_reason = "admission_deadline_wait"; + decision_reason = "admission_wait"; decision_timestamp_ns = now_ns; refresh_control_snapshot(now_ns); } +void Low_Latency_Feedback_Controller::note_render_admitted(std::uint64_t now_ns) { + if (!admission_wait_begin_ns && !admission_wait_elapsed_ns && !admission_wait_remaining_ns) + return; + admission_wait_elapsed_ns = admission_wait_begin_ns && now_ns > admission_wait_begin_ns ? now_ns - admission_wait_begin_ns : 0; + admission_wait_remaining_ns = 0; + admission_wait_begin_ns = 0; + refresh_control_snapshot(now_ns); +} + +void Low_Latency_Feedback_Controller::cancel_admission_wait(std::uint64_t now_ns) { + if (!admission_wait_begin_ns && !admission_wait_elapsed_ns && !admission_wait_remaining_ns) + return; + admission_wait_begin_ns = 0; + admission_wait_elapsed_ns = 0; + admission_wait_remaining_ns = 0; + refresh_control_snapshot(now_ns); +} + void Low_Latency_Feedback_Controller::note_update_posted(std::uint64_t now_ns) { ++performance_counters.update_posted_count; refresh_control_snapshot(now_ns); } -void Low_Latency_Feedback_Controller::note_update_coalesced(std::uint64_t now_ns) { - ++performance_counters.update_coalesced_count; +void Low_Latency_Feedback_Controller::note_duplicate_present_request_suppressed(std::uint64_t now_ns) { + ++performance_counters.duplicate_present_request_suppressed_count; refresh_control_snapshot(now_ns); } @@ -714,7 +737,8 @@ void Low_Latency_Feedback_Controller::refresh_control_snapshot(std::uint64_t now state_value.target_period_ns = target_period; state_value.effective_min_render_interval_ns = effective_interval; state_value.next_render_time_ns = resolved_next_render_time; - state_value.admission_deadline_wait_ns = admission_deadline_wait_ns; + state_value.admission_wait_elapsed_ns = admission_wait_elapsed_ns; + state_value.admission_wait_remaining_ns = admission_wait_remaining_ns; state_value.executor_queue_wait_ns = executor_queue_period.srtt_ns(); state_value.present_wait_ns = raw_display_interval.srtt_ns(); state_value.consumer_sample_accepted_count = consumer_sample_accepted_count; @@ -737,7 +761,7 @@ void Low_Latency_Feedback_Controller::refresh_control_snapshot(std::uint64_t now state_value.mode_enter_count = mode_enter_count; state_value.mode_exit_count = mode_exit_count; state_value.update_posted_count = performance_counters.update_posted_count; - state_value.update_coalesced_count = performance_counters.update_coalesced_count; + state_value.duplicate_present_request_suppressed_count = performance_counters.duplicate_present_request_suppressed_count; state_value.update_ack_count = performance_counters.update_ack_count; state_value.update_repost_count = performance_counters.update_repost_count; state_value.paint_without_posted_update_count = performance_counters.paint_without_posted_update_count; diff --git a/Core/flow/low_latency/Low_Latency_Feedback_Controller.h b/Core/flow/low_latency/Low_Latency_Feedback_Controller.h index 1f5c11f..517e818 100644 --- a/Core/flow/low_latency/Low_Latency_Feedback_Controller.h +++ b/Core/flow/low_latency/Low_Latency_Feedback_Controller.h @@ -39,9 +39,11 @@ public: void on_frame_underrun(); void on_frame_dropped(Frame_Lifecycle_Record& frame, Frame_Outcome outcome); void observe_runtime(std::uint64_t now_ns, bool backlog_pressure, bool dirty, bool render_active); - void note_admission_deadline_wait(std::uint64_t wait_ns, std::uint64_t now_ns); + void note_admission_wait(std::uint64_t remaining_ns, std::uint64_t now_ns); + void note_render_admitted(std::uint64_t now_ns); + void cancel_admission_wait(std::uint64_t now_ns); void note_update_posted(std::uint64_t now_ns); - void note_update_coalesced(std::uint64_t now_ns); + void note_duplicate_present_request_suppressed(std::uint64_t now_ns); void note_update_ack(std::uint64_t now_ns); void note_update_repost(std::uint64_t now_ns); void note_paint_without_posted_update(std::uint64_t now_ns); @@ -93,7 +95,7 @@ private: std::uint64_t latest_input_version{}; std::uint64_t last_input_change_ns{}; std::uint64_t last_render_begin_ns{}; - std::uint64_t last_render_admission_ns{}; + std::uint64_t last_render_start_ns{}; std::uint64_t last_consume_sample_ns{}; std::uint64_t last_consumed_frame_id{}; std::uint64_t latest_event_ns{}; @@ -130,7 +132,9 @@ private: std::string decision_reason = "initial"; std::uint64_t decision_timestamp_ns{}; std::uint64_t effective_interval_current_ns{}; - std::uint64_t admission_deadline_wait_ns{}; + std::uint64_t admission_wait_begin_ns{}; + std::uint64_t admission_wait_elapsed_ns{}; + std::uint64_t admission_wait_remaining_ns{}; Low_Latency_Performance_Diagnostics performance_counters; std::uint64_t presented_frame_count{}; std::uint64_t superseded_frame_count{}; diff --git a/Core/flow/low_latency/Low_Latency_Frame_Flow.cpp b/Core/flow/low_latency/Low_Latency_Frame_Flow.cpp index 683862b..27723dd 100644 --- a/Core/flow/low_latency/Low_Latency_Frame_Flow.cpp +++ b/Core/flow/low_latency/Low_Latency_Frame_Flow.cpp @@ -45,8 +45,8 @@ void record_pipeline_publish_result(Low_Latency_Feedback_Controller& feedback, c feedback.note_middle_superseded(now_ns); if (result.update_posted) feedback.note_update_posted(now_ns); - if (result.update_coalesced) - feedback.note_update_coalesced(now_ns); + if (result.duplicate_present_request_suppressed) + feedback.note_duplicate_present_request_suppressed(now_ns); } } // namespace @@ -113,8 +113,8 @@ struct Low_Latency_Frame_Flow::Private { record_feedback_event("MiddleSuperseded", now_ns, result.superseded_frame_record.get(), nullptr, nullptr, true); if (result.update_posted) record_feedback_event("UpdatePosted", now_ns); - if (result.update_coalesced) - record_feedback_event("UpdateCoalesced", now_ns); + if (result.duplicate_present_request_suppressed) + record_feedback_event("DuplicatePresentRequestSuppressed", now_ns); } void evaluate(std::uint64_t now_ns) { @@ -123,6 +123,7 @@ struct Low_Latency_Frame_Flow::Private { feedback.set_max_render_fps(max_render_fps.load(std::memory_order_acquire)); Frame_Flow_Runtime_Snapshot runtime = host->runtime_snapshot(now_ns); if (!active.load(std::memory_order_acquire) || runtime.destroying) { + feedback.cancel_admission_wait(runtime.now_ns); host->cancel_render_deadline(); return; } @@ -130,32 +131,37 @@ struct Low_Latency_Frame_Flow::Private { Refresh_Control_Snapshot before_observe = feedback.state(); feedback.observe_runtime(runtime.now_ns, runtime.middle_has_new_frame || update_posted || runtime.paint_active, runtime.dirty, runtime.render_job_active); record_state_transition_events(before_observe, runtime.now_ns, nullptr, &runtime); - if (runtime.middle_has_new_frame && !runtime.paint_active) { - if (!update_posted) { - Refresh_Control_Snapshot before_repost = feedback.state(); - feedback.note_update_repost(runtime.now_ns); - record_feedback_event("UpdateRepost", runtime.now_ns, nullptr, &runtime, &before_repost); - record_state_transition_events(before_repost, runtime.now_ns, nullptr, &runtime); - } + if (runtime.middle_has_new_frame && !runtime.paint_active && !update_posted) { + Refresh_Control_Snapshot before_repost = feedback.state(); + feedback.note_update_repost(runtime.now_ns); + record_feedback_event("UpdateRepost", runtime.now_ns, nullptr, &runtime, &before_repost); + record_state_transition_events(before_repost, runtime.now_ns, nullptr, &runtime); host->request_paint_from_middle(); } if (!runtime.dirty || runtime.render_job_active) { - if (!runtime.dirty) + if (!runtime.dirty) { + feedback.cancel_admission_wait(runtime.now_ns); host->cancel_render_deadline(); + } return; } std::uint64_t next_ns = feedback.next_render_time_ns(); if (next_ns && !feedback.rate_limit_ready(runtime.now_ns)) { Refresh_Control_Snapshot before_wait = feedback.state(); - feedback.note_admission_deadline_wait(next_ns > runtime.now_ns ? next_ns - runtime.now_ns : 0, runtime.now_ns); + feedback.note_admission_wait(next_ns > runtime.now_ns ? next_ns - runtime.now_ns : 0, runtime.now_ns); record_feedback_event("AdmissionDeadlineWait", runtime.now_ns, nullptr, &runtime, &before_wait); record_state_transition_events(before_wait, runtime.now_ns, nullptr, &runtime); host->schedule_render_deadline(next_ns); return; } - record_feedback_event("RenderAdmitted", runtime.now_ns, nullptr, &runtime); - if (host->try_render_once()) - record_feedback_event("RenderStarted", runtime.now_ns, nullptr, &runtime); + Refresh_Control_Snapshot before_admit = feedback.state(); + if (!host->try_render_once()) { + feedback.cancel_admission_wait(runtime.now_ns); + return; + } + feedback.note_render_admitted(runtime.now_ns); + record_feedback_event("RenderAdmitted", runtime.now_ns, nullptr, &runtime, &before_admit); + record_state_transition_events(before_admit, runtime.now_ns, nullptr, &runtime); } }; @@ -352,10 +358,16 @@ void Low_Latency_Frame_Flow::notify_viewport_changed(Size, std::uint64_t now_ns) } void Low_Latency_Frame_Flow::notify_render_finished(Frame_Lifecycle_Record& frame, std::uint64_t now_ns) { - Refresh_Control_Snapshot before = d->feedback.state(); + if (frame.render_begin_ns) { + Refresh_Control_Snapshot before_start = d->feedback.state(); + d->feedback.on_render_started(frame, frame.render_begin_ns); + d->record_feedback_event("RenderStarted", frame.render_begin_ns, &frame, nullptr, &before_start); + d->record_state_transition_events(before_start, frame.render_begin_ns, &frame); + } + Refresh_Control_Snapshot before_complete = d->feedback.state(); d->feedback.on_render_completed(frame); - d->record_feedback_event("RenderCompleted", now_ns, &frame, nullptr, &before); - d->record_state_transition_events(before, now_ns, &frame); + d->record_feedback_event("RenderCompleted", now_ns, &frame, nullptr, &before_complete); + d->record_state_transition_events(before_complete, now_ns, &frame); d->evaluate(now_ns); } diff --git a/Core/flow/low_latency/Low_Latency_Frame_Pipeline.cpp b/Core/flow/low_latency/Low_Latency_Frame_Pipeline.cpp index 3c15978..e7aa439 100644 --- a/Core/flow/low_latency/Low_Latency_Frame_Pipeline.cpp +++ b/Core/flow/low_latency/Low_Latency_Frame_Pipeline.cpp @@ -158,7 +158,7 @@ Low_Latency_Frame_Pipeline::Frame_Publish_Result Low_Latency_Frame_Pipeline::req return result; if (paint_request_pending.load(std::memory_order_acquire)) { - result.update_coalesced = true; + result.duplicate_present_request_suppressed = true; return result; } result.update_request_id = ++next_present_request_id; diff --git a/Core/flow/low_latency/Low_Latency_Frame_Pipeline.h b/Core/flow/low_latency/Low_Latency_Frame_Pipeline.h index 3e264f2..dce77ca 100644 --- a/Core/flow/low_latency/Low_Latency_Frame_Pipeline.h +++ b/Core/flow/low_latency/Low_Latency_Frame_Pipeline.h @@ -49,7 +49,7 @@ public: bool request_present{}; bool middle_published{}; bool update_posted{}; - bool update_coalesced{}; + bool duplicate_present_request_suppressed{}; }; struct Frame_Consume_Result { Low_Latency_Frame_Lease lease; diff --git a/Core/performance/Performance_Log_Service.cpp b/Core/performance/Performance_Log_Service.cpp index b7bcee1..8f1ede7 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 = 2; +constexpr int Log_Schema_Version = 3; std::uint64_t process_id() { #ifdef _WIN32 @@ -532,8 +532,11 @@ bool Performance_Log_Service::enqueue_frame(Performance_Log_Plot_Identity identi 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("admission_wait_elapsed_ns", r.admission_wait_elapsed_ns); + out.add("admission_wait_remaining_ns", r.admission_wait_remaining_ns); + out.add("render_slot_idle_wait_ns", frame->render_slot_idle_wait_ns); + out.add("executor_queue_wait_current_ns", frame->executor_queue_wait_ns); + out.add("executor_queue_wait_srtt_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); @@ -554,7 +557,7 @@ bool Performance_Log_Service::enqueue_frame(Performance_Log_Plot_Identity identi 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("duplicate_present_request_suppressed", r.duplicate_present_request_suppressed_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); @@ -568,17 +571,19 @@ bool Performance_Log_Service::enqueue_frame(Performance_Log_Plot_Identity identi 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("executor_queued_frame_jobs", e.queued_frame_jobs); + out.add("executor_active_frame_jobs", e.active_frame_jobs); + out.add("executor_submitted_topologies", e.submitted_topologies); + out.add("executor_started_topologies", e.started_topologies); + out.add("executor_completed_topologies", e.completed_topologies); + out.add("executor_started_task_nodes", e.started_task_nodes); + out.add("executor_completed_task_nodes", e.completed_task_nodes); + out.add("executor_rejected_frame_jobs", e.rejected_frame_jobs); + out.add("frame_business_task_count", frame->worker.business_task_count); + out.add("frame_business_task_peak_parallelism", frame->worker.business_task_peak_parallelism); + out.add("frame_topology_queue_wait_ns", frame->worker.topology_queue_wait_max_ns); + out.add("frame_business_task_run_total_ns", frame->worker.business_task_run_total_ns); + out.add("render_request_to_start_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)); diff --git a/Core/plot/Plot_Core.cpp b/Core/plot/Plot_Core.cpp index bca16e7..adae023 100644 --- a/Core/plot/Plot_Core.cpp +++ b/Core/plot/Plot_Core.cpp @@ -69,8 +69,7 @@ public: frame.pixel_height = static_cast(size.height); frame.viewport_version = context->viewport_version.load(std::memory_order_acquire); frame.dirty_reason_mask = pending_dirty_reason_mask.exchange(0, std::memory_order_acq_rel); - frame.render_queue_wait_ns = submit_time > frame.render_role_enter_ns ? submit_time - frame.render_role_enter_ns : 0; - frame.render_begin_ns = submit_time; + frame.render_slot_idle_wait_ns = submit_time > frame.render_role_enter_ns ? submit_time - frame.render_role_enter_ns : 0; auto job = std::make_shared(); job->owner = shared_from_this(); job->generation = generation.load(std::memory_order_acquire); @@ -138,7 +137,7 @@ public: if (submitted) return true; frame.outcome = Frame_Outcome::Worker_Budget_Dropped; - frame.worker.rejected_task_count++; + frame.worker.rejected_topology_count++; if (flow) flow->discard_render_frame(std::move(job->frame_surface)); release_frame_views(job); @@ -164,7 +163,9 @@ public: if (!frame_job_valid(job)) return; Frame_Lifecycle_Record& frame = *job->lifecycle; - frame.prepare_begin_ns = steady_now_ns(); + std::uint64_t begin_ns = steady_now_ns(); + frame.render_begin_ns = begin_ns; + frame.prepare_begin_ns = begin_ns; job->prepared_output_count.store(0, std::memory_order_release); } void dispatch_prepare_subflow(const std::shared_ptr& job, Render_Task_Subflow& subflow) { @@ -231,8 +232,10 @@ public: if (!job || !job->buffer || !job->lifecycle) return; Frame_Lifecycle_Record& frame = *job->lifecycle; - if (job->worker_stat) + if (job->worker_stat) { frame.worker = *job->worker_stat; + frame.executor_queue_wait_ns = frame.worker.topology_queue_wait_total_ns; + } bool valid_generation = job->generation == generation.load(std::memory_order_acquire); bool valid_context = !destroying(); bool render_complete = job->buffer->render_complete.load(std::memory_order_acquire); diff --git a/Core/plottable/Performance_Overlay.cpp b/Core/plottable/Performance_Overlay.cpp index 8a632c3..f647c2d 100644 --- a/Core/plottable/Performance_Overlay.cpp +++ b/Core/plottable/Performance_Overlay.cpp @@ -183,9 +183,11 @@ static void request_performance_update(const std::shared_ptr& state) { +void schedule_performance_metrics_worker(const std::shared_ptr& state, bool request_repaint) { if (!state || state->cancelled.load(std::memory_order_acquire)) return; + if (request_repaint) + state->repaint_requested.store(true, std::memory_order_release); state->work_requested.store(true, std::memory_order_release); if (state->worker_active.exchange(true, std::memory_order_acq_rel)) return; @@ -332,13 +334,14 @@ void Performance_Overlay::set_enabled(bool enabled) { d()->enabled_value.store(enabled, std::memory_order_release); worker->enabled.store(enabled, std::memory_order_release); if (!enabled) { + worker->repaint_requested.store(false, std::memory_order_release); worker->published_snapshot.store({}, std::memory_order_release); request_performance_update(worker); return; } worker->reset_requested.store(true, std::memory_order_release); worker->snapshot_rebuild_requested.store(true, std::memory_order_release); - schedule_performance_metrics_worker(worker); + schedule_performance_metrics_worker(worker, true); } bool Performance_Overlay::enabled() const { return const_cast(this)->d()->enabled_value.load(std::memory_order_acquire); @@ -356,7 +359,7 @@ void Performance_Overlay::set_options(Performance_Overlay_Options options) { } worker->snapshot_rebuild_requested.store(true, std::memory_order_release); if (enabled()) - schedule_performance_metrics_worker(worker); + schedule_performance_metrics_worker(worker, true); } Performance_Overlay_Options Performance_Overlay::options() const { auto worker = const_cast(this)->d()->metrics_worker; @@ -417,7 +420,7 @@ void Performance_Overlay::set_viewport(Size viewport, std::uint64_t version) { d()->metrics_worker->viewport_height.store(viewport.height, std::memory_order_release); d()->metrics_worker->viewport_version.store(version, std::memory_order_release); d()->metrics_worker->snapshot_rebuild_requested.store(true, std::memory_order_release); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); } bool Performance_Overlay::handle_wheel(PointF position, double angle_delta_y, double pixel_delta_y) { auto snapshot = display_snapshot(); @@ -431,7 +434,7 @@ bool Performance_Overlay::handle_wheel(PointF position, double angle_delta_y, do delta = -(angle_delta_y / 120.0) * 3.0 * std::max(1.0, line_height); if (delta != 0.0) { performance_atomic_add(d()->metrics_worker->pending_wheel_delta_px, delta); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); } return true; } @@ -451,13 +454,13 @@ bool Performance_Overlay::handle_pointer_press(PointF position) { d()->metrics_worker->drag_position_y.store(position.y, std::memory_order_release); d()->metrics_worker->drag_end_requested.store(false, std::memory_order_release); d()->metrics_worker->drag_active.store(true, std::memory_order_release); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); return true; } if (snapshot->scroll_track_rect.contains(position)) { int page = position.y < snapshot->scroll_thumb_rect.y ? -1 : 1; d()->metrics_worker->pending_page_delta.fetch_add(page, std::memory_order_acq_rel); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); return true; } return false; @@ -465,7 +468,7 @@ bool Performance_Overlay::handle_pointer_press(PointF position) { bool Performance_Overlay::handle_pointer_move(PointF position) { if (d()->metrics_worker->drag_active.load(std::memory_order_acquire)) { d()->metrics_worker->drag_position_y.store(position.y, std::memory_order_release); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); return true; } auto snapshot = display_snapshot(); @@ -493,7 +496,7 @@ bool Performance_Overlay::handle_pointer_release(PointF position) { return false; d()->metrics_worker->drag_position_y.store(position.y, std::memory_order_release); d()->metrics_worker->drag_end_requested.store(true, std::memory_order_release); - schedule_performance_metrics_worker(d()->metrics_worker); + schedule_performance_metrics_worker(d()->metrics_worker, true); return true; } bool Performance_Overlay::handle_pointer_leave() { diff --git a/Core/plottable/Performance_Overlay_p.h b/Core/plottable/Performance_Overlay_p.h index 5122662..40f216d 100644 --- a/Core/plottable/Performance_Overlay_p.h +++ b/Core/plottable/Performance_Overlay_p.h @@ -74,8 +74,9 @@ struct Renderable_Aggregate_Stat { struct Performance_Aggregate { Psc::Value_Statistics request_wait_ms; Psc::Value_Statistics producer_interval_ms; - Psc::Value_Statistics admission_deadline_wait_ms; - Psc::Value_Statistics render_queue_wait_ms; + Psc::Value_Statistics admission_wait_ms; + Psc::Value_Statistics render_slot_idle_wait_ms; + Psc::Value_Statistics executor_queue_wait_ms; Psc::Value_Statistics prepare_ms; Psc::Value_Statistics draw_ms; Psc::Value_Statistics render_ms; @@ -130,7 +131,8 @@ struct Performance_Aggregate { summary.paint_end_ns = frame.paint_end_ns; summary.presented_frame_id = frame.presented_frame_id; summary.transition_32_ns = frame.transition_32_ns; - summary.render_queue_wait_ns = frame.render_queue_wait_ns; + summary.render_slot_idle_wait_ns = frame.render_slot_idle_wait_ns; + summary.executor_queue_wait_ns = frame.executor_queue_wait_ns; summary.ready_queue_wait_ns = frame.ready_queue_wait_ns; summary.present_queue_wait_ns = frame.present_queue_wait_ns; summary.paint_return_wait_ns = frame.paint_return_wait_ns; @@ -161,9 +163,9 @@ struct Performance_Aggregate { update_duration(request_wait_ms, frame.render_request_ns, frame.render_begin_ns); if (frame.refresh.producer_interval_ns) producer_interval_ms.update(ns_to_ms(frame.refresh.producer_interval_ns)); - if (frame.refresh.admission_deadline_wait_ns) - admission_deadline_wait_ms.update(ns_to_ms(frame.refresh.admission_deadline_wait_ns)); - update_duration(render_queue_wait_ms, frame.render_role_enter_ns, frame.render_begin_ns); + admission_wait_ms.update(ns_to_ms(frame.refresh.admission_wait_elapsed_ns)); + render_slot_idle_wait_ms.update(ns_to_ms(frame.render_slot_idle_wait_ns)); + executor_queue_wait_ms.update(ns_to_ms(frame.executor_queue_wait_ns)); update_duration(prepare_ms, frame.prepare_begin_ns, frame.prepare_end_ns); update_duration(draw_ms, frame.draw_begin_ns, frame.draw_end_ns); update_duration(render_ms, frame.render_begin_ns, frame.render_end_ns); @@ -299,7 +301,8 @@ enum class Performance_Metric_Id : std::uint16_t { Paint_Period, User_Period, Target_Period, - Render_Queue_Wait, + Render_Slot_Idle_Wait, + Executor_Queue_Wait, Ready_Queue_Wait, Present_Queue_Wait, Paint_Return_Wait, @@ -307,18 +310,20 @@ enum class Performance_Metric_Id : std::uint16_t { Active_Workers, Queued_Frame_Jobs, Active_Frame_Jobs, - Submitted_Jobs, + Submitted_Topologies, + Started_Topologies, + Completed_Topologies, Started_Task_Nodes, Completed_Task_Nodes, Rejected_Frame_Jobs, - Queue_Wait_Avg, - Queue_Wait_Max, - Task_Run_Avg, - Task_Run_Max, - Frame_Task_Count, - Frame_Peak_Parallelism, - Frame_Wait_Max, - Frame_Run_Total, + Topology_Queue_Wait_Avg, + Topology_Queue_Wait_Max, + Task_Node_Run_Avg, + Task_Node_Run_Max, + Frame_Business_Task_Count, + Frame_Business_Task_Peak_Parallelism, + Frame_Topology_Queue_Wait, + Frame_Business_Task_Run_Total, Outcome, Cache_Hit, Cache_Miss, @@ -384,6 +389,7 @@ struct Performance_Worker_State { std::atomic_bool cancelled{false}; std::atomic_bool reset_requested{false}; std::atomic_bool snapshot_rebuild_requested{false}; + std::atomic_bool repaint_requested{false}; std::atomic copy_button_state{Button_State::Normal}; std::atomic close_button_state{Button_State::Normal}; std::atomic scroll_offset{0.0}; @@ -427,7 +433,7 @@ inline void performance_atomic_add(std::atomic& value, double delta) { double current = value.load(std::memory_order_acquire); while (!value.compare_exchange_weak(current, current + delta, std::memory_order_acq_rel, std::memory_order_acquire)) {} } -void schedule_performance_metrics_worker(const std::shared_ptr& state); +void schedule_performance_metrics_worker(const std::shared_ptr& state, bool request_repaint = false); struct Performance_Metric_Cell { std::string label; @@ -532,8 +538,10 @@ struct Performance_Layout_Builder { return Performance_Metric_Id::User_Period; if (key == "target_period") return Performance_Metric_Id::Target_Period; - if (key == "render_queue_wait") - return Performance_Metric_Id::Render_Queue_Wait; + if (key == "render_slot_idle_wait") + return Performance_Metric_Id::Render_Slot_Idle_Wait; + if (key == "executor_queue_wait") + return Performance_Metric_Id::Executor_Queue_Wait; if (key == "ready_queue_wait") return Performance_Metric_Id::Ready_Queue_Wait; if (key == "present_queue_wait") @@ -549,7 +557,11 @@ struct Performance_Layout_Builder { if (key == "taskflow_active_frames") return Performance_Metric_Id::Active_Frame_Jobs; if (key == "taskflow_submitted") - return Performance_Metric_Id::Submitted_Jobs; + return Performance_Metric_Id::Submitted_Topologies; + if (key == "taskflow_topologies_started") + return Performance_Metric_Id::Started_Topologies; + if (key == "taskflow_topologies_completed") + return Performance_Metric_Id::Completed_Topologies; if (key == "taskflow_started") return Performance_Metric_Id::Started_Task_Nodes; if (key == "taskflow_completed") @@ -557,21 +569,21 @@ struct Performance_Layout_Builder { if (key == "taskflow_rejected") return Performance_Metric_Id::Rejected_Frame_Jobs; if (key == "taskflow_queue_wait_avg") - return Performance_Metric_Id::Queue_Wait_Avg; - if (key == "taskflow_queue_wait_p95") - return Performance_Metric_Id::Queue_Wait_Max; + return Performance_Metric_Id::Topology_Queue_Wait_Avg; + if (key == "taskflow_queue_wait_max") + return Performance_Metric_Id::Topology_Queue_Wait_Max; if (key == "taskflow_run_avg") - return Performance_Metric_Id::Task_Run_Avg; - if (key == "taskflow_run_p95") - return Performance_Metric_Id::Task_Run_Max; + return Performance_Metric_Id::Task_Node_Run_Avg; + if (key == "taskflow_run_max") + return Performance_Metric_Id::Task_Node_Run_Max; if (key == "frame_worker_tasks") - return Performance_Metric_Id::Frame_Task_Count; + return Performance_Metric_Id::Frame_Business_Task_Count; if (key == "frame_worker_peak") - return Performance_Metric_Id::Frame_Peak_Parallelism; + return Performance_Metric_Id::Frame_Business_Task_Peak_Parallelism; if (key == "frame_worker_wait_max") - return Performance_Metric_Id::Frame_Wait_Max; + return Performance_Metric_Id::Frame_Topology_Queue_Wait; if (key == "frame_worker_run_total") - return Performance_Metric_Id::Frame_Run_Total; + return Performance_Metric_Id::Frame_Business_Task_Run_Total; if (key == "frame_outcome") return Performance_Metric_Id::Outcome; if (key == "cache_hit_count") @@ -955,19 +967,22 @@ struct Performance_Layout_Builder { lines.push_back("[low_latency] consumer_samples accepted:" + count_text("consumer_accepted", refresh.consumer_sample_accepted_count) + " rejected:" + count_text("consumer_rejected", refresh.consumer_sample_total_count - refresh.consumer_sample_accepted_count) + " ratio:" + number_text("consumer_ratio", refresh.consumer_sample_accepted_ratio * 100.0) + "% last:" + consumer_sample_result_text(refresh.last_consumer_sample_result)); lines.push_back("[low_latency] timing producer_interval:" + period_text("producer_interval", refresh.producer_interval_ns) + " render_service:" + period_text("render_period", refresh.render_period_ns) + " request_to_post:" + period_text("request_to_update_post", refresh.request_to_update_post_srtt_ns) + " post_to_paint:" + period_text("update_to_paint", refresh.update_post_to_paint_srtt_ns) + " paint_service:" + period_text("paint_period", refresh.paint_service_ns) + " raw_display:" + period_text("raw_display", refresh.raw_display_interval_srtt_ns) + " accepted_consumer:" + period_text("accepted_consumer", refresh.accepted_consumer_interval_srtt_ns)); lines.push_back("[low_latency] consumer_window size:" + count_text("consumer_window_size", refresh.consumer_window_size) + " accepted:" + count_text("consumer_window_accepted", refresh.consumer_window_accepted) + " rejected:" + count_text("consumer_window_rejected", refresh.consumer_window_size - refresh.consumer_window_accepted) + " ratio:" + number_text("consumer_window_ratio", refresh.consumer_window_accepted_ratio * 100.0) + "%"); - lines.push_back("[low_latency] queue admission_deadline_wait:" + ns_text("admission_deadline_wait", refresh.admission_deadline_wait_ns) + "ms executor_queue_wait:" + ns_text("executor_queue_wait", frame.render_queue_wait_ns) + "ms present_wait:" + ns_text("present_wait", frame.present_queue_wait_ns) + "ms paint_return:" + ns_text("paint_return_wait", frame.paint_return_wait_ns) + "ms"); - lines.push_back("[low_latency] update posted:" + count_text("update_posted_count", refresh.update_posted_count) + " coalesced:" + count_text("update_coalesced_count", refresh.update_coalesced_count) + " ack:" + count_text("update_ack_count", refresh.update_ack_count) + " repost:" + count_text("update_repost_count", refresh.update_repost_count) + " paint_without_posted:" + count_text("paint_without_posted", refresh.paint_without_posted_update_count)); + lines.push_back("[low_latency] pacing admission_wait:" + ns_text("admission_wait", refresh.admission_wait_elapsed_ns) + "ms render_slot_idle:" + ns_text("render_slot_idle_wait", frame.render_slot_idle_wait_ns) + "ms"); + lines.push_back("[pipeline] queue executor_wait:" + ns_text("executor_queue_wait", frame.executor_queue_wait_ns) + "ms present_wait:" + ns_text("present_wait", frame.present_queue_wait_ns) + "ms paint_return:" + ns_text("paint_return_wait", frame.paint_return_wait_ns) + "ms"); + lines.push_back("[low_latency] update posted:" + count_text("update_posted_count", refresh.update_posted_count) + " duplicate_suppressed:" + count_text("duplicate_present_request_suppressed_count", refresh.duplicate_present_request_suppressed_count) + " ack:" + count_text("update_ack_count", refresh.update_ack_count) + " repost:" + count_text("update_repost_count", refresh.update_repost_count) + " paint_without_posted:" + count_text("paint_without_posted", refresh.paint_without_posted_update_count)); lines.push_back("[logger] dropped:" + count_text("logger_dropped", performance_log_service().dropped_record_count())); lines.push_back("[low_latency] buffers rendered:" + count_text("presented_feedback", refresh.presented_frame_count) + " middle_published:" + count_text("middle_published", refresh.middle_published_count) + " middle_superseded:" + count_text("middle_superseded", refresh.middle_superseded_count) + " painting_advanced:" + count_text("painting_advanced", refresh.painting_advanced_count) + " painting_repeated:" + count_text("repeated_feedback", refresh.repeated_frame_count) + " underrun:" + count_text("underrun_feedback", refresh.underrun_count)); lines.push_back("[low_latency] decision:" + feedback_decision_text(refresh.last_decision) + " reason:" + refresh.decision_reason + " at:" + count_text("decision_time", refresh.decision_timestamp_ns) + " producer_starvation:" + count_text("producer_starvation", refresh.producer_starvation_count) + " starvation_active:" + (refresh.producer_starvation_active ? std::string("1") : std::string("0")) + " enter:" + count_text("mode_enter", refresh.mode_enter_count) + " exit:" + count_text("mode_exit", refresh.mode_exit_count) + " efficiency:" + number_text("display_efficiency", refresh.display_efficiency * 100.0) + "%"); - lines.push_back("[executor] taskflow workers:" + count_text("taskflow_workers", static_cast(executor.worker_count)) + " active:" + count_text("taskflow_active", static_cast(executor.active_workers)) + " queued_frames:" + count_text("taskflow_queued_frames", static_cast(executor.queued_frame_jobs)) + " active_frames:" + count_text("taskflow_active_frames", static_cast(executor.active_frame_jobs))); - lines.push_back("[executor] taskflow tasks submitted:" + count_text("taskflow_submitted", executor.submitted_jobs) + " started:" + count_text("taskflow_started", executor.started_task_nodes) + " completed:" + count_text("taskflow_completed", executor.completed_task_nodes) + " rejected_frames:" + count_text("taskflow_rejected", executor.rejected_frame_jobs)); - lines.push_back("[executor] taskflow wait avg:" + ns_text("taskflow_queue_wait_avg", executor.average_queue_wait_ns) + "ms p95:" + ns_text("taskflow_queue_wait_p95", executor.max_queue_wait_ns) + "ms run avg:" + ns_text("taskflow_run_avg", executor.average_task_duration_ns) + "ms p95:" + ns_text("taskflow_run_p95", executor.max_task_duration_ns) + "ms"); - lines.push_back("frame worker tasks:" + count_text("frame_worker_tasks", worker.task_count) + " peak_parallel:" + count_text("frame_worker_peak", worker.peak_parallelism) + " wait_max:" + ns_text("frame_worker_wait_max", worker.queue_wait_max_ns) + "ms run_total:" + ns_text("frame_worker_run_total", worker.worker_run_total_ns) + "ms"); - lines.push_back(duration_line("request_wait", "lifecycle request_wait", aggregate.request_wait_ms)); + lines.push_back("[executor/global] workers:" + count_text("taskflow_workers", static_cast(executor.worker_count)) + " active_workers:" + count_text("taskflow_active", static_cast(executor.active_workers)) + " queued_frame_jobs:" + count_text("taskflow_queued_frames", static_cast(executor.queued_frame_jobs)) + " active_frame_jobs:" + count_text("taskflow_active_frames", static_cast(executor.active_frame_jobs))); + lines.push_back("[executor/global] topologies submitted:" + count_text("taskflow_submitted", executor.submitted_topologies) + " started:" + count_text("taskflow_topologies_started", executor.started_topologies) + " completed:" + count_text("taskflow_topologies_completed", executor.completed_topologies) + " rejected_frame_jobs:" + count_text("taskflow_rejected", executor.rejected_frame_jobs)); + lines.push_back("[executor/global] task_nodes started:" + count_text("taskflow_started", executor.started_task_nodes) + " completed:" + count_text("taskflow_completed", executor.completed_task_nodes)); + lines.push_back("[executor/global] topology_queue_wait avg:" + ns_text("taskflow_queue_wait_avg", executor.average_topology_queue_wait_ns) + "ms max:" + ns_text("taskflow_queue_wait_max", executor.max_topology_queue_wait_ns) + "ms task_node_run avg:" + ns_text("taskflow_run_avg", executor.average_task_node_duration_ns) + "ms max:" + ns_text("taskflow_run_max", executor.max_task_node_duration_ns) + "ms"); + lines.push_back("[executor/frame] business_tasks:" + count_text("frame_worker_tasks", worker.business_task_count) + " peak_parallel:" + count_text("frame_worker_peak", worker.business_task_peak_parallelism) + " topology_queue_wait:" + ns_text("frame_worker_wait_max", worker.topology_queue_wait_max_ns) + "ms business_run_total:" + ns_text("frame_worker_run_total", worker.business_task_run_total_ns) + "ms"); + lines.push_back(duration_line("request_wait", "lifecycle render_request_to_start", aggregate.request_wait_ms)); lines.push_back(duration_line("producer_interval", "timing producer_interval", aggregate.producer_interval_ms)); - lines.push_back(duration_line("admission_deadline_wait", "timing admission_deadline_wait", aggregate.admission_deadline_wait_ms)); - lines.push_back(duration_line("render_queue_wait", "timing executor_queue_wait", aggregate.render_queue_wait_ms)); + lines.push_back(duration_line("admission_wait", "timing admission_wait", aggregate.admission_wait_ms)); + lines.push_back(duration_line("render_slot_idle_wait", "timing render_slot_idle_wait", aggregate.render_slot_idle_wait_ms)); + lines.push_back(duration_line("executor_queue_wait", "timing executor_queue_wait", aggregate.executor_queue_wait_ms)); lines.push_back(duration_line("prepare", "lifecycle prepare", aggregate.prepare_ms)); lines.push_back(duration_line("draw", "lifecycle draw", aggregate.draw_ms)); lines.push_back(duration_line("render", "lifecycle render_total", aggregate.render_ms)); @@ -1288,7 +1303,7 @@ struct Performance_Overlay_Private { metrics_worker->close_button_state.store(close_button_interaction.state(), std::memory_order_release); metrics_worker->snapshot_rebuild_requested.store(true, std::memory_order_release); if (enabled_value.load(std::memory_order_acquire)) - schedule_performance_metrics_worker(metrics_worker); + schedule_performance_metrics_worker(metrics_worker, true); } void reset_button_states() { @@ -1359,7 +1374,8 @@ struct Performance_Overlay_Private { } if (changed && state->enabled.load(std::memory_order_acquire)) { state->published_snapshot.store(build_display_snapshot(*state), std::memory_order_release); - invoke_update_callback(*state); + if (state->repaint_requested.exchange(false, std::memory_order_acq_rel)) + invoke_update_callback(*state); } if (state->work_requested.load(std::memory_order_acquire)) continue; diff --git a/Qt/plot/Plot.cpp b/Qt/plot/Plot.cpp index 10d8826..0a4c221 100644 --- a/Qt/plot/Plot.cpp +++ b/Qt/plot/Plot.cpp @@ -123,7 +123,7 @@ void Abs_Plot::paintEvent(QPaintEvent* event) { bool Abs_Plot::event(QEvent* event) { bool base_result = QWidget::event(event); - return d->event(this, event, base_result); + return d->event(event, base_result); } void Abs_Plot_Private::paint_event(Abs_Plot* plot, QPaintEvent* event) { @@ -155,19 +155,7 @@ void Abs_Plot_Private::paint_event(Abs_Plot* plot, QPaintEvent* event) { core->end_present(std::move(frame), paint_begin_time, steady_now_ns()); } -void Abs_Plot_Private::request_performance_overlay_update(Abs_Plot* plot) { - if (!plot || performance_update_pending->exchange(true, std::memory_order_acq_rel)) - return; - QPointer guarded_plot(plot); - auto pending = performance_update_pending; - QTimer::singleShot(0, plot, [guarded_plot, pending]() mutable { - pending->store(false, std::memory_order_release); - if (guarded_plot) - guarded_plot->update(); - }); -} - -bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { +bool Abs_Plot_Private::event(QEvent* event, bool base_result) { switch (event->type()) { case QEvent::Resize: { auto* resize_event = static_cast(event); @@ -190,8 +178,7 @@ bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { break; } case QEvent::Leave: { - if (performance_overlay_handle_pointer_leave(*core)) - request_performance_overlay_update(plot); + performance_overlay_handle_pointer_leave(*core); Event leave_event(Event_Type::Leave); core->dispatch_event(leave_event); break; @@ -200,7 +187,6 @@ bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { auto wheel_event = Qt_Event_Adapter::to_wheel_event(static_cast(event)); if (performance_overlay_handle_wheel(*core, wheel_event.position, wheel_event.angle_delta_y, wheel_event.pixel_delta_y)) { event->accept(); - request_performance_overlay_update(plot); return true; } core->dispatch_event(wheel_event); @@ -210,7 +196,6 @@ bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { auto pointer_event = Qt_Event_Adapter::to_pointer_event(static_cast(event), Event_Type::Pointer_Move); if (performance_overlay_handle_pointer_move(*core, pointer_event.position)) { event->accept(); - request_performance_overlay_update(plot); return true; } core->dispatch_event(pointer_event); @@ -221,7 +206,6 @@ bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { auto pointer_event = Qt_Event_Adapter::to_pointer_event(mouse_event, Event_Type::Pointer_Press); if (mouse_event->button() == Qt::LeftButton && performance_overlay_handle_pointer_press(*core, pointer_event.position)) { event->accept(); - request_performance_overlay_update(plot); return true; } core->dispatch_event(pointer_event); @@ -232,7 +216,6 @@ bool Abs_Plot_Private::event(Abs_Plot* plot, QEvent* event, bool base_result) { auto pointer_event = Qt_Event_Adapter::to_pointer_event(mouse_event, Event_Type::Pointer_Release); if (mouse_event->button() == Qt::LeftButton && performance_overlay_handle_pointer_release(*core, pointer_event.position)) { event->accept(); - request_performance_overlay_update(plot); return true; } core->dispatch_event(pointer_event); diff --git a/Qt/plot/Plot_p.h b/Qt/plot/Plot_p.h index bf30edb..02c23da 100644 --- a/Qt/plot/Plot_p.h +++ b/Qt/plot/Plot_p.h @@ -14,9 +14,8 @@ struct Abs_Plot_Private { virtual ~Abs_Plot_Private(); void attach_widget(Abs_Plot* plot); - bool event(Abs_Plot* plot, QEvent* event, bool base_result); + bool event(QEvent* event, bool base_result); void paint_event(Abs_Plot* plot, QPaintEvent* event); - void request_performance_overlay_update(Abs_Plot* plot); Frame_Flow* flow{}; std::unique_ptr core; diff --git a/test/Renderive_Core_Tests.cpp b/test/Renderive_Core_Tests.cpp index b117174..de138c5 100644 --- a/test/Renderive_Core_Tests.cpp +++ b/test/Renderive_Core_Tests.cpp @@ -31,6 +31,7 @@ #include #include #include +#include #include #include #include @@ -248,31 +249,33 @@ std::vector read_lines(const std::filesystem::path& path) { lines.push_back(line); return lines; } -std::vector split_csv_row(const std::string& line) { - std::vector cells; - std::string cell; - bool in_quote = false; - for (std::size_t i = 0; i < line.size(); ++i) { - char ch = line[i]; - if (ch == '"') { - if (in_quote && i + 1 < line.size() && line[i + 1] == '"') { - cell.push_back('"'); - ++i; - } - else { - in_quote = !in_quote; - } +using Parsed_Log_Record = std::map; +std::vector read_log_records(const std::filesystem::path& path, std::string_view kind) { + std::vector records; + Parsed_Log_Record current; + bool in_record = false; + std::string begin = "[" + std::string(kind) + "]"; + std::string end = "[/" + std::string(kind) + "]"; + for (const auto& line : read_lines(path)) { + if (line == begin) { + current.clear(); + in_record = true; continue; } - if (ch == ',' && !in_quote) { - cells.push_back(cell); - cell.clear(); + if (line == end) { + if (in_record) + records.push_back(std::move(current)); + current = {}; + in_record = false; continue; } - cell.push_back(ch); + if (!in_record) + continue; + std::size_t separator = line.find('='); + if (separator != std::string::npos) + current.emplace(line.substr(0, separator), line.substr(separator + 1)); } - cells.push_back(cell); - return cells; + return records; } Frame_Feedback_Event_Record feedback_event(std::string event, const Frame_Lifecycle_Record& frame, std::uint64_t timestamp_ns) { Frame_Feedback_Event_Record record; @@ -1471,7 +1474,7 @@ TEST(Renderive_Frame_Feedback, AdmissionDeadlineWaitIsNotProducerStarvation) { auto frame = feedback_frame(3, 100000000, 2000000, 1000000); controller.note_middle_published(frame.transition_12_ns); controller.on_render_completed(frame); - controller.note_admission_deadline_wait(20000000, frame.transition_12_ns + 1); + controller.note_admission_wait(20000000, frame.transition_12_ns + 1); controller.on_frame_presented(frame); EXPECT_EQ(controller.state().consumer_sample_accepted_count, accepted + 1); @@ -1596,6 +1599,26 @@ TEST(Renderive_Frame_Feedback, ProducerStarvationCountsStateTransitionOnce) { controller.observe_runtime(deadline + 500000000, false, true, false); EXPECT_EQ(controller.state().producer_starvation_count, 1u); } +TEST(Renderive_Frame_Feedback, ProducerIntervalUsesActualRenderStart) { + Low_Latency_Feedback_Controller controller; + auto first = feedback_frame(1, 100000000, 2000000, 1000000); + auto second = feedback_frame(2, 116666667, 2000000, 1000000); + controller.on_render_completed(first); + controller.on_render_completed(second); + EXPECT_NEAR(static_cast(controller.state().producer_interval_current_ns), 16666667.0, 1.0); +} +TEST(Renderive_Frame_Feedback, AdmissionWaitRecordsActualElapsedTimeAndClears) { + Low_Latency_Feedback_Controller controller; + controller.note_admission_wait(5000000, 100000000); + EXPECT_EQ(controller.state().admission_wait_remaining_ns, 5000000u); + controller.note_render_admitted(104000000); + EXPECT_EQ(controller.state().admission_wait_elapsed_ns, 4000000u); + EXPECT_EQ(controller.state().admission_wait_remaining_ns, 0u); + controller.note_admission_wait(5000000, 200000000); + controller.cancel_admission_wait(201000000); + EXPECT_EQ(controller.state().admission_wait_elapsed_ns, 0u); + EXPECT_EQ(controller.state().admission_wait_remaining_ns, 0u); +} TEST(Renderive_Frame_Flow, LatencyEagerRendersWhileMiddleIsPending) { Low_Latency_Frame_Flow flow; @@ -1609,19 +1632,33 @@ TEST(Renderive_Frame_Flow, LatencyEagerRendersWhileMiddleIsPending) { EXPECT_EQ(host.paint_requests, 1); EXPECT_EQ(host.render_attempts, 1); } +TEST(Renderive_Frame_Flow, PendingPresentRequestSuppressesDuplicateRequest) { + Low_Latency_Frame_Flow flow; + auto published = publish_low_latency_flow_frame(flow, 1, 20); + ASSERT_TRUE(published.request_present); + Flow_Test_Host host; + host.snapshot.middle_has_new_frame = true; + flow.attach(host); + flow.activate_view(30); + EXPECT_EQ(host.paint_requests, 0); +} TEST(Renderive_Frame_Flow, LowLatencyEmitsFeedbackEventsThroughHost) { Low_Latency_Frame_Flow flow; Flow_Test_Host host; host.snapshot.dirty = true; flow.attach(host); - flow.notify_model_dirty(Dirty_Reason::Core_Data, 10); flow.activate_view(20); - EXPECT_NE(std::find(host.feedback_events.begin(), host.feedback_events.end(), "InputChanged"), host.feedback_events.end()); EXPECT_NE(std::find(host.feedback_events.begin(), host.feedback_events.end(), "RenderAdmitted"), host.feedback_events.end()); + EXPECT_EQ(std::find(host.feedback_events.begin(), host.feedback_events.end(), "RenderStarted"), host.feedback_events.end()); + Frame_Lifecycle_Record frame; + frame.render_begin_ns = 30; + frame.render_end_ns = 40; + flow.notify_render_finished(frame, 40); EXPECT_NE(std::find(host.feedback_events.begin(), host.feedback_events.end(), "RenderStarted"), host.feedback_events.end()); + EXPECT_NE(std::find(host.feedback_events.begin(), host.feedback_events.end(), "RenderCompleted"), host.feedback_events.end()); } TEST(Renderive_Frame_Pipeline, NewRenderSupersedesOldMiddle) { @@ -1638,7 +1675,7 @@ TEST(Renderive_Frame_Pipeline, NewRenderSupersedesOldMiddle) { EXPECT_TRUE(third.middle_published); ASSERT_NE(third.superseded_frame_record, nullptr); EXPECT_EQ(third.superseded_frame_record->frame_id, 2u); - EXPECT_TRUE(third.update_coalesced); + EXPECT_TRUE(third.duplicate_present_request_suppressed); } TEST(Renderive_Frame_Pipeline, OnlyOneUpdateRemainsPosted) { @@ -1649,7 +1686,7 @@ TEST(Renderive_Frame_Pipeline, OnlyOneUpdateRemainsPosted) { auto repeated = pipeline.request_present(30); EXPECT_FALSE(repeated.request_present); - EXPECT_TRUE(repeated.update_coalesced); + EXPECT_TRUE(repeated.duplicate_present_request_suppressed); EXPECT_TRUE(Low_Latency_Frame_Pipeline_Test_Probe::paint_request_pending(pipeline)); } TEST(Renderive_Frame_Flow, LowLatencyOwnsActiveState) { @@ -2208,6 +2245,27 @@ TEST(Renderive_Hover_Tooltip, DefaultTextPenContrastsWithDefaultBackground) { EXPECT_EQ(state.tooltip_background_brush.color, Color::white()); EXPECT_EQ(state.tooltip_text_pen.color, Color::black()); } +TEST(Renderive_Performance_Overlay, MetricUpdatesDoNotRequestIndependentRepaint) { + auto state = std::make_shared(); + state->enabled.store(true, std::memory_order_release); + std::atomic_int update_count{}; + state->update_callback = [&update_count]() { + update_count.fetch_add(1, std::memory_order_relaxed); + }; + Performance_Frame_Record frame = performance_frame(1); + ASSERT_TRUE(state->metric_queue.try_push(frame)); + schedule_performance_metrics_worker(state); + ASSERT_TRUE(wait_until([&]() { + return state->published_snapshot.load(std::memory_order_acquire) && !state->worker_active.load(std::memory_order_acquire); + })); + EXPECT_EQ(update_count.load(std::memory_order_acquire), 0); + state->snapshot_rebuild_requested.store(true, std::memory_order_release); + schedule_performance_metrics_worker(state, true); + ASSERT_TRUE(wait_until([&]() { + return update_count.load(std::memory_order_acquire) == 1 && !state->worker_active.load(std::memory_order_acquire); + })); + state->cancelled.store(true, std::memory_order_release); +} TEST(Renderive_Performance_Overlay, WorkerConsumesSharedFrameRecord) { auto state = std::make_shared(); state->enabled.store(true, std::memory_order_release); @@ -2256,7 +2314,7 @@ TEST(Renderive_Performance_Overlay, LowLatencyDiagnosticsExposePresentFeedbackFi frame->refresh.producer_starvation_count = 2; frame->refresh.middle_superseded_count = 3; frame->refresh.update_posted_count = 4; - frame->refresh.update_coalesced_count = 1; + frame->refresh.duplicate_present_request_suppressed_count = 1; frame->refresh.update_ack_count = 3; frame->refresh.update_repost_count = 1; shower.collect_frame(frame); @@ -2275,7 +2333,7 @@ TEST(Renderive_Performance_Overlay, LowLatencyDiagnosticsExposePresentFeedbackFi EXPECT_NE(text.find("update_to_paint"), std::string::npos); EXPECT_NE(text.find("producer_starvation"), std::string::npos); EXPECT_NE(text.find("middle_superseded"), std::string::npos); - EXPECT_NE(text.find("coalesced:"), std::string::npos); + EXPECT_NE(text.find("duplicate_suppressed:"), std::string::npos); } TEST(Renderive_Performance_Overlay, PerformanceLogDisabledWritesNothing) { @@ -2290,8 +2348,8 @@ TEST(Renderive_Performance_Overlay, PerformanceLogDisabledWritesNothing) { shower.set_enabled(false); shower.collect_frame(performance_frame(1)); performance_log_service().shutdown(); - EXPECT_FALSE(std::filesystem::exists(directory / "disabled_frames.csv")); - EXPECT_FALSE(std::filesystem::exists(directory / "disabled_feedback.csv")); + EXPECT_FALSE(std::filesystem::exists(directory / "disabled_frames.log")); + EXPECT_FALSE(std::filesystem::exists(directory / "disabled_feedback.log")); EXPECT_FALSE(std::filesystem::exists(directory / "disabled_meta.json")); std::filesystem::remove_all(directory); } @@ -2320,18 +2378,20 @@ TEST(Renderive_Performance_Overlay, PerformanceLogWorksWhenOverlayHidden) { shower.collect_feedback_event(event); performance_log_service().shutdown(); - auto frame_lines = read_lines(directory / "hidden_frames.csv"); - auto feedback_lines = read_lines(directory / "hidden_feedback.csv"); - ASSERT_GE(frame_lines.size(), 2u); - ASSERT_GE(feedback_lines.size(), 2u); - EXPECT_EQ(frame_lines.front(), performance_frame_csv_header()); - EXPECT_EQ(feedback_lines.front(), performance_feedback_csv_header()); - EXPECT_EQ(split_csv_row(frame_lines.front()).size(), split_csv_row(frame_lines[1]).size()); - EXPECT_EQ(split_csv_row(feedback_lines.front()).size(), split_csv_row(feedback_lines[1]).size()); - auto frame_cells = split_csv_row(frame_lines[1]); - ASSERT_GT(frame_cells.size(), 4u); - EXPECT_EQ(frame_cells[2], "42"); - EXPECT_EQ(frame_cells[3], "hidden,plot\"a"); + auto frame_records = read_log_records(directory / "hidden_frames.log", "frame"); + auto feedback_records = read_log_records(directory / "hidden_feedback.log", "feedback"); + ASSERT_EQ(frame_records.size(), 1u); + ASSERT_EQ(feedback_records.size(), 1u); + const auto& frame_record = frame_records.front(); + EXPECT_EQ(frame_record.at("schema_version"), "3"); + EXPECT_EQ(frame_record.at("plot_id"), "42"); + EXPECT_EQ(frame_record.at("plot_name"), "hidden,plot\"a"); + EXPECT_TRUE(frame_record.contains("render_slot_idle_wait_ns")); + EXPECT_TRUE(frame_record.contains("executor_queue_wait_current_ns")); + EXPECT_TRUE(frame_record.contains("executor_started_topologies")); + EXPECT_TRUE(frame_record.contains("executor_completed_topologies")); + EXPECT_TRUE(frame_record.contains("render_request_to_start_ns")); + EXPECT_TRUE(frame_record.contains("duplicate_present_request_suppressed")); EXPECT_TRUE(std::filesystem::exists(directory / "hidden_meta.json")); std::filesystem::remove_all(directory); } @@ -2357,15 +2417,13 @@ TEST(Renderive_Performance_Overlay, PerformanceLogSeparatesMultiplePlots) { second.collect_frame(performance_frame(2)); performance_log_service().shutdown(); - auto lines = read_lines(directory / "multi_frames.csv"); - ASSERT_GE(lines.size(), 3u); + auto records = read_log_records(directory / "multi_frames.log", "frame"); + ASSERT_EQ(records.size(), 2u); bool saw_spectrum = false; bool saw_waterfall = false; - for (std::size_t i = 1; i < lines.size(); ++i) { - auto cells = split_csv_row(lines[i]); - ASSERT_GT(cells.size(), 4u); - saw_spectrum = saw_spectrum || (cells[2] == "11" && cells[3] == "spectrum"); - saw_waterfall = saw_waterfall || (cells[2] == "12" && cells[3] == "waterfall"); + for (const auto& record : records) { + saw_spectrum = saw_spectrum || (record.at("plot_id") == "11" && record.at("plot_name") == "spectrum"); + saw_waterfall = saw_waterfall || (record.at("plot_id") == "12" && record.at("plot_name") == "waterfall"); } EXPECT_TRUE(saw_spectrum); EXPECT_TRUE(saw_waterfall); @@ -2398,27 +2456,20 @@ TEST(Renderive_Performance_Overlay, FeedbackEventLogUsesRuntimeEventRecord) { shower.collect_feedback_event(event); performance_log_service().shutdown(); - auto lines = read_lines(directory / "feedback_feedback.csv"); - ASSERT_GE(lines.size(), 2u); - auto header = split_csv_row(lines.front()); - auto row = split_csv_row(lines[1]); - ASSERT_EQ(header.size(), row.size()); - auto index_of = [&](const std::string& name) { - auto it = std::find(header.begin(), header.end(), name); - EXPECT_NE(it, header.end()); - return static_cast(std::distance(header.begin(), it)); - }; - EXPECT_EQ(row[index_of("event")], "ProducerStarvationEnter"); - EXPECT_EQ(row[index_of("mode_before")], "latency_eager"); - EXPECT_EQ(row[index_of("mode_after")], "consumer_paced"); - EXPECT_EQ(row[index_of("dirty")], "1"); - EXPECT_EQ(row[index_of("producer_starved")], "1"); - EXPECT_EQ(row[index_of("effective_interval_before_ns")], "16666667"); - EXPECT_EQ(row[index_of("effective_interval_after_ns")], "33333333"); + auto records = read_log_records(directory / "feedback_feedback.log", "feedback"); + ASSERT_EQ(records.size(), 1u); + const auto& record = records.front(); + EXPECT_EQ(record.at("event"), "ProducerStarvationEnter"); + EXPECT_EQ(record.at("mode_before"), "latency_eager"); + EXPECT_EQ(record.at("mode_after"), "consumer_paced"); + EXPECT_EQ(record.at("dirty"), "1"); + EXPECT_EQ(record.at("producer_starved"), "1"); + EXPECT_EQ(record.at("effective_interval_before_ns"), "16666667"); + EXPECT_EQ(record.at("effective_interval_after_ns"), "33333333"); std::filesystem::remove_all(directory); } -TEST(Renderive_Performance_Overlay, SummaryUsesMultipleColumnsAndTextRoles) { +TEST(Renderive_Performance_Overlay, SummaryUsesSingleColumnAndTextRoles) { Performance_Overlay shower; Performance_Overlay_Options options; options.section_color = Color{10, 20, 30, 255}; @@ -2445,26 +2496,13 @@ TEST(Renderive_Performance_Overlay, SummaryUsesMultipleColumnsAndTextRoles) { bool has_label = false; bool has_value = false; bool has_warning = false; - int max_column = 0; - std::array section_x{}; - std::array saw_section_column{}; for (const auto& run : snapshot->text_runs) { - max_column = std::max(max_column, run.column_index); + EXPECT_EQ(run.column_index, 0); has_section = has_section || run.role == Performance_Text_Role::Section; has_label = has_label || run.role == Performance_Text_Role::Label; has_value = has_value || run.role == Performance_Text_Role::Value; has_warning = has_warning || run.role == Performance_Text_Role::Warning; - if (run.role == Performance_Text_Role::Section && run.column_index >= 0 && run.column_index < 4) { - if (!saw_section_column[static_cast(run.column_index)]) { - section_x[static_cast(run.column_index)] = run.rect.x; - saw_section_column[static_cast(run.column_index)] = true; - } - else { - EXPECT_EQ(run.rect.x, section_x[static_cast(run.column_index)]); - } - } } - EXPECT_GE(max_column, 2); EXPECT_TRUE(has_section); EXPECT_TRUE(has_label); EXPECT_TRUE(has_value);