Fixed broken Timing::Timer due to inconsistent timing function usage.

Added some basic profiling timers for processors, which can be seen in the world inspector.

Author: fLindahl

code/application/game/frameevent.cc

@@ -75,8 +75,7 @@ FrameEvent::AddProcessor(Processor* processor)
     // try to insert into existing batches
     for (i = 0; i < this->batches.Size(); i++)
     {
-        if (this->batches[i]->async == processor->async &&
-            this->batches[i]->order == processor->order)
+        if (this->batches[i]->async == processor->async && this->batches[i]->order == processor->order)
         {
             accepted = this->batches[i]->TryInsert(processor);
             if (accepted)
@@ -224,7 +223,8 @@ FrameEvent::Batch::Prefilter(World* world, bool force)
         Processor* processor = this->processors[i];
         if (!processor->cacheValid || force)
         {
-            processor->cache = world->GetDatabase()->Query(GetInclusiveTableMask(processor->filter), GetExclusiveTableMask(processor->filter));
+            processor->cache =
+                world->GetDatabase()->Query(GetInclusiveTableMask(processor->filter), GetExclusiveTableMask(processor->filter));
             processor->cacheValid = true;
         }
     }
@@ -284,6 +284,15 @@ FrameEvent::Batch::ExecuteAsync(World* world)
     {
         Processor* processor = this->processors[i];
 
+        if (!processor->active)
+            continue;
+
+#ifdef NEBULA_ENABLE_PROFILING
+        // TODO: Async batch processors will have the same timings for now. We should figure out some good way of measuring their elapsed time.
+        processor->timer.Reset();
+        processor->timer.Start();
+#endif
+
 #ifdef WITH_NEBULA_EDITOR
         if (Game::EditorState::HasInstance())
         {
@@ -294,11 +303,22 @@ FrameEvent::Batch::ExecuteAsync(World* world)
 #endif
         datasets[i] = world->Query(processor->filter, processor->cache);
         numJobs += datasets[i].numViews;
-
     }
 
     if (numJobs == 0)
+    {
+#ifdef NEBULA_ENABLE_PROFILING
+        for (IndexT i = 0; i < this->processors.Size(); i++)
+        {
+            Processor* processor = this->processors[i];
+            if (!processor->active)
+                continue;
+
+            processor->timer.Stop();
+        }
+#endif
         return;
+    }
 
     ProcessorJobContext context;
     context.world = world;
@@ -318,6 +338,17 @@ FrameEvent::Batch::ExecuteAsync(World* world)
     Jobs2::JobDispatch(FrameBatchJob, numJobs, 1, context, nullptr, nullptr, &event);
     event.Wait();
 
+#ifdef NEBULA_ENABLE_PROFILING
+    for (IndexT i = 0; i < this->processors.Size(); i++)
+    {
+        Processor* processor = this->processors[i];
+        if (!processor->active)
+            continue;
+
+        processor->timer.Stop();
+    }
+#endif
+
     delete[] context.inputs;
 }
 
@@ -343,11 +374,20 @@ FrameEvent::Batch::ExecuteSequential(World* world)
         }
 #endif
 
+#ifdef NEBULA_ENABLE_PROFILING
+        processor->timer.Reset();
+        processor->timer.Start();
+#endif
+
         Dataset data = world->Query(processor->filter, processor->cache);
         for (int v = 0; v < data.numViews; v++)
         {
             processor->callback(world, data.views[v]);
         }
+
+#ifdef NEBULA_ENABLE_PROFILING
+        processor->timer.Stop();
+#endif
     }
 }
 
@@ -529,4 +569,3 @@ FramePipeline::GetFrameEvents() const
 }
 
 } // namespace Game
-

code/application/game/processor.h

@@ -7,6 +7,7 @@
     (C) 2022 Individual contributors, see AUTHORS file
 */
 //------------------------------------------------------------------------------
+#include "timing/timer.h"
 #include "util/stringatom.h"
 #include "filter.h"
 #include "processorid.h"
@@ -37,6 +38,10 @@ class Processor
     bool cacheValid = false;
     /// set to false if the processor shouldn't execute in the frame.
     bool active = true;
+#ifdef NEBULA_ENABLE_PROFILING
+    /// Profiling timer, handled by the frame pipeline.
+    Timing::Timer timer;
+#endif
 #ifdef WITH_NEBULA_EDITOR
     /// set to true if you want this processor to always run in editor
     bool runInEditor = false;

code/application/game/world.cc

@@ -527,7 +527,6 @@ World::ManageEntities()
 
     // Delete all remaining invalid instances
     Ptr<MemDb::Database> const& db = this->db;
-
     if (db.isvalid())
     {
         db->ForEachTable(
@@ -1544,6 +1543,10 @@ World::RenderDebug()
                         }
                         ImGui::Unindent();
                     }
+#ifdef NEBULA_ENABLE_PROFILING
+                    ImGui::SameLine();
+                    ImGui::Text(" | [ %0.3fms ]", (float)(processor->timer.GetTime() * 1000.0));
+#endif
                 }
                 ImGui::Unindent();
             }
