Merge branch 'imbris/fix-3' into 'master'

Tweak clock related things and fix voxygen tracy feature

See merge request veloren/veloren!1506
This commit is contained in:
Imbris 2020-11-14 01:39:33 +00:00
commit 51dd5110d0
10 changed files with 108 additions and 75 deletions

2
Cargo.lock generated
View File

@ -5140,6 +5140,7 @@ dependencies = [
"notify",
"num-derive",
"num-traits 0.2.12",
"ordered-float 2.0.0",
"parking_lot 0.11.0",
"rand 0.7.3",
"rayon",
@ -5263,6 +5264,7 @@ dependencies = [
"tracing-appender",
"tracing-log",
"tracing-subscriber",
"tracing-tracy",
"treeculler",
"uvth 3.1.1",
"vek 0.12.0",

View File

@ -26,7 +26,7 @@ fn main() {
info!("Starting chat-cli...");
// Set up an fps clock.
let mut clock = Clock::new(Duration::from_millis(1000 / TPS));
let mut clock = Clock::new(Duration::from_secs_f64(1.0 / TPS as f64));
println!("Enter your username");
let username = read_input();

View File

@ -13,34 +13,44 @@ default = ["simd"]
[dependencies]
arraygen = "0.1.13"
specs-idvs = { git = "https://gitlab.com/veloren/specs-idvs.git", branch = "specs-git" }
crossbeam = "0.7"
enum-iterator = "0.6"
lazy_static = "1.4.0"
num-derive = "0.3"
num-traits = "0.2"
ordered-float = { version = "2.0.0", default-features = false }
parking_lot = "0.11.0"
rand = "0.7"
rayon = "1.3.0"
roots = "0.0.6"
specs = { git = "https://github.com/amethyst/specs.git", features = ["serde", "storage-event-control"], rev = "7a2e348ab2223818bad487695c66c43db88050a5" }
spin_sleep = "1.0"
sum_type = "0.2.0"
tracing = { version = "0.1", default-features = false }
vek = { version = "0.12.0", features = ["serde"] }
# Assets
directories-next = "2.0"
dot_vox = "4.0"
image = { version = "0.23.8", default-features = false, features = ["png"] }
notify = "5.0.0-pre.3"
# Auth
authc = { git = "https://gitlab.com/veloren/auth.git", rev = "b943c85e4a38f5ec60cd18c34c73097640162bfe" }
# Data structures
hashbrown = { version = "0.7.2", features = ["rayon", "serde", "nightly"] }
indexmap = "1.3.0"
slab = "0.4.2"
# ECS
specs = { git = "https://github.com/amethyst/specs.git", features = ["serde", "storage-event-control"], rev = "7a2e348ab2223818bad487695c66c43db88050a5" }
specs-idvs = { git = "https://gitlab.com/veloren/specs-idvs.git", branch = "specs-git" }
# Serde
ron = { version = "0.6", default-features = false }
serde = { version = "1.0.110", features = ["derive", "rc"] }
serde_json = "1.0.50"
serde_repr = "0.1.6"
ron = { version = "0.6", default-features = false }
tracing = { version = "0.1", default-features = false }
rand = "0.7"
rayon = "1.3.0"
lazy_static = "1.4.0"
hashbrown = { version = "0.7.2", features = ["rayon", "serde", "nightly"] }
parking_lot = "0.11.0"
crossbeam = "0.7"
notify = "5.0.0-pre.3"
indexmap = "1.3.0"
sum_type = "0.2.0"
authc = { git = "https://gitlab.com/veloren/auth.git", rev = "b943c85e4a38f5ec60cd18c34c73097640162bfe" }
slab = "0.4.2"
enum-iterator = "0.6"
spin_sleep = "1.0"
num-traits = "0.2"
num-derive = "0.3"
# Tracy
tracy-client = { version = "0.9.0", optional = true }

View File

@ -1,4 +1,5 @@
use crate::span;
use ordered_float::NotNan;
use std::{
collections::VecDeque,
time::{Duration, Instant},
@ -18,26 +19,28 @@ use std::{
pub struct Clock {
/// This is the dt that the Clock tries to archive with each call of tick.
target_dt: Duration,
/// last time `tick` was called
/// Last time `tick` was called
last_sys_time: Instant,
/// will be calculated in `tick` returns the dt used by the next iteration
/// Will be calculated in `tick` returns the dt used by the next iteration
/// of the main loop
last_dt: Duration,
/// summed up `last_dt`
/// Summed up `last_dt`
total_tick_time: Duration,
// Stats only
// stored as millis in u16 to save space. if it's more than u16::MAX (16s) we have other
// problems
last_dts_millis: VecDeque<u16>,
last_dts_millis_sorted: Vec<u16>,
// uses f32 so we have enough precision to display fps values while saving space
// This is in seconds
last_dts: VecDeque<NotNan<f32>>,
last_dts_sorted: Vec<NotNan<f32>>,
last_busy_dts: VecDeque<NotNan<f32>>,
stats: ClockStats,
}
pub struct ClockStats {
/// busy_dt is the part of the last tick that we didn't sleep.
/// Busy dt is the part of the tick that we didn't sleep.
/// e.g. the total tick is 33ms, including 25ms sleeping. then this returns
/// 8ms
pub last_busy_dt: Duration,
/// This is in seconds
pub average_busy_dt: Duration,
/// avg over the last NUMBER_OF_OLD_DELTAS_KEPT ticks
pub average_tps: f64,
/// = 50% percentile
@ -59,9 +62,10 @@ impl Clock {
last_sys_time: Instant::now(),
last_dt: target_dt,
total_tick_time: Duration::default(),
last_dts_millis: VecDeque::with_capacity(NUMBER_OF_OLD_DELTAS_KEPT),
last_dts_millis_sorted: Vec::with_capacity(NUMBER_OF_OLD_DELTAS_KEPT),
stats: ClockStats::new(&Vec::new(), target_dt),
last_dts: VecDeque::with_capacity(NUMBER_OF_OLD_DELTAS_KEPT),
last_dts_sorted: Vec::with_capacity(NUMBER_OF_OLD_DELTAS_KEPT),
last_busy_dts: VecDeque::with_capacity(NUMBER_OF_OLD_DELTAS_KEPT),
stats: ClockStats::new(&[], &VecDeque::new()),
}
}
@ -74,13 +78,14 @@ impl Clock {
/// Do not modify without asking @xMAC94x first!
pub fn tick(&mut self) {
span!(_guard, "tick", "Clock::tick");
span!(guard, "clock work");
let current_sys_time = Instant::now();
let busy_delta = current_sys_time.duration_since(self.last_sys_time);
// Maintain TPS
self.last_dts_millis_sorted = self.last_dts_millis.iter().copied().collect();
self.last_dts_millis_sorted.sort_unstable();
self.stats = ClockStats::new(&self.last_dts_millis_sorted, busy_delta);
self.last_dts_sorted = self.last_dts.iter().copied().collect();
self.last_dts_sorted.sort_unstable();
self.stats = ClockStats::new(&self.last_dts_sorted, &self.last_busy_dts);
drop(guard);
// Attempt to sleep to fill the gap.
if let Some(sleep_dur) = self.target_dt.checked_sub(busy_delta) {
spin_sleep::sleep(sleep_dur);
@ -88,50 +93,60 @@ impl Clock {
let after_sleep_sys_time = Instant::now();
self.last_dt = after_sleep_sys_time.duration_since(self.last_sys_time);
if self.last_dts_millis.len() >= NUMBER_OF_OLD_DELTAS_KEPT {
self.last_dts_millis.pop_front();
if self.last_dts.len() >= NUMBER_OF_OLD_DELTAS_KEPT {
self.last_dts.pop_front();
}
self.last_dts_millis
.push_back((self.last_dt.as_millis() as u16).min(std::u16::MAX));
if self.last_busy_dts.len() >= NUMBER_OF_OLD_DELTAS_KEPT {
self.last_busy_dts.pop_front();
}
self.last_dts.push_back(
NotNan::new(self.last_dt.as_secs_f32())
.expect("Duration::as_secs_f32 never returns NaN"),
);
self.last_busy_dts.push_back(
NotNan::new(busy_delta.as_secs_f32()).expect("Duration::as_secs_f32 never returns NaN"),
);
self.total_tick_time += self.last_dt;
self.last_sys_time = after_sleep_sys_time;
}
}
impl ClockStats {
fn new(sorted: &[u16], last_busy_dt: Duration) -> Self {
const NANOS_PER_SEC: f64 = Duration::from_secs(1).as_nanos() as f64;
const NANOS_PER_MILLI: f64 = Duration::from_millis(1).as_nanos() as f64;
fn new(sorted: &[NotNan<f32>], busy_dt_list: &VecDeque<NotNan<f32>>) -> Self {
let average_frame_time =
sorted.iter().sum::<NotNan<f32>>().into_inner() / sorted.len().max(1) as f32;
let len = sorted.len();
let average_millis = sorted.iter().fold(0, |a, x| a + *x as u32) / len.max(1) as u32;
let average_busy_dt = busy_dt_list.iter().sum::<NotNan<f32>>().into_inner()
/ busy_dt_list.len().max(1) as f32;
let average_tps = NANOS_PER_SEC / (average_millis as f64 * NANOS_PER_MILLI);
let (median_tps, percentile_90_tps, percentile_95_tps, percentile_99_tps) = if len
>= NUMBER_OF_OLD_DELTAS_KEPT
{
let median_millis = sorted[len / 2];
let percentile_90_millis = sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.1) as usize];
let percentile_95_millis = sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.05) as usize];
let percentile_99_millis = sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.01) as usize];
let average_tps = 1.0 / average_frame_time as f64;
let (median_tps, percentile_90_tps, percentile_95_tps, percentile_99_tps) =
if sorted.len() >= NUMBER_OF_OLD_DELTAS_KEPT {
let median_frame_time = *sorted[sorted.len() / 2];
let percentile_90_frame_time =
*sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.1) as usize];
let percentile_95_frame_time =
*sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.05) as usize];
let percentile_99_frame_time =
*sorted[(NUMBER_OF_OLD_DELTAS_KEPT as f32 * 0.01) as usize];
let median_tps = NANOS_PER_SEC / (median_millis as f64 * NANOS_PER_MILLI);
let percentile_90_tps = NANOS_PER_SEC / (percentile_90_millis as f64 * NANOS_PER_MILLI);
let percentile_95_tps = NANOS_PER_SEC / (percentile_95_millis as f64 * NANOS_PER_MILLI);
let percentile_99_tps = NANOS_PER_SEC / (percentile_99_millis as f64 * NANOS_PER_MILLI);
(
median_tps,
percentile_90_tps,
percentile_95_tps,
percentile_99_tps,
)
} else {
let avg_tps = NANOS_PER_SEC / last_busy_dt.as_nanos() as f64;
(avg_tps, avg_tps, avg_tps, avg_tps)
};
let median_tps = 1.0 / median_frame_time as f64;
let percentile_90_tps = 1.0 / percentile_90_frame_time as f64;
let percentile_95_tps = 1.0 / percentile_95_frame_time as f64;
let percentile_99_tps = 1.0 / percentile_99_frame_time as f64;
(
median_tps,
percentile_90_tps,
percentile_95_tps,
percentile_99_tps,
)
} else {
let avg_tps = 1.0 / average_busy_dt as f64;
(avg_tps, avg_tps, avg_tps, avg_tps)
};
Self {
last_busy_dt,
average_busy_dt: Duration::from_secs_f32(average_busy_dt),
average_tps,
median_tps,
percentile_90_tps,

View File

@ -140,7 +140,7 @@ fn main() -> io::Result<()> {
let mut shutdown_coordinator = ShutdownCoordinator::new(Arc::clone(&sigusr1_signal));
// Set up an fps clock
let mut clock = Clock::new(Duration::from_millis(1000 / TPS));
let mut clock = Clock::new(Duration::from_secs_f64(1.0 / TPS as f64));
// Wait for a tick so we don't start with a zero dt
loop {

View File

@ -14,6 +14,7 @@ hot-anim = ["anim/use-dyn-lib"]
singleplayer = ["server"]
tweak = ["const-tweaker"]
simd = ["vek/platform_intrinsics"]
tracy = ["tracing-tracy", "common/tracy"]
default = ["gl", "singleplayer", "native-dialog", "simd"]
@ -84,6 +85,9 @@ const-tweaker = {version = "0.3.1", optional = true}
inline_tweak = "1.0.2"
itertools = "0.9.0"
# Tracy
tracing-tracy = { version = "0.3.0", optional = true }
# Logging
tracing = "0.1"
tracing-appender = "0.1"

View File

@ -184,8 +184,10 @@ fn main() {
audio,
profile,
window,
clock: Clock::new(std::time::Duration::from_secs_f64(
1.0 / settings.graphics.max_fps as f64,
)),
settings,
clock: Clock::new(std::time::Duration::from_millis(30)),
info_message: None,
#[cfg(feature = "singleplayer")]
singleplayer: None,

View File

@ -178,8 +178,8 @@ fn handle_main_events_cleared(
if !exit {
// Wait for the next tick.
span!(_guard, "Main thread sleep");
global_state.clock.set_target_dt(Duration::from_millis(
1000 / global_state.settings.graphics.max_fps as u64,
global_state.clock.set_target_dt(Duration::from_secs_f64(
1.0 / global_state.settings.graphics.max_fps as f64,
));
global_state.clock.tick();

View File

@ -694,7 +694,7 @@ impl PlayState for SessionState {
.toggle_debug
.then(|| DebugInfo {
tps: global_state.clock.stats().average_tps,
frame_time: global_state.clock.stats().last_busy_dt,
frame_time: global_state.clock.stats().average_busy_dt,
ping_ms: self.client.borrow().get_ping_ms_rolling_avg(),
coordinates: self
.client

View File

@ -152,7 +152,7 @@ fn run_server(mut server: Server, rec: Receiver<Msg>, paused: Arc<AtomicBool>) {
info!("Starting server-cli...");
// Set up an fps clock
let mut clock = Clock::new(Duration::from_millis(1000 / TPS));
let mut clock = Clock::new(Duration::from_secs_f64(1.0 / TPS as f64));
loop {
// Check any event such as stopping and pausing