diff --git a/runtime-light/state/instance-state.cpp b/runtime-light/state/instance-state.cpp index 4b27210266..8f8c512103 100644 --- a/runtime-light/state/instance-state.cpp +++ b/runtime-light/state/instance-state.cpp @@ -4,6 +4,7 @@ #include "runtime-light/state/instance-state.h" +#include #include #include #include @@ -134,6 +135,12 @@ kphp::coro::task<> InstanceState::init_server_instance() noexcept { template kphp::coro::task<> InstanceState::run_instance_prologue() noexcept { + { + k2::SystemTime start_time{}; + k2::system_time(std::addressof(start_time)); + start_time_ns = start_time.since_epoch_ns; + } + static_assert(kind != image_kind::invalid); image_kind_ = kind; @@ -244,4 +251,13 @@ kphp::coro::task<> InstanceState::run_instance_epilogue() noexcept { while (!ignore_answer_request_await_set.empty()) { co_await ignore_answer_request_await_set.next(); } + + k2::SystemTime end_time{}; + k2::system_time(std::addressof(end_time)); + + // TEMPORARY: log instance-cache and confdata timings + kphp::log::info("instance stats (approximately): confdata -> {}ms, instance cache -> {}ms, instance time -> {}ms", + std::chrono::duration_cast(std::chrono::nanoseconds{confdata_instance_state.time_ns}).count(), + std::chrono::duration_cast(std::chrono::nanoseconds{instance_cache_instance_state.time_ns}).count(), + std::chrono::duration_cast(std::chrono::nanoseconds{end_time.since_epoch_ns - start_time_ns}).count()); } diff --git a/runtime-light/state/instance-state.h b/runtime-light/state/instance-state.h index ddec40a59d..ee086f3cee 100644 --- a/runtime-light/state/instance-state.h +++ b/runtime-light/state/instance-state.h @@ -133,6 +133,7 @@ struct InstanceState final : vk::not_copyable { enum class shutdown_state : uint8_t { not_started, in_progress, finished }; shutdown_state shutdown_state_{shutdown_state::not_started}; + uint64_t start_time_ns{}; enum image_kind image_kind_ { image_kind::invalid }; enum instance_kind instance_kind_ { instance_kind::invalid }; diff --git a/runtime-light/stdlib/confdata/confdata-functions.cpp b/runtime-light/stdlib/confdata/confdata-functions.cpp index b3e6c154e6..e9dfe7472e 100644 --- a/runtime-light/stdlib/confdata/confdata-functions.cpp +++ b/runtime-light/stdlib/confdata/confdata-functions.cpp @@ -6,10 +6,12 @@ #include #include +#include #include #include #include +#include "common/containers/final_action.h" #include "runtime-common/core/allocator/script-allocator.h" #include "runtime-common/core/runtime-core.h" #include "runtime-common/core/std/containers.h" @@ -52,11 +54,20 @@ kphp::coro::task f$confdata_get_value(string key) noexcept { co_return mixed{}; } - auto& confdata_key_cache{ConfdataInstanceState::get().key_cache()}; + auto& confdata_instance_st{ConfdataInstanceState::get()}; + auto& confdata_key_cache{confdata_instance_st.key_cache()}; if (auto it{confdata_key_cache.find(key)}; it != confdata_key_cache.end()) { co_return it->second; } + k2::SystemTime start_time{}; + k2::system_time(std::addressof(start_time)); + const auto finalizer{vk::finally([&start_time, &confdata_instance_st] noexcept { + k2::SystemTime end_time{}; + k2::system_time(std::addressof(end_time)); + confdata_instance_st.time_ns += (end_time.since_epoch_ns - start_time.since_epoch_ns); + })}; + tl::ConfdataGet confdata_get{.key = {.value = {key.c_str(), key.size()}}}; tl::storer tls{confdata_get.footprint()}; confdata_get.store(tls); @@ -93,11 +104,20 @@ kphp::coro::task> f$confdata_get_values_by_any_wildcard(string wild co_return array{}; } - auto& confdata_wildcard_cache{ConfdataInstanceState::get().wildcard_cache()}; + auto& confdata_instance_st{ConfdataInstanceState::get()}; + auto& confdata_wildcard_cache{confdata_instance_st.wildcard_cache()}; if (auto it{confdata_wildcard_cache.find(wildcard)}; it != confdata_wildcard_cache.end()) { co_return it->second; } + k2::SystemTime start_time{}; + k2::system_time(std::addressof(start_time)); + const auto finalizer{vk::finally([&start_time, &confdata_instance_st] noexcept { + k2::SystemTime end_time{}; + k2::system_time(std::addressof(end_time)); + confdata_instance_st.time_ns += (end_time.since_epoch_ns - start_time.since_epoch_ns); + })}; + const std::string_view wildcard_view{wildcard.c_str(), wildcard.size()}; const tl::ConfdataGetWildcard confdata_get_wildcard{.wildcard = {.value = wildcard_view}}; diff --git a/runtime-light/stdlib/confdata/confdata-state.h b/runtime-light/stdlib/confdata/confdata-state.h index 58c23776c3..6a98335f21 100644 --- a/runtime-light/stdlib/confdata/confdata-state.h +++ b/runtime-light/stdlib/confdata/confdata-state.h @@ -5,6 +5,7 @@ #pragma once #include +#include #include "common/mixin/not_copyable.h" #include "runtime-common/core/allocator/script-allocator.h" @@ -18,6 +19,8 @@ class ConfdataInstanceState final : private vk::not_copyable { kphp::stl::unordered_map, kphp::memory::script_allocator, hasher_type> m_wildcard_cache; public: + uint64_t time_ns{}; + ConfdataInstanceState() noexcept = default; auto& key_cache() noexcept { diff --git a/runtime-light/stdlib/instance-cache/instance-cache-functions.h b/runtime-light/stdlib/instance-cache/instance-cache-functions.h index 01c9405f8f..08471841fd 100644 --- a/runtime-light/stdlib/instance-cache/instance-cache-functions.h +++ b/runtime-light/stdlib/instance-cache/instance-cache-functions.h @@ -46,6 +46,15 @@ kphp::coro::task f$instance_cache_store(string key, InstanceType instance, ttl = 0; } + auto& instance_cache_st{InstanceCacheInstanceState::get()}; + k2::SystemTime start_time{}; + k2::system_time(std::addressof(start_time)); + const auto finalizer{vk::finally([&start_time, &instance_cache_st] noexcept { + k2::SystemTime end_time{}; + k2::system_time(std::addressof(end_time)); + instance_cache_st.time_ns += (end_time.since_epoch_ns - start_time.since_epoch_ns); + })}; + auto serialized_instance{f$instance_serialize(instance)}; if (!serialized_instance.has_value()) [[unlikely]] { kphp::log::warning("can't serialize instance: key -> {}", key.c_str()); @@ -78,12 +87,21 @@ kphp::coro::task f$instance_cache_store(string key, InstanceType instance, template kphp::coro::task f$instance_cache_fetch(string /*class_name*/, string key, bool /*even_if_expired*/ = false) noexcept { - auto& request_cache{InstanceCacheInstanceState::get().request_cache}; + auto& instance_cache_st{InstanceCacheInstanceState::get()}; + auto& request_cache{instance_cache_st.request_cache}; if (auto it{request_cache.find(key)}; it != request_cache.end()) { auto cached_instance{from_mixed(it->second, {})}; co_return std::move(cached_instance); } + k2::SystemTime start_time{}; + k2::system_time(std::addressof(start_time)); + const auto finalizer{vk::finally([&start_time, &instance_cache_st] noexcept { + k2::SystemTime end_time{}; + k2::system_time(std::addressof(end_time)); + instance_cache_st.time_ns += (end_time.since_epoch_ns - start_time.since_epoch_ns); + })}; + tl::CacheFetch cache_fetch{.key = tl::string{.value = {key.c_str(), key.size()}}}; tl::storer tls{cache_fetch.footprint()}; cache_fetch.store(tls); diff --git a/runtime-light/stdlib/instance-cache/instance-cache-state.h b/runtime-light/stdlib/instance-cache/instance-cache-state.h index 88f65d3b95..684a38b609 100644 --- a/runtime-light/stdlib/instance-cache/instance-cache-state.h +++ b/runtime-light/stdlib/instance-cache/instance-cache-state.h @@ -5,6 +5,7 @@ #pragma once #include +#include #include "common/mixin/not_copyable.h" #include "runtime-common/core/allocator/script-allocator.h" @@ -12,6 +13,7 @@ #include "runtime-common/core/std/containers.h" struct InstanceCacheInstanceState final : private vk::not_copyable { + uint64_t time_ns{}; kphp::stl::unordered_map(s.hash()); })> request_cache;