@@ -1589,105 +1592,110 @@ World::RenderDebug()
 
     static bool listInactive = false;
     ImGui::Checkbox("List inactive instances", &listInactive);
-    ImGui::Text("Entity map:");
-    ImGui::BeginChild(
-        "ScrollingRegion", ImVec2(0, -ImGui::GetFrameHeightWithSpacing()), false, ImGuiWindowFlags_HorizontalScrollbar
-    );
+    static bool showEntities = false;
+    ImGui::Checkbox("Show Entity List", &showEntities);
+    if (showEntities)
     {
-        for (uint entityIndex = 0; entityIndex < this->entityMap.Size(); entityIndex++)
+        ImGui::Text("Entity map:");
+        ImGui::BeginChild(
+            "ScrollingRegion", ImVec2(0, -ImGui::GetFrameHeightWithSpacing()), false, ImGuiWindowFlags_HorizontalScrollbar
+        );
         {
-            Game::EntityMapping entityMapping = this->entityMap[entityIndex];
-            
-            if (!listInactive && (entityMapping.table == MemDb::InvalidTableId || entityMapping.instance == MemDb::InvalidRow))
-                continue;
-
-            ImGui::BeginGroup();
-            ImGui::Text("[%i] ", entityIndex);
-            ImGui::SameLine();
-            ImGui::TextColored(
-                {1, 0.3f, 0, 1},
-                "tid:%i, partition: %i, index: %i",
-                entityMapping.table,
-                entityMapping.instance.partition,
-                entityMapping.instance.index
-            );
-            if (entityMapping.table != MemDb::TableId::Invalid())
+            for (uint entityIndex = 0; entityIndex < this->entityMap.Size(); entityIndex++)
             {
-                ImGui::TextDisabled("- %s", this->db->GetTable(entityMapping.table).name.Value());
-                ImGui::EndGroup();
-                if (ImGui::IsItemHovered())
+                Game::EntityMapping entityMapping = this->entityMap[entityIndex];
+                
+                if (!listInactive && (entityMapping.table == MemDb::InvalidTableId || entityMapping.instance == MemDb::InvalidRow))
+                    continue;
+
+                ImGui::BeginGroup();
+                ImGui::Text("[%i] ", entityIndex);
+                ImGui::SameLine();
+                ImGui::TextColored(
+                    {1, 0.3f, 0, 1},
+                    "tid:%i, partition: %i, index: %i",
+                    entityMapping.table,
+                    entityMapping.instance.partition,
+                    entityMapping.instance.index
+                );
+                if (entityMapping.table != MemDb::TableId::Invalid())
                 {
-                    ImGui::BeginTooltip();
                     ImGui::TextDisabled("- %s", this->db->GetTable(entityMapping.table).name.Value());
-                    MemDb::TableId const table = entityMapping.table;
-                    MemDb::RowId const row = entityMapping.instance;
-
-                    void* ownerBuffer = this->GetInstanceBuffer(table, row.partition, Game::Entity::Traits::fixed_column_index);
-                    ownerBuffer = (byte*)ownerBuffer + (row.index * sizeof(Game::Entity));
-                    Game::Entity owner = *(Game::Entity*)ownerBuffer;
-
-                    ImGui::TextDisabled("Entity: %llu", (uint64_t)owner);
-                    ImGui::TextDisabled("Entity.world: %llu", (uint64_t)owner.world);
-                    ImGui::TextDisabled("Entity.reserved: %llu", (uint64_t)owner.reserved);
-                    ImGui::TextDisabled("Entity.generation: %llu", (uint64_t)owner.generation);
-                    ImGui::TextDisabled("Entity.index: %llu", (uint64_t)owner.index);
-
-                    bool prevDebugState = Game::ComponentInspection::Instance()->debug;
-                    Game::ComponentInspection::Instance()->debug = true;
-                    auto const& components = this->db->GetTable(table).GetAttributes();
-                    for (auto component : components)
+                    ImGui::EndGroup();
+                    if (ImGui::IsItemHovered())
                     {
-                        Game::ComponentInterface* cInterface =
-                            (Game::ComponentInterface*)MemDb::AttributeRegistry::GetAttribute(component);
-                        if (cInterface->GetNumFields() == 0)
+                        ImGui::BeginTooltip();
+                        ImGui::TextDisabled("- %s", this->db->GetTable(entityMapping.table).name.Value());
+                        MemDb::TableId const table = entityMapping.table;
+                        MemDb::RowId const row = entityMapping.instance;
+
+                        void* ownerBuffer = this->GetInstanceBuffer(table, row.partition, Game::Entity::Traits::fixed_column_index);
+                        ownerBuffer = (byte*)ownerBuffer + (row.index * sizeof(Game::Entity));
+                        Game::Entity owner = *(Game::Entity*)ownerBuffer;
+
+                        ImGui::TextDisabled("Entity: %llu", (uint64_t)owner);
+                        ImGui::TextDisabled("Entity.world: %llu", (uint64_t)owner.world);
+                        ImGui::TextDisabled("Entity.reserved: %llu", (uint64_t)owner.reserved);
+                        ImGui::TextDisabled("Entity.generation: %llu", (uint64_t)owner.generation);
+                        ImGui::TextDisabled("Entity.index: %llu", (uint64_t)owner.index);
+
+                        bool prevDebugState = Game::ComponentInspection::Instance()->debug;
+                        Game::ComponentInspection::Instance()->debug = true;
+                        auto const& components = this->db->GetTable(table).GetAttributes();
+                        for (auto component : components)
                         {
-                            // Type is flag type, just print the name, and then continue
-                            ImGui::Text("_flag_: %s", MemDb::AttributeRegistry::GetAttribute(component)->name.Value());
+                            Game::ComponentInterface* cInterface =
+                                (Game::ComponentInterface*)MemDb::AttributeRegistry::GetAttribute(component);
+                            if (cInterface->GetNumFields() == 0)
+                            {
+                                // Type is flag type, just print the name, and then continue
+                                ImGui::Text("_flag_: %s", MemDb::AttributeRegistry::GetAttribute(component)->name.Value());
+                                ImGui::Separator();
+                                continue;
+                            }
+                            else
+                            {
+                                ImGui::Text(MemDb::AttributeRegistry::GetAttribute(component)->name.Value());
+                            }
+                            SizeT const typeSize = MemDb::AttributeRegistry::TypeSize(component);
+                            void* data = this->GetInstanceBuffer(table, row.partition, component);
+                            data = (byte*)data + (row.index * typeSize);
+
+                            const ImGuiTableFlags flags = ImGuiTableFlags_SizingFixedFit | ImGuiTableFlags_Borders |
+                                                        ImGuiTableFlags_RowBg | ImGuiTableFlags_Reorderable | ImGuiTableFlags_Hideable;
+                            ImGui::PushID(row.index + 0xF23);
+                            if (ImGui::BeginTable(MemDb::AttributeRegistry::GetAttribute(component)->name.Value(), 2, flags))
+                            {
+                                ImGui::TableSetupColumn("FieldName", ImGuiTableColumnFlags_WidthFixed);
+                                ImGui::TableSetupColumn("FieldValue", ImGuiTableColumnFlags_WidthStretch);
+
+                                ImGui::TableNextRow();
+                                bool commitChange = false;
+                                
+                                Game::ComponentInspection::DrawInspector(owner, component, data, &commitChange);
+                                ImGui::EndTable();
+                                ImGui::Spacing();
+                                ImGui::Spacing();
+                                ImGui::Spacing();
+                            }
+                            ImGui::PopID();
+
                             ImGui::Separator();
-                            continue;
-                        }
-                        else
-                        {
-                            ImGui::Text(MemDb::AttributeRegistry::GetAttribute(component)->name.Value());
-                        }
-                        SizeT const typeSize = MemDb::AttributeRegistry::TypeSize(component);
-                        void* data = this->GetInstanceBuffer(table, row.partition, component);
-                        data = (byte*)data + (row.index * typeSize);
-
-                        const ImGuiTableFlags flags = ImGuiTableFlags_SizingFixedFit | ImGuiTableFlags_Borders |
-                                                      ImGuiTableFlags_RowBg | ImGuiTableFlags_Reorderable | ImGuiTableFlags_Hideable;
-                        ImGui::PushID(row.index + 0xF23);
-                        if (ImGui::BeginTable(MemDb::AttributeRegistry::GetAttribute(component)->name.Value(), 2, flags))
-                        {
-                            ImGui::TableSetupColumn("FieldName", ImGuiTableColumnFlags_WidthFixed);
-                            ImGui::TableSetupColumn("FieldValue", ImGuiTableColumnFlags_WidthStretch);
-
-                            ImGui::TableNextRow();
-                            bool commitChange = false;
-                            
-                            Game::ComponentInspection::DrawInspector(owner, component, data, &commitChange);
-                            ImGui::EndTable();
-                            ImGui::Spacing();
-                            ImGui::Spacing();
-                            ImGui::Spacing();
                         }
-                        ImGui::PopID();
-
-                        ImGui::Separator();
+                        Game::ComponentInspection::Instance()->debug = prevDebugState;
+                        ImGui::EndTooltip();
                     }
-                    Game::ComponentInspection::Instance()->debug = prevDebugState;
-                    ImGui::EndTooltip();
                 }
+                else
+                {
+                    ImGui::EndGroup();
+                    ImGui::TextDisabled("- ");
+                }
+                ImGui::Separator();
             }
-            else
-            {
-                ImGui::EndGroup();
-                ImGui::TextDisabled("- ");
-            }
-            ImGui::Separator();
         }
+        ImGui::EndChild();
     }
-    ImGui::EndChild();
 }
 
 //------------------------------------------------------------------------------

code/foundation/timing/posix/posixtimer.cc

@@ -56,7 +56,9 @@ void
 PosixTimer::Stop()
 {
     n_assert(this->running);
-    this->stopTime = clock();
+    timespec times;
+    n_assert(clock_gettime(CLOCK_MONOTONIC,&times) == 0);
+    this->stopTime = ToTime(times);
     this->running = false;
 }