add profiler framework.

CMakeLists.txt

@@ -421,6 +421,7 @@ set(TINYUSDZ_SOURCES
     ${PROJECT_SOURCE_DIR}/src/stage.hh
     ${PROJECT_SOURCE_DIR}/src/uuid-gen.cc
     ${PROJECT_SOURCE_DIR}/src/uuid-gen.hh
+    ${PROJECT_SOURCE_DIR}/src/parser-timing.cc
 
     )
 

src/ascii-parser.cc

@@ -31,6 +31,7 @@
 #include <vector>
 
 #include "ascii-parser.hh"
+#include "parser-timing.hh"
 #include "path-util.hh"
 #include "str-util.hh"
 #include "tiny-format.hh"
@@ -5124,13 +5125,19 @@ bool AsciiParser::ParseBlock(const Specifier spec, const int64_t primIdx,
 ///
 bool AsciiParser::Parse(const uint32_t load_states,
                         const AsciiParserOption &parser_option) {
+  TINYUSDZ_PROFILE_FUNCTION("ascii-parser");
+  
   _toplevel = (load_states & static_cast<uint32_t>(LoadState::Toplevel));
   _sub_layered = (load_states & static_cast<uint32_t>(LoadState::Sublayer));
   _referenced = (load_states & static_cast<uint32_t>(LoadState::Reference));
   _payloaded = (load_states & static_cast<uint32_t>(LoadState::Payload));
   _option = parser_option;
 
-  bool header_ok = ParseMagicHeader();
+  bool header_ok;
+  {
+    TINYUSDZ_PROFILE_SCOPE("ascii-parser", "ParseMagicHeader");
+    header_ok = ParseMagicHeader();
+  }
   if (!header_ok) {
     PUSH_ERROR_AND_RETURN("Failed to parse USDA magic header.\n");
   }
@@ -5150,6 +5157,7 @@ bool AsciiParser::Parse(const uint32_t load_states,
 
     if (c == '(') {
       // stage meta.
+      TINYUSDZ_PROFILE_SCOPE("ascii-parser", "ParseStageMetas");
       if (!ParseStageMetas()) {
         PUSH_ERROR_AND_RETURN("Failed to parse Stage metas.");
       }
@@ -5170,47 +5178,54 @@ bool AsciiParser::Parse(const uint32_t load_states,
   PushPrimPath("/");
 
   // parse blocks
-  while (!Eof()) {
-    if (!SkipCommentAndWhitespaceAndNewline()) {
-      return false;
-    }
+  {
+    TINYUSDZ_PROFILE_SCOPE("ascii-parser", "ParseBlocks");
+    while (!Eof()) {
+      if (!SkipCommentAndWhitespaceAndNewline()) {
+        return false;
+      }
 
-    if (Eof()) {
-      // Whitespaces in the end of line.
-      break;
-    }
+      if (Eof()) {
+        // Whitespaces in the end of line.
+        break;
+      }
 
-    // Look ahead token
-    auto curr_loc = _sr->tell();
+      // Look ahead token
+      auto curr_loc = _sr->tell();
 
-    Identifier tok;
-    if (!ReadBasicType(&tok)) {
-      PUSH_ERROR_AND_RETURN("Identifier expected.\n");
-    }
+      Identifier tok;
+      if (!ReadBasicType(&tok)) {
+        PUSH_ERROR_AND_RETURN("Identifier expected.\n");
+      }
 
-    // Rewind
-    if (!SeekTo(curr_loc)) {
-      return false;
-    }
+      // Rewind
+      if (!SeekTo(curr_loc)) {
+        return false;
+      }
 
-    Specifier spec{Specifier::Invalid};
-    if (tok == "def") {
-      spec = Specifier::Def;
-    } else if (tok == "over") {
-      spec = Specifier::Over;
-    } else if (tok == "class") {
-      spec = Specifier::Class;
-    } else {
-      PUSH_ERROR_AND_RETURN("Invalid specifier token '" + tok + "'");
-    }
+      Specifier spec{Specifier::Invalid};
+      if (tok == "def") {
+        spec = Specifier::Def;
+      } else if (tok == "over") {
+        spec = Specifier::Over;
+      } else if (tok == "class") {
+        spec = Specifier::Class;
+      } else {
+        PUSH_ERROR_AND_RETURN("Invalid specifier token '" + tok + "'");
+      }
 
-    int64_t primIdx = _prim_idx_assign_fun(-1);
-    DCOUT("Enter parseDef. primIdx = " << primIdx
-                                       << ", parentPrimIdx = root(-1)");
-    bool block_ok = ParseBlock(spec, primIdx, /* parent */ -1, /* depth */ 0,
-                               /* in_variantStmt */ false);
-    if (!block_ok) {
-      PUSH_ERROR_AND_RETURN("Failed to parse `def` block.");
+      int64_t primIdx = _prim_idx_assign_fun(-1);
+      DCOUT("Enter parseDef. primIdx = " << primIdx
+                                         << ", parentPrimIdx = root(-1)");
+      bool block_ok;
+      {
+        TINYUSDZ_PROFILE_SCOPE("ascii-parser", "ParseBlock");
+        block_ok = ParseBlock(spec, primIdx, /* parent */ -1, /* depth */ 0,
+                             /* in_variantStmt */ false);
+      }
+      if (!block_ok) {
+        PUSH_ERROR_AND_RETURN("Failed to parse `def` block.");
+      }
     }
   }
 

src/crate-reader.cc

@@ -25,6 +25,7 @@
 #include <stack>
 
 #include "crate-format.hh"
+#include "parser-timing.hh"
 #include "crate-pprint.hh"
 #include "integerCoding.h"
 #include "lz4-compression.hh"
@@ -5442,6 +5443,7 @@ bool CrateReader::ReadSection(crate::Section *s) {
 }
 
 bool CrateReader::ReadTokens() {
+  TINYUSDZ_PROFILE_SCOPE("crate-reader", "ReadTokens");
   if ((_tokens_index < 0) || (_tokens_index >= int64_t(_toc.sections.size()))) {
     PUSH_ERROR_AND_RETURN_TAG(kTag, "Invalid index for `TOKENS` section.");
   }
@@ -5619,6 +5621,7 @@ bool CrateReader::ReadTokens() {
 }
 
 bool CrateReader::ReadStrings() {
+  TINYUSDZ_PROFILE_SCOPE("crate-reader", "ReadStrings");
   if ((_strings_index < 0) ||
       (_strings_index >= int64_t(_toc.sections.size()))) {
     _err += "Invalid index for `STRINGS` section.\n";
@@ -6129,6 +6132,7 @@ bool CrateReader::ReadSpecs() {
 }
 
 bool CrateReader::ReadPaths() {
+  TINYUSDZ_PROFILE_SCOPE("crate-reader", "ReadPaths");
   if ((_paths_index < 0) || (_paths_index >= int64_t(_toc.sections.size()))) {
     PUSH_ERROR("Invalid index for `PATHS` section.");
     return false;
@@ -6188,6 +6192,7 @@ bool CrateReader::ReadPaths() {
 }
 
 bool CrateReader::ReadBootStrap() {
+  TINYUSDZ_PROFILE_FUNCTION("crate-reader");
   // parse header.
   uint8_t magic[8];
   if (8 != _sr->read(/* req */ 8, /* dst len */ 8, magic)) {
@@ -6249,6 +6254,7 @@ bool CrateReader::ReadBootStrap() {
 }
 
 bool CrateReader::ReadTOC() {
+  TINYUSDZ_PROFILE_FUNCTION("crate-reader");
 
   DCOUT(fmt::format("Memory budget: {} bytes", _config.maxMemoryBudget));
 

src/parser-timing.cc

@@ -0,0 +1,173 @@
+// SPDX-License-Identifier: Apache 2.0
+// Copyright 2023 - Present, Light Transport Entertainment Inc.
+//
+// Parser execution time profiling implementation
+
+#include "parser-timing.hh"
+#include <algorithm>
+#include <iomanip>
+#include <sstream>
+
+namespace tinyusdz {
+
+void ParserTimer::StartTimer(const std::string& operation_name) {
+  active_timers_[operation_name] = Clock::now();
+}
+
+ParserTimer::Duration ParserTimer::EndTimer(const std::string& operation_name) {
+  auto end_time = Clock::now();
+  auto it = active_timers_.find(operation_name);
+  if (it == active_timers_.end()) {
+    return Duration{0};
+  }
+
+  auto elapsed = std::chrono::duration_cast<Duration>(end_time - it->second);
+  active_timers_.erase(it);
+
+  RecordTiming(operation_name, elapsed);
+  return elapsed;
+}
+
+void ParserTimer::RecordTiming(const std::string& operation_name, Duration elapsed) {
+  auto& data = timing_data_[operation_name];
+  data.total_time += elapsed;
+  data.count++;
+}
+
+ParserTimer::Duration ParserTimer::GetTotalTime(const std::string& operation_name) const {
+  auto it = timing_data_.find(operation_name);
+  return (it != timing_data_.end()) ? it->second.total_time : Duration{0};
+}
+
+size_t ParserTimer::GetOperationCount(const std::string& operation_name) const {
+  auto it = timing_data_.find(operation_name);
+  return (it != timing_data_.end()) ? it->second.count : 0;
+}
+
+ParserTimer::Duration ParserTimer::GetAverageTime(const std::string& operation_name) const {
+  auto it = timing_data_.find(operation_name);
+  if (it == timing_data_.end() || it->second.count == 0) {
+    return Duration{0};
+  }
+  return Duration{it->second.total_time.count() / it->second.count};
+}
+
+std::vector<std::string> ParserTimer::GetOperationNames() const {
+  std::vector<std::string> names;
+  names.reserve(timing_data_.size());
+  for (const auto& pair : timing_data_) {
+    names.push_back(pair.first);
+  }
+  return names;
+}
+
+void ParserTimer::Clear() {
+  active_timers_.clear();
+  timing_data_.clear();
+}
+
+std::string ParserTimer::GenerateReport() const {
+  std::ostringstream oss;
+  oss << std::fixed << std::setprecision(3);
+  
+  oss << "Parser Timing Report:\n";
+  oss << "=====================\n";
+  
+  if (timing_data_.empty()) {
+    oss << "No timing data recorded.\n";
+    return oss.str();
+  }
+
+  // Calculate column widths
+  size_t max_name_width = 20;
+  for (const auto& pair : timing_data_) {
+    max_name_width = std::max(max_name_width, pair.first.length() + 2);
+  }
+
+  // Header
+  oss << std::left << std::setw(max_name_width) << "Operation"
+      << std::right << std::setw(12) << "Total (ms)"
+      << std::setw(10) << "Count"
+      << std::setw(12) << "Avg (ms)" << "\n";
+  
+  oss << std::string(max_name_width + 34, '-') << "\n";
+
+  // Sort operations by total time (descending)
+  std::vector<std::pair<std::string, TimingData>> sorted_data(timing_data_.begin(), timing_data_.end());
+  std::sort(sorted_data.begin(), sorted_data.end(),
+    [](const auto& a, const auto& b) {
+      return a.second.total_time > b.second.total_time;
+    });
+
+  // Data rows
+  for (const auto& pair : sorted_data) {
+    const std::string& name = pair.first;
+    const TimingData& data = pair.second;
+    
+    double total_ms = data.total_time.count() / 1000000.0;
+    double avg_ms = (data.count > 0) ? total_ms / data.count : 0.0;
+    
+    oss << std::left << std::setw(max_name_width) << name
+        << std::right << std::setw(12) << total_ms
+        << std::setw(10) << data.count
+        << std::setw(12) << avg_ms << "\n";
+  }
+
+  return oss.str();
+}
+
+ScopedTimer::ScopedTimer(ParserTimer* timer, const std::string& operation_name)
+    : timer_(timer), operation_name_(operation_name) {
+  if (timer_) {
+    timer_->StartTimer(operation_name_);
+  }
+}
+
+ScopedTimer::~ScopedTimer() {
+  if (timer_) {
+    timer_->EndTimer(operation_name_);
+  }
+}
+
+ParserProfiler& ParserProfiler::GetInstance() {
+  static ParserProfiler instance;
+  return instance;
+}
+
+void ParserProfiler::SetConfig(const ParserProfilingConfig& config) {
+  config_ = config;
+}
+
+const ParserProfilingConfig& ParserProfiler::GetConfig() const {
+  return config_;
+}
+
+ParserTimer* ParserProfiler::GetTimer(const std::string& parser_name) {
+  return &timers_[parser_name];
+}
+
+std::string ParserProfiler::GenerateReport() const {
+  std::ostringstream oss;
+  oss << "TinyUSDZ Parser Profiling Report\n";
+  oss << "================================\n\n";
+  
+  if (timers_.empty()) {
+    oss << "No profiling data available.\n";
+    return oss.str();
+  }
+
+  for (const auto& pair : timers_) {
+    oss << "Parser: " << pair.first << "\n";
+    oss << pair.second.GenerateReport() << "\n";
+  }
+
+  return oss.str();
+}
+
+void ParserProfiler::ClearAll() {
+  for (auto& pair : timers_) {
+    pair.second.Clear();
+  }
+}
+
+}  // namespace tinyusdz

src/parser-timing.hh

@@ -0,0 +1,160 @@
+// SPDX-License-Identifier: Apache 2.0
+// Copyright 2023 - Present, Light Transport Entertainment Inc.
+//
+// Parser execution time profiling infrastructure
+
+#pragma once
+
+#include <chrono>
+#include <map>
+#include <string>
+#include <vector>
+
+namespace tinyusdz {
+
+///
+/// High-resolution timing utilities for parser profiling
+///
+class ParserTimer {
+ public:
+  using Clock = std::chrono::high_resolution_clock;
+  using TimePoint = Clock::time_point;
+  using Duration = std::chrono::nanoseconds;
+
+  ///
+  /// Start timing a named operation
+  ///
+  void StartTimer(const std::string& operation_name);
+
+  ///
+  /// End timing for the named operation
+  /// Returns elapsed time in nanoseconds
+  ///
+  Duration EndTimer(const std::string& operation_name);
+
+  ///
+  /// Record a timing measurement directly
+  ///
+  void RecordTiming(const std::string& operation_name, Duration elapsed);
+
+  ///
+  /// Get total elapsed time for an operation (sum of all measurements)
+  ///
+  Duration GetTotalTime(const std::string& operation_name) const;
+
+  ///
+  /// Get number of times an operation was measured
+  ///
+  size_t GetOperationCount(const std::string& operation_name) const;
+
+  ///
+  /// Get average time per operation
+  ///
+  Duration GetAverageTime(const std::string& operation_name) const;
+
+  ///
+  /// Get all recorded operation names
+  ///
+  std::vector<std::string> GetOperationNames() const;
+
+  ///
+  /// Clear all timing data
+  ///
+  void Clear();
+
+  ///
+  /// Generate human-readable timing report
+  ///
+  std::string GenerateReport() const;
+
+ private:
+  struct TimingData {
+    Duration total_time{0};
+    size_t count{0};
+  };
+
+  std::map<std::string, TimePoint> active_timers_;
+  std::map<std::string, TimingData> timing_data_;
+};
+
+///
+/// RAII timer for automatic scope-based timing
+///
+class ScopedTimer {
+ public:
+  ScopedTimer(ParserTimer* timer, const std::string& operation_name);
+  ~ScopedTimer();
+
+  // Non-copyable
+  ScopedTimer(const ScopedTimer&) = delete;
+  ScopedTimer& operator=(const ScopedTimer&) = delete;
+
+ private:
+  ParserTimer* timer_;
+  std::string operation_name_;
+};
+
+///
+/// Profiling configuration for parsers
+///
+struct ParserProfilingConfig {
+  bool enable_profiling{false};           ///< Enable/disable profiling
+  bool profile_parsing_phases{true};      ///< Profile major parsing phases
+  bool profile_property_parsing{false};   ///< Profile individual property parsing
+  bool profile_value_parsing{false};      ///< Profile value type parsing
+  bool profile_memory_operations{false};  ///< Profile memory allocations
+};
+
+///
+/// Centralized profiling interface for all parsers
+///
+class ParserProfiler {
+ public:
+  static ParserProfiler& GetInstance();
+
+  ///
+  /// Configure profiling settings
+  ///
+  void SetConfig(const ParserProfilingConfig& config);
+  const ParserProfilingConfig& GetConfig() const;
+
+  ///
+  /// Get timer instance for a parser
+  ///
+  ParserTimer* GetTimer(const std::string& parser_name);
+
+  ///
+  /// Generate comprehensive profiling report for all parsers
+  ///
+  std::string GenerateReport() const;
+
+  ///
+  /// Clear all profiling data
+  ///
+  void ClearAll();
+
+ private:
+  ParserProfiler() = default;
+  
+  ParserProfilingConfig config_;
+  std::map<std::string, ParserTimer> timers_;
+};
+
+// Convenience macros for profiling
+#define TINYUSDZ_PROFILE_FUNCTION(parser_name) \
+  tinyusdz::ScopedTimer timer_scope(tinyusdz::ParserProfiler::GetInstance().GetTimer(parser_name), __FUNCTION__)
+
+#define TINYUSDZ_PROFILE_SCOPE(parser_name, scope_name) \
+  tinyusdz::ScopedTimer timer_scope(tinyusdz::ParserProfiler::GetInstance().GetTimer(parser_name), scope_name)
+
+#define TINYUSDZ_PROFILE_START(parser_name, operation) \
+  if (tinyusdz::ParserProfiler::GetInstance().GetConfig().enable_profiling) { \
+    tinyusdz::ParserProfiler::GetInstance().GetTimer(parser_name)->StartTimer(operation); \
+  }
+
+#define TINYUSDZ_PROFILE_END(parser_name, operation) \
+  if (tinyusdz::ParserProfiler::GetInstance().GetConfig().enable_profiling) { \
+    tinyusdz::ParserProfiler::GetInstance().GetTimer(parser_name)->EndTimer(operation); \
+  }
+
+}  // namespace tinyusdz

src/usda-reader.cc

@@ -30,6 +30,7 @@
 #include <vector>
 
 #include "usda-reader.hh"
+#include "parser-timing.hh"
 
 //
 #if !defined(TINYUSDZ_DISABLE_MODULE_USDA_READER)
@@ -1634,6 +1635,7 @@ bool USDAReader::Impl::ReconstructPrim(
 ///
 
 bool USDAReader::Impl::Read(const uint32_t state_flags, bool as_primspec) {
+  TINYUSDZ_PROFILE_FUNCTION("usda-reader");
 
   ///
   /// Convert parser option.

src/usdc-reader.cc

@@ -19,6 +19,7 @@
 #endif
 
 #include "usdc-reader.hh"
+#include "parser-timing.hh"
 
 #if !defined(TINYUSDZ_DISABLE_MODULE_USDC_READER)
 
@@ -3781,6 +3782,7 @@ bool USDCReader::Impl::ToLayer(Layer *layer) {
 }
 
 bool USDCReader::Impl::ReadUSDC() {
+  TINYUSDZ_PROFILE_FUNCTION("usdc-reader");
   if (crate_reader) {
     delete crate_reader;
   }
@@ -3807,30 +3809,42 @@ bool USDCReader::Impl::ReadUSDC() {
   _warn.clear();
   _err.clear();
 
-  if (!crate_reader->ReadBootStrap()) {
-    _warn = crate_reader->GetWarning();
-    _err = crate_reader->GetError();
-    return false;
+  {
+    TINYUSDZ_PROFILE_SCOPE("usdc-reader", "ReadBootStrap");
+    if (!crate_reader->ReadBootStrap()) {
+      _warn = crate_reader->GetWarning();
+      _err = crate_reader->GetError();
+      return false;
+    }
   }
 
-  if (!crate_reader->ReadTOC()) {
-    _warn = crate_reader->GetWarning();
-    _err = crate_reader->GetError();
-    return false;
+  {
+    TINYUSDZ_PROFILE_SCOPE("usdc-reader", "ReadTOC");
+    if (!crate_reader->ReadTOC()) {
+      _warn = crate_reader->GetWarning();
+      _err = crate_reader->GetError();
+      return false;
+    }
   }
 
   // Read known sections
 
-  if (!crate_reader->ReadTokens()) {
-    _warn = crate_reader->GetWarning();
-    _err = crate_reader->GetError();
-    return false;
+  {
+    TINYUSDZ_PROFILE_SCOPE("usdc-reader", "ReadTokens");
+    if (!crate_reader->ReadTokens()) {
+      _warn = crate_reader->GetWarning();
+      _err = crate_reader->GetError();
+      return false;
+    }
   }
 
-  if (!crate_reader->ReadStrings()) {
-    _warn = crate_reader->GetWarning();
-    _err = crate_reader->GetError();
-    return false;
+  {
+    TINYUSDZ_PROFILE_SCOPE("usdc-reader", "ReadStrings");
+    if (!crate_reader->ReadStrings()) {
+      _warn = crate_reader->GetWarning();
+      _err = crate_reader->GetError();
+      return false;
+    }
   }
 
   if (!crate_reader->ReadFields()) {