From 2b325d4699abfecd8a13c8832a69d3d9d522eac5 Mon Sep 17 00:00:00 2001 From: Jens Koenen <koenen@vr.rwth-aachen.de> Date: Thu, 1 Dec 2022 12:58:41 +0100 Subject: [PATCH] Combined log for pass timer and statistics --- src/headset/remote_headset.cpp | 2 +- src/utility/pass_timer.cpp | 325 ++++++++------------------------- src/utility/pass_timer.hpp | 55 +++--- src/utility/statistic.cpp | 77 +++++--- src/utility/statistic.hpp | 9 +- src/vr_application.cpp | 24 +-- 6 files changed, 170 insertions(+), 322 deletions(-) diff --git a/src/headset/remote_headset.cpp b/src/headset/remote_headset.cpp index 972cd173..72456cbe 100644 --- a/src/headset/remote_headset.cpp +++ b/src/headset/remote_headset.cpp @@ -289,7 +289,7 @@ void RemoteHeadset::submit_frame(VkCommandBuffer command_buffer, VkImageLayout f uint32_t frame_number = this->frame_number; uint32_t transform_id = this->transform_id; - pass_timer->begin_pass(command_buffer, "Encode Setup " + std::to_string(frame_id)); + pass_timer->begin_pass(command_buffer, "encode_setup_" + std::to_string(frame_id)); EncoderResult result = encoder->encode(command_buffer, renderer, framebuffer, frame_layout, [this, frame_number, frame_id, transform_id](const std::span<uint8_t>& content, bool is_config) { if (is_config) diff --git a/src/utility/pass_timer.cpp b/src/utility/pass_timer.cpp index 4f9fe8bc..b78b6bf2 100644 --- a/src/utility/pass_timer.cpp +++ b/src/utility/pass_timer.cpp @@ -1,17 +1,9 @@ #include "pass_timer.hpp" -#include <fstream> #include <algorithm> -#include <chrono> -#include <filesystem> -PassTimer::PassTimer(const std::string& base_directory) : base_directory(base_directory) +bool PassTimer::create(lava::device_ptr device, StatisticLog::Ptr log, uint32_t frame_count, uint32_t pass_count) { - -} - -bool PassTimer::create(lava::device_ptr device, uint32_t frame_count, uint32_t pass_count) -{ - if (!this->load_timestamp_specs(device)) + if (!this->check_timestamp_properties(device)) { return false; } @@ -27,18 +19,19 @@ bool PassTimer::create(lava::device_ptr device, uint32_t frame_count, uint32_t p for (uint32_t frame = 0; frame < frame_count; frame++) { VkQueryPool query_pool = nullptr; + if (vkCreateQueryPool(device->get(), &pool_create_info, lava::memory::alloc(), &query_pool) != VK_SUCCESS) { lava::log()->error("can't create query pool for pass timer!"); - this->destroy(device); - return false; } this->query_pools.push_back(query_pool); } + this->statistic_log = log; + this->frame_count = frame_count; this->timestamp_count = pass_count * 2; @@ -68,32 +61,46 @@ void PassTimer::destroy(lava::device_ptr device) this->timestamp_zero = {}; } -void PassTimer::interface() +bool PassTimer::wait(lava::device_ptr device) { - for (Statistic::Ptr statistic : this->pass_statistcs) + for (uint32_t offset = 0; offset < this->frame_count; offset++) { - statistic->interface(128); + uint32_t frame = (this->current_frame + offset + 1) % this->frame_count; + + if (!this->check_submissions(device, frame, true)) + { + return false; + } } + + return true; } -bool PassTimer::write_to_file(lava::device_ptr device) +void PassTimer::interface() { - if (!this->wait_timestamps(device)) + for (const PassTimerStatistic& pass_statistic : this->statistic_list) { - return false; + if (pass_statistic.inactive_frames < PASS_TIMER_STATISTIC_INACTIVE_FRAMES) + { + if (!pass_statistic.statistic->is_log_only()) + { + pass_statistic.statistic->interface(128); + } + } } +} - if (!std::filesystem::exists(this->base_directory)) +bool PassTimer::next_frame(VkCommandBuffer command_buffer, lava::index frame, lava::device_ptr device) +{ + for (PassTimerStatistic& pass_statistic : this->statistic_list) { - std::filesystem::create_directory(this->base_directory); + pass_statistic.inactive_frames++; } - return this->write_timestamps(); -} - -void PassTimer::next_frame(VkCommandBuffer command_buffer, lava::index frame, lava::device_ptr device) -{ - this->evaluate_wating_passes(device, frame, false); + if(!this->check_submissions(device, frame, false)) + { + return false; + } this->current_frame = frame; this->current_timestamp = 0; @@ -101,46 +108,52 @@ void PassTimer::next_frame(VkCommandBuffer command_buffer, lava::index frame, la //Rest all timestamps to the unavailable state for the upcomming frame VkQueryPool current_pool = this->query_pools[frame]; vkCmdResetQueryPool(command_buffer, current_pool, 0, this->timestamp_count); + + return true; } -void PassTimer::begin_pass(VkCommandBuffer command_buffer, const std::string& pass_name) +bool PassTimer::begin_pass(VkCommandBuffer command_buffer, const std::string& pass_name) { if (this->current_timestamp >= this->timestamp_count) { lava::log()->error("Not enough timestamps available! Please increase the number of passes for the pass timer."); - return; + return false; } - PassWaitInfo wait_info; - wait_info.name = pass_name; - wait_info.frame_index = this->current_frame; - wait_info.timestamp_index = this->current_timestamp; + PassTimerQuerySubmission submission; + submission.name = pass_name; + submission.frame_index = this->current_frame; + submission.timestamp_index = this->current_timestamp; - this->wait_infos.push_back(wait_info); + this->query_submissions.push_back(submission); VkQueryPool current_pool = this->query_pools[this->current_frame]; vkCmdWriteTimestamp(command_buffer, VK_PIPELINE_STAGE_TOP_OF_PIPE_BIT, current_pool, this->current_timestamp); this->current_timestamp++; + + return true; } -void PassTimer::end_pass(VkCommandBuffer command_buffer) +bool PassTimer::end_pass(VkCommandBuffer command_buffer) { if (this->current_timestamp >= this->timestamp_count) { lava::log()->error("Not enough timestamps available! Please increase the number of passes for the pass timer."); - return; + return false; } VkQueryPool current_pool = this->query_pools[this->current_frame]; vkCmdWriteTimestamp(command_buffer, VK_PIPELINE_STAGE_BOTTOM_OF_PIPE_BIT, current_pool, this->current_timestamp); this->current_timestamp++; + + return true; } -bool PassTimer::load_timestamp_specs(lava::device_ptr device) +bool PassTimer::check_timestamp_properties(lava::device_ptr device) { uint32_t property_count = 0; vkGetPhysicalDeviceQueueFamilyProperties(device->get_vk_physical_device(), &property_count, nullptr); @@ -165,14 +178,13 @@ bool PassTimer::load_timestamp_specs(lava::device_ptr device) return true; } -bool PassTimer::evaluate_wating_passes(lava::device_ptr device, lava::index frame, bool wait) +bool PassTimer::check_submissions(lava::device_ptr device, lava::index frame, bool wait) { VkQueryPool current_pool = this->query_pools[frame]; - FrameStatistic frame_statistic; - for (const PassWaitInfo& wait_info : this->wait_infos) + for (const PassTimerQuerySubmission& submission : this->query_submissions) { - if (wait_info.frame_index == frame) + if (submission.frame_index == frame) { uint32_t flags = VK_QUERY_RESULT_64_BIT; @@ -183,14 +195,14 @@ bool PassTimer::evaluate_wating_passes(lava::device_ptr device, lava::index fram std::array<uint64_t, 2> timestamps; - if (vkGetQueryPoolResults(device->get(), current_pool, wait_info.timestamp_index, 1, sizeof(uint64_t), ×tamps[0], 0, flags) != VK_SUCCESS) + if (vkGetQueryPoolResults(device->get(), current_pool, submission.timestamp_index, 1, sizeof(uint64_t), ×tamps[0], 0, flags) != VK_SUCCESS) { lava::log()->error("can't get the timestamp results for the pass timer"); return false; } - if (vkGetQueryPoolResults(device->get(), current_pool, wait_info.timestamp_index + 1, 1, sizeof(uint64_t), ×tamps[1], 0, flags) != VK_SUCCESS) + if (vkGetQueryPoolResults(device->get(), current_pool, submission.timestamp_index + 1, 1, sizeof(uint64_t), ×tamps[1], 0, flags) != VK_SUCCESS) { lava::log()->error("can't get the timestamp results for the pass timer"); @@ -209,232 +221,43 @@ bool PassTimer::evaluate_wating_passes(lava::device_ptr device, lava::index fram double end_time = ((double)(timestamps[1] - this->timestamp_zero.value()) * this->timestamp_period) / 1000000.0; double delta_time = ((double)(timestamps[1] - timestamps[0]) * this->timestamp_period) / 1000000.0; - PassStatistic pass_statistic; - pass_statistic.name = wait_info.name; - pass_statistic.start_time = start_time; - pass_statistic.end_time = end_time; - pass_statistic.delta_time = delta_time; - - frame_statistic.push_back(pass_statistic); + this->add_sample("timestamp_" + submission.name + "_start", true, start_time); + this->add_sample("timestamp_" + submission.name + "_end", true, end_time); + this->add_sample(submission.name, false, delta_time); } } - this->frame_statistics.push_back(frame_statistic); - - for (uint32_t index = 0; index < this->pass_statistcs.size();) + this->query_submissions.erase(std::remove_if(this->query_submissions.begin(), this->query_submissions.end(), [=](const PassTimerQuerySubmission& submission) { - Statistic::Ptr statistic = this->pass_statistcs[index]; - bool found = false; - - for (const PassStatistic& pass_statistic : frame_statistic) - { - if (statistic->get_name() == pass_statistic.name) - { - statistic->add_sample(pass_statistic.delta_time); - found = true; - - break; - } - } - - if (!found) - { - bool inactive = true; - - for (int32_t index = 1; index < glm::min((uint32_t)PASS_TIMER_STATISTIC_INACTIVE_FRAMES, (uint32_t)this->frame_statistics.size()); index++) - { - uint32_t old_index = (this->frame_statistics.size() - 1) - index; - FrameStatistic old_statistic = this->frame_statistics[old_index]; - - for (const PassStatistic& pass_statistic : old_statistic) - { - if (statistic->get_name() == pass_statistic.name) - { - inactive = false; - break; - } - } - - if (!inactive) - { - break; - } - } - - if (inactive) - { - this->pass_statistcs.erase(this->pass_statistcs.begin() + index); - - continue; - } - } - - index++; - } - - for (const PassStatistic& pass_statistic : frame_statistic) - { - bool found = false; - - for (Statistic::Ptr statistic : this->pass_statistcs) - { - if (statistic->get_name() == pass_statistic.name) - { - found = true; - break; - } - } - - if (!found) - { - Statistic::Ptr statistic = make_statistic(pass_statistic.name, UNIT_MILLISECONDS); - statistic->add_sample(pass_statistic.delta_time); - - this->pass_statistcs.push_back(statistic); - } - } - - this->wait_infos.erase(std::remove_if(this->wait_infos.begin(), this->wait_infos.end(), [=](const PassWaitInfo& wait_info) - { - return wait_info.frame_index == frame; - }), this->wait_infos.end()); + return submission.frame_index == frame; + }), this->query_submissions.end()); return true; } -bool PassTimer::wait_timestamps(lava::device_ptr device) +void PassTimer::add_sample(const std::string& name, bool log_only, double value) { - for (uint32_t offset = 0; offset < this->frame_count; offset++) + for (PassTimerStatistic& pass_statistic : this->statistic_list) { - uint32_t frame = (this->current_frame + offset + 1) % this->frame_count; - - if (!this->evaluate_wating_passes(device, frame, true)) + if (pass_statistic.statistic->get_name() == name) { - return false; - } - } - - return true; -} - -bool PassTimer::write_timestamps() -{ - std::string file_name = this->build_file_name(); - - std::fstream file; - file.open(this->base_directory + "/" + file_name, std::ios::out); + pass_statistic.inactive_frames = 0; + pass_statistic.statistic->add_sample(value); - if (!file.good()) - { - lava::log()->error("can't write to file '" + file_name + "' for pass statistic"); - - return false; - } - - std::vector<std::string> pass_name_list; - - for (const std::vector<PassStatistic>& frame : this->frame_statistics) - { - for (const PassStatistic& pass : frame) - { - bool found = false; - - for (const std::string& name : pass_name_list) - { - if (name == pass.name) - { - found = true; - - break; - } - } - - if (!found) - { - pass_name_list.push_back(pass.name); - } + return; } } - for (uint32_t index = 0; index < pass_name_list.size(); index++) - { - file << pass_name_list[index] << "_start_time;"; - file << pass_name_list[index] << "_end_time;"; - file << pass_name_list[index] << "_delta_time"; + PassTimerStatistic pass_statistic; + pass_statistic.inactive_frames = 0; + pass_statistic.statistic = make_statistic(name, UNIT_MILLISECONDS, log_only); + pass_statistic.statistic->add_sample(value); - if (index < pass_name_list.size() - 1) - { - file << ";"; - } - } - - file << std::endl; - - for (const std::vector<PassStatistic>& frame : this->frame_statistics) - { - if (frame.empty()) - { - continue; - } - - for (uint32_t index = 0; index < pass_name_list.size(); index++) - { - const PassStatistic* pass = nullptr; - - for (const PassStatistic& frame_pass : frame) - { - if (frame_pass.name == pass_name_list[index]) - { - pass = &frame_pass; - - break; - } - } - - if (pass != nullptr) - { - file << pass->start_time << ";"; - file << pass->end_time << ";"; - file << pass->delta_time; - } - - else - { - file << ";;"; - } - - if (index < pass_name_list.size() - 1) - { - file << ";"; - } - } - - file << std::endl; - } - - file.close(); - - return true; -} - -std::string PassTimer::build_file_name() -{ - time_t system_time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); - tm local_time = *localtime(&system_time); - - std::string name = "statistic"; - name += "_" + std::to_string(local_time.tm_mday); - name += "-" + std::to_string(local_time.tm_mon + 1); - name += "-" + std::to_string(local_time.tm_year + 1900); - name += "_" + std::to_string(local_time.tm_hour); - name += "-" + std::to_string(local_time.tm_min); - name += "-" + std::to_string(local_time.tm_sec); - name += ".csv"; - - return name; + this->statistic_log->add_statistic(pass_statistic.statistic); + this->statistic_list.push_back(pass_statistic); } -PassTimer::Ptr make_pass_timer(const std::string& base_directory) +PassTimer::Ptr make_pass_timer() { - return std::make_shared<PassTimer>(base_directory); + return std::make_shared<PassTimer>(); } \ No newline at end of file diff --git a/src/utility/pass_timer.hpp b/src/utility/pass_timer.hpp index eb048da1..1551be9f 100644 --- a/src/utility/pass_timer.hpp +++ b/src/utility/pass_timer.hpp @@ -2,7 +2,6 @@ With the pass timer it is possible to measure the time that a pass needs to be completed on the gpu. The pass timer can be accessed inside of a stereo strategy by calling the function get_pass_timer(). To measure the time of a pass call begin_pass(...) before and end_pass(...) after the pass. - The resulting statistic is then stored in a csv-file. Example: get_pass_timer().begin_pass(command_buffer, "pass_name"); @@ -13,61 +12,56 @@ #pragma once #include <liblava/lava.hpp> #include <vector> -#include <cstdint> #include <string> #include <optional> #include <memory> +#include <cstdint> #include "utility/statistic.hpp" #define PASS_TIMER_STATISTIC_INACTIVE_FRAMES 128 -struct PassWaitInfo +struct PassTimerStatistic { - std::string name; - uint32_t frame_index = 0; - uint32_t timestamp_index = 0; + Statistic::Ptr statistic; + uint32_t inactive_frames = 0; }; -struct PassStatistic +struct PassTimerQuerySubmission { std::string name; - double start_time = 0.0; - double end_time = 0.0; - double delta_time = 0.0; + uint32_t frame_index = 0; + uint32_t timestamp_index = 0; }; -typedef std::vector<PassStatistic> FrameStatistic; - class PassTimer { public: typedef std::shared_ptr<PassTimer> Ptr; public: - PassTimer(const std::string& base_directory); + PassTimer() = default; - bool create(lava::device_ptr device, uint32_t frame_count, uint32_t pass_count); + bool create(lava::device_ptr device, StatisticLog::Ptr log, uint32_t frame_count, uint32_t pass_count); void destroy(lava::device_ptr device); + bool wait(lava::device_ptr device); void interface(); - - bool write_to_file(lava::device_ptr device); - void next_frame(VkCommandBuffer command_buffer, lava::index frame, lava::device_ptr device); - void begin_pass(VkCommandBuffer command_buffer, const std::string& pass_name); - void end_pass(VkCommandBuffer command_buffer); + bool next_frame(VkCommandBuffer command_buffer, lava::index frame, lava::device_ptr device); + bool begin_pass(VkCommandBuffer command_buffer, const std::string& pass_name); + bool end_pass(VkCommandBuffer command_buffer); private: - bool load_timestamp_specs(lava::device_ptr device); - bool evaluate_wating_passes(lava::device_ptr device, lava::index frame, bool wait); - - bool wait_timestamps(lava::device_ptr device); - bool write_timestamps(); - - std::string build_file_name(); + bool check_timestamp_properties(lava::device_ptr device); + bool check_submissions(lava::device_ptr device, lava::index frame, bool wait); + void add_sample(const std::string& name, bool log_only, double value); private: - std::string base_directory = ""; + StatisticLog::Ptr statistic_log; + std::vector<PassTimerStatistic> statistic_list; + + std::vector<VkQueryPool> query_pools; + std::vector<PassTimerQuerySubmission> query_submissions; uint32_t frame_count = 0; uint32_t timestamp_count = 0; @@ -79,11 +73,6 @@ private: double timestamp_period = 0; //one increment of the timestamp in nanoseconds std::optional<uint64_t> timestamp_zero; //the timestamp that defines the zero time-point - - std::vector<VkQueryPool> query_pools; - std::vector<PassWaitInfo> wait_infos; - std::vector<std::vector<PassStatistic>> frame_statistics; - std::vector<Statistic::Ptr> pass_statistcs; }; -PassTimer::Ptr make_pass_timer(const std::string& base_directory); \ No newline at end of file +PassTimer::Ptr make_pass_timer(); \ No newline at end of file diff --git a/src/utility/statistic.cpp b/src/utility/statistic.cpp index be57146b..045edc98 100644 --- a/src/utility/statistic.cpp +++ b/src/utility/statistic.cpp @@ -369,26 +369,40 @@ bool StatisticLog::write(const std::string& directory) } } - file << "frame_number"; - file << "; transform_id"; + std::vector<std::string> row_cells; - for (const std::string& label : ordered_sample_labels) + if (!ordered_sample_labels.empty()) { - file << "; " << label; + row_cells.push_back("frame_number"); + row_cells.push_back("transform_id"); + + for (const std::string& label : ordered_sample_labels) + { + row_cells.push_back(label); + } + + if (!unordered_sample_labels.empty()) + { + row_cells.push_back(""); + } } - if (!ordered_sample_labels.empty() && !unordered_sample_labels.empty()) + for (const std::string& label : unordered_sample_labels) { - file << "; "; + row_cells.push_back(label); } - for (const std::string& label : unordered_sample_labels) + for (uint32_t index = 0; index < row_cells.size(); index++) { - file << "; " << label; + if (index > 0) + { + file << ";"; + } + + file << row_cells[index]; } file << std::endl; - file << std::fixed << std::setprecision(3); std::map<StatisticKey, std::vector<std::optional<double>>>::iterator row_iter = ordered_samples.begin(); uint32_t row_index = 0; @@ -396,6 +410,7 @@ bool StatisticLog::write(const std::string& directory) while (row_added) { + row_cells.clear(); row_added = false; if (row_iter != ordered_samples.end()) @@ -403,57 +418,73 @@ bool StatisticLog::write(const std::string& directory) const StatisticKey& key = row_iter->first; const std::vector<std::optional<double>>& row = row_iter->second; - file << key.frame_number << "; " << key.transform_id; + row_cells.push_back(std::to_string(key.frame_number)); + row_cells.push_back(std::to_string(key.transform_id)); for (uint32_t index = 0; index < row.size(); index++) { - file << "; "; - if (row[index].has_value()) { - file << row[index].value(); + row_cells.push_back(std::to_string(row[index].value())); + } + + else + { + row_cells.push_back(""); } } for (uint32_t index = 0; index < (ordered_sample_labels.size() - row.size()); index++) { - file << "; "; + row_cells.push_back(""); } row_added = true; row_iter++; } - else + else if (!ordered_sample_labels.empty()) { - file << " ; "; + row_cells.push_back(""); + row_cells.push_back(""); for (uint32_t index = 0; index < ordered_sample_labels.size(); index++) { - file << "; "; + row_cells.push_back(""); } } if (!ordered_sample_labels.empty() && !unordered_sample_labels.empty()) { - file << "; "; + row_cells.push_back(""); } for (const std::vector<double>& column : unordered_samples) { - file << "; "; - if (row_index < column.size()) { - file << column[row_index]; - + row_cells.push_back(std::to_string(column[row_index])); row_added = true; } + + else + { + row_cells.push_back(""); + } } - row_index++; + for (uint32_t index = 0; index < row_cells.size(); index++) + { + if (index > 0) + { + file << ";"; + } + + file << row_cells[index]; + } file << std::endl; + row_index++; } file.close(); diff --git a/src/utility/statistic.hpp b/src/utility/statistic.hpp index 27dfde52..f8883be7 100644 --- a/src/utility/statistic.hpp +++ b/src/utility/statistic.hpp @@ -1,11 +1,16 @@ /* With an statistic object it is possible to measure a value over time and calculate average, min and max. - Besides that it is possible to draw a plot of the measurements by calling the function interface(). + Besides that it is possible to draw a plot of the measurements by calling the function interface(...). + With the help of an statistic log object it is possible to create single a .csv file for a list of statistic objects. Example: - Statistic::Ptr statistic = make_statistic("Statistic Name", 128); + Statistic::Ptr statistic = make_statistic("statistic_name", UNIT_UNDEFINED); statistic->add_sample(42.0f); statistic->interface(); + + StatisticLog::Ptr statistic_log = make_statistic_log(); + statistic_log->add_statistic(statistic); + statistic_log->write("directory"); */ #pragma once diff --git a/src/vr_application.cpp b/src/vr_application.cpp index af896acb..9168aac7 100644 --- a/src/vr_application.cpp +++ b/src/vr_application.cpp @@ -402,6 +402,10 @@ bool VRApplication::on_create() } } + this->statistic_log = make_statistic_log(); + this->frame_time = make_statistic("frame_time", UNIT_MILLISECONDS); + this->statistic_log->add_statistic(this->frame_time); + this->companion_window = make_companion_window(); this->companion_window->set_enabled(this->command_parser.should_show_companion_window()); @@ -422,9 +426,9 @@ bool VRApplication::on_create() return false; } - this->pass_timer = make_pass_timer("statistics"); + this->pass_timer = make_pass_timer(); - if (!this->pass_timer->create(this->app->device, this->get_frame_count(), 10)) + if (!this->pass_timer->create(this->app->device, this->statistic_log, this->get_frame_count(), 10)) { lava::log()->error("Can't create pass timer!"); @@ -458,20 +462,11 @@ bool VRApplication::on_create() return false; } - this->statistic_log = make_statistic_log(); - this->frame_time = make_statistic("frame_time", UNIT_MILLISECONDS); - this->statistic_log->add_statistic(this->frame_time); - return this->create_config(); } void VRApplication::on_destroy() { - if(!this->statistic_log->write("statistic")) - { - lava::log()->error("Can't write statistic!"); - } - this->destroy_config(); if (this->headset != nullptr) @@ -481,7 +476,7 @@ void VRApplication::on_destroy() if (this->pass_timer != nullptr) { - this->pass_timer->write_to_file(this->app->device); + this->pass_timer->wait(this->app->device); this->pass_timer->destroy(this->app->device); } @@ -514,6 +509,11 @@ void VRApplication::on_destroy() { this->scene->destroy(); } + + if (!this->statistic_log->write("statistics")) + { + lava::log()->error("Can't write statistic!"); + } } bool VRApplication::on_resize() -- GitLab