Mirrored_Repos/veloren
1
0
Fork 0
mirror of https://gitlab.com/veloren/veloren.git synced 2024-08-30 18:12:32 +00:00
Code Issues Packages Projects Releases Wiki Activity

add detailed information on state tick timings

Browse Source
This commit is contained in:
Marcel Märtens 2020-09-14 14:56:05 +02:00
parent 184d405f10
commit 3c58b64689
14 changed files with 216 additions and 17 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
common/src/lib.rs
View File

@ -28,6 +28,7 @@ pub mod figure;
pub mod generation;
pub mod loadout_builder;
pub mod lottery;
pub mod metrics;
pub mod msg;
pub mod npc;
pub mod outcome;

13
common/src/metrics.rs Normal file
View File

@ -0,0 +1,13 @@
use std::sync::atomic::AtomicI64;
#[derive(Default)]
pub struct SysMetrics {
pub agent_ns: AtomicI64,
pub mount_ns: AtomicI64,
pub controller_ns: AtomicI64,
pub character_behavior_ns: AtomicI64,
pub stats_ns: AtomicI64,
pub phys_ns: AtomicI64,
pub projectile_ns: AtomicI64,
pub combat_ns: AtomicI64,
}

2
common/src/state.rs
View File

@ -1,6 +1,7 @@
use crate::{
comp,
event::{EventBus, LocalEvent, ServerEvent},
metrics::SysMetrics,
region::RegionMap,
sync::WorldSyncExt,
sys,
@ -176,6 +177,7 @@ impl State {
ecs.insert(EventBus::<ServerEvent>::default());
ecs.insert(comp::group::GroupManager::default());
ecs.insert(RegionMap::new());
ecs.insert(SysMetrics::default());
ecs
}

8
common/src/sys/agent.rs
View File

@ -10,6 +10,7 @@ use crate::{
Vel,
},
event::{EventBus, ServerEvent},
metrics::SysMetrics,
path::{Chaser, TraversalConfig},
span,
state::{DeltaTime, Time},
@ -34,6 +35,7 @@ impl<'a> System<'a> for Sys {
Read<'a, Time>,
Read<'a, DeltaTime>,
Read<'a, group::GroupManager>,
ReadExpect<'a, SysMetrics>,
Write<'a, EventBus<ServerEvent>>,
Entities<'a>,
ReadStorage<'a, Pos>,
@ -63,6 +65,7 @@ impl<'a> System<'a> for Sys {
time,
dt,
group_manager,
sys_metrics,
event_bus,
entities,
positions,
@ -84,6 +87,7 @@ impl<'a> System<'a> for Sys {
invites,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "agent::Sys::run");
for (
entity,
@ -572,5 +576,9 @@ impl<'a> System<'a> for Sys {
.push(ControlEvent::GroupManip(GroupManip::Decline));
}
}
sys_metrics.agent_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

11
common/src/sys/character_behavior.rs
View File

@ -4,6 +4,7 @@ use crate::{
Loadout, Mounting, Ori, PhysicsState, Pos, StateUpdate, Stats, Vel,
},
event::{EventBus, LocalEvent, ServerEvent},
metrics::SysMetrics,
span,
state::DeltaTime,
states,
@ -13,7 +14,8 @@ use crate::{
use specs::{
hibitset,
storage::{PairedStorage, SequentialRestriction},
Entities, Entity, FlaggedStorage, Join, LazyUpdate, Read, ReadStorage, System, WriteStorage,
Entities, Entity, FlaggedStorage, Join, LazyUpdate, Read, ReadExpect, ReadStorage, System,
WriteStorage,
};
use specs_idvs::IdvStorage;
@ -144,6 +146,7 @@ impl<'a> System<'a> for Sys {
Read<'a, EventBus<LocalEvent>>,
Read<'a, DeltaTime>,
Read<'a, LazyUpdate>,
ReadExpect<'a, SysMetrics>,
WriteStorage<'a, CharacterState>,
WriteStorage<'a, Pos>,
WriteStorage<'a, Vel>,
@ -169,6 +172,7 @@ impl<'a> System<'a> for Sys {
local_bus,
dt,
updater,
sys_metrics,
mut character_states,
mut positions,
mut velocities,
@ -184,6 +188,7 @@ impl<'a> System<'a> for Sys {
mountings,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "character_behavior::Sys::run");
let mut server_emitter = server_bus.emitter();
let mut local_emitter = local_bus.emitter();
@ -287,5 +292,9 @@ impl<'a> System<'a> for Sys {
server_emitter.append(&mut state_update.server_events);
incorporate_update(&mut tuple, state_update);
}
sys_metrics.character_behavior_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

10
common/src/sys/combat.rs
View File

@ -4,11 +4,12 @@ use crate::{
Loadout, Ori, Pos, Scale, Stats,
},
event::{EventBus, LocalEvent, ServerEvent},
metrics::SysMetrics,
span,
sync::Uid,
util::Dir,
};
use specs::{Entities, Join, Read, ReadStorage, System, WriteStorage};
use specs::{Entities, Join, Read, ReadExpect, ReadStorage, System, WriteStorage};
use vek::*;
pub const BLOCK_EFFICIENCY: f32 = 0.9;
@ -23,6 +24,7 @@ impl<'a> System<'a> for Sys {
Entities<'a>,
Read<'a, EventBus<ServerEvent>>,
Read<'a, EventBus<LocalEvent>>,
ReadExpect<'a, SysMetrics>,
ReadStorage<'a, Uid>,
ReadStorage<'a, Pos>,
ReadStorage<'a, Ori>,
@ -41,6 +43,7 @@ impl<'a> System<'a> for Sys {
entities,
server_bus,
local_bus,
sys_metrics,
uids,
positions,
orientations,
@ -53,6 +56,7 @@ impl<'a> System<'a> for Sys {
character_states,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "combat::Sys::run");
let mut server_emitter = server_bus.emitter();
let mut local_emitter = local_bus.emitter();
@ -160,5 +164,9 @@ impl<'a> System<'a> for Sys {
}
}
}
sys_metrics.combat_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

10
common/src/sys/controller.rs
View File

@ -4,13 +4,14 @@ use crate::{
CharacterState, ControlEvent, Controller, InventoryManip,
},
event::{EventBus, LocalEvent, ServerEvent},
metrics::SysMetrics,
span,
state::DeltaTime,
sync::{Uid, UidAllocator},
};
use specs::{
saveload::{Marker, MarkerAllocator},
Entities, Join, Read, ReadStorage, System, WriteStorage,
Entities, Join, Read, ReadExpect, ReadStorage, System, WriteStorage,
};
// const CHARGE_COST: i32 = 200;
@ -26,6 +27,7 @@ impl<'a> System<'a> for Sys {
Read<'a, EventBus<ServerEvent>>,
Read<'a, EventBus<LocalEvent>>,
Read<'a, DeltaTime>,
ReadExpect<'a, SysMetrics>,
WriteStorage<'a, Controller>,
WriteStorage<'a, CharacterState>,
ReadStorage<'a, Uid>,
@ -39,11 +41,13 @@ impl<'a> System<'a> for Sys {
server_bus,
_local_bus,
_dt,
sys_metrics,
mut controllers,
mut character_states,
uids,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "controller::Sys::run");
let mut server_emitter = server_bus.emitter();
@ -105,5 +109,9 @@ impl<'a> System<'a> for Sys {
}
}
}
sys_metrics.controller_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

10
common/src/sys/mount.rs
View File

@ -1,11 +1,12 @@
use crate::{
comp::{Controller, MountState, Mounting, Ori, Pos, Vel},
metrics::SysMetrics,
span,
sync::UidAllocator,
};
use specs::{
saveload::{Marker, MarkerAllocator},
Entities, Join, Read, System, WriteStorage,
Entities, Join, Read, ReadExpect, System, WriteStorage,
};
use vek::*;
@ -15,6 +16,7 @@ impl<'a> System<'a> for Sys {
#[allow(clippy::type_complexity)]
type SystemData = (
Read<'a, UidAllocator>,
ReadExpect<'a, SysMetrics>,
Entities<'a>,
WriteStorage<'a, Controller>,
WriteStorage<'a, MountState>,
@ -28,6 +30,7 @@ impl<'a> System<'a> for Sys {
&mut self,
(
uid_allocator,
sys_metrics,
entities,
mut controllers,
mut mount_state,
@ -37,6 +40,7 @@ impl<'a> System<'a> for Sys {
mut orientations,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "mount::Sys::run");
// Mounted entities.
for (entity, mut mount_states) in (&entities, &mut mount_state.restrict_mut()).join() {
@ -88,5 +92,9 @@ impl<'a> System<'a> for Sys {
for entity in to_unmount {
mountings.remove(entity);
}
sys_metrics.mount_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

8
common/src/sys/phys.rs
View File

@ -4,6 +4,7 @@ use crate::{
Sticky, Vel,
},
event::{EventBus, ServerEvent},
metrics::SysMetrics,
span,
state::DeltaTime,
sync::{Uid, UidAllocator},
@ -55,6 +56,7 @@ impl<'a> System<'a> for Sys {
ReadExpect<'a, TerrainGrid>,
Read<'a, DeltaTime>,
Read<'a, UidAllocator>,
ReadExpect<'a, SysMetrics>,
Read<'a, EventBus<ServerEvent>>,
ReadStorage<'a, Scale>,
ReadStorage<'a, Sticky>,
@ -80,6 +82,7 @@ impl<'a> System<'a> for Sys {
terrain,
dt,
uid_allocator,
sys_metrics,
event_bus,
scales,
stickies,
@ -95,6 +98,7 @@ impl<'a> System<'a> for Sys {
projectiles,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "phys::Sys::run");
let mut event_emitter = event_bus.emitter();
@ -658,5 +662,9 @@ impl<'a> System<'a> for Sys {
land_on_grounds.into_iter().for_each(|(entity, vel)| {
event_emitter.emit(ServerEvent::LandOnGround { entity, vel: vel.0 });
});
sys_metrics.phys_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

12
common/src/sys/projectile.rs
View File

@ -4,12 +4,15 @@ use crate::{
Loadout, Ori, PhysicsState, Pos, Projectile, Vel,
},
event::{EventBus, LocalEvent, ServerEvent},
metrics::SysMetrics,
span,
state::DeltaTime,
sync::UidAllocator,
util::Dir,
};
use specs::{saveload::MarkerAllocator, Entities, Join, Read, ReadStorage, System, WriteStorage};
use specs::{
saveload::MarkerAllocator, Entities, Join, Read, ReadExpect, ReadStorage, System, WriteStorage,
};
use std::time::Duration;
use vek::*;
@ -23,6 +26,7 @@ impl<'a> System<'a> for Sys {
Read<'a, UidAllocator>,
Read<'a, EventBus<LocalEvent>>,
Read<'a, EventBus<ServerEvent>>,
ReadExpect<'a, SysMetrics>,
ReadStorage<'a, Pos>,
ReadStorage<'a, PhysicsState>,
ReadStorage<'a, Vel>,
@ -40,6 +44,7 @@ impl<'a> System<'a> for Sys {
uid_allocator,
local_bus,
server_bus,
sys_metrics,
positions,
physics_states,
velocities,
@ -49,6 +54,7 @@ impl<'a> System<'a> for Sys {
loadouts,
): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "projectile::Sys::run");
let mut local_emitter = local_bus.emitter();
let mut server_emitter = server_bus.emitter();
@ -190,5 +196,9 @@ impl<'a> System<'a> for Sys {
.checked_sub(Duration::from_secs_f32(dt.0))
.unwrap_or_default();
}
sys_metrics.projectile_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

11
common/src/sys/stats.rs
View File

@ -1,10 +1,11 @@
use crate::{
comp::{CharacterState, Energy, EnergySource, HealthSource, Stats},
event::{EventBus, ServerEvent},
metrics::SysMetrics,
span,
state::DeltaTime,
};
use specs::{Entities, Join, Read, ReadStorage, System, WriteStorage};
use specs::{Entities, Join, Read, ReadExpect, ReadStorage, System, WriteStorage};
const ENERGY_REGEN_ACCEL: f32 = 10.0;
@ -16,6 +17,7 @@ impl<'a> System<'a> for Sys {
Entities<'a>,
Read<'a, DeltaTime>,
Read<'a, EventBus<ServerEvent>>,
ReadExpect<'a, SysMetrics>,
ReadStorage<'a, CharacterState>,
WriteStorage<'a, Stats>,
WriteStorage<'a, Energy>,
@ -23,8 +25,9 @@ impl<'a> System<'a> for Sys {
fn run(
&mut self,
(entities, dt, server_event_bus, character_states, mut stats, mut energies): Self::SystemData,
(entities, dt, server_event_bus, sys_metrics, character_states, mut stats, mut energies): Self::SystemData,
) {
let start_time = std::time::Instant::now();
span!(_guard, "run", "stats::Sys::run");
let mut server_event_emitter = server_event_bus.emitter();
@ -133,5 +136,9 @@ impl<'a> System<'a> for Sys {
CharacterState::Roll { .. } | CharacterState::Climb { .. } => {},
}
}
sys_metrics.stats_ns.store(
start_time.elapsed().as_nanos() as i64,
std::sync::atomic::Ordering::Relaxed,
);
}
}

62
server/src/lib.rs
View File

@ -45,14 +45,14 @@ use common::{
use futures_executor::block_on;
use futures_timer::Delay;
use futures_util::{select, FutureExt};
use metrics::{ServerMetrics, TickMetrics};
use metrics::{ServerMetrics, StateTickMetrics, TickMetrics};
use network::{Network, Pid, ProtocolAddr};
use persistence::character::{CharacterLoader, CharacterLoaderResponseType, CharacterUpdater};
use specs::{join::Join, Builder, Entity as EcsEntity, RunNow, SystemData, WorldExt};
use std::{
i32,
ops::{Deref, DerefMut},
sync::Arc,
sync::{atomic::Ordering, Arc},
time::{Duration, Instant},
};
#[cfg(not(feature = "worldgen"))]
@ -90,6 +90,7 @@ pub struct Server {
metrics: ServerMetrics,
tick_metrics: TickMetrics,
state_tick_metrics: StateTickMetrics,
}
impl Server {
@ -286,10 +287,13 @@ impl Server {
// register all metrics submodules here
let (tick_metrics, registry_tick) = TickMetrics::new(metrics.tick_clone())
.expect("Failed to initialize server tick metrics submodule.");
let (state_tick_metrics, registry_state) = StateTickMetrics::new().unwrap();
registry_chunk(&metrics.registry()).expect("failed to register chunk gen metrics");
registry_network(&metrics.registry()).expect("failed to register network request metrics");
registry_player(&metrics.registry()).expect("failed to register player metrics");
registry_tick(&metrics.registry()).expect("failed to register tick metrics");
registry_state(&metrics.registry()).expect("failed to register state metrics");
let thread_pool = ThreadPoolBuilder::new()
.name("veloren-worker".to_string())
@ -313,6 +317,7 @@ impl Server {
metrics,
tick_metrics,
state_tick_metrics,
};
// Run pending DB migrations (if any)
@ -655,6 +660,59 @@ impl Server {
.with_label_values(&["persistence:stats"])
.set(stats_persistence_nanos);
//detailed state metrics
{
let res = self
.state
.ecs()
.read_resource::<common::metrics::SysMetrics>();
let c = &self.state_tick_metrics.state_tick_time_count;
let agent_ns = res.agent_ns.load(Ordering::Relaxed);
let mount_ns = res.mount_ns.load(Ordering::Relaxed);
let controller_ns = res.controller_ns.load(Ordering::Relaxed);
let character_behavior_ns = res.character_behavior_ns.load(Ordering::Relaxed);
let stats_ns = res.stats_ns.load(Ordering::Relaxed);
let phys_ns = res.phys_ns.load(Ordering::Relaxed);
let projectile_ns = res.projectile_ns.load(Ordering::Relaxed);
let combat_ns = res.combat_ns.load(Ordering::Relaxed);
c.with_label_values(&[common::sys::AGENT_SYS])
.inc_by(agent_ns);
c.with_label_values(&[common::sys::MOUNT_SYS])
.inc_by(mount_ns);
c.with_label_values(&[common::sys::CONTROLLER_SYS])
.inc_by(controller_ns);
c.with_label_values(&[common::sys::CHARACTER_BEHAVIOR_SYS])
.inc_by(character_behavior_ns);
c.with_label_values(&[common::sys::STATS_SYS])
.inc_by(stats_ns);
c.with_label_values(&[common::sys::PHYS_SYS])
.inc_by(phys_ns);
c.with_label_values(&[common::sys::PROJECTILE_SYS])
.inc_by(projectile_ns);
c.with_label_values(&[common::sys::COMBAT_SYS])
.inc_by(combat_ns);
const NANOSEC_PER_SEC: f64 = Duration::from_secs(1).as_nanos() as f64;
let h = &self.state_tick_metrics.state_tick_time_hist;
h.with_label_values(&[common::sys::AGENT_SYS])
.observe(agent_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::MOUNT_SYS])
.observe(mount_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::CONTROLLER_SYS])
.observe(controller_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::CHARACTER_BEHAVIOR_SYS])
.observe(character_behavior_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::STATS_SYS])
.observe(stats_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::PHYS_SYS])
.observe(phys_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::PROJECTILE_SYS])
.observe(projectile_ns as f64 / NANOSEC_PER_SEC);
h.with_label_values(&[common::sys::COMBAT_SYS])
.observe(combat_ns as f64 / NANOSEC_PER_SEC);
}
// Report other info
self.tick_metrics
.time_of_day

73
server/src/metrics.rs
View File

@ -1,5 +1,6 @@
use prometheus::{
Encoder, Gauge, IntCounter, IntCounterVec, IntGauge, IntGaugeVec, Opts, Registry, TextEncoder,
Encoder, Gauge, HistogramOpts, HistogramVec, IntCounter, IntCounterVec, IntGauge, IntGaugeVec,
Opts, Registry, TextEncoder,
};
use std::{
convert::TryInto,
@ -16,6 +17,13 @@ use tracing::{debug, error};
type RegistryFn = Box<dyn FnOnce(&Registry) -> Result<(), prometheus::Error>>;
pub struct StateTickMetrics {
// Counter will only give us granularity on pool speed (2s?) for actuall spike detection we
// need the Historgram
pub state_tick_time_hist: HistogramVec,
pub state_tick_time_count: IntCounterVec,
}
pub struct PlayerMetrics {
pub players_connected: IntCounter,
pub players_disconnected: IntCounterVec, // timeout, network_error, gracefully
@ -23,7 +31,7 @@ pub struct PlayerMetrics {
pub struct NetworkRequestMetrics {
pub chunks_request_dropped: IntCounter,
pub chunks_served_from_cache: IntCounter,
pub chunks_served_from_memory: IntCounter,
pub chunks_generation_triggered: IntCounter,
}
@ -52,6 +60,57 @@ pub struct ServerMetrics {
tick: Arc<AtomicU64>,
}
impl StateTickMetrics {
pub fn new() -> Result<(Self, RegistryFn), prometheus::Error> {
let bucket = vec![
Duration::from_micros(1).as_secs_f64(),
Duration::from_micros(10).as_secs_f64(),
Duration::from_micros(100).as_secs_f64(),
Duration::from_micros(200).as_secs_f64(),
Duration::from_micros(400).as_secs_f64(),
Duration::from_millis(2).as_secs_f64(),
Duration::from_millis(5).as_secs_f64(),
Duration::from_millis(10).as_secs_f64(),
Duration::from_millis(20).as_secs_f64(),
Duration::from_millis(30).as_secs_f64(),
Duration::from_millis(50).as_secs_f64(),
Duration::from_millis(100).as_secs_f64(),
];
let state_tick_time_hist = HistogramVec::new(
HistogramOpts::new(
"state_tick_time_hist",
"shows the number of clients joined to the server",
)
.buckets(bucket),
&["system"],
)?;
let state_tick_time_count = IntCounterVec::new(
Opts::new(
"state_tick_time_count",
"shows the detailed time inside the `state_tick` for each system",
),
&["system"],
)?;
let state_tick_time_hist_clone = state_tick_time_hist.clone();
let state_tick_time_count_clone = state_tick_time_count.clone();
let f = |registry: &Registry| {
registry.register(Box::new(state_tick_time_hist_clone))?;
registry.register(Box::new(state_tick_time_count_clone))?;
Ok(())
};
Ok((
Self {
state_tick_time_hist,
state_tick_time_count,
},
Box::new(f),
))
}
}
impl PlayerMetrics {
pub fn new() -> Result<(Self, RegistryFn), prometheus::Error> {
let players_connected = IntCounter::with_opts(Opts::new(
@ -91,8 +150,8 @@ impl NetworkRequestMetrics {
"chunks_request_dropped",
"number of all chunk request dropped, e.g because the player was to far away",
))?;
let chunks_served_from_cache = IntCounter::with_opts(Opts::new(
"chunks_served_from_cache",
let chunks_served_from_memory = IntCounter::with_opts(Opts::new(
"chunks_served_from_memory",
"number of all requested chunks already generated and could be served out of cache",
))?;
let chunks_generation_triggered = IntCounter::with_opts(Opts::new(
@ -101,12 +160,12 @@ impl NetworkRequestMetrics {
))?;
let chunks_request_dropped_clone = chunks_request_dropped.clone();
let chunks_served_from_cache_clone = chunks_served_from_cache.clone();
let chunks_served_from_memory_clone = chunks_served_from_memory.clone();
let chunks_generation_triggered_clone = chunks_generation_triggered.clone();
let f = |registry: &Registry| {
registry.register(Box::new(chunks_request_dropped_clone))?;
registry.register(Box::new(chunks_served_from_cache_clone))?;
registry.register(Box::new(chunks_served_from_memory_clone))?;
registry.register(Box::new(chunks_generation_triggered_clone))?;
Ok(())
};
@ -114,7 +173,7 @@ impl NetworkRequestMetrics {
Ok((
Self {
chunks_request_dropped,
chunks_served_from_cache,
chunks_served_from_memory,
chunks_generation_triggered,
},
Box::new(f),

2
server/src/sys/message.rs
View File

@ -338,7 +338,7 @@ impl Sys {
if in_vd {
match terrain.get_key(key) {
Some(chunk) => {
network_metrics.chunks_served_from_cache.inc();
network_metrics.chunks_served_from_memory.inc();
client.notify(ServerMsg::TerrainChunkUpdate {
key,
chunk: Ok(Box::new(chunk.clone())),