vsg::Profiler development underway

[robertosfield]

Hi All,

Over the past few days I have been working on a vsg::Profiler class that is an vsg::Instrumentation implementation that captures CPU and GPU timing zones to a vsg::ProfileLog while the application runs and is able to report the results at completion.

The new class is still in development, but is far enough along for others to have a look and perhaps test it, the work in the Profiler branch of the VSG and vsgExamples:

/~https://github.com/vsg-dev/VulkanSceneGraph/tree/Profiler
/~https://github.com/vsg-dev/vsgExamples/tree/Profiler

To test out the functionality I have added vsg::Profiler support to vsgviewer, vsganimation, vsgdynamicload, vsgshadow and a new vsginstrumentation testbed example that I used for the initial development of the vsg::Profiler.

To assign the vsg::Profiler to collect stats you do something similar to what I've done to the above examples:

    if (arguments.read({"--profiler", "--pr"}))
    {
        // set Profiler options
        auto settings = vsg::Profiler::Settings::create();
        arguments.read("--cpu", settings->cpu_instrumentation_level);
        arguments.read("--gpu", settings->gpu_instrumentation_level);
        arguments.read("--log-size", settings->log_size);
        arguments.read("--gpu-size", settings->gpu_timestamp_size);

        // create the profiler
        instrumentation = vsg::Profiler::create(settings);
    }

    ....

    if (instrumentation) viewer->assignInstrumentation(instrumentation);

The main loop requires no changes so will look something like:

        // rendering main loop
        while (viewer->advanceToNextFrame() && (numFrames < 0 || (numFrames--) > 0))
        {
            // pass any events into EventHandlers assigned to the Viewer
            viewer->handleEvents();

            viewer->update();

            viewer->recordAndSubmit();

            viewer->present();
        }

What the vsg::Profiler will do is record CPU and GPU time stamps placing the results into std::vectorvsg::ProfileLog::Entry, each time zoned has an enter and leave Entry, and each of these paired Entry objects has a uint64_t reference value that points index position of the other member of the pair. Each entry has various details recorded that allow applications to compute both time since start of application and the duration of zones.

To get the results we call finish on instrumentation/profiler object so it can get any of it's outstanding GPU results and then write them out to a stream, such as simply writing to the console:

        if (auto profiler = instrumentation.cast<vsg::Profiler>())
        {
            profiler->finish();
            profiler->log->report(std::cout);
        }

When running:

vsgviewer models/lz.vsgt --profiler 

The typical frame of output from ProfileLog::report(..) looks something like:

