Fix frame time measurement in the GL backend, and add it to the NanoVG demo

This commit is contained in:
Patrick Walton 2020-04-09 17:49:28 -07:00
parent 19aa9c8e54
commit 47919db8f3
7 changed files with 212 additions and 93 deletions

View File

@ -102,7 +102,6 @@ pub struct DemoApp<W> where W: Window {
last_mouse_position: Vector2I,
current_frame: Option<Frame>,
build_time: Option<Duration>,
ui_model: DemoUIModel,
ui_presenter: DemoUIPresenter<DeviceImpl>,
@ -202,7 +201,6 @@ impl<W> DemoApp<W> where W: Window {
last_mouse_position: Vector2I::default(),
current_frame: None,
build_time: None,
ui_presenter,
ui_model,
@ -512,24 +510,14 @@ impl<W> DemoApp<W> where W: Window {
return
}
let build_time = self.build_time.unwrap();
let zero = RenderStats::default();
let aggregate_stats = frame.scene_stats.iter().fold(zero, |sum, item| sum + *item);
let total_rendering_time = if frame.scene_rendering_times.is_empty() {
None
} else {
Some(
frame
.scene_rendering_times
if !frame.scene_rendering_times.is_empty() {
let total_rendering_time = frame.scene_rendering_times
.iter()
.fold(RenderTime::default(), |sum, item| sum + *item),
)
};
self.renderer.debug_ui_presenter.add_sample(aggregate_stats,
build_time,
total_rendering_time);
.fold(RenderTime::default(), |sum, item| sum + *item);
self.renderer.debug_ui_presenter.add_sample(aggregate_stats, total_rendering_time);
}
}
fn maybe_take_screenshot(&mut self) {

View File

@ -21,7 +21,6 @@ use pathfinder_geometry::rect::RectI;
use pathfinder_geometry::transform3d::Transform4F;
use pathfinder_geometry::vector::{Vector2I, Vector4F};
use pathfinder_renderer::gpu::options::{DestFramebuffer, RendererOptions};
use pathfinder_renderer::gpu_data::RenderCommand;
use pathfinder_renderer::options::RenderTransform;
use std::path::PathBuf;
@ -260,10 +259,6 @@ impl<W> DemoApp<W> where W: Window {
// Issue render commands!
for command in self.render_command_stream.as_mut().unwrap() {
self.renderer.render_command(&command);
if let RenderCommand::Finish { build_time } = command {
self.build_time = Some(build_time);
}
}
self.current_frame

View File

@ -38,6 +38,7 @@ use pathfinder_simd::default::F32x2;
use sdl2::event::Event;
use sdl2::keyboard::Keycode;
use sdl2::video::GLProfile;
use std::collections::VecDeque;
use std::f32::consts::PI;
use std::sync::Arc;
use std::time::Instant;
@ -57,6 +58,10 @@ const FRAC_PI_2_3: f32 = PI * 2.0 / 3.0;
const WINDOW_WIDTH: i32 = 1024;
const WINDOW_HEIGHT: i32 = WINDOW_WIDTH * 3 / 4;
const GRAPH_WIDTH: f32 = 200.0;
const GRAPH_HEIGHT: f32 = 35.0;
const GRAPH_HISTORY_COUNT: usize = 100;
static FONT_NAME_REGULAR: &'static str = "Roboto-Regular";
static FONT_NAME_BOLD: &'static str = "Roboto-Bold";
static FONT_NAME_EMOJI: &'static str = "NotoEmoji";
@ -1076,6 +1081,119 @@ fn draw_spinner(context: &mut CanvasRenderingContext2D, center: Vector2F, radius
context.restore();
}
struct PerfGraph {
style: GraphStyle,
values: VecDeque<f32>,
name: &'static str,
}
impl PerfGraph {
fn new(style: GraphStyle, name: &'static str) -> PerfGraph {
PerfGraph { style, name, values: VecDeque::new() }
}
fn push(&mut self, frame_time: f32) {
if self.values.len() == GRAPH_HISTORY_COUNT {
self.values.pop_front();
}
self.values.push_back(frame_time);
}
fn render(&self, context: &mut CanvasRenderingContext2D, origin: Vector2F) {
let rect = RectF::new(origin, vec2f(GRAPH_WIDTH, GRAPH_HEIGHT));
context.set_fill_style(rgbau(0, 0, 0, 128));
context.fill_rect(rect);
let mut path = Path2D::new();
path.move_to(rect.lower_left());
let scale = vec2f(rect.width() / (GRAPH_HISTORY_COUNT as f32 - 1.0), rect.height());
for (index, value) in self.values.iter().enumerate() {
let mut value = *value;
if self.style == GraphStyle::FPS && value != 0.0 {
value = 1.0 / value;
}
value = (value * self.style.scale()).min(self.style.max());
let point = rect.lower_left() + vec2f(index as f32, -value / self.style.max()) * scale;
path.line_to(point);
}
path.line_to(rect.lower_left() + vec2f(self.values.len() as f32 - 1.0, 0.0) * scale);
context.set_fill_style(rgbau(255, 192, 0, 128));
context.fill_path(path, FillRule::Winding);
context.set_font(FONT_NAME_REGULAR);
context.set_text_baseline(TextBaseline::Top);
if !self.name.is_empty() {
context.set_font_size(12.0);
context.set_text_align(TextAlign::Left);
context.set_fill_style(rgbau(240, 240, 240, 192));
context.fill_text(self.name, origin + vec2f(3.0, 3.0));
}
context.set_font_size(15.0);
context.set_text_align(TextAlign::Right);
context.set_fill_style(rgbau(240, 240, 240, 255));
self.draw_label(context, self.style, rect.upper_right() + vec2f(-3.0, 3.0));
if self.style == GraphStyle::FPS {
context.set_text_baseline(TextBaseline::Alphabetic);
context.set_fill_style(rgbau(240, 240, 240, 160));
self.draw_label(context, GraphStyle::MS, rect.lower_right() + vec2f(-3.0, -3.0));
}
}
fn draw_label(&self,
context: &mut CanvasRenderingContext2D,
style: GraphStyle,
origin: Vector2F) {
let mut average = self.average();
if style == GraphStyle::FPS && average != 0.0 {
average = 1.0 / average;
}
average *= style.scale();
context.fill_text(&format!("{}{}", average, style.label()), origin);
}
fn average(&self) -> f32 {
let mut sum: f32 = self.values.iter().sum();
if !self.values.is_empty() {
sum /= self.values.len() as f32;
}
sum
}
}
#[derive(Clone, Copy, PartialEq, Debug)]
enum GraphStyle {
FPS,
MS,
}
impl GraphStyle {
fn scale(self) -> f32 {
match self {
GraphStyle::FPS => 1.0,
GraphStyle::MS => 1000.0,
}
}
fn max(self) -> f32 {
match self {
GraphStyle::MS => 20.0,
GraphStyle::FPS => 80.0,
}
}
fn label(self) -> &'static str {
match self {
GraphStyle::FPS => " FPS",
GraphStyle::MS => " ms",
}
}
}
fn set_linear_gradient_fill_style(context: &mut CanvasRenderingContext2D,
from_position: Vector2F,
to_position: Vector2F,
@ -1177,21 +1295,48 @@ fn main() {
let mut mouse_position = Vector2F::zero();
let start_time = Instant::now();
// Initialize performance graphs.
let mut fps_graph = PerfGraph::new(GraphStyle::FPS, "Frame Time");
let mut cpu_graph = PerfGraph::new(GraphStyle::MS, "CPU Time");
let mut gpu_graph = PerfGraph::new(GraphStyle::MS, "GPU Time");
// Enter the main loop.
loop {
// Make a canvas.
let mut context = Canvas::new(drawable_size.to_f32()).get_context_2d(font_context.clone());
// Start performance timing.
let frame_start_time = Instant::now();
let frame_start_elapsed_time = (frame_start_time - start_time).as_secs_f32();
// Render the demo.
let time = (Instant::now() - start_time).as_secs_f32();
context.scale(hidpi_factor);
render_demo(&mut context, mouse_position, window_size.to_f32(), time, &demo_data);
render_demo(&mut context,
mouse_position,
window_size.to_f32(),
frame_start_elapsed_time,
&demo_data);
// Render performance graphs.
let frame_elapsed_time = (Instant::now() - frame_start_time).as_secs_f32();
fps_graph.render(&mut context, vec2f(5.0, 5.0));
cpu_graph.render(&mut context, vec2f(210.0, 5.0));
gpu_graph.render(&mut context, vec2f(415.0, 5.0));
// Render the canvas to screen.
let scene = SceneProxy::from_scene(context.into_canvas().into_scene(), RayonExecutor);
scene.build_and_render(&mut renderer, BuildOptions::default());
window.gl_swap_window();
// Add stats to performance graphs.
if let Some(gpu_time) = renderer.shift_rendering_time() {
let cpu_time = renderer.stats.cpu_build_time.as_secs_f32() + frame_elapsed_time;
let gpu_time = gpu_time.gpu_time.as_secs_f32();
fps_graph.push(cpu_time.max(gpu_time));
cpu_graph.push(cpu_time);
gpu_graph.push(gpu_time);
}
for event in event_pump.poll_iter() {
match event {
Event::Quit {..} | Event::KeyDown { keycode: Some(Keycode::Escape), .. } => return,

View File

@ -159,8 +159,8 @@ impl<'a> SceneBuilder<'a> {
self.finish_building(&paint_metadata, built_draw_paths);
let build_time = Instant::now() - start_time;
self.listener.send(RenderCommand::Finish { build_time });
let cpu_build_time = Instant::now() - start_time;
self.listener.send(RenderCommand::Finish { cpu_build_time });
}
fn build_clip_path(&self, params: PathBuildParams) -> BuiltPath {

View File

@ -38,9 +38,8 @@ where
D: Device,
{
pub ui_presenter: UIPresenter<D>,
cpu_samples: SampleBuffer<CPUSample>,
gpu_samples: SampleBuffer<GPUSample>,
cpu_samples: SampleBuffer<RenderStats>,
gpu_samples: SampleBuffer<RenderTime>,
}
impl<D> DebugUIPresenter<D>
@ -60,28 +59,17 @@ where
}
}
pub fn add_sample(
&mut self,
stats: RenderStats,
tile_time: Duration,
rendering_time: Option<RenderTime>,
) {
self.cpu_samples.push(CPUSample {
stats,
elapsed: tile_time,
});
if let Some(time) = rendering_time {
self.gpu_samples.push(GPUSample { time })
}
pub fn add_sample(&mut self, stats: RenderStats, rendering_time: RenderTime) {
self.cpu_samples.push(stats);
self.gpu_samples.push(rendering_time);
}
pub fn draw(&self, device: &D) {
let mean_cpu_sample = self.cpu_samples.mean();
self.draw_stats_window(device, &mean_cpu_sample);
self.draw_performance_window(device, &mean_cpu_sample);
self.draw_stats_window(device);
self.draw_performance_window(device);
}
fn draw_stats_window(&self, device: &D, mean_cpu_sample: &CPUSample) {
fn draw_stats_window(&self, device: &D) {
let framebuffer_size = self.ui_presenter.framebuffer_size();
let bottom = framebuffer_size.y() - PADDING;
let window_rect = RectI::new(
@ -92,34 +80,35 @@ where
self.ui_presenter.draw_solid_rounded_rect(device, window_rect, WINDOW_COLOR);
let mean_cpu_sample = self.cpu_samples.mean();
let origin = window_rect.origin() + vec2i(PADDING, PADDING + FONT_ASCENT);
self.ui_presenter.draw_text(
device,
&format!("Paths: {}", mean_cpu_sample.stats.path_count),
&format!("Paths: {}", mean_cpu_sample.path_count),
origin,
false,
);
self.ui_presenter.draw_text(
device,
&format!("Solid Tiles: {}", mean_cpu_sample.stats.solid_tile_count),
&format!("Solid Tiles: {}", mean_cpu_sample.solid_tile_count),
origin + vec2i(0, LINE_HEIGHT * 1),
false,
);
self.ui_presenter.draw_text(
device,
&format!("Alpha Tiles: {}", mean_cpu_sample.stats.alpha_tile_count),
&format!("Alpha Tiles: {}", mean_cpu_sample.alpha_tile_count),
origin + vec2i(0, LINE_HEIGHT * 2),
false,
);
self.ui_presenter.draw_text(
device,
&format!("Fills: {}", mean_cpu_sample.stats.fill_count),
&format!("Fills: {}", mean_cpu_sample.fill_count),
origin + vec2i(0, LINE_HEIGHT * 3),
false,
);
}
fn draw_performance_window(&self, device: &D, mean_cpu_sample: &CPUSample) {
fn draw_performance_window(&self, device: &D) {
let framebuffer_size = self.ui_presenter.framebuffer_size();
let bottom = framebuffer_size.y() - PADDING;
let window_rect = RectI::new(
@ -130,13 +119,11 @@ where
self.ui_presenter.draw_solid_rounded_rect(device, window_rect, WINDOW_COLOR);
let mean_cpu_sample = self.cpu_samples.mean();
let origin = window_rect.origin() + vec2i(PADDING, PADDING + FONT_ASCENT);
self.ui_presenter.draw_text(
device,
&format!(
"Stage 0 CPU: {:.3} ms",
duration_to_ms(mean_cpu_sample.elapsed)
),
&format!("CPU: {:.3} ms", duration_to_ms(mean_cpu_sample.cpu_build_time)),
origin,
false,
);
@ -144,13 +131,13 @@ where
let mean_gpu_sample = self.gpu_samples.mean();
self.ui_presenter.draw_text(
device,
&format!("GPU: {:.3} ms", duration_to_ms(mean_gpu_sample.time.time)),
&format!("GPU: {:.3} ms", duration_to_ms(mean_gpu_sample.gpu_time)),
origin + vec2i(0, LINE_HEIGHT * 1),
false,
);
let wallclock_time = f64::max(duration_to_ms(mean_gpu_sample.time.time),
duration_to_ms(mean_cpu_sample.elapsed));
let wallclock_time = f64::max(duration_to_ms(mean_gpu_sample.gpu_time),
duration_to_ms(mean_cpu_sample.cpu_build_time));
self.ui_presenter.draw_text(
device,
&format!("Wallclock: {:.3} ms", wallclock_time),
@ -225,27 +212,6 @@ impl Div<usize> for CPUSample {
}
}
#[derive(Clone, Default)]
struct GPUSample {
time: RenderTime,
}
impl Add<GPUSample> for GPUSample {
type Output = GPUSample;
fn add(self, other: GPUSample) -> GPUSample {
GPUSample {
time: self.time + other.time,
}
}
}
impl Div<usize> for GPUSample {
type Output = GPUSample;
fn div(self, divisor: usize) -> GPUSample {
GPUSample { time: RenderTime { time: self.time.time / divisor as u32 } }
}
}
fn duration_to_ms(time: Duration) -> f64 {
time.as_secs() as f64 * 1000.0 + time.subsec_nanos() as f64 / 1000000.0
}

View File

@ -144,8 +144,9 @@ where
// Debug
pub stats: RenderStats,
current_cpu_build_time: Option<Duration>,
current_timer: Option<D::TimerQuery>,
pending_timers: VecDeque<D::TimerQuery>,
pending_timers: VecDeque<PendingTimer<D>>,
free_timer_queries: Vec<D::TimerQuery>,
pub debug_ui_presenter: DebugUIPresenter<D>,
@ -280,6 +281,7 @@ where
reprojection_vertex_array,
stats: RenderStats::default(),
current_cpu_build_time: None,
current_timer: None,
pending_timers: VecDeque::new(),
free_timer_queries: timer_queries,
@ -335,7 +337,7 @@ where
batch.blend_mode,
batch.filter)
}
RenderCommand::Finish { .. } => {}
RenderCommand::Finish { cpu_build_time } => self.stats.cpu_build_time = cpu_build_time,
}
}
@ -353,8 +355,11 @@ where
if let Some(timer_query) = self.current_timer.take() {
self.device.end_timer_query(&timer_query);
self.pending_timers.push_back(timer_query);
self.pending_timers.push_back(PendingTimer {
gpu_timer_query: timer_query,
});
}
self.current_cpu_build_time = None;
}
fn start_rendering(&mut self,
@ -379,12 +384,13 @@ where
}
pub fn shift_rendering_time(&mut self) -> Option<RenderTime> {
if let Some(query) = self.pending_timers.pop_front() {
if let Some(time) = self.device.try_recv_timer_query(&query) {
self.free_timer_queries.push(query);
return Some(RenderTime { time });
if let Some(pending_timer) = self.pending_timers.pop_front() {
if let Some(gpu_time) =
self.device.try_recv_timer_query(&pending_timer.gpu_timer_query) {
self.free_timer_queries.push(pending_timer.gpu_timer_query);
return Some(RenderTime { gpu_time });
}
self.pending_timers.push_front(query);
self.pending_timers.push_front(pending_timer);
}
None
}
@ -1085,6 +1091,7 @@ pub struct RenderStats {
pub fill_count: usize,
pub alpha_tile_count: usize,
pub solid_tile_count: usize,
pub cpu_build_time: Duration,
}
impl Add<RenderStats> for RenderStats {
@ -1095,6 +1102,7 @@ impl Add<RenderStats> for RenderStats {
solid_tile_count: self.solid_tile_count + other.solid_tile_count,
alpha_tile_count: self.alpha_tile_count + other.alpha_tile_count,
fill_count: self.fill_count + other.fill_count,
cpu_build_time: self.cpu_build_time + other.cpu_build_time,
}
}
}
@ -1107,19 +1115,25 @@ impl Div<usize> for RenderStats {
solid_tile_count: self.solid_tile_count / divisor,
alpha_tile_count: self.alpha_tile_count / divisor,
fill_count: self.fill_count / divisor,
cpu_build_time: self.cpu_build_time / divisor as u32,
}
}
}
#[derive(Clone, Copy, Debug)]
struct PendingTimer<D> where D: Device {
gpu_timer_query: D::TimerQuery,
}
#[derive(Clone, Copy, Debug)]
pub struct RenderTime {
pub time: Duration,
pub gpu_time: Duration,
}
impl Default for RenderTime {
#[inline]
fn default() -> RenderTime {
RenderTime { time: Duration::new(0, 0) }
RenderTime { gpu_time: Duration::new(0, 0) }
}
}
@ -1128,7 +1142,16 @@ impl Add<RenderTime> for RenderTime {
#[inline]
fn add(self, other: RenderTime) -> RenderTime {
RenderTime { time: self.time + other.time }
RenderTime { gpu_time: self.gpu_time + other.gpu_time }
}
}
impl Div<usize> for RenderTime {
type Output = RenderTime;
#[inline]
fn div(self, divisor: usize) -> RenderTime {
RenderTime { gpu_time: self.gpu_time / divisor as u32 }
}
}

View File

@ -74,7 +74,7 @@ pub enum RenderCommand {
DrawTiles(TileBatch),
// Presents a rendered frame.
Finish { build_time: Duration },
Finish { cpu_build_time: Duration },
}
#[derive(Clone, Copy, PartialEq, Debug)]
@ -186,7 +186,9 @@ impl Debug for RenderCommand {
batch.mask_0_fill_rule,
batch.blend_mode)
}
RenderCommand::Finish { .. } => write!(formatter, "Finish"),
RenderCommand::Finish { cpu_build_time } => {
write!(formatter, "Finish({} ms)", cpu_build_time.as_secs_f64() * 1000.0)
}
}
}
}