diff --git a/cmake/module_manifest.cmake b/cmake/module_manifest.cmake index 16e575a7..f267ed6f 100644 --- a/cmake/module_manifest.cmake +++ b/cmake/module_manifest.cmake @@ -74,6 +74,13 @@ eve_declare_module(NAME timer REQUIRED LAYER 0 SCRIPT Timer SLOT timer eve_declare_module(NAME system LAYER 0 SCRIPT System SLOT system THIRDPARTY sdl2 GROUP minimal 2d 3d web) +# Profiler: built-in engine-wide profiler. Scoped zones (common/Profile.h) are +# sprinkled across the core hot systems (physics, animation, particles, audio, +# ui, scene, map, crowd, event, graphics passes) and aggregated per frame into a +# per-module/per-zone call tree with self/total time; GPU frame time comes from +# Vulkan timestamp queries. Zero overhead when disabled. +eve_declare_module(NAME profiler LAYER 0 SCRIPT Profiler SLOT profiler + GROUP minimal 2d 3d web) eve_declare_module(NAME thread LAYER 0 SCRIPT Thread SLOT thread GROUP minimal 2d 3d web) eve_declare_module(NAME spatial LAYER 0 SCRIPT Spatial SLOT spatial diff --git a/src/engine/common/GpuTimer.h b/src/engine/common/GpuTimer.h new file mode 100644 index 00000000..780a7e6c --- /dev/null +++ b/src/engine/common/GpuTimer.h @@ -0,0 +1,28 @@ +#pragma once + +#include + +// GPU timing capability. The graphics module (LAYER 3) provides a live +// implementation; lower-layer consumers (e.g. the profiler module) query it via +// eve::cap::query() and cope with nullptr (when graphics is absent / disabled). +// This keeps the interface in common/ so layering is not violated. + +namespace eve::service { + +/** + * @brief Reads the GPU frame timing captured by the renderer via Vulkan + * timestamp queries. + * Providers: eve::graphics::Graphics. + */ +class IGpuTimer { +public: + static constexpr const char *capabilityName = "IGpuTimer"; + virtual ~IGpuTimer() = default; + + /** @brief True when the renderer captured a valid GPU frame this frame. */ + virtual bool gpuTimingAvailable() const = 0; + /** @brief GPU execution time of the last presented frame, in milliseconds. */ + virtual float gpuFrameMs() const = 0; +}; + +} // namespace eve::service diff --git a/src/engine/common/Profile.cpp b/src/engine/common/Profile.cpp new file mode 100644 index 00000000..411068cc --- /dev/null +++ b/src/engine/common/Profile.cpp @@ -0,0 +1,248 @@ +#include "common/Profile.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace eve::prof { + +namespace { +std::atomic g_enabled{false}; + +int64_t nowNs() { + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); +} + +// Module id interning (thread-safe). +std::mutex g_modulesMutex; +std::vector g_moduleNames{""}; // index 0 = "default" +std::unordered_map g_moduleIds; + +uint64_t zoneKey(uint32_t module, const char* name) { + return (static_cast(module) << 32) ^ std::hash{}(name); +} +} // namespace + +struct Profiler::ThreadBuffer { + uint32_t threadId = 0; + std::string threadName = "main"; + std::vector records; + std::vector stack; // indices of open zones +}; + +struct Profiler::Frame { + int64_t beginNs = 0; + int64_t endNs = 0; + std::vector samples; +}; + +namespace { +std::mutex g_threadsMutex; +} // namespace + +Profiler::ThreadBuffer& Profiler::currentBuffer() { + static thread_local ThreadBuffer tb; + if (tb.threadId == 0) { + tb.threadId = + static_cast(std::hash{}(std::this_thread::get_id())); + const bool isMain = std::this_thread::get_id() == std::thread::id(); + tb.threadName = isMain ? "main" : "worker"; + std::lock_guard lock(g_threadsMutex); + threads().push_back(&tb); + } + return tb; +} + +std::vector& Profiler::threads() { + static std::vector t; + return t; +} + +Profiler::Frame& Profiler::lastFrameStorage() { + static Frame f; + return f; +} + +bool& Profiler::hasFrameFlag() { + static bool b = false; + return b; +} + +uint32_t Profiler::moduleId(const char* module) { + if (!module || !module[0]) return 0; + std::lock_guard lock(g_modulesMutex); + auto it = g_moduleIds.find(module); + if (it != g_moduleIds.end()) return it->second; + const uint32_t id = static_cast(g_moduleNames.size()); + g_moduleNames.push_back(module); + g_moduleIds.emplace(module, id); + return id; +} + +// --- public API ------------------------------------------------------------- + +void Profiler::setEnabled(bool on) { g_enabled.store(on, std::memory_order_relaxed); } + +bool Profiler::enabled() { return g_enabled.load(std::memory_order_relaxed); } + +void Profiler::zoneBegin(const char* name, const char* module) { + if (!g_enabled.load(std::memory_order_relaxed)) return; + ThreadBuffer& tb = currentBuffer(); + ZoneRecord r; + r.name = name ? name : ""; + r.module = moduleId(module); + r.threadId = tb.threadId; + r.parent = tb.stack.empty() ? -1 : tb.stack.back(); + r.depth = static_cast(tb.stack.size()); + r.startNs = nowNs(); + r.endNs = 0; + r.kind = 0; + const int32_t idx = static_cast(tb.records.size()); + tb.records.push_back(r); + tb.stack.push_back(idx); +} + +void Profiler::zoneEnd() { + if (!g_enabled.load(std::memory_order_relaxed)) return; + ThreadBuffer& tb = currentBuffer(); + if (tb.stack.empty()) return; + const int32_t idx = tb.stack.back(); + tb.stack.pop_back(); + tb.records[static_cast(idx)].endNs = nowNs(); +} + +void Profiler::reset() { + std::lock_guard lock(g_threadsMutex); + for (auto* tb : threads()) { + tb->records.clear(); + tb->stack.clear(); + } + lastFrameStorage() = Frame{}; + hasFrameFlag() = false; +} + +double Profiler::frameMark() { + if (!g_enabled.load(std::memory_order_relaxed)) return 0.0; + + const int64_t t0 = nowNs(); + + // Snapshot and clear every thread buffer. + struct Snap { + uint32_t tid; + std::string tname; + std::vector records; + }; + std::vector snaps; + { + std::lock_guard lock(g_threadsMutex); + for (auto* tb : threads()) { + Snap s; + s.tid = tb->threadId; + s.tname = tb->threadName; + for (auto& r : tb->records) + if (r.endNs == 0) r.endNs = t0; + s.records = std::move(tb->records); + tb->records.clear(); + tb->stack.clear(); + snaps.push_back(std::move(s)); + } + } + + // Aggregate per (module, name): self = own total - sum of children totals. + struct Agg { + double selfMs = 0.0; + double totalMs = 0.0; + int count = 0; + int minDepth = 0x7fffffff; + uint32_t module = 0; + std::string name; + std::string thread; + }; + std::unordered_map aggMap; + + for (const auto& s : snaps) { + const size_t n = s.records.size(); + std::vector total(n, 0); + std::vector child(n, 0); + for (size_t i = 0; i < n; ++i) { + int64_t t = s.records[i].endNs - s.records[i].startNs; + if (t < 0) t = 0; + total[i] = t; + } + for (size_t i = 0; i < n; ++i) { + const int32_t p = s.records[i].parent; + if (p >= 0 && p < static_cast(n)) child[static_cast(p)] += total[i]; + } + for (size_t i = 0; i < n; ++i) { + const auto& r = s.records[i]; + const int64_t self = total[i] - child[i]; + Agg& a = aggMap[zoneKey(r.module, r.name)]; + a.selfMs += static_cast(self) / 1'000'000.0; + a.totalMs += static_cast(total[i]) / 1'000'000.0; + ++a.count; + a.module = r.module; + a.name = r.name ? r.name : ""; + a.thread = s.tname; + if (r.depth < a.minDepth) a.minDepth = r.depth; + } + } + + Frame f; + f.beginNs = t0; + for (auto& kv : aggMap) { + Agg& a = kv.second; + ZoneSample sm; + sm.module = a.module < g_moduleNames.size() ? g_moduleNames[a.module] + : std::string("default"); + sm.name = a.name; + sm.thread = a.thread; + sm.selfMs = a.selfMs; + sm.totalMs = a.totalMs; + sm.count = a.count; + sm.minDepth = a.minDepth; + f.samples.push_back(std::move(sm)); + } + std::sort(f.samples.begin(), f.samples.end(), + [](const ZoneSample& x, const ZoneSample& y) { return x.selfMs > y.selfMs; }); + f.endNs = nowNs(); + + lastFrameStorage() = std::move(f); + hasFrameFlag() = true; + return static_cast(lastFrameStorage().endNs - lastFrameStorage().beginNs) / 1'000'000.0; +} + +bool Profiler::hasFrame() { return hasFrameFlag(); } + +const std::vector& Profiler::lastFrame() { return lastFrameStorage().samples; } + +std::string Profiler::textReport() { + if (!hasFrameFlag()) return "=== Profiler: no frame captured yet ===\n"; + std::ostringstream os; + char buf[64]; + const double totalMs = + static_cast(lastFrameStorage().endNs - lastFrameStorage().beginNs) / 1'000'000.0; + std::snprintf(buf, sizeof(buf), "%.2f", totalMs); + os << "=== Profiler frame (" << buf << " ms) ===\n"; + os << "-- Per-module / per-zone (self time, sorted) --\n"; + for (const auto& s : lastFrameStorage().samples) { + std::snprintf(buf, sizeof(buf), "%.3f", s.selfMs); + os << " [" << s.module << "/" << s.thread << "] " << s.name + << " self=" << buf << " ms"; + std::snprintf(buf, sizeof(buf), "%.3f", s.totalMs); + os << " total=" << buf << " ms"; + if (s.count > 1) os << " x" << s.count; + os << "\n"; + } + return os.str(); +} + +} // namespace eve::prof + diff --git a/src/engine/common/Profile.h b/src/engine/common/Profile.h new file mode 100644 index 00000000..28c9dfad --- /dev/null +++ b/src/engine/common/Profile.h @@ -0,0 +1,140 @@ +#pragma once + +#ifndef EVENGINE_COMMON_PROFILE_H +#define EVENGINE_COMMON_PROFILE_H + +#include "common/Export.h" + +#include +#include +#include +#include + +// --------------------------------------------------------------------------- +// Engine-wide profiling core (Tracy / UE Insights style scoped zones). +// +// Any module may sprinkle scoped zones at its per-frame entry points: +// +// void World::update(float dt) { +// EV_PROFILE_MODULE("physics", "World::update"); +// ... +// } +// +// Zones are cheap when disabled (a single atomic branch); when enabled they +// push {name, module, thread, start, end, parent} into a per-thread buffer and +// frameMark() aggregates the frame into a call tree with self/total time per +// module and per zone. This core lives in common/ so lower layers can use it +// without violating the module layering rules. +// --------------------------------------------------------------------------- + +namespace eve::prof { + +/** + * @brief One completed profiling zone (pre-order, parent-linked within a thread). + */ +struct EVENGINE_API ZoneRecord { + const char* name = nullptr; // pointer is static storage, never freed + uint32_t module = 0; // interned module id (0 = default) + uint32_t threadId = 0; + int32_t parent = -1; // index into the same thread's buffer + int16_t depth = 0; + int64_t startNs = 0; + int64_t endNs = 0; // 0 while open + uint8_t kind = 0; // 0 = CPU, 1 = GPU +}; + +/** + * @brief Per-module/per-zone aggregate of the last completed frame. + */ +struct EVENGINE_API ZoneSample { + std::string module; + std::string name; + std::string thread; + double selfMs = 0.0; + double totalMs = 0.0; + int count = 0; + int minDepth = 0x7fffffff; +}; + +/** + * @brief Global zone collector + per-frame aggregator. + * + * All methods are cheap when disabled. Most methods are called from the main + * thread; the collector also snapshots off-main-thread buffers at frameMark(). + */ +class EVENGINE_API Profiler { +public: + /** @brief Turns collection on/off globally (off = single-branch no-op). */ + static void setEnabled(bool on); + /** @brief True when collection is active. */ + static bool enabled(); + + /** @brief Opens a scoped zone on the current thread. */ + static void zoneBegin(const char* name, const char* module = nullptr); + /** @brief Closes the innermost open zone on the current thread. */ + static void zoneEnd(); + + /** + * @brief Finalizes the current frame: snapshots all thread buffers and + * aggregates them into lastFrame(). + * @return Wall time spent aggregating (not the frame duration). + */ + static double frameMark(); + + /** @brief True once at least one frame has been aggregated. */ + static bool hasFrame(); + /** @brief Per-module/per-zone samples of the last frame, sorted by self time. */ + static const std::vector& lastFrame(); + /** @brief Human-readable report of the last frame. */ + static std::string textReport(); + + /** @brief Clears all collected state. */ + static void reset(); + + /** @brief Interns a module name and returns its stable id. */ + static uint32_t moduleId(const char* module); + +private: + struct ThreadBuffer; + struct Frame; + + static ThreadBuffer& currentBuffer(); + + /** @brief Registry of live thread buffers (locked internally). */ + static std::vector& threads(); + /** @brief Storage for the last aggregated frame (main thread only). */ + static Frame& lastFrameStorage(); + static bool& hasFrameFlag(); +}; + +/** + * @brief RAII scoped zone (used via the EV_PROFILE_* macros). + */ +class EVENGINE_API ZoneScope { +public: + ZoneScope(const char* name, const char* module = nullptr) { + Profiler::zoneBegin(name, module); + } + ~ZoneScope() { Profiler::zoneEnd(); } + ZoneScope(const ZoneScope&) = delete; + ZoneScope& operator=(const ZoneScope&) = delete; +}; + +} // namespace eve::prof + +#define EV_PROFILE_CAT_I(a, b) a##b +#define EV_PROFILE_CAT(a, b) EV_PROFILE_CAT_I(a, b) + +/** @brief Profile the enclosing scope, auto-named from the current function. */ +#define EV_PROFILE_ZONE_FUNC() \ + ::eve::prof::ZoneScope EV_PROFILE_CAT(ev_zone_, __LINE__)(__func__) + +/** @brief Profile the enclosing scope with an explicit name. */ +#define EV_PROFILE_ZONE(name) \ + ::eve::prof::ZoneScope EV_PROFILE_CAT(ev_zone_, __LINE__)(name) + +/** @brief Profile the enclosing scope, tagged with a module for grouping. */ +#define EV_PROFILE_MODULE(module, name) \ + ::eve::prof::ZoneScope EV_PROFILE_CAT(ev_zone_, __LINE__)(name, module) + +#endif diff --git a/src/modules/animation/Animation.cpp b/src/modules/animation/Animation.cpp index adb32f0f..a6434d44 100644 --- a/src/modules/animation/Animation.cpp +++ b/src/modules/animation/Animation.cpp @@ -28,6 +28,7 @@ #include "animation/SpriteSheet.h" #include "common/Exception.h" +#include "common/Profile.h" #include "graphics/Graphics.h" #include "graphics/Texture.h" #include "graphics/Mesh.h" @@ -429,6 +430,7 @@ void Animation::unregisterSpineAnim(SpineAnim *a) { } void Animation::update(float dt) { + EV_PROFILE_MODULE("animation", "Animation::update"); // Copy pointer lists: destructors during update must not invalidate iteration. std::vector tweenSnap = tweens_; for (Tween *t : tweenSnap) { diff --git a/src/modules/audio/Audio.cpp b/src/modules/audio/Audio.cpp index b9ceccd2..83b51b4a 100644 --- a/src/modules/audio/Audio.cpp +++ b/src/modules/audio/Audio.cpp @@ -3,6 +3,7 @@ #include "AudioCapabilities.h" #include "common/Exception.h" +#include "common/Profile.h" #include "common/StartupTiming.h" #include "sound/Decoder.h" #include "sound/Sound.h" @@ -174,6 +175,7 @@ void Audio::setOrientation(float fx, float fy, float fz, float ux, float uy, flo } void Audio::pump() { + EV_PROFILE_MODULE("audio", "Audio::pump"); // Same guarantee as workerMain: destruction removes the source under this // mutex, so the pointer stays valid for the whole iteration. std::lock_guard lock(mutex); diff --git a/src/modules/crowd/Crowd.cpp b/src/modules/crowd/Crowd.cpp index e7e85137..e1a4a64d 100644 --- a/src/modules/crowd/Crowd.cpp +++ b/src/modules/crowd/Crowd.cpp @@ -1,6 +1,7 @@ #include "crowd/Crowd.h" #include "common/Exception.h" +#include "common/Profile.h" #include @@ -663,6 +664,7 @@ void Crowd::setResolveOverlaps(bool enable) { impl_->resolveOverlaps = enable; } void Crowd::setClampToField(bool enable) { impl_->clampToField = enable; } void Crowd::step(float dt) { + EV_PROFILE_MODULE("crowd", "Crowd::step"); if (dt <= 0.f) return; impl_->simTime += dt; impl_->rebuildGrid(); diff --git a/src/modules/event/sdl/Event.cpp b/src/modules/event/sdl/Event.cpp index c0b2c415..c0a15232 100644 --- a/src/modules/event/sdl/Event.cpp +++ b/src/modules/event/sdl/Event.cpp @@ -4,6 +4,7 @@ #include "common/Capability.h" #include "common/Exception.h" #include "common/Module.h" +#include "common/Profile.h" #include "common/config.h" #include "event/PlatformEventSink.h" @@ -30,6 +31,7 @@ Event::~Event() void Event::pump() { + EV_PROFILE_MODULE("event", "Event::pump"); SDL_Event e; while (SDL_PollEvent(&e)) diff --git a/src/modules/graphics/vulkan/Graphics.cpp b/src/modules/graphics/vulkan/Graphics.cpp index 5c9031e8..c3e3cecf 100644 --- a/src/modules/graphics/vulkan/Graphics.cpp +++ b/src/modules/graphics/vulkan/Graphics.cpp @@ -58,6 +58,8 @@ std::string Graphics::getBackendName() const { return "vulkan"; } Graphics::~Graphics() { if (!initialized) return; device->waitIdle(); + if (gpuQueryPool_) device->destroyQueryPool(gpuQueryPool_); + gpuQueryPool_ = nullptr; // Pipeline objects hold raw Shader* owned by ownedShaders. Drop them // first so their destructors do not see freed shader pointers. pipelineAA_.reset(); @@ -347,6 +349,7 @@ void Graphics::initHeadless(int width, int height) { } void Graphics::initWithWindow(void *nativeWindow) { + eve::cap::provide(this); StartupStage initStage("graphics: initWithWindow (total)"); if (initialized) { // Window module may destroy/recreate the SDL window (tests, setWindowSettings). @@ -633,7 +636,10 @@ bool Graphics::beginPresentCommandBuffer() { for (int attempt = 0; attempt < 3; ++attempt) { if (!rebuildSwapchainIfNeeded()) return false; presentRecording = presentModel.begin(); - if (presentRecording) return true; + if (presentRecording) { + writeGpuTimestampBegin(); + return true; + } // Acquire failed without beginning the CB (see Present::begin). Rebuild once. if (presentModel.needs_recreate) { presentModel.needs_recreate = false; @@ -745,5 +751,51 @@ void Graphics::present() { void Graphics::draw(eve::graphics::Graphics *, const glm::mat4 &) const {} void Graphics::draw(Canvas *, const glm::mat4 &) const {} +// ---- GPU frame timing ------------------------------------------------------ + +void Graphics::initGpuTiming() { + if (gpuQueryPool_) return; + try { + timestampPeriod_ = device.physical_device.properties.limits.timestampPeriod; + vk::QueryPoolCreateInfo ci; + ci.queryType = vk::QueryType::eTimestamp; + ci.queryCount = 2; + gpuQueryPool_ = device->createQueryPool(ci); + gpuTimingReady_ = true; + } catch (...) { + gpuTimingReady_ = false; + gpuQueryPool_ = nullptr; + } +} + +void Graphics::writeGpuTimestampBegin() { + if (!gpuTimingReady_ || !presentRecording) return; + vk::CommandBuffer cb = presentRecording.commandBuffer(); + cb.resetQueryPool(gpuQueryPool_, 0, 2); + cb.writeTimestamp(vk::PipelineStageFlagBits::eTopOfPipe, gpuQueryPool_, 0); +} + +void Graphics::writeGpuTimestampEnd() { + if (!gpuTimingReady_ || !presentRecording) return; + vk::CommandBuffer cb = presentRecording.commandBuffer(); + cb.writeTimestamp(vk::PipelineStageFlagBits::eBottomOfPipe, gpuQueryPool_, 1); +} + +void Graphics::readGpuFrameTiming() { + if (!gpuTimingReady_ || !gpuQueryPool_) return; + // drawFrame() waits on the in-flight fence, so results are valid here. + std::array ts{}; + const auto r = device->getQueryPoolResults( + gpuQueryPool_, 0, 2, sizeof(ts), ts.data(), sizeof(uint64_t), + vk::QueryResultFlagBits::e64 | vk::QueryResultFlagBits::eWait); + if (r == vk::Result::eSuccess && ts[1] > ts[0]) + gpuFrameMs_ = float(double(ts[1] - ts[0]) * double(timestampPeriod_) / 1'000'000.0); + else + gpuFrameMs_ = 0.f; +} + +bool Graphics::gpuTimingAvailable() const { return gpuTimingReady_ && gpuFrameMs_ > 0.f; } + +float Graphics::gpuFrameMs() const { return gpuFrameMs_; } } // namespace eve::graphics::vulkan diff --git a/src/modules/graphics/vulkan/Graphics.h b/src/modules/graphics/vulkan/Graphics.h index 6f857a75..486f0b9f 100644 --- a/src/modules/graphics/vulkan/Graphics.h +++ b/src/modules/graphics/vulkan/Graphics.h @@ -20,6 +20,8 @@ #include "graphics/vulkan/GpuDriven.h" #include "graphics/vulkan/FrameArena.h" #include "graphics/vulkan/ComputePass.h" +#include "common/Capability.h" +#include "common/GpuTimer.h" namespace eve::graphics::vulkan { @@ -216,7 +218,7 @@ struct GpuShader { Shader *owner = nullptr; }; -class Graphics final : public eve::graphics::Graphics { +class Graphics final : public eve::graphics::Graphics, public eve::service::IGpuTimer { public: // Keep the base draw(Drawable*, mat4) overload visible alongside the // canvas composite overloads below. @@ -224,6 +226,19 @@ public: ~Graphics() override; + // ---- GPU frame timing (eve::service::IGpuTimer) ---------------------- + /** @brief Creates the GPU timestamp query pool; call after device init. */ + void initGpuTiming(); + /** @brief Writes a begin timestamp into the current present command buffer. */ + void writeGpuTimestampBegin(); + /** @brief Writes an end timestamp into the current present command buffer. */ + void writeGpuTimestampEnd(); + /** @brief Reads the query results after the frame's submit has completed. */ + void readGpuFrameTiming(); + + bool gpuTimingAvailable() const override; + float gpuFrameMs() const override; + std::string getBackendName() const override; void initWithWindow(void *nativeWindow) override; @@ -1236,6 +1251,12 @@ private: vkb::DepthStencilImage depthImage; vk::Format depthFormat = vk::Format::eD32Sfloat; + // GPU timestamp queries (one pool of 2: [0]=frame begin, [1]=frame end). + vk::QueryPool gpuQueryPool_{}; + float timestampPeriod_ = 1.f; + bool gpuTimingReady_ = false; + float gpuFrameMs_ = 0.f; + struct SolidBatch { BlendMode blend = BlendMode::Alpha; Batcher batch; diff --git a/src/modules/graphics/vulkan/Graphics2D.cpp b/src/modules/graphics/vulkan/Graphics2D.cpp index 7f1298cc..6425ec51 100644 --- a/src/modules/graphics/vulkan/Graphics2D.cpp +++ b/src/modules/graphics/vulkan/Graphics2D.cpp @@ -1615,7 +1615,9 @@ void Graphics::flushToSwapchain() { swapchainPass = {}; const bool captured = screenReadbackEnabled ? recordSwapchainReadback(presentRecording.commandBuffer()) : false; + writeGpuTimestampEnd(); presentRecording.end().submitAndPresent(); + readGpuFrameTiming(); presentRecording = {}; if (captured) { hasPresentedFrame = true; diff --git a/src/modules/graphics/vulkan/GraphicsPipeline.cpp b/src/modules/graphics/vulkan/GraphicsPipeline.cpp index bfb5ca5a..219cf984 100644 --- a/src/modules/graphics/vulkan/GraphicsPipeline.cpp +++ b/src/modules/graphics/vulkan/GraphicsPipeline.cpp @@ -138,6 +138,7 @@ vk::Pipeline createSolidColorPipeline(vkb::Device &device, const vkb::BuiltRende // --- Swapchain and graphics pipelines ----------------------------------------- void Graphics::createSwapchainAndPipeline() { + initGpuTiming(); // Framebuffers / command buffers alias the current swapchain images; tear // them down before replacing the swapchain (destroy() waitIdles first). presentRecording = {}; diff --git a/src/modules/map/TileSystem.cpp b/src/modules/map/TileSystem.cpp index dd60be97..3f6b8e19 100644 --- a/src/modules/map/TileSystem.cpp +++ b/src/modules/map/TileSystem.cpp @@ -7,6 +7,7 @@ #include "graphics/Canvas.h" #include "filesystem/Filesystem.h" #include "common/Module.h" +#include "common/Profile.h" #include #include @@ -262,6 +263,7 @@ int TileRenderSystem::lastVisitedChunkCount() { return gLastVisitedChunkCount; } int TileRenderSystem::lastVisitedCellCount() { return gLastVisitedCellCount; } void TileRenderSystem::update(float dt) { + EV_PROFILE_MODULE("map", "TileRenderSystem::update"); if (dt > 0.f && std::isfinite(dt)) gAnimationTimeMs += double(dt) * 1000.0; } diff --git a/src/modules/particles/Particles.cpp b/src/modules/particles/Particles.cpp index 6391d2d2..84c1bcc1 100644 --- a/src/modules/particles/Particles.cpp +++ b/src/modules/particles/Particles.cpp @@ -1,5 +1,6 @@ #include "particles/Particles.h" #include "common/Module.h" +#include "common/Profile.h" #include "data/DataModule.h" #include "data/JsonDocument.h" #include "filesystem/FileData.h" @@ -68,6 +69,7 @@ ParticleEmitter *Particles::newEmitterFromFile(const std::string &path) { } void Particles::update(float dt) { + EV_PROFILE_MODULE("particles", "Particles::update"); ParticleConfigSystem::poll(); ParticleSimSystem::update(dt); ParticleLightSystem::update(); diff --git a/src/modules/physics/World.cpp b/src/modules/physics/World.cpp index 37e91613..571a66b1 100644 --- a/src/modules/physics/World.cpp +++ b/src/modules/physics/World.cpp @@ -1,8 +1,9 @@ -#include "physics/World.h" +#include "physics/World.h" #include "physics/Body.h" #include "physics/Fixture.h" #include "common/Exception.h" +#include "common/Profile.h" #include "event/Event.h" #include "graphics/Graphics.h" #include "graphics/Canvas.h" @@ -283,7 +284,7 @@ void World::destroy() { if (destroyed_) return; destroyed_ = true; - // Copy sets — Body/Fixture destructors erase from them. + // Copy sets 鈥?Body/Fixture destructors erase from them. std::vector bodies(bodies_.begin(), bodies_.end()); for (Body *b : bodies) { if (b) { @@ -363,6 +364,7 @@ bool World::pointProbe(float x, float y, float radius, ClothContact *out) const void World::update(float dt) { updateFull(dt, 8, 3); } void World::updateFull(float dt, int velocityIterations, int positionIterations) { + EV_PROFILE_MODULE("physics", "World::update"); if (!world_ || destroyed_) return; if (dt < 0.f) dt = 0.f; // Cap to avoid spiral-of-death on hitch frames. @@ -688,3 +690,4 @@ int World::getQueryBodyId(int index) const { } } // namespace eve::physics + diff --git a/src/modules/physics/World3D.cpp b/src/modules/physics/World3D.cpp index 6adc3058..42237a73 100644 --- a/src/modules/physics/World3D.cpp +++ b/src/modules/physics/World3D.cpp @@ -4,6 +4,7 @@ #include "physics/PhysicsCapabilities.h" #include "common/Exception.h" +#include "common/Profile.h" #include "event/Event.h" #include @@ -107,6 +108,7 @@ bool World3D::sphereCast(float x1, float y1, float z1, float x2, float y2, float void World3D::update(float dt) { updateFull(dt, 4); } void World3D::updateFull(float dt, int subStepCount) { + EV_PROFILE_MODULE("physics", "World3D::update"); if (!isValid()) return; if (dt < 0.f) dt = 0.f; if (dt > 0.05f) dt = 0.05f; diff --git a/src/modules/profiler/Profiler.cpp b/src/modules/profiler/Profiler.cpp new file mode 100644 index 00000000..b589d57c --- /dev/null +++ b/src/modules/profiler/Profiler.cpp @@ -0,0 +1,128 @@ +#include "profiler/Profiler.h" + +#include "common/GpuTimer.h" +#include "common/Capability.h" + +#include + +#include +#include + +namespace eve::profiler { + +Module_IMPL(Profiler, new Profiler()); + +namespace { +int64_t nowNs() { + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); +} +} // namespace + +Profiler::Profiler() { eve::debug::setRenderTracer(this); } + +Profiler::~Profiler() { + if (eve::debug::renderTracer() == this) eve::debug::setRenderTracer(nullptr); +} + +void Profiler::setEnabled(bool on) { + eve::prof::Profiler::setEnabled(on); + if (!on) { + frameMs_ = 0.f; + } +} + +bool Profiler::enabled() const { return eve::prof::Profiler::enabled(); } + +void Profiler::reset() { + eve::prof::Profiler::reset(); + frameMs_ = 0.f; +} + +void Profiler::beginFrame() { frameBeginNs_ = nowNs(); } + +void Profiler::endFrame() { + if (!enabled()) return; + const double totalMs = static_cast(nowNs() - frameBeginNs_) / 1'000'000.0; + frameMs_ = static_cast(totalMs); + eve::prof::Profiler::frameMark(); +} + +void Profiler::begin(const char* name) { + if (!enabled()) return; + eve::prof::Profiler::zoneBegin(name ? name : "scope", nullptr); +} + +void Profiler::end() { + if (!enabled()) return; + eve::prof::Profiler::zoneEnd(); +} + +void Profiler::passBegin(const char* name) { + if (!enabled()) return; + eve::prof::Profiler::zoneBegin(name ? name : "pass", "graphics"); +} + +void Profiler::passEnd(const char* name) { + if (!enabled()) return; + eve::prof::Profiler::zoneEnd(); +} + +bool Profiler::hasFrame() const { return eve::prof::Profiler::hasFrame(); } + +float Profiler::frameMs() const { return frameMs_; } + +float Profiler::gpuFrameMs() const { + auto* t = eve::cap::query(); + return t ? t->gpuFrameMs() : 0.f; +} + +std::string Profiler::textReport() const { + std::string report = eve::prof::Profiler::textReport(); + auto* t = eve::cap::query(); + if (t && t->gpuTimingAvailable()) { + char buf[64]; + std::snprintf(buf, sizeof(buf), " GPU frame: %.2f ms\n", t->gpuFrameMs()); + report += buf; + } + return report; +} + +ssq::Object Profiler::capture() { + ssq::Array out(vm_); + for (const auto& s : eve::prof::Profiler::lastFrame()) { + ssq::Table t(vm_); + t.set("module", s.module); + t.set("name", s.name); + t.set("thread", s.thread); + t.set("selfMs", static_cast(s.selfMs)); + t.set("totalMs", static_cast(s.totalMs)); + t.set("count", s.count); + out.push(t); + } + return out; +} + +void Profiler::expose(ssq::Table& table) { + if (Profiler* self = Profiler::create()) self->vm_ = table.getHandle(); + auto cls = table.addClass(name, Profiler::create, false); + expose(cls); +} + +void Profiler::expose(ssq::Class& cls) { + cls.addFunc("setEnabled", &Profiler::setEnabled); + cls.addFunc("enabled", &Profiler::enabled); + cls.addFunc("reset", &Profiler::reset); + cls.addFunc("beginFrame", &Profiler::beginFrame); + cls.addFunc("endFrame", &Profiler::endFrame); + cls.addFunc("begin", &Profiler::begin); + cls.addFunc("end", &Profiler::end); + cls.addFunc("hasFrame", &Profiler::hasFrame); + cls.addFunc("frameMs", &Profiler::frameMs); + cls.addFunc("gpuFrameMs", &Profiler::gpuFrameMs); + cls.addFunc("textReport", &Profiler::textReport); + cls.addFunc("capture", &Profiler::capture); +} + +} // namespace eve::profiler diff --git a/src/modules/profiler/Profiler.h b/src/modules/profiler/Profiler.h new file mode 100644 index 00000000..3e9a0c3e --- /dev/null +++ b/src/modules/profiler/Profiler.h @@ -0,0 +1,93 @@ +#pragma once + +#include "common/Module.h" +#include "common/Profile.h" +#include "common/RenderTrace.h" + +#include + +#include +#include + +namespace ssq { +class Object; +} + +namespace eve::profiler { + +/** + * @brief Script-facing wrapper around the engine-wide profiler core + * (eve::prof, see common/Profile.h). + * + * The core collects scoped zones from every engine system (physics, animation, + * particles, audio, ui, scene, graphics passes, ...) into a per-frame call tree + * with self/total time per module and per zone. This module exposes that data + * to Squirrel and adds GPU frame timing (via eve::service::IGpuTimer). + * + * Script usage: + * @code + * profiler.setEnabled(true); // start collecting engine-wide zones + * // ... run a few frames ... + * print(profiler.textReport()); // per-module/per-zone hotspot report + * local rows = profiler.capture(); // array of {module,name,selfMs,totalMs,count,thread} + * profiler.setEnabled(false); + * @endcode + * + * The frame driver (src/scripts/load.nut) calls frameBegin()/endFrame() each + * frame; render passes are converted from the existing IRenderTracer hooks. + */ +class Profiler : public Module, public eve::debug::IRenderTracer { +public: + Module_REG(Profiler); + Profiler(); + ~Profiler() override; + + /** @brief Enables/disables engine-wide collection. Disabled = cheap no-op. */ + void setEnabled(bool on); + /** @brief True when collection is active. */ + bool enabled() const; + /** @brief Clears all collected data. */ + void reset(); + + /** @brief Marks the start of a frame for total-frame timing. */ + void beginFrame(); + /** @brief Finalizes the current frame and aggregates the collected zones. */ + void endFrame(); + + /** + * @brief Opens a user timing scope under the current frame. + * @param name Scope name (must be non-null). + */ + void begin(const char* name); + /** @brief Closes the innermost open user scope. */ + void end(); + + /** @brief True once at least one frame has been aggregated. */ + bool hasFrame() const; + /** @brief Total CPU frame time of the last frame, in milliseconds. */ + float frameMs() const; + /** @brief GPU execution time of the last presented frame (0 when unavailable). */ + float gpuFrameMs() const; + /** @brief Human-readable hotspot report (per module / per zone). */ + std::string textReport() const; + /** + * @brief Structured report of the last frame. + * @return Array of tables {module, name, thread, selfMs, totalMs, count}, + * sorted by self time descending. + */ + ssq::Object capture(); + + // IRenderTracer: route render passes into the core as "graphics" zones. + void frameBegin() override {} + void frameEnd() override {} + void passBegin(const char* name) override; + void passEnd(const char* name) override; + void draw(const char* api, const char* detail) override {} + +private: + int64_t frameBeginNs_ = 0; + float frameMs_ = 0.f; + HSQUIRRELVM vm_ = nullptr; +}; + +} // namespace eve::profiler diff --git a/src/modules/scene/TransformSystem.cpp b/src/modules/scene/TransformSystem.cpp index 69cdb6d4..b3dd4ec6 100644 --- a/src/modules/scene/TransformSystem.cpp +++ b/src/modules/scene/TransformSystem.cpp @@ -1,5 +1,6 @@ #include "scene/TransformSystem.h" +#include "common/Profile.h" #include "scene/SceneHost.h" #include "scene/SceneLink.h" @@ -161,6 +162,7 @@ void TransformSystem::updateHost(SceneHost *host) { } void TransformSystem::updateAll() { + EV_PROFILE_MODULE("scene", "TransformSystem::updateAll"); if (ecs::current()->getManager() == nullptr) return; auto view = ecs::View(); for (auto it = view.begin(); it != view.end(); ++it) { diff --git a/src/modules/ui/UISystem.cpp b/src/modules/ui/UISystem.cpp index f92a3774..f976f8f1 100644 --- a/src/modules/ui/UISystem.cpp +++ b/src/modules/ui/UISystem.cpp @@ -6,6 +6,7 @@ #include "ui/UIBackend.h" #include "common/Module.h" +#include "common/Profile.h" #include "graphics/Graphics.h" #include @@ -1059,6 +1060,7 @@ UIHost *UISystem::findHostByOwner(uint32_t ownerId) { } void UISystem::render() { + EV_PROFILE_MODULE("ui", "UISystem::render"); if (ecs::current()->getManager() == nullptr) return; applyThemeToImGui(globalTheme()); diff --git a/src/scripts/load.nut b/src/scripts/load.nut index 7d86c2aa..766f1afc 100644 --- a/src/scripts/load.nut +++ b/src/scripts/load.nut @@ -38,6 +38,19 @@ function has_module(slot) { return slot in getroottable() && getroottable()[slot] != null; } +// --------------------------------------------------------------------------- +// Profiler markers (built-in profiler module). These are no-ops when the +// profiler is absent or disabled, so they cost nothing in normal builds. +// --------------------------------------------------------------------------- +function _prof(name) { + if (!has_module("profiler")) return; + profiler.begin(name); +} +function _prof_end() { + if (!has_module("profiler")) return; + profiler.end(); +} + // --------------------------------------------------------------------------- // 通用游戏开发辅助(在 main.nut 之前定义;示例脚本可直接使用, // 游戏脚本里可以按需用同名定义覆盖)。 @@ -543,6 +556,8 @@ eve_frame <- function() { _startup_ms("first frame begins"); } local running = true; + if (has_module("profiler")) profiler.frameBegin(); + _prof("events"); event.pump(); while (true) { local name = event.poll(); @@ -559,6 +574,7 @@ eve_frame <- function() { running = false; } } + _prof_end(); if (startup_frames > 0) startup_frames -= 1; @@ -579,14 +595,18 @@ eve_frame <- function() { // Playground pause: the page sets the eve_playground_paused root // flag to freeze game logic while the render keeps presenting. if (!("eve_playground_paused" in getroottable()) || !eve_playground_paused) { + _prof("update"); eve_update(dt); + _prof_end(); // Flush reactions scheduled during eve_update. if ("async_pump" in getroottable()) async_pump(); } dev_notify_frame_done(); } + _prof("render"); eve_render(); + _prof_end(); // ImGui AI/MCP panel (requires ui.beginFrameAndRender in eve_render). dev_draw_ai(); dev_draw_console(); @@ -598,7 +618,9 @@ eve_frame <- function() { // before throwing. Skipping present leaves swapchainPassOpen and every // later frame fails with "begin3DFrame: swapchain pass already open". try { + _prof("present"); gfx.present(); + _prof_end(); if (has_module("ui")) ui.dispatchEvents(); } catch (e) { print("present error: " + e + "\n"); @@ -607,8 +629,11 @@ eve_frame <- function() { getroottable()._startup_first_present <- true; _startup_ms("first present - window shows content"); } - if ("bootBench" in eve && eve.bootBench) + if ("bootBench" in eve && eve.bootBench) { + if (has_module("profiler")) profiler.endFrame(); return false; + } + if (has_module("profiler")) profiler.endFrame(); return running; }; diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 1f1c6e3d..00c15ca2 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -265,6 +265,7 @@ file(GLOB all_test_scripts timer.nut decal.nut crowd.nut + profiler.nut ) add_custom_command(OUTPUT ${CMAKE_CURRENT_BINARY_DIR}/nut_scripts.cpp COMMAND ${CMAKE_COMMAND} -DOUTPUT_DIR="${CMAKE_CURRENT_BINARY_DIR}" -P "${CMAKE_SOURCE_DIR}/cmake/integrate.cmake" diff --git a/test/profiler.cpp b/test/profiler.cpp new file mode 100644 index 00000000..30625268 --- /dev/null +++ b/test/profiler.cpp @@ -0,0 +1,75 @@ +#include "zeroerr/assert.h" +#include "zeroerr/unittest.h" + +#include "common/Profile.h" +#include "profiler/Profiler.h" + +#include + +using eve::profiler::Profiler; + +TEST_CASE("profiler.core.disabled.isNoop") { + eve::prof::Profiler::reset(); + eve::prof::Profiler::setEnabled(false); + eve::prof::Profiler::zoneBegin("a"); + eve::prof::Profiler::zoneEnd(); + eve::prof::Profiler::frameMark(); + CHECK_NOT(eve::prof::Profiler::hasFrame()); + eve::prof::Profiler::reset(); +} + +TEST_CASE("profiler.core.aggregatesSelfAndTotal") { + eve::prof::Profiler::reset(); + eve::prof::Profiler::setEnabled(true); + eve::prof::Profiler::zoneBegin("parent", "physics"); + eve::prof::Profiler::zoneBegin("child", "physics"); + eve::prof::Profiler::zoneEnd(); + eve::prof::Profiler::zoneEnd(); + const double frameMs = eve::prof::Profiler::frameMark(); + CHECK_GT(frameMs, 0.0); + CHECK(eve::prof::Profiler::hasFrame()); + const auto& samples = eve::prof::Profiler::lastFrame(); + bool foundParent = false, foundChild = false; + for (const auto& s : samples) { + if (s.name == "parent" && s.module == "physics") { + foundParent = true; + // parent self time must be < its total time (a child ran inside it). + CHECK_LT(s.selfMs, s.totalMs); + } + if (s.name == "child") foundChild = true; + } + CHECK(foundParent); + CHECK(foundChild); + CHECK(eve::prof::Profiler::textReport().find("parent") != std::string::npos); + eve::prof::Profiler::setEnabled(false); + eve::prof::Profiler::reset(); +} + +TEST_CASE("profiler.module.frameCapture") { + auto* p = Profiler::create(); + p->reset(); + p->setEnabled(true); + p->beginFrame(); + p->begin("moduleScope"); + p->end(); + p->endFrame(); + CHECK(p->hasFrame()); + CHECK(p->frameMs() >= 0.f); + CHECK(p->textReport().find("moduleScope") != std::string::npos); + p->setEnabled(false); + p->reset(); +} + +TEST_CASE("profiler.module.renderPassZones") { + auto* p = Profiler::create(); + p->reset(); + p->setEnabled(true); + p->beginFrame(); + p->passBegin("ShadowPass"); // IRenderTracer pass -> graphics zone + p->passEnd("ShadowPass"); + p->endFrame(); + CHECK(p->hasFrame()); + CHECK(p->textReport().find("ShadowPass") != std::string::npos); + p->setEnabled(false); + p->reset(); +} diff --git a/test/profiler.nut b/test/profiler.nut new file mode 100644 index 00000000..fd89b755 --- /dev/null +++ b/test/profiler.nut @@ -0,0 +1,23 @@ +// Built-in profiler script API smoke test. +function captureWorks() { + local p = eve.Profiler(); + p.setEnabled(true); + p.beginFrame(); + p.begin("scriptScope"); + for (local i = 0; i < 1000; ++i) { /* busy */ } + p.end(); + p.endFrame(); + local rows = p.capture(); + if (typeof rows != "array") return false; + local found = false; + foreach (r in rows) { + if (typeof r != "table") return false; + if (!("name" in r) || !("selfMs" in r) || !("totalMs" in r)) return false; + if (r.name == "scriptScope") found = true; + } + if (!found) return false; + if (p.frameMs() < 0.0) return false; + if (p.textReport().find("scriptScope") == null) return false; + p.setEnabled(false); + return true; +} diff --git a/test/profiler_script.cpp b/test/profiler_script.cpp new file mode 100644 index 00000000..ad5e7050 --- /dev/null +++ b/test/profiler_script.cpp @@ -0,0 +1,8 @@ +#include "ScriptTest.h" + +extern const char* profiler_content; +UnitSciptTest(ProfilerScriptTest, profiler_content); + +TEST_CASE_FIXTURE(ProfilerScriptTest, "ProfilerScriptTest.capture") { + CHECK(vm.callFunc(vm.findFunc("captureWorks"), vm).toBool()); +}