ProfileLog::report(5010)
{
 { FRAME, cpu_duration = 16.8537ms, , func=virtual bool vsg::Viewer::advanceToNextFrame(double), line=155
  { CPU, cpu_duration = 0.00045ms, , func=void vsg::RecordAndSubmitTask::advance(), line=47
   { CPU, cpu_duration = 0.00012ms, , func=void vsg::TransferTask::advance(), line=37 }
   { CPU, cpu_duration = 9e-05ms, , func=void vsg::TransferTask::advance(), line=37 }
  } CPU, cpu_duration = 0.00045ms, , func=void vsg::RecordAndSubmitTask::advance(), line=47
  { CPU, cpu_duration = 0.00055ms, , func=virtual void vsg::Viewer::handleEvents(), line=262 }
  { CPU, cpu_duration = 0.00053ms, , func=virtual void vsg::Viewer::update(), line=811
   { CPU, cpu_duration = 7e-05ms, , func=virtual void vsg::AnimationManager::run(vsg::ref_ptr<vsg::FrameStamp>), line=81 }
  } CPU, cpu_duration = 0.00053ms, , func=virtual void vsg::Viewer::update(), line=811
  { CPU, cpu_duration = 16.7914ms, , func=virtual void vsg::Viewer::recordAndSubmit(), line=833
   { CPU, cpu_duration = 16.7908ms, , func=virtual VkResult vsg::RecordAndSubmitTask::submit(vsg::ref_ptr<vsg::FrameStamp>), line=87
    { CPU, cpu_duration = 16.5829ms, , func=virtual VkResult vsg::RecordAndSubmitTask::start(), line=105 }
    { CPU, cpu_duration = 0.00018ms, , func=virtual VkResult vsg::TransferTask::transferDynamicData(), line=334 }
    { CPU, cpu_duration = 0.148881ms, , func=virtual VkResult vsg::RecordAndSubmitTask::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>), line=123
     { CPU, cpu_duration = 0.147931ms, , func=virtual void vsg::CommandGraph::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>, vsg::ref_ptr<vsg::DatabasePager>), line=77
      { CPU, cpu_duration = 7e-05ms, , func=vsg::ref_ptr<vsg::RecordTraversal> vsg::CommandGraph::getOrCreateRecordTraversal(), line=66 }
      { COMMAND_BUFFER, cpu_duration = 0.11406ms, , gpu_duration = 0.015744ms, , func=virtual void vsg::CommandGraph::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>, vsg::ref_ptr<vsg::DatabasePager>), line=134
       { GPU, cpu_duration = 0.11014ms, , gpu_duration = 0.012512ms, , func=virtual void vsg::RenderGraph::accept(vsg::RecordTraversal&) const, line=105
        { GPU, cpu_duration = 0.08662ms, , gpu_duration = 0.004736ms, , func=void vsg::RecordTraversal::apply(const vsg::View&), line=476
         { GPU, cpu_duration = 0.05454ms, , func=void vsg::RecordTraversal::apply(const vsg::Bin&), line=468 }
         { CPU, cpu_duration = 0.00048ms, , func=virtual void vsg::ViewDependentState::traverse(vsg::RecordTraversal&) const, line=502 }
        } GPU, cpu_duration = 0.08662ms, , gpu_duration = 0.004736ms, , func=void vsg::RecordTraversal::apply(const vsg::View&), line=476
       } GPU, cpu_duration = 0.11014ms, , gpu_duration = 0.012512ms, , func=virtual void vsg::RenderGraph::accept(vsg::RecordTraversal&) const, line=105
      } COMMAND_BUFFER, cpu_duration = 0.11406ms, , gpu_duration = 0.015744ms, , func=virtual void vsg::CommandGraph::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>, vsg::ref_ptr<vsg::DatabasePager>), line=134
     } CPU, cpu_duration = 0.147931ms, , func=virtual void vsg::CommandGraph::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>, vsg::ref_ptr<vsg::DatabasePager>), line=77
    } CPU, cpu_duration = 0.148881ms, , func=virtual VkResult vsg::RecordAndSubmitTask::record(vsg::ref_ptr<vsg::RecordedCommandBuffers>, vsg::ref_ptr<vsg::FrameStamp>), line=123
    { CPU, cpu_duration = 0.046521ms, , func=virtual VkResult vsg::RecordAndSubmitTask::finish(vsg::ref_ptr<vsg::RecordedCommandBuffers>), line=135
     { CPU, cpu_duration = 0.038341ms, , func=virtual VkResult vsg::TransferTask::transferDynamicData(), line=334
      { COMMAND_BUFFER, cpu_duration = 0.00296ms, , gpu_duration = 0.008128ms, , func=virtual VkResult vsg::TransferTask::transferDynamicData(), line=400
       { CPU, cpu_duration = 0.00204ms, , func=void vsg::TransferTask::_transferBufferInfos(VkCommandBuffer, vsg::TransferTask::Frame&, VkDeviceSize&), line=108 }
       { CPU, cpu_duration = 6e-05ms, , func=void vsg::TransferTask::_transferImageInfos(VkCommandBuffer, vsg::TransferTask::Frame&, VkDeviceSize&), line=218 }
      } COMMAND_BUFFER, cpu_duration = 0.00296ms, , gpu_duration = 0.008128ms, , func=virtual VkResult vsg::TransferTask::transferDynamicData(), line=400
     } CPU, cpu_duration = 0.038341ms, , func=virtual VkResult vsg::TransferTask::transferDynamicData(), line=334
    } CPU, cpu_duration = 0.046521ms, , func=virtual VkResult vsg::RecordAndSubmitTask::finish(vsg::ref_ptr<vsg::RecordedCommandBuffers>), line=135
   } CPU, cpu_duration = 16.7908ms, , func=virtual VkResult vsg::RecordAndSubmitTask::submit(vsg::ref_ptr<vsg::FrameStamp>), line=87
  } CPU, cpu_duration = 16.7914ms, , func=virtual void vsg::Viewer::recordAndSubmit(), line=833
  { CPU, cpu_duration = 0.05694ms, , func=virtual void vsg::Viewer::present(), line=867 }
  { CPU, cpu_duration = 0.00028ms, , func=bool vsg::Viewer::active() const, line=115 }
 } FRAME, cpu_duration = 16.8537ms, , func=virtual bool vsg::Viewer::advanceToNextFrame(double), line=155
}

As this stand the vsg::Profiler is mainly about recording time stamps, threading info and code location info to the vsg::ProfileLog and the ProfileLog::report(..) is mainly there right now for development purposes, my hope is that this just the very first way to interrogate a ProfileLog and as time goes on will add both statistical analysis of the results and interactive tools.

One approach would be to have an ImGui interface to show all the data off, something that could be part of vsgImGui. The data stored in ProfileLog is similar to what Tracy records so there is potentially quite a bit one could do with the data. My thought for the near term is something quite simple would still be very helpful for users - even the OSG's on screen stats are helpful and is far less fine grained than what vsg::Profiler/ProfileLog can provide so I'm sure something pretty useful could be done even without the depth of stats that Tracy provides.

Why not just use Tracy? vsg::Profiler handle Vulkan better than Tracy and we can record logs to file and browse them/search them by hand, record traces and compare multiple runs so utilize them for unit tests that require no GUI interaction.

The initial kick for me to develop vsg::Profiler is to help track performance changes when I start optimize the shadow support and other parts of the VSG, so being able to run a standard animation path with a standard model then iterate the implementation to see how things progress in a way see actual figures for the CPU and GPU costs of different changes.

My hope is that others in the community will be inspired by vsg::Profiler and come up with neat ways to analyze and present the results. I don't yet have proper ImGui/ImPlot usage under my belt so others may be far better place to create an interface to ProfileLog.

Over the next few days I'll start using vsg::Profiler with my work on shadows so I expect I'll gain insights on what is useful and what other features are required. Once the new functionality looks solid I'll merge with VSG and vsgExamples master, perhaps even by end of week.

[robertosfield]

While there is still more work to do, I am happy enough to the present status of vsg::Profiler to merge with VSG master and vsgExamples master:

#1117
vsg-dev/vsgExamples#289