From 123ee5995c989d7c2f0bb320fe94ef1702a48c13 Mon Sep 17 00:00:00 2001 From: Juan Linietsky Date: Fri, 20 Sep 2019 17:58:06 -0300 Subject: [PATCH] Visual GPU profiler and related profiling support in Vulkan. --- core/color.cpp | 8 - core/color.h | 7 +- drivers/vulkan/rendering_device_vulkan.cpp | 76 ++ drivers/vulkan/rendering_device_vulkan.h | 35 + editor/editor_visual_profiler.cpp | 833 ++++++++++++++++++ editor/editor_visual_profiler.h | 124 +++ editor/icons/icon_track_color.svg | 61 ++ editor/script_editor_debugger.cpp | 62 +- editor/script_editor_debugger.h | 3 + scene/debugger/script_debugger_remote.cpp | 41 +- scene/debugger/script_debugger_remote.h | 3 +- servers/visual/rasterizer.h | 14 + .../rasterizer_scene_forward_rd.cpp | 13 + .../rasterizer_rd/rasterizer_storage_rd.cpp | 25 + .../rasterizer_rd/rasterizer_storage_rd.h | 8 + servers/visual/rendering_device.h | 12 + servers/visual/visual_server_canvas.cpp | 8 + servers/visual/visual_server_raster.cpp | 37 +- servers/visual/visual_server_raster.h | 7 + servers/visual/visual_server_scene.cpp | 18 + servers/visual/visual_server_viewport.cpp | 18 + servers/visual/visual_server_wrap_mt.h | 12 + servers/visual_server.h | 10 + 23 files changed, 1418 insertions(+), 17 deletions(-) create mode 100644 editor/editor_visual_profiler.cpp create mode 100644 editor/editor_visual_profiler.h create mode 100644 editor/icons/icon_track_color.svg diff --git a/core/color.cpp b/core/color.cpp index 1baa8af45d..cb3068c487 100644 --- a/core/color.cpp +++ b/core/color.cpp @@ -529,14 +529,6 @@ Color Color::operator+(const Color &p_color) const { a + p_color.a); } -void Color::operator+=(const Color &p_color) { - - r = r + p_color.r; - g = g + p_color.g; - b = b + p_color.b; - a = a + p_color.a; -} - Color Color::operator-(const Color &p_color) const { return Color( diff --git a/core/color.h b/core/color.h index cfdd211b69..75a2b07d71 100644 --- a/core/color.h +++ b/core/color.h @@ -70,7 +70,12 @@ struct Color { } Color operator+(const Color &p_color) const; - void operator+=(const Color &p_color); + _FORCE_INLINE_ void operator+=(const Color &p_color) { + r = r + p_color.r; + g = g + p_color.g; + b = b + p_color.b; + a = a + p_color.a; + } Color operator-() const; Color operator-(const Color &p_color) const; diff --git a/drivers/vulkan/rendering_device_vulkan.cpp b/drivers/vulkan/rendering_device_vulkan.cpp index 09b0f7113e..dd638bb7ba 100644 --- a/drivers/vulkan/rendering_device_vulkan.cpp +++ b/drivers/vulkan/rendering_device_vulkan.cpp @@ -31,6 +31,7 @@ #include "rendering_device_vulkan.h" #include "core/hashfuncs.h" #include "core/os/file_access.h" +#include "core/os/os.h" #include "core/project_settings.h" #include "drivers/vulkan/vulkan_context.h" #include "thirdparty/spirv-reflect/spirv_reflect.h" @@ -6167,6 +6168,20 @@ void RenderingDeviceVulkan::advance_frame() { staging_buffer_current = (staging_buffer_current + 1) % staging_buffer_blocks.size(); staging_buffer_used = false; } + + if (frames[frame].timestamp_count) { + vkGetQueryPoolResults(device, frames[frame].timestamp_pool, 0, frames[frame].timestamp_count, sizeof(uint64_t) * max_timestamp_query_elements, frames[frame].timestamp_result_values, sizeof(uint64_t), VK_QUERY_RESULT_64_BIT); + SWAP(frames[frame].timestamp_names, frames[frame].timestamp_result_names); + SWAP(frames[frame].timestamp_cpu_values, frames[frame].timestamp_cpu_result_values); + } + + frames[frame].timestamp_result_count = frames[frame].timestamp_count; + frames[frame].timestamp_count = 0; + frames[frame].index = Engine::get_singleton()->get_frames_drawn(); +} + +uint32_t RenderingDeviceVulkan::get_frame_delay() const { + return frame_count; } void RenderingDeviceVulkan::_flush(bool p_current_frame) { @@ -6209,6 +6224,7 @@ void RenderingDeviceVulkan::initialize(VulkanContext *p_context) { device = p_context->get_device(); frame_count = p_context->get_swapchain_image_count() + 1; //always need one extra to ensure it's unused at any time, without having to use a fence for this. limits = p_context->get_device_limits(); + max_timestamp_query_elements = 256; { //initialize allocator @@ -6224,6 +6240,8 @@ void RenderingDeviceVulkan::initialize(VulkanContext *p_context) { //create setup and frame buffers for (int i = 0; i < frame_count; i++) { + frames[i].index = 0; + { //create command pool, one per frame is recommended VkCommandPoolCreateInfo cmd_pool_info; cmd_pool_info.sType = VK_STRUCTURE_TYPE_COMMAND_POOL_CREATE_INFO; @@ -6251,6 +6269,27 @@ void RenderingDeviceVulkan::initialize(VulkanContext *p_context) { err = vkAllocateCommandBuffers(device, &cmdbuf, &frames[i].draw_command_buffer); ERR_CONTINUE(err); } + + { + //create query pool + VkQueryPoolCreateInfo query_pool_create_info; + query_pool_create_info.sType = VK_STRUCTURE_TYPE_QUERY_POOL_CREATE_INFO; + query_pool_create_info.flags = 0; + query_pool_create_info.pNext = NULL; + query_pool_create_info.queryType = VK_QUERY_TYPE_TIMESTAMP; + query_pool_create_info.queryCount = max_timestamp_query_elements; + query_pool_create_info.pipelineStatistics = 0; + + vkCreateQueryPool(device, &query_pool_create_info, NULL, &frames[i].timestamp_pool); + + frames[i].timestamp_names = memnew_arr(String, max_timestamp_query_elements); + frames[i].timestamp_cpu_values = memnew_arr(uint64_t, max_timestamp_query_elements); + frames[i].timestamp_count = 0; + frames[i].timestamp_result_names = memnew_arr(String, max_timestamp_query_elements); + frames[i].timestamp_cpu_result_values = memnew_arr(uint64_t, max_timestamp_query_elements); + frames[i].timestamp_result_values = memnew_arr(uint64_t, max_timestamp_query_elements); + frames[i].timestamp_result_count = 0; + } } { @@ -6319,6 +6358,37 @@ void RenderingDeviceVulkan::_free_rids(T &p_owner, const char *p_type) { } } +void RenderingDeviceVulkan::capture_timestamp(const String &p_name, bool p_sync_to_draw) { + + ERR_FAIL_COND(frames[frame].timestamp_count >= max_timestamp_query_elements); + + vkCmdWriteTimestamp(p_sync_to_draw ? frames[frame].draw_command_buffer : frames[frame].setup_command_buffer, VK_PIPELINE_STAGE_BOTTOM_OF_PIPE_BIT, frames[frame].timestamp_pool, frames[frame].timestamp_count); + frames[frame].timestamp_names[frames[frame].timestamp_count] = p_name; + frames[frame].timestamp_cpu_values[frames[frame].timestamp_count] = OS::get_singleton()->get_ticks_usec(); + frames[frame].timestamp_count++; +} + +uint32_t RenderingDeviceVulkan::get_captured_timestamps_count() const { + return frames[frame].timestamp_result_count; +} + +uint64_t RenderingDeviceVulkan::get_captured_timestamps_frame() const { + return frames[frame].index; +} + +uint64_t RenderingDeviceVulkan::get_captured_timestamp_gpu_time(uint32_t p_index) const { + ERR_FAIL_INDEX_V(p_index, frames[frame].timestamp_result_count, 0); + return frames[frame].timestamp_result_values[p_index]; +} +uint64_t RenderingDeviceVulkan::get_captured_timestamp_cpu_time(uint32_t p_index) const { + ERR_FAIL_INDEX_V(p_index, frames[frame].timestamp_result_count, 0); + return frames[frame].timestamp_cpu_result_values[p_index]; +} +String RenderingDeviceVulkan::get_captured_timestamp_name(uint32_t p_index) const { + ERR_FAIL_INDEX_V(p_index, frames[frame].timestamp_result_count, String()); + return frames[frame].timestamp_result_names[p_index]; +} + int RenderingDeviceVulkan::limit_get(Limit p_limit) { switch (p_limit) { case LIMIT_MAX_BOUND_UNIFORM_SETS: return limits.maxBoundDescriptorSets; @@ -6400,6 +6470,12 @@ void RenderingDeviceVulkan::finalize() { int f = (frame + i) % frame_count; _free_pending_resources(f); vkDestroyCommandPool(device, frames[i].command_pool, NULL); + vkDestroyQueryPool(device, frames[i].timestamp_pool, NULL); + memdelete_arr(frames[i].timestamp_names); + memdelete_arr(frames[i].timestamp_cpu_values); + memdelete_arr(frames[i].timestamp_result_names); + memdelete_arr(frames[i].timestamp_result_values); + memdelete_arr(frames[i].timestamp_cpu_result_values); } for (int i = 0; i < split_draw_list_allocators.size(); i++) { diff --git a/drivers/vulkan/rendering_device_vulkan.h b/drivers/vulkan/rendering_device_vulkan.h index c4e5b789bd..be776bd6e2 100644 --- a/drivers/vulkan/rendering_device_vulkan.h +++ b/drivers/vulkan/rendering_device_vulkan.h @@ -828,8 +828,26 @@ class RenderingDeviceVulkan : public RenderingDevice { VkCommandPool command_pool; VkCommandBuffer setup_command_buffer; //used at the begining of every frame for set-up VkCommandBuffer draw_command_buffer; //used at the begining of every frame for set-up + + struct Timestamp { + String description; + uint64_t value; + }; + + VkQueryPool timestamp_pool; + + String *timestamp_names; + uint64_t *timestamp_cpu_values; + uint32_t timestamp_count; + String *timestamp_result_names; + uint64_t *timestamp_cpu_result_values; + uint64_t *timestamp_result_values; + uint32_t timestamp_result_count; + uint64_t index; }; + uint32_t max_timestamp_query_elements; + Frame *frames; //frames available, they are cycled (usually 3) int frame; //current frame int frame_count; //total amount of frames @@ -958,6 +976,21 @@ public: virtual void free(RID p_id); + /****************/ + /**** Timing ****/ + /****************/ + + virtual void capture_timestamp(const String &p_name, bool p_sync_to_draw); + virtual uint32_t get_captured_timestamps_count() const; + virtual uint64_t get_captured_timestamps_frame() const; + virtual uint64_t get_captured_timestamp_gpu_time(uint32_t p_index) const; + virtual uint64_t get_captured_timestamp_cpu_time(uint32_t p_index) const; + virtual String get_captured_timestamp_name(uint32_t p_index) const; + + /****************/ + /**** Limits ****/ + /****************/ + virtual int limit_get(Limit p_limit); virtual void prepare_screen_for_drawing(); @@ -967,6 +1000,8 @@ public: virtual void finalize_frame(); virtual void advance_frame(); + virtual uint32_t get_frame_delay() const; + RenderingDeviceVulkan(); }; diff --git a/editor/editor_visual_profiler.cpp b/editor/editor_visual_profiler.cpp new file mode 100644 index 0000000000..6511e6e911 --- /dev/null +++ b/editor/editor_visual_profiler.cpp @@ -0,0 +1,833 @@ +#include "editor_visual_profiler.h" + +#include "core/os/os.h" +#include "editor_scale.h" +#include "editor_settings.h" + +void EditorVisualProfiler::add_frame_metric(const Metric &p_metric) { + + ++last_metric; + if (last_metric >= frame_metrics.size()) + last_metric = 0; + + frame_metrics.write[last_metric] = p_metric; + // _make_metric_ptrs(frame_metrics.write[last_metric]); + + List stack; + for (int i = 0; i < frame_metrics[last_metric].areas.size(); i++) { + String name = frame_metrics[last_metric].areas[i].name; + frame_metrics.write[last_metric].areas.write[i].color_cache = _get_color_from_signature(name); + String full_name; + + if (name[0] == '<') { + stack.pop_back(); + } + + if (stack.size()) { + full_name = stack.back()->get() + name; + } else { + full_name = name; + } + + if (name[0] == '>') { + + stack.push_back(full_name + "/"); + } + + frame_metrics.write[last_metric].areas.write[i].fullpath_cache = full_name; + } + + updating_frame = true; + cursor_metric_edit->set_max(frame_metrics[last_metric].frame_number); + cursor_metric_edit->set_min(MAX(frame_metrics[last_metric].frame_number - frame_metrics.size(), 0)); + + if (!seeking) { + cursor_metric_edit->set_value(frame_metrics[last_metric].frame_number); + if (hover_metric != -1) { + hover_metric++; + if (hover_metric >= frame_metrics.size()) { + hover_metric = 0; + } + } + } + updating_frame = false; + + if (frame_delay->is_stopped()) { + + frame_delay->set_wait_time(0.1); + frame_delay->start(); + } + + if (plot_delay->is_stopped()) { + plot_delay->set_wait_time(0.1); + plot_delay->start(); + } +} + +void EditorVisualProfiler::clear() { + + int metric_size = EditorSettings::get_singleton()->get("debugger/profiler_frame_history_size"); + metric_size = CLAMP(metric_size, 60, 1024); + frame_metrics.clear(); + frame_metrics.resize(metric_size); + last_metric = -1; + variables->clear(); + //activate->set_pressed(false); + + updating_frame = true; + cursor_metric_edit->set_min(0); + cursor_metric_edit->set_max(0); + cursor_metric_edit->set_value(0); + updating_frame = false; + hover_metric = -1; + seeking = false; +} + +static String _get_percent_txt(float p_value, float p_total) { + if (p_total == 0) + p_total = 0.00001; + return String::num((p_value / p_total) * 100, 1) + "%"; +} + +String EditorVisualProfiler::_get_time_as_text(float p_time) { + + int dmode = display_mode->get_selected(); + + if (dmode == DISPLAY_FRAME_TIME) { + return rtos(p_time) + "ms"; + } else if (dmode == DISPLAY_FRAME_PERCENT) { + return String::num(p_time * 100 / graph_limit, 2) + "%"; //_get_percent_txt(p_time, m.frame_time); + } + + return "err"; +} + +Color EditorVisualProfiler::_get_color_from_signature(const StringName &p_signature) const { + + Color bc = get_color("error_color", "Editor"); + double rot = ABS(double(p_signature.hash()) / double(0x7FFFFFFF)); + Color c; + c.set_hsv(rot, bc.get_s(), bc.get_v()); + return c.linear_interpolate(get_color("base_color", "Editor"), 0.07); +} + +void EditorVisualProfiler::_item_selected() { + + if (updating_frame) + return; + + TreeItem *item = variables->get_selected(); + if (!item) + return; + selected_area = item->get_metadata(0); + _update_plot(); +} + +void EditorVisualProfiler::_update_plot() { + + int w = graph->get_size().width; + int h = graph->get_size().height; + + bool reset_texture = false; + + int desired_len = w * h * 4; + + if (graph_image.size() != desired_len) { + reset_texture = true; + graph_image.resize(desired_len); + } + + PoolVector::Write wr = graph_image.write(); + + //clear + for (int i = 0; i < desired_len; i += 4) { + wr[i + 0] = 0; + wr[i + 1] = 0; + wr[i + 2] = 0; + wr[i + 3] = 255; + } + + //find highest value + + float highest_cpu = 0; + float highest_gpu = 0; + + for (int i = 0; i < frame_metrics.size(); i++) { + const Metric &m = frame_metrics[i]; + if (!m.valid) + continue; + + if (m.areas.size()) { + highest_cpu = MAX(highest_cpu, m.areas[m.areas.size() - 1].cpu_time); + highest_gpu = MAX(highest_gpu, m.areas[m.areas.size() - 1].gpu_time); + } + } + + if (highest_cpu > 0 || highest_gpu > 0) { + + if (frame_relative->is_pressed()) { + highest_cpu = MAX(graph_limit, highest_cpu); + highest_gpu = MAX(graph_limit, highest_gpu); + } + + if (linked->is_pressed()) { + float highest = MAX(highest_cpu, highest_gpu); + highest_cpu = highest_gpu = highest; + } + + //means some data exists.. + highest_cpu *= 1.2; //leave some upper room + highest_gpu *= 1.2; //leave some upper room + graph_height_cpu = highest_cpu; + graph_height_gpu = highest_gpu; + + Vector columnv_cpu; + columnv_cpu.resize(h); + Color *column_cpu = columnv_cpu.ptrw(); + + Vector columnv_gpu; + columnv_gpu.resize(h); + Color *column_gpu = columnv_gpu.ptrw(); + + int half_w = w / 2; + for (int i = 0; i < half_w; i++) { + for (int j = 0; j < h; j++) { + column_cpu[j] = Color(0, 0, 0, 0); + column_gpu[j] = Color(0, 0, 0, 0); + } + + int current = i * frame_metrics.size() / half_w; + int next = (i + 1) * frame_metrics.size() / half_w; + if (next > frame_metrics.size()) { + next = frame_metrics.size(); + } + if (next == current) + next = current + 1; //just because for loop must work + + for (int j = current; j < next; j++) { + + //wrap + int idx = last_metric + 1 + j; + while (idx >= frame_metrics.size()) { + idx -= frame_metrics.size(); + } + + int area_count = frame_metrics[idx].areas.size(); + const Metric::Area *areas = frame_metrics[idx].areas.ptr(); + int prev_cpu = 0; + int prev_gpu = 0; + for (int k = 1; k < area_count; k++) { + int ofs_cpu = int(areas[k].cpu_time * h / highest_cpu); + ofs_cpu = CLAMP(ofs_cpu, 0, h - 1); + Color color = selected_area == areas[k - 1].fullpath_cache ? Color(1, 1, 1, 1) : areas[k - 1].color_cache; + + for (int l = prev_cpu; l < ofs_cpu; l++) { + column_cpu[h - l - 1] += color; + } + prev_cpu = ofs_cpu; + + int ofs_gpu = int(areas[k].gpu_time * h / highest_gpu); + ofs_gpu = CLAMP(ofs_gpu, 0, h - 1); + for (int l = prev_gpu; l < ofs_gpu; l++) { + column_gpu[h - l - 1] += color; + } + + prev_gpu = ofs_gpu; + } + } + + //plot CPU + for (int j = 0; j < h; j++) { + + uint8_t r, g, b; + + if (column_cpu[j].a == 0) { + r = 0; + g = 0; + b = 0; + } else { + r = CLAMP((column_cpu[j].r / column_cpu[j].a) * 255.0, 0, 255); + g = CLAMP((column_cpu[j].g / column_cpu[j].a) * 255.0, 0, 255); + b = CLAMP((column_cpu[j].b / column_cpu[j].a) * 255.0, 0, 255); + } + + int widx = (j * w + i) * 4; + wr[widx + 0] = r; + wr[widx + 1] = g; + wr[widx + 2] = b; + wr[widx + 3] = 255; + } + //plot GPU + for (int j = 0; j < h; j++) { + + uint8_t r, g, b; + + if (column_gpu[j].a == 0) { + r = 0; + g = 0; + b = 0; + } else { + r = CLAMP((column_gpu[j].r / column_gpu[j].a) * 255.0, 0, 255); + g = CLAMP((column_gpu[j].g / column_gpu[j].a) * 255.0, 0, 255); + b = CLAMP((column_gpu[j].b / column_gpu[j].a) * 255.0, 0, 255); + } + + int widx = (j * w + w / 2 + i) * 4; + wr[widx + 0] = r; + wr[widx + 1] = g; + wr[widx + 2] = b; + wr[widx + 3] = 255; + } + } + } + + wr.release(); + + Ref img; + img.instance(); + img->create(w, h, 0, Image::FORMAT_RGBA8, graph_image); + + if (reset_texture) { + + if (graph_texture.is_null()) { + graph_texture.instance(); + } + graph_texture->create_from_image(img); + } + + graph_texture->update(img, true); + + graph->set_texture(graph_texture); + graph->update(); +} + +void EditorVisualProfiler::_update_frame(bool p_focus_selected) { + + int cursor_metric = _get_cursor_index(); + + Ref track_icon = get_icon("TrackColor", "EditorIcons"); + + ERR_FAIL_INDEX(cursor_metric, frame_metrics.size()); + + updating_frame = true; + variables->clear(); + + TreeItem *root = variables->create_item(); + const Metric &m = frame_metrics[cursor_metric]; + + List stack; + List categories; + + TreeItem *ensure_selected = nullptr; + + for (int i = 1; i < m.areas.size() - 1; i++) { + + TreeItem *parent = stack.size() ? stack.back()->get() : root; + + String name = m.areas[i].name; + + float cpu_time = m.areas[i].cpu_time; + float gpu_time = m.areas[i].gpu_time; + if (i < m.areas.size() - 1) { + cpu_time = m.areas[i + 1].cpu_time - cpu_time; + gpu_time = m.areas[i + 1].gpu_time - gpu_time; + } + + if (name.begins_with(">")) { + TreeItem *category = variables->create_item(parent); + + stack.push_back(category); + categories.push_back(category); + + name = name.substr(1, name.length()); + + category->set_text(0, name); + category->set_metadata(1, cpu_time); + category->set_metadata(2, gpu_time); + continue; + } + + if (name.begins_with("<")) { + stack.pop_back(); + continue; + } + TreeItem *category = variables->create_item(parent); + + for (List::Element *E = stack.front(); E; E = E->next()) { + float total_cpu = E->get()->get_metadata(1); + float total_gpu = E->get()->get_metadata(2); + total_cpu += cpu_time; + total_gpu += gpu_time; + E->get()->set_metadata(1, cpu_time); + E->get()->set_metadata(2, gpu_time); + } + + category->set_icon(0, track_icon); + category->set_icon_modulate(0, m.areas[i].color_cache); + category->set_selectable(0, true); + category->set_metadata(0, m.areas[i].fullpath_cache); + category->set_text(0, m.areas[i].name); + category->set_text(1, _get_time_as_text(cpu_time)); + category->set_metadata(1, m.areas[i].cpu_time); + category->set_text(2, _get_time_as_text(gpu_time)); + category->set_metadata(2, m.areas[i].gpu_time); + + if (selected_area == m.areas[i].fullpath_cache) { + category->select(0); + if (p_focus_selected) { + ensure_selected = category; + } + } + } + + for (List::Element *E = categories.front(); E; E = E->next()) { + float total_cpu = E->get()->get_metadata(1); + float total_gpu = E->get()->get_metadata(2); + E->get()->set_text(1, _get_time_as_text(total_cpu)); + E->get()->set_text(2, _get_time_as_text(total_gpu)); + } + + if (ensure_selected) { + variables->ensure_cursor_is_visible(); + } + updating_frame = false; +} + +void EditorVisualProfiler::_activate_pressed() { + + if (activate->is_pressed()) { + activate->set_icon(get_icon("Stop", "EditorIcons")); + activate->set_text(TTR("Stop")); + _clear_pressed(); //always clear on start + } else { + activate->set_icon(get_icon("Play", "EditorIcons")); + activate->set_text(TTR("Start")); + } + emit_signal("enable_profiling", activate->is_pressed()); +} + +void EditorVisualProfiler::_clear_pressed() { + + clear(); + _update_plot(); +} + +void EditorVisualProfiler::_notification(int p_what) { + + if (p_what == NOTIFICATION_ENTER_TREE) { + activate->set_icon(get_icon("Play", "EditorIcons")); + clear_button->set_icon(get_icon("Clear", "EditorIcons")); + } +} + +void EditorVisualProfiler::_graph_tex_draw() { + + if (last_metric < 0) + return; + Ref font = get_font("font", "Label"); + if (seeking) { + + int max_frames = frame_metrics.size(); + int frame = cursor_metric_edit->get_value() - (frame_metrics[last_metric].frame_number - max_frames + 1); + if (frame < 0) + frame = 0; + + int half_width = graph->get_size().x / 2; + int cur_x = frame * half_width / max_frames; + //cur_x /= 2.0; + + graph->draw_line(Vector2(cur_x, 0), Vector2(cur_x, graph->get_size().y), Color(1, 1, 1, 0.8)); + graph->draw_line(Vector2(cur_x + half_width, 0), Vector2(cur_x + half_width, graph->get_size().y), Color(1, 1, 1, 0.8)); + } + + if (graph_height_cpu > 0) { + int frame_y = graph->get_size().y - graph_limit * graph->get_size().y / graph_height_cpu - 1; + + int half_width = graph->get_size().x / 2; + + graph->draw_line(Vector2(0, frame_y), Vector2(half_width, frame_y), Color(1, 1, 1, 0.3)); + + String limit_str = String::num(graph_limit, 2); + graph->draw_string(font, Vector2(half_width - font->get_string_size(limit_str).x - 2, frame_y - 2), limit_str, Color(1, 1, 1, 0.6)); + } + + if (graph_height_gpu > 0) { + int frame_y = graph->get_size().y - graph_limit * graph->get_size().y / graph_height_gpu - 1; + + int half_width = graph->get_size().x / 2; + + graph->draw_line(Vector2(half_width, frame_y), Vector2(graph->get_size().x, frame_y), Color(1, 1, 1, 0.3)); + + String limit_str = String::num(graph_limit, 2); + graph->draw_string(font, Vector2(half_width * 2 - font->get_string_size(limit_str).x - 2, frame_y - 2), limit_str, Color(1, 1, 1, 0.6)); + } + + graph->draw_string(font, Vector2(font->get_string_size("X").x, font->get_ascent() + 2), "CPU:", Color(1, 1, 1, 0.8)); + graph->draw_string(font, Vector2(font->get_string_size("X").x + graph->get_size().width / 2, font->get_ascent() + 2), "GPU:", Color(1, 1, 1, 0.8)); + + /* + if (hover_metric != -1 && frame_metrics[hover_metric].valid) { + + int max_frames = frame_metrics.size(); + int frame = frame_metrics[hover_metric].frame_number - (frame_metrics[last_metric].frame_number - max_frames + 1); + if (frame < 0) + frame = 0; + + int cur_x = frame * graph->get_size().x / max_frames; + + graph->draw_line(Vector2(cur_x, 0), Vector2(cur_x, graph->get_size().y), Color(1, 1, 1, 0.4)); + } +*/ +} + +void EditorVisualProfiler::_graph_tex_mouse_exit() { + + hover_metric = -1; + graph->update(); +} + +void EditorVisualProfiler::_cursor_metric_changed(double) { + if (updating_frame) + return; + + graph->update(); + _update_frame(); +} + +void EditorVisualProfiler::_graph_tex_input(const Ref &p_ev) { + + if (last_metric < 0) + return; + + Ref me = p_ev; + Ref mb = p_ev; + Ref mm = p_ev; + + if ( + (mb.is_valid() && mb->get_button_index() == BUTTON_LEFT && mb->is_pressed()) || + (mm.is_valid())) { + + int half_w = graph->get_size().width / 2; + int x = me->get_position().x; + if (x > half_w) { + x -= half_w; + } + x = x * frame_metrics.size() / half_w; + + bool show_hover = x >= 0 && x < frame_metrics.size(); + + if (x < 0) { + x = 0; + } + + if (x >= frame_metrics.size()) { + x = frame_metrics.size() - 1; + } + + int metric = frame_metrics.size() - x - 1; + metric = last_metric - metric; + while (metric < 0) { + metric += frame_metrics.size(); + } + + if (show_hover) { + + hover_metric = metric; + + } else { + hover_metric = -1; + } + + if (mb.is_valid() || mm->get_button_mask() & BUTTON_MASK_LEFT) { + //cursor_metric=x; + updating_frame = true; + + //metric may be invalid, so look for closest metric that is valid, this makes snap feel better + bool valid = false; + for (int i = 0; i < frame_metrics.size(); i++) { + + if (frame_metrics[metric].valid) { + valid = true; + break; + } + + metric++; + if (metric >= frame_metrics.size()) + metric = 0; + } + + if (!valid) { + return; + } + + cursor_metric_edit->set_value(frame_metrics[metric].frame_number); + + updating_frame = false; + + if (activate->is_pressed()) { + if (!seeking) { + //probably not need to break request, can just stop profiling + //emit_signal("break_request"); + } + } + + seeking = true; + + if (!frame_delay->is_processing()) { + frame_delay->set_wait_time(0.1); + frame_delay->start(); + } + + bool touched_cpu = me->get_position().x < graph->get_size().width * 0.5; + + const Metric::Area *areas = frame_metrics[metric].areas.ptr(); + int area_count = frame_metrics[metric].areas.size(); + float posy = (1.0 - (me->get_position().y / graph->get_size().height)) * (touched_cpu ? graph_height_cpu : graph_height_gpu); + int last_valid = -1; + bool found = false; + for (int i = 0; i < area_count - 1; i++) { + + if (areas[i].name[0] != '<' && areas[i].name[0] != '>') { + last_valid = i; + } + float h = touched_cpu ? areas[i + 1].cpu_time : areas[i + 1].gpu_time; + + if (h > posy) { + found = true; + break; + } + } + + StringName area_found; + if (found && last_valid != -1) { + area_found = areas[last_valid].fullpath_cache; + } + + if (area_found != selected_area) { + selected_area = area_found; + _update_frame(true); + _update_plot(); + } + } + + graph->update(); + } +} + +int EditorVisualProfiler::_get_cursor_index() const { + + if (last_metric < 0) + return 0; + if (!frame_metrics[last_metric].valid) + return 0; + + int diff = (frame_metrics[last_metric].frame_number - cursor_metric_edit->get_value()); + + int idx = last_metric - diff; + while (idx < 0) { + idx += frame_metrics.size(); + } + + return idx; +} + +void EditorVisualProfiler::disable_seeking() { + + seeking = false; + graph->update(); +} + +void EditorVisualProfiler::_combo_changed(int) { + + _update_frame(); + _update_plot(); +} + +void EditorVisualProfiler::_bind_methods() { + + ClassDB::bind_method(D_METHOD("_update_frame"), &EditorVisualProfiler::_update_frame, DEFVAL(false)); + ClassDB::bind_method(D_METHOD("_update_plot"), &EditorVisualProfiler::_update_plot); + ClassDB::bind_method(D_METHOD("_activate_pressed"), &EditorVisualProfiler::_activate_pressed); + ClassDB::bind_method(D_METHOD("_clear_pressed"), &EditorVisualProfiler::_clear_pressed); + ClassDB::bind_method(D_METHOD("_graph_tex_draw"), &EditorVisualProfiler::_graph_tex_draw); + ClassDB::bind_method(D_METHOD("_graph_tex_input"), &EditorVisualProfiler::_graph_tex_input); + ClassDB::bind_method(D_METHOD("_graph_tex_mouse_exit"), &EditorVisualProfiler::_graph_tex_mouse_exit); + ClassDB::bind_method(D_METHOD("_cursor_metric_changed"), &EditorVisualProfiler::_cursor_metric_changed); + ClassDB::bind_method(D_METHOD("_combo_changed"), &EditorVisualProfiler::_combo_changed); + + ClassDB::bind_method(D_METHOD("_item_selected"), &EditorVisualProfiler::_item_selected); + ADD_SIGNAL(MethodInfo("enable_profiling", PropertyInfo(Variant::BOOL, "enable"))); + ADD_SIGNAL(MethodInfo("break_request")); +} + +void EditorVisualProfiler::set_enabled(bool p_enable) { + + activate->set_disabled(!p_enable); +} + +bool EditorVisualProfiler::is_profiling() { + return activate->is_pressed(); +} + +Vector > EditorVisualProfiler::get_data_as_csv() const { + Vector > res; +#if 0 + if (frame_metrics.empty()) { + return res; + } + + // signatures + Vector signatures; + const Vector &categories = frame_metrics[0].categories; + + for (int j = 0; j < categories.size(); j++) { + + const EditorFrameProfiler::Metric::Category &c = categories[j]; + signatures.push_back(c.signature); + + for (int k = 0; k < c.items.size(); k++) { + signatures.push_back(c.items[k].signature); + } + } + res.push_back(signatures); + + // values + Vector values; + values.resize(signatures.size()); + + int index = last_metric; + + for (int i = 0; i < frame_metrics.size(); i++) { + + ++index; + + if (index >= frame_metrics.size()) { + index = 0; + } + + if (!frame_metrics[index].valid) { + continue; + } + int it = 0; + const Vector &frame_cat = frame_metrics[index].categories; + + for (int j = 0; j < frame_cat.size(); j++) { + + const EditorFrameProfiler::Metric::Category &c = frame_cat[j]; + values.write[it++] = String::num_real(c.total_time); + + for (int k = 0; k < c.items.size(); k++) { + values.write[it++] = String::num_real(c.items[k].total); + } + } + res.push_back(values); + } +#endif + return res; +} + +EditorVisualProfiler::EditorVisualProfiler() { + + HBoxContainer *hb = memnew(HBoxContainer); + add_child(hb); + activate = memnew(Button); + activate->set_toggle_mode(true); + activate->set_text(TTR("Start")); + activate->connect("pressed", this, "_activate_pressed"); + hb->add_child(activate); + + clear_button = memnew(Button); + clear_button->set_text(TTR("Clear")); + clear_button->connect("pressed", this, "_clear_pressed"); + hb->add_child(clear_button); + + hb->add_child(memnew(Label(TTR("Measure:")))); + + display_mode = memnew(OptionButton); + display_mode->add_item(TTR("Frame Time (msec)")); + display_mode->add_item(TTR("Frame %")); + display_mode->connect("item_selected", this, "_combo_changed"); + + hb->add_child(display_mode); + + frame_relative = memnew(CheckBox(TTR("Fit to Frame"))); + frame_relative->set_pressed(true); + hb->add_child(frame_relative); + frame_relative->connect("pressed", this, "_update_plot"); + linked = memnew(CheckBox(TTR("Linked"))); + linked->set_pressed(true); + hb->add_child(linked); + linked->connect("pressed", this, "_update_plot"); + + hb->add_spacer(); + + hb->add_child(memnew(Label(TTR("Frame #:")))); + + cursor_metric_edit = memnew(SpinBox); + cursor_metric_edit->set_h_size_flags(SIZE_FILL); + hb->add_child(cursor_metric_edit); + cursor_metric_edit->connect("value_changed", this, "_cursor_metric_changed"); + + hb->add_constant_override("separation", 8 * EDSCALE); + + h_split = memnew(HSplitContainer); + add_child(h_split); + h_split->set_v_size_flags(SIZE_EXPAND_FILL); + + variables = memnew(Tree); + variables->set_custom_minimum_size(Size2(300, 0) * EDSCALE); + variables->set_hide_folding(true); + h_split->add_child(variables); + variables->set_hide_root(true); + variables->set_columns(3); + variables->set_column_titles_visible(true); + variables->set_column_title(0, TTR("Name")); + variables->set_column_expand(0, true); + variables->set_column_min_width(0, 60); + variables->set_column_title(1, TTR("CPU")); + variables->set_column_expand(1, false); + variables->set_column_min_width(1, 60 * EDSCALE); + variables->set_column_title(2, TTR("GPU")); + variables->set_column_expand(2, false); + variables->set_column_min_width(2, 60 * EDSCALE); + variables->connect("cell_selected", this, "_item_selected"); + + graph = memnew(TextureRect); + graph->set_expand(true); + graph->set_mouse_filter(MOUSE_FILTER_STOP); + //graph->set_ignore_mouse(false); + graph->connect("draw", this, "_graph_tex_draw"); + graph->connect("gui_input", this, "_graph_tex_input"); + graph->connect("mouse_exited", this, "_graph_tex_mouse_exit"); + + h_split->add_child(graph); + graph->set_h_size_flags(SIZE_EXPAND_FILL); + + int metric_size = CLAMP(int(EDITOR_DEF("debugger/profiler_frame_history_size", 600)), 60, 1024); + frame_metrics.resize(metric_size); + last_metric = -1; + //cursor_metric=-1; + hover_metric = -1; + + //display_mode=DISPLAY_FRAME_TIME; + + frame_delay = memnew(Timer); + frame_delay->set_wait_time(0.1); + frame_delay->set_one_shot(true); + add_child(frame_delay); + frame_delay->connect("timeout", this, "_update_frame"); + + plot_delay = memnew(Timer); + plot_delay->set_wait_time(0.1); + plot_delay->set_one_shot(true); + add_child(plot_delay); + plot_delay->connect("timeout", this, "_update_plot"); + + seeking = false; + graph_height_cpu = 1; + graph_height_gpu = 1; + + graph_limit = 1000 / 60.0; + + //activate->set_disabled(true); +} diff --git a/editor/editor_visual_profiler.h b/editor/editor_visual_profiler.h new file mode 100644 index 0000000000..e5e5688997 --- /dev/null +++ b/editor/editor_visual_profiler.h @@ -0,0 +1,124 @@ +#ifndef EDITOR_FRAME_PROFILER_H +#define EDITOR_FRAME_PROFILER_H + +#include "scene/gui/box_container.h" +#include "scene/gui/button.h" +#include "scene/gui/check_box.h" +#include "scene/gui/label.h" +#include "scene/gui/option_button.h" +#include "scene/gui/spin_box.h" +#include "scene/gui/split_container.h" +#include "scene/gui/texture_rect.h" +#include "scene/gui/tree.h" + +class EditorVisualProfiler : public VBoxContainer { + + GDCLASS(EditorVisualProfiler, VBoxContainer); + +public: + struct Metric { + + bool valid; + + uint64_t frame_number; + + struct Area { + String name; + Color color_cache; + StringName fullpath_cache; + float cpu_time = 0; + float gpu_time = 0; + }; + + Vector areas; + + Metric() { + valid = false; + } + }; + + enum DisplayTimeMode { + DISPLAY_FRAME_TIME, + DISPLAY_FRAME_PERCENT, + }; + +private: + Button *activate; + Button *clear_button; + + TextureRect *graph; + Ref graph_texture; + PoolVector graph_image; + Tree *variables; + HSplitContainer *h_split; + CheckBox *frame_relative; + CheckBox *linked; + + OptionButton *display_mode; + + SpinBox *cursor_metric_edit; + + Vector frame_metrics; + int last_metric; + + StringName selected_area; + + bool updating_frame; + + //int cursor_metric; + int hover_metric; + + float graph_height_cpu; + float graph_height_gpu; + + float graph_limit; + + bool seeking; + + Timer *frame_delay; + Timer *plot_delay; + + void _update_frame(bool p_focus_selected = false); + + void _activate_pressed(); + void _clear_pressed(); + + String _get_time_as_text(float p_time); + + //void _make_metric_ptrs(Metric &m); + void _item_selected(); + + void _update_plot(); + + void _graph_tex_mouse_exit(); + + void _graph_tex_draw(); + void _graph_tex_input(const Ref &p_ev); + + int _get_cursor_index() const; + + Color _get_color_from_signature(const StringName &p_signature) const; + + void _cursor_metric_changed(double); + + void _combo_changed(int); + +protected: + void _notification(int p_what); + static void _bind_methods(); + +public: + void add_frame_metric(const Metric &p_metric); + void set_enabled(bool p_enable); + bool is_profiling(); + bool is_seeking() { return seeking; } + void disable_seeking(); + + void clear(); + + Vector > get_data_as_csv() const; + + EditorVisualProfiler(); +}; + +#endif // EDITOR_FRAME_PROFILER_H diff --git a/editor/icons/icon_track_color.svg b/editor/icons/icon_track_color.svg new file mode 100644 index 0000000000..6a736c7a84 --- /dev/null +++ b/editor/icons/icon_track_color.svg @@ -0,0 +1,61 @@ + + + + + + image/svg+xml + + + + + + + + + diff --git a/editor/script_editor_debugger.cpp b/editor/script_editor_debugger.cpp index 3d73124dd7..fe6f92f0a5 100644 --- a/editor/script_editor_debugger.cpp +++ b/editor/script_editor_debugger.cpp @@ -35,8 +35,9 @@ #include "core/ustring.h" #include "editor/plugins/canvas_item_editor_plugin.h" #include "editor/plugins/spatial_editor_plugin.h" -#include "editor_log.h" -#include "editor_network_profiler.h" +#include "editor/editor_log.h" +#include "editor/editor_network_profiler.h" +#include "editor/editor_visual_profiler.h" #include "editor_node.h" #include "editor_profiler.h" #include "editor_scale.h" @@ -833,6 +834,32 @@ void ScriptEditorDebugger::_parse_message(const String &p_msg, const Array &p_da } perf_history.push_front(p); perf_draw->update(); + } else if (p_msg == "visual_profile") { + uint64_t frame = p_data[0]; + PoolVector names = p_data[1]; + PoolVector values = p_data[2]; + + EditorVisualProfiler::Metric metric; + metric.areas.resize(names.size()); + metric.frame_number = frame; + metric.valid = true; + + { + EditorVisualProfiler::Metric::Area *areas_ptr = metric.areas.ptrw(); + int metric_count = names.size(); + + PoolVector::Read rs = names.read(); + PoolVector::Read rr = values.read(); + + for (int i = 0; i < metric_count; i++) { + + areas_ptr[i].name = rs[i]; + areas_ptr[i].cpu_time = rr[i * 2 + 0]; + areas_ptr[i].gpu_time = rr[i * 2 + 1]; + } + } + + visual_profiler->add_frame_metric(metric); } else if (p_msg == "error") { @@ -1565,12 +1592,33 @@ void ScriptEditorDebugger::_profiler_activate(bool p_enable) { } } +void ScriptEditorDebugger::_visual_profiler_activate(bool p_enable) { + + if (!connection.is_valid()) + return; + + if (p_enable) { + profiler_signature.clear(); + Array msg; + msg.push_back("start_visual_profiling"); + ppeer->put_var(msg); + print_verbose("Starting visual profiling."); + + } else { + Array msg; + msg.push_back("stop_visual_profiling"); + ppeer->put_var(msg); + print_verbose("Ending visual profiling."); + } +} + void ScriptEditorDebugger::_network_profiler_activate(bool p_enable) { if (!connection.is_valid()) return; if (p_enable) { + profiler_signature.clear(); Array msg; msg.push_back("start_network_profiling"); ppeer->put_var(msg); @@ -2224,6 +2272,7 @@ void ScriptEditorDebugger::_bind_methods() { ClassDB::bind_method(D_METHOD("_expand_errors_list"), &ScriptEditorDebugger::_expand_errors_list); ClassDB::bind_method(D_METHOD("_collapse_errors_list"), &ScriptEditorDebugger::_collapse_errors_list); ClassDB::bind_method(D_METHOD("_profiler_activate"), &ScriptEditorDebugger::_profiler_activate); + ClassDB::bind_method(D_METHOD("_visual_profiler_activate"), &ScriptEditorDebugger::_visual_profiler_activate); ClassDB::bind_method(D_METHOD("_network_profiler_activate"), &ScriptEditorDebugger::_network_profiler_activate); ClassDB::bind_method(D_METHOD("_profiler_seeked"), &ScriptEditorDebugger::_profiler_seeked); ClassDB::bind_method(D_METHOD("_clear_errors_list"), &ScriptEditorDebugger::_clear_errors_list); @@ -2455,11 +2504,20 @@ ScriptEditorDebugger::ScriptEditorDebugger(EditorNode *p_editor) { profiler->connect("break_request", this, "_profiler_seeked"); } + { //frame profiler + visual_profiler = memnew(EditorVisualProfiler); + visual_profiler->set_name(TTR("Visual Profiler")); + tabs->add_child(visual_profiler); + visual_profiler->connect("enable_profiling", this, "_visual_profiler_activate"); + visual_profiler->connect("break_request", this, "_profiler_seeked"); + } + { //network profiler network_profiler = memnew(EditorNetworkProfiler); network_profiler->set_name(TTR("Network Profiler")); tabs->add_child(network_profiler); network_profiler->connect("enable_profiling", this, "_network_profiler_activate"); + network_profiler->connect("break_request", this, "_profiler_seeked"); } { //monitors diff --git a/editor/script_editor_debugger.h b/editor/script_editor_debugger.h index 589a011bff..5a821a4a88 100644 --- a/editor/script_editor_debugger.h +++ b/editor/script_editor_debugger.h @@ -51,6 +51,7 @@ class TreeItem; class HSplitContainer; class ItemList; class EditorProfiler; +class EditorVisualProfiler; class EditorNetworkProfiler; class ScriptEditorDebuggerInspectedObject; @@ -169,6 +170,7 @@ private: Map res_path_cache; EditorProfiler *profiler; + EditorVisualProfiler *visual_profiler; EditorNetworkProfiler *network_profiler; EditorNode *editor; @@ -213,6 +215,7 @@ private: void _expand_errors_list(); void _collapse_errors_list(); + void _visual_profiler_activate(bool p_enable); void _profiler_activate(bool p_enable); void _profiler_seeked(); diff --git a/scene/debugger/script_debugger_remote.cpp b/scene/debugger/script_debugger_remote.cpp index 0a075df060..3608a11ed7 100644 --- a/scene/debugger/script_debugger_remote.cpp +++ b/scene/debugger/script_debugger_remote.cpp @@ -805,14 +805,22 @@ void ScriptDebuggerRemote::_poll_events() { profiling = false; _send_profiling_data(false); print_line("PROFILING END!"); + } else if (command == "start_visual_profiling") { + + visual_profiling = true; + VS::get_singleton()->set_frame_profiling_enabled(true); + } else if (command == "stop_visual_profiling") { + + visual_profiling = false; + VS::get_singleton()->set_frame_profiling_enabled(false); } else if (command == "start_network_profiling") { + network_profiling = true; multiplayer->profiling_start(); - profiling_network = true; } else if (command == "stop_network_profiling") { + network_profiling = false; multiplayer->profiling_end(); - profiling_network = false; } else if (command == "override_camera_2D:set") { bool enforce = cmd[1]; @@ -985,6 +993,30 @@ void ScriptDebuggerRemote::idle_poll() { packet_peer_stream->put_var(arr); } } + if (visual_profiling) { + Vector profile_areas = VS::get_singleton()->get_frame_profile(); + if (profile_areas.size()) { + PoolVector area_names; + PoolVector area_times; + area_names.resize(profile_areas.size()); + area_times.resize(profile_areas.size() * 2); + { + PoolVector::Write area_namesw = area_names.write(); + PoolVector::Write area_timesw = area_times.write(); + + for (int i = 0; i < profile_areas.size(); i++) { + area_namesw[i] = profile_areas[i].name; + area_timesw[i * 2 + 0] = profile_areas[i].cpu_msec; + area_timesw[i * 2 + 1] = profile_areas[i].gpu_msec; + } + } + packet_peer_stream->put_var("visual_profile"); + packet_peer_stream->put_var(3); + packet_peer_stream->put_var(VS::get_singleton()->get_frame_profile_frame()); + packet_peer_stream->put_var(area_names); + packet_peer_stream->put_var(area_times); + } + } if (profiling) { @@ -996,7 +1028,7 @@ void ScriptDebuggerRemote::idle_poll() { } } - if (profiling_network) { + if (network_profiling) { uint64_t pt = OS::get_singleton()->get_ticks_msec(); if (pt - last_net_bandwidth_time > 200) { last_net_bandwidth_time = pt; @@ -1229,7 +1261,8 @@ ScriptDebuggerRemote::ResourceUsageFunc ScriptDebuggerRemote::resource_usage_fun ScriptDebuggerRemote::ScriptDebuggerRemote() : profiling(false), - profiling_network(false), + visual_profiling(false), + network_profiling(false), max_frame_functions(16), skip_profile_frame(false), reload_all_scripts(false), diff --git a/scene/debugger/script_debugger_remote.h b/scene/debugger/script_debugger_remote.h index 2c0dccdaf7..ae44bf9ca2 100644 --- a/scene/debugger/script_debugger_remote.h +++ b/scene/debugger/script_debugger_remote.h @@ -62,7 +62,8 @@ class ScriptDebuggerRemote : public ScriptDebugger { float frame_time, idle_time, physics_time, physics_frame_time; bool profiling; - bool profiling_network; + bool visual_profiling; + bool network_profiling; int max_frame_functions; bool skip_profile_frame; bool reload_all_scripts; diff --git a/servers/visual/rasterizer.h b/servers/visual/rasterizer.h index f5ce604b04..02d44c5c5d 100644 --- a/servers/visual/rasterizer.h +++ b/servers/visual/rasterizer.h @@ -638,6 +638,20 @@ public: Color get_default_clear_color() const { return default_clear_color; } +#define RENDER_TIMESTAMP(m_text) \ + { \ + if (VSG::storage->capturing_timestamps) VSG::storage->capture_timestamp(m_text); \ + } + + bool capturing_timestamps = false; + + virtual void capture_timestamps_begin() = 0; + virtual void capture_timestamp(const String &p_name) = 0; + virtual uint32_t get_captured_timestamps_count() const = 0; + virtual uint64_t get_captured_timestamps_frame() const = 0; + virtual uint64_t get_captured_timestamp_gpu_time(uint32_t p_index) const = 0; + virtual uint64_t get_captured_timestamp_cpu_time(uint32_t p_index) const = 0; + virtual String get_captured_timestamp_name(uint32_t p_index) const = 0; RasterizerStorage(); virtual ~RasterizerStorage() {} diff --git a/servers/visual/rasterizer_rd/rasterizer_scene_forward_rd.cpp b/servers/visual/rasterizer_rd/rasterizer_scene_forward_rd.cpp index 82a5d8ba65..2ef331291a 100644 --- a/servers/visual/rasterizer_rd/rasterizer_scene_forward_rd.cpp +++ b/servers/visual/rasterizer_rd/rasterizer_scene_forward_rd.cpp @@ -1654,6 +1654,8 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co } #endif + RENDER_TIMESTAMP("Setup 3D Scene"); + bool using_shadows = true; if (p_reflection_probe.is_valid()) { @@ -2085,6 +2087,8 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co } } + RENDER_TIMESTAMP("Render Opaque Pass"); + _setup_render_base_uniform_set(RID(), RID(), RID(), RID(), radiance_cubemap, p_shadow_atlas, p_reflection_atlas); render_list.sort_by_key(false); @@ -2104,6 +2108,7 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co } if (draw_sky) { + RENDER_TIMESTAMP("Render Sky"); RD::DrawListID draw_list = RD::get_singleton()->draw_list_begin(opaque_framebuffer, RD::INITIAL_ACTION_CONTINUE, can_continue ? RD::FINAL_ACTION_CONTINUE : RD::FINAL_ACTION_READ_COLOR_AND_DEPTH); _draw_sky(draw_list, RD::get_singleton()->framebuffer_get_format(opaque_framebuffer), p_environment, p_cam_projection, p_cam_transform, 1.0); RD::get_singleton()->draw_list_end(); @@ -2201,6 +2206,9 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co glEnable(GL_DEPTH_TEST); glDisable(GL_SCISSOR_TEST); #endif + + RENDER_TIMESTAMP("Render Transparent Pass"); + render_list.sort_by_reverse_depth_and_priority(true); _fill_instances(&render_list.elements[render_list.max_elements - render_list.alpha_element_count], render_list.alpha_element_count); @@ -2232,6 +2240,7 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co RasterizerEffectsRD *effects = storage->get_effects(); { + RENDER_TIMESTAMP("Tonemap"); //tonemap RasterizerEffectsRD::TonemapSettings tonemap; @@ -2326,6 +2335,8 @@ void RasterizerSceneForwardRD::_render_scene(RenderBufferData *p_buffer_data, co } void RasterizerSceneForwardRD::_render_shadow(RID p_framebuffer, InstanceBase **p_cull_result, int p_cull_count, const CameraMatrix &p_projection, const Transform &p_transform, float p_zfar, float p_bias, float p_normal_bias, bool p_use_dp, bool p_use_dp_flip) { + RENDER_TIMESTAMP("Setup Rendering Shadow"); + render_pass++; scene_state.ubo.shadow_z_offset = p_bias; @@ -2343,6 +2354,8 @@ void RasterizerSceneForwardRD::_render_shadow(RID p_framebuffer, InstanceBase ** _setup_render_base_uniform_set(RID(), RID(), RID(), RID(), RID(), RID(), RID()); + RENDER_TIMESTAMP("Render Shadow"); + render_list.sort_by_key(false); _fill_instances(render_list.elements, render_list.element_count); diff --git a/servers/visual/rasterizer_rd/rasterizer_storage_rd.cpp b/servers/visual/rasterizer_rd/rasterizer_storage_rd.cpp index e73efa1e12..639b78ec79 100644 --- a/servers/visual/rasterizer_rd/rasterizer_storage_rd.cpp +++ b/servers/visual/rasterizer_rd/rasterizer_storage_rd.cpp @@ -3656,6 +3656,31 @@ RasterizerEffectsRD *RasterizerStorageRD::get_effects() { return &effects; } +void RasterizerStorageRD::capture_timestamps_begin() { + RD::get_singleton()->capture_timestamp("Frame Begin", false); +} + +void RasterizerStorageRD::capture_timestamp(const String &p_name) { + RD::get_singleton()->capture_timestamp(p_name, true); +} + +uint32_t RasterizerStorageRD::get_captured_timestamps_count() const { + return RD::get_singleton()->get_captured_timestamps_count(); +} +uint64_t RasterizerStorageRD::get_captured_timestamps_frame() const { + return RD::get_singleton()->get_captured_timestamps_frame(); +} + +uint64_t RasterizerStorageRD::get_captured_timestamp_gpu_time(uint32_t p_index) const { + return RD::get_singleton()->get_captured_timestamp_gpu_time(p_index); +} +uint64_t RasterizerStorageRD::get_captured_timestamp_cpu_time(uint32_t p_index) const { + return RD::get_singleton()->get_captured_timestamp_cpu_time(p_index); +} +String RasterizerStorageRD::get_captured_timestamp_name(uint32_t p_index) const { + return RD::get_singleton()->get_captured_timestamp_name(p_index); +} + RasterizerStorageRD::RasterizerStorageRD() { for (int i = 0; i < SHADER_TYPE_MAX; i++) { diff --git a/servers/visual/rasterizer_rd/rasterizer_storage_rd.h b/servers/visual/rasterizer_rd/rasterizer_storage_rd.h index ef22a6689b..670c97a1c1 100644 --- a/servers/visual/rasterizer_rd/rasterizer_storage_rd.h +++ b/servers/visual/rasterizer_rd/rasterizer_storage_rd.h @@ -1018,6 +1018,14 @@ public: String get_video_adapter_name() const { return String(); } String get_video_adapter_vendor() const { return String(); } + virtual void capture_timestamps_begin(); + virtual void capture_timestamp(const String &p_name); + virtual uint32_t get_captured_timestamps_count() const; + virtual uint64_t get_captured_timestamps_frame() const; + virtual uint64_t get_captured_timestamp_gpu_time(uint32_t p_index) const; + virtual uint64_t get_captured_timestamp_cpu_time(uint32_t p_index) const; + virtual String get_captured_timestamp_name(uint32_t p_index) const; + static RasterizerStorage *base_singleton; RasterizerEffectsRD *get_effects(); diff --git a/servers/visual/rendering_device.h b/servers/visual/rendering_device.h index 32d5520c0a..859a9e798c 100644 --- a/servers/visual/rendering_device.h +++ b/servers/visual/rendering_device.h @@ -936,6 +936,17 @@ public: virtual void free(RID p_id) = 0; + /****************/ + /**** Timing ****/ + /****************/ + + virtual void capture_timestamp(const String &p_name, bool p_sync_to_draw) = 0; + virtual uint32_t get_captured_timestamps_count() const = 0; + virtual uint64_t get_captured_timestamps_frame() const = 0; + virtual uint64_t get_captured_timestamp_gpu_time(uint32_t p_index) const = 0; + virtual uint64_t get_captured_timestamp_cpu_time(uint32_t p_index) const = 0; + virtual String get_captured_timestamp_name(uint32_t p_index) const = 0; + /****************/ /**** LIMITS ****/ /****************/ @@ -976,6 +987,7 @@ public: virtual void prepare_screen_for_drawing() = 0; virtual void finalize_frame() = 0; virtual void advance_frame() = 0; + virtual uint32_t get_frame_delay() const = 0; static RenderingDevice *get_singleton(); diff --git a/servers/visual/visual_server_canvas.cpp b/servers/visual/visual_server_canvas.cpp index 80d7f70f2b..69f843eb4b 100644 --- a/servers/visual/visual_server_canvas.cpp +++ b/servers/visual/visual_server_canvas.cpp @@ -37,6 +37,8 @@ static const int z_range = VS::CANVAS_ITEM_Z_MAX - VS::CANVAS_ITEM_Z_MIN + 1; void VisualServerCanvas::_render_canvas_item_tree(RID p_to_render_target, Canvas::ChildItem *p_child_items, int p_child_item_count, Item *p_canvas_item, const Transform2D &p_transform, const Rect2 &p_clip_rect, const Color &p_modulate, RasterizerCanvas::Light *p_lights) { + RENDER_TIMESTAMP("Cull CanvasItem Tree"); + memset(z_list, 0, z_range * sizeof(RasterizerCanvas::Item *)); memset(z_last_list, 0, z_range * sizeof(RasterizerCanvas::Item *)); @@ -62,6 +64,8 @@ void VisualServerCanvas::_render_canvas_item_tree(RID p_to_render_target, Canvas } } + RENDER_TIMESTAMP("Render Canvas Items"); + VSG::canvas_render->canvas_render_items(p_to_render_target, list, p_modulate, p_lights, p_transform); } @@ -240,6 +244,8 @@ void VisualServerCanvas::_light_mask_canvas_items(int p_z, RasterizerCanvas::Ite void VisualServerCanvas::render_canvas(RID p_render_target, Canvas *p_canvas, const Transform2D &p_transform, RasterizerCanvas::Light *p_lights, RasterizerCanvas::Light *p_masked_lights, const Rect2 &p_clip_rect) { + RENDER_TIMESTAMP(">Render Canvas"); + if (p_canvas->children_order_dirty) { p_canvas->child_items.sort(); @@ -286,6 +292,8 @@ void VisualServerCanvas::render_canvas(RID p_render_target, Canvas *p_canvas, co } } } + + RENDER_TIMESTAMP("begin_frame(frame_step); + VSG::storage->capture_timestamps_begin(); + VSG::scene_render->update(); //update scenes stuff before updating instances VSG::scene->update_dirty_instances(); //update scene stuff - VSG::viewport->draw_viewports(); VSG::scene->render_probes(); + VSG::viewport->draw_viewports(); VSG::canvas_render->update(); _draw_margins(); @@ -130,6 +132,25 @@ void VisualServerRaster::draw(bool p_swap_buffers, double frame_step) { frame_drawn_callbacks.pop_front(); } VS::get_singleton()->emit_signal("frame_post_draw"); + + if (VSG::storage->get_captured_timestamps_count()) { + Vector new_profile; + new_profile.resize(VSG::storage->get_captured_timestamps_count()); + + uint64_t base_cpu = VSG::storage->get_captured_timestamp_cpu_time(0); + uint64_t base_gpu = VSG::storage->get_captured_timestamp_gpu_time(0); + for (int i = 0; i < VSG::storage->get_captured_timestamps_count(); i++) { + uint64_t time_cpu = VSG::storage->get_captured_timestamp_cpu_time(i) - base_cpu; + uint64_t time_gpu = VSG::storage->get_captured_timestamp_gpu_time(i) - base_gpu; + new_profile.write[i].gpu_msec = float(time_gpu / 1000) / 1000.0; + new_profile.write[i].cpu_msec = float(time_cpu) / 1000.0; + new_profile.write[i].name = VSG::storage->get_captured_timestamp_name(i); + } + + frame_profile = new_profile; + } + + frame_profile_frame = VSG::storage->get_captured_timestamps_frame(); } void VisualServerRaster::sync() { } @@ -167,6 +188,18 @@ String VisualServerRaster::get_video_adapter_vendor() const { return VSG::storage->get_video_adapter_vendor(); } +void VisualServerRaster::set_frame_profiling_enabled(bool p_enable) { + VSG::storage->capturing_timestamps = p_enable; +} + +uint64_t VisualServerRaster::get_frame_profile_frame() { + return frame_profile_frame; +} + +Vector VisualServerRaster::get_frame_profile() { + return frame_profile; +} + /* TESTING */ void VisualServerRaster::set_boot_image(const Ref &p_image, const Color &p_color, bool p_scale, bool p_use_filter) { @@ -217,6 +250,8 @@ VisualServerRaster::VisualServerRaster() { VSG::canvas_render = VSG::rasterizer->get_canvas(); VSG::scene_render = VSG::rasterizer->get_scene(); + frame_profile_frame = 0; + for (int i = 0; i < 4; i++) { black_margin[i] = 0; black_image[i] = RID(); diff --git a/servers/visual/visual_server_raster.h b/servers/visual/visual_server_raster.h index 8543289083..510296f11c 100644 --- a/servers/visual/visual_server_raster.h +++ b/servers/visual/visual_server_raster.h @@ -72,6 +72,9 @@ class VisualServerRaster : public VisualServer { void _draw_margins(); static void _changes_changed() {} + uint64_t frame_profile_frame; + Vector frame_profile; + public: //if editor is redrawing when it shouldn't, enable this and put a breakpoint in _changes_changed() //#define DEBUG_CHANGES @@ -693,6 +696,10 @@ public: virtual String get_video_adapter_name() const; virtual String get_video_adapter_vendor() const; + virtual void set_frame_profiling_enabled(bool p_enable); + virtual Vector get_frame_profile(); + virtual uint64_t get_frame_profile_frame(); + virtual RID get_test_cube(); /* TESTING */ diff --git a/servers/visual/visual_server_scene.cpp b/servers/visual/visual_server_scene.cpp index 96831d1cc2..f240f91b12 100644 --- a/servers/visual/visual_server_scene.cpp +++ b/servers/visual/visual_server_scene.cpp @@ -1366,6 +1366,8 @@ bool VisualServerScene::_light_instance_update_shadow(Instance *p_instance, cons for (int i = 0; i < splits; i++) { + RENDER_TIMESTAMP("Culling Directional Light split" + itos(i)); + // setup a camera matrix for that range! CameraMatrix camera_matrix; @@ -1551,6 +1553,7 @@ bool VisualServerScene::_light_instance_update_shadow(Instance *p_instance, cons for (int i = 0; i < 2; i++) { //using this one ensures that raster deferred will have it + RENDER_TIMESTAMP("Culling Shadow Paraboloid" + itos(i)); float radius = VSG::storage->light_get_param(p_instance->base, VS::LIGHT_PARAM_RANGE); @@ -1594,6 +1597,7 @@ bool VisualServerScene::_light_instance_update_shadow(Instance *p_instance, cons for (int i = 0; i < 6; i++) { + RENDER_TIMESTAMP("Culling Shadow Cube side" + itos(i)); //using this one ensures that raster deferred will have it static const Vector3 view_normals[6] = { @@ -1647,6 +1651,8 @@ bool VisualServerScene::_light_instance_update_shadow(Instance *p_instance, cons } break; case VS::LIGHT_SPOT: { + RENDER_TIMESTAMP("Culling Spot Light"); + float radius = VSG::storage->light_get_param(p_instance->base, VS::LIGHT_PARAM_RANGE); float angle = VSG::storage->light_get_param(p_instance->base, VS::LIGHT_PARAM_SPOT_ANGLE); @@ -1829,6 +1835,8 @@ void VisualServerScene::_prepare_scene(const Transform p_cam_transform, const Ca VSG::scene_render->set_scene_pass(render_pass); + RENDER_TIMESTAMP("Frustum Culling"); + //rasterizer->set_camera(camera->transform, camera_matrix,ortho); Vector planes = p_cam_projection.get_projection_planes(p_cam_transform); @@ -2037,7 +2045,11 @@ void VisualServerScene::_prepare_scene(const Transform p_cam_transform, const Ca for (int i = 0; i < directional_shadow_count; i++) { + RENDER_TIMESTAMP(">Rendering Directional Light " + itos(i)); + _light_instance_update_shadow(lights_with_shadow[i], p_cam_transform, p_cam_projection, p_cam_orthogonal, p_shadow_atlas, scenario); + + RENDER_TIMESTAMP("Rendering Light " + itos(i)); light->shadow_dirty = _light_instance_update_shadow(ins, p_cam_transform, p_cam_projection, p_cam_orthogonal, p_shadow_atlas, scenario); + RENDER_TIMESTAMP("render_scene(p_render_buffers, p_cam_transform, p_cam_projection, p_cam_orthogonal, (RasterizerScene::InstanceBase **)instance_cull_result, instance_cull_count, light_instance_cull_result, light_cull_count + directional_light_count, reflection_probe_instance_cull_result, reflection_probe_cull_count, environment, p_shadow_atlas, p_reflection_probe.is_valid() ? RID() : scenario->reflection_atlas, p_reflection_probe, p_reflection_probe_pass); } @@ -2172,6 +2187,7 @@ void VisualServerScene::render_empty_scene(RID p_render_buffers, RID p_scenario, environment = scenario->environment; else environment = scenario->fallback_environment; + RENDER_TIMESTAMP("Render Empty Scene "); VSG::scene_render->render_scene(p_render_buffers, Transform(), CameraMatrix(), true, NULL, 0, NULL, 0, NULL, 0, environment, p_shadow_atlas, scenario->reflection_atlas, RID(), 0); #endif } @@ -2236,11 +2252,13 @@ bool VisualServerScene::_render_reflection_probe_step(Instance *p_instance, int shadow_atlas = scenario->reflection_probe_shadow_atlas; } + RENDER_TIMESTAMP("Render Reflection Probe, Step " + itos(p_step)); _prepare_scene(xform, cm, false, RID(), VSG::storage->reflection_probe_get_cull_mask(p_instance->base), p_instance->scenario->self, shadow_atlas, reflection_probe->instance, use_shadows); _render_scene(RID(), xform, cm, false, RID(), p_instance->scenario->self, shadow_atlas, reflection_probe->instance, p_step); } else { //do roughness postprocess step until it believes it's done + RENDER_TIMESTAMP("Post-Process Reflection Probe, Step " + itos(p_step)); return VSG::scene_render->reflection_probe_instance_postprocess_step(reflection_probe->instance); } diff --git a/servers/visual/visual_server_viewport.cpp b/servers/visual/visual_server_viewport.cpp index 75a90d988b..0bb16003a1 100644 --- a/servers/visual/visual_server_viewport.cpp +++ b/servers/visual/visual_server_viewport.cpp @@ -64,6 +64,8 @@ static Transform2D _canvas_get_transform(VisualServerViewport::Viewport *p_viewp void VisualServerViewport::_draw_3d(Viewport *p_viewport, ARVRInterface::Eyes p_eye) { + RENDER_TIMESTAMP(">Begin Rendering 3D Scene"); + Ref arvr_interface; if (ARVRServer::get_singleton() != NULL) { arvr_interface = ARVRServer::get_singleton()->get_primary_interface(); @@ -74,6 +76,7 @@ void VisualServerViewport::_draw_3d(Viewport *p_viewport, ARVRInterface::Eyes p_ } else { VSG::scene->render_camera(p_viewport->render_buffers, p_viewport->camera, p_viewport->scenario, p_viewport->size, p_viewport->shadow_atlas); } + RENDER_TIMESTAMP("::Element *E = p_viewport->canvas_map.front(); E; E = E->next()) { VisualServerCanvas::Canvas *canvas = static_cast(E->get().canvas); @@ -194,6 +198,9 @@ void VisualServerViewport::_draw_viewport(Viewport *p_viewport, ARVRInterface::E RasterizerCanvas::LightOccluderInstance *occluders = NULL; + RENDER_TIMESTAMP(">Render 2D Shadows"); + RENDER_TIMESTAMP("Cull Occluders"); + //make list of occluders for (Map::Element *E = p_viewport->canvas_map.front(); E; E = E->next()) { @@ -213,14 +220,18 @@ void VisualServerViewport::_draw_viewport(Viewport *p_viewport, ARVRInterface::E } } //update the light shadowmaps with them + RasterizerCanvas::Light *light = lights_with_shadow; while (light) { + RENDER_TIMESTAMP("Render Shadow"); + VSG::canvas_render->light_update_shadow(light->light_internal, light->xform_cache.affine_inverse(), light->item_shadow_mask, light->radius_cache / 1000.0, light->radius_cache * 1.1, occluders); light = light->shadows_next_ptr; } //VSG::canvas_render->reset_canvas(); + RENDER_TIMESTAMP("key().get_layer() > scenario_canvas_max_layer) { @@ -303,6 +314,8 @@ void VisualServerViewport::draw_viewports() { Map > blit_to_screen_list; //draw viewports + RENDER_TIMESTAMP(">Render Viewports"); + for (int i = 0; i < active_viewports.size(); i++) { Viewport *vp = active_viewports[i]; @@ -321,6 +334,8 @@ void VisualServerViewport::draw_viewports() { if (!visible) continue; + RENDER_TIMESTAMP(">Rendering Viewport " + itos(i)); + VSG::storage->render_target_set_as_unused(vp->render_target); #if 0 if (vp->use_arvr && arvr_interface.is_valid()) { @@ -391,9 +406,12 @@ void VisualServerViewport::draw_viewports() { if (vp->update_mode == VS::VIEWPORT_UPDATE_ONCE) { vp->update_mode = VS::VIEWPORT_UPDATE_DISABLED; } + + RENDER_TIMESTAMP("set_debug_draw_mode(VS::VIEWPORT_DEBUG_DRAW_DISABLED); + RENDER_TIMESTAMP("prepare_for_blitting_render_targets(); diff --git a/servers/visual/visual_server_wrap_mt.h b/servers/visual/visual_server_wrap_mt.h index a58d36f279..e1873e5999 100644 --- a/servers/visual/visual_server_wrap_mt.h +++ b/servers/visual/visual_server_wrap_mt.h @@ -628,6 +628,18 @@ public: return visual_server->is_low_end(); } + virtual uint64_t get_frame_profile_frame() { + return visual_server->get_frame_profile_frame(); + } + + virtual void set_frame_profiling_enabled(bool p_enabled) { + visual_server->set_frame_profiling_enabled(p_enabled); + } + + virtual Vector get_frame_profile() { + return visual_server->get_frame_profile(); + } + VisualServerWrapMT(VisualServer *p_contained, bool p_create_thread); ~VisualServerWrapMT(); diff --git a/servers/visual_server.h b/servers/visual_server.h index 06dba99860..4c89e3d976 100644 --- a/servers/visual_server.h +++ b/servers/visual_server.h @@ -1027,6 +1027,16 @@ public: virtual String get_video_adapter_name() const = 0; virtual String get_video_adapter_vendor() const = 0; + struct FrameProfileArea { + String name; + float gpu_msec; + float cpu_msec; + }; + + virtual void set_frame_profiling_enabled(bool p_enable) = 0; + virtual Vector get_frame_profile() = 0; + virtual uint64_t get_frame_profile_frame() = 0; + /* Materials for 2D on 3D */ /* TESTING */