add trace

examples/tusdcat/main.cc

@@ -10,6 +10,7 @@
 #include "str-util.hh"
 #include "io-util.hh"
 #include "usd-to-json.hh"
+#include "logger.hh"
 
 #include "tydra/scene-access.hh"
 
@@ -56,7 +57,7 @@ static std::string format_memory_size(size_t bytes) {
 }
 
 void print_help() {
-    std::cout << "Usage tusdcat [--flatten] [--loadOnly] [--composition=STRLIST] [--relative] [--extract-variants] [--memstat] [-j|--json] input.usda/usdc/usdz\n";
+    std::cout << "Usage tusdcat [--flatten] [--loadOnly] [--composition=STRLIST] [--relative] [--extract-variants] [--memstat] [--memory-trace] [--trace] [--trace-format=FORMAT] [--trace-tags=TAGS] [-j|--json] input.usda/usdc/usdz\n";
     std::cout << "\n --flatten (not fully implemented yet) Do composition(load sublayers, refences, payload, evaluate `over`, inherit, variants..)";
     std::cout << "  --composition: Specify which composition feature to be "
                  "enabled(valid when `--flatten` is supplied). Comma separated "
@@ -69,6 +70,10 @@ void print_help() {
     std::cout << "\n -l, --loadOnly Load(Parse) USD file only(Check if input USD is valid or not)\n";
     std::cout << "\n -j, --json Output parsed USD as JSON string\n";
     std::cout << "\n --memstat Print memory usage statistics for loaded Layer and Stage\n";
+    std::cout << "\n --memory-trace Enable detailed memory allocation trace logging (outputs to stderr)\n";
+    std::cout << "\n --trace Enable performance tracing and print summary at the end\n";
+    std::cout << "\n --trace-format=FORMAT Set trace output format: text (default) or json\n";
+    std::cout << "\n --trace-tags=TAGS Comma-separated list of trace tags to enable (e.g., parser,composition,io)\n";
 
 }
 
@@ -84,6 +89,10 @@ int main(int argc, char **argv) {
   bool load_only{false};
   bool json_output{false};
   bool memstat{false};
+  bool memory_trace{false};
+  bool enable_trace{false};
+  std::string trace_format{"text"};
+  std::vector<std::string> trace_tags;
 
   constexpr int kMaxIteration = 128;
 
@@ -109,6 +118,19 @@ int main(int argc, char **argv) {
       has_extract_variants = true;
     } else if (arg.compare("--memstat") == 0) {
       memstat = true;
+    } else if (arg.compare("--memory-trace") == 0) {
+      memory_trace = true;
+    } else if (arg.compare("--trace") == 0) {
+      enable_trace = true;
+    } else if (tinyusdz::startsWith(arg, "--trace-format=")) {
+      trace_format = tinyusdz::removePrefix(arg, "--trace-format=");
+      if (trace_format != "text" && trace_format != "json") {
+        std::cerr << "Invalid trace format. Must be 'text' or 'json'\n";
+        return EXIT_FAILURE;
+      }
+    } else if (tinyusdz::startsWith(arg, "--trace-tags=")) {
+      std::string tags_str = tinyusdz::removePrefix(arg, "--trace-tags=");
+      trace_tags = tinyusdz::split(tags_str, ",");
     } else if (tinyusdz::startsWith(arg, "--composition=")) {
       std::string value_str = tinyusdz::removePrefix(arg, "--composition=");
       if (value_str.empty()) {
@@ -157,6 +179,44 @@ int main(int argc, char **argv) {
   std::string warn;
   std::string err;
 
+  // Enable memory trace logging if requested
+  if (memory_trace) {
+    // Set log level to INFO to enable memory logging
+    tinyusdz::logging::Logger::getInstance().setLogLevel(tinyusdz::logging::LogLevel::Info);
+    // Redirect logging to stderr so it doesn't interfere with USD output
+    tinyusdz::logging::Logger::getInstance().setStream(&std::cerr);
+    std::cerr << "# Memory trace logging enabled\n";
+  }
+
+  // Enable performance tracing if requested
+  if (enable_trace) {
+    // Enable the trace manager
+    tinyusdz::logging::TraceManager::getInstance().setEnabled(true);
+    
+    // Set output format
+    if (trace_format == "json") {
+      tinyusdz::logging::TraceManager::getInstance().setReportFormat(
+          tinyusdz::logging::TraceReportFormat::JSON);
+    } else {
+      tinyusdz::logging::TraceManager::getInstance().setReportFormat(
+          tinyusdz::logging::TraceReportFormat::PlainText);
+    }
+    
+    // Enable specific tags if provided
+    if (!trace_tags.empty()) {
+      // First disable all tags
+      tinyusdz::logging::TraceManager::getInstance().clearTagSettings();
+      // Then enable only the specified ones
+      for (const auto& tag : trace_tags) {
+        tinyusdz::logging::TraceManager::getInstance().setTagEnabled(tag, true);
+        std::cerr << "# Trace enabled for tag: " << tag << "\n";
+      }
+    }
+    // If no tags specified, all tags are enabled by default
+    
+    std::cerr << "# Performance tracing enabled (format: " << trace_format << ")\n";
+  }
+
   std::string ext = str_tolower(GetFileExtension(filepath));
   std::string base_dir;
   base_dir = tinyusdz::io::GetBaseDir(filepath);
@@ -444,6 +504,9 @@ int main(int argc, char **argv) {
     tinyusdz::Stage stage;
 
     tinyusdz::USDLoadOptions options;
+    if (memory_trace) {
+      options.enable_memory_trace_logging = true;
+    }
 
     // auto detect format.
     bool ret = tinyusdz::LoadUSDFromFile(filepath, &stage, &warn, &err, options);
@@ -505,5 +568,11 @@ int main(int argc, char **argv) {
     }
   }
 
+  // Print trace summary if tracing was enabled
+  if (enable_trace) {
+    std::cerr << "\n";
+    tinyusdz::logging::TraceManager::getInstance().printSummary(std::cerr);
+  }
+
   return EXIT_SUCCESS;
 }

src/ascii-parser.cc

@@ -22,6 +22,7 @@
 #include <map>
 #include <set>
 #include <sstream>
+#include <iomanip>
 #include <stack>
 #if defined(__wasi__)
 #else
@@ -31,6 +32,7 @@
 #include <vector>
 
 #include "ascii-parser.hh"
+#include "logger.hh"
 #include "parser-timing.hh"
 #include "path-util.hh"
 #include "str-util.hh"
@@ -58,16 +60,49 @@
 //
 
 #include "common-macros.inc"
+#include "logger.hh"
 
 #define CHECK_MEMORY_USAGE(__nbytes) do { \
   _memory_usage += (__nbytes); \
+  if (_enable_memory_logging && logging::Logger::getInstance().shouldLog(logging::LogLevel::Info)) { \
+    std::stringstream ss; \
+    ss << "[MEM_USE] Requested: " << FormatBytesSimple(__nbytes) \
+       << " | Total: " << FormatBytesSimple(_memory_usage) \
+       << " | Limit: " << FormatBytesSimple(_max_memory_limit_bytes) \
+       << " | Available: " << FormatBytesSimple(_max_memory_limit_bytes - _memory_usage); \
+    TUSDZ_LOG_I(ss.str()); \
+  } \
   if (_memory_usage > _max_memory_limit_bytes) { \
+    if (_enable_memory_logging && logging::Logger::getInstance().shouldLog(logging::LogLevel::Info)) { \
+      std::stringstream ss; \
+      ss << "[MEM_REJECT] Would exceed limit by " \
+         << FormatBytesSimple(_memory_usage - _max_memory_limit_bytes); \
+      TUSDZ_LOG_I(ss.str()); \
+    } \
     PushError(fmt::format("Memory limit exceeded. Limit: {} MB, Current usage: {} MB", \
       _max_memory_limit_bytes / (1024*1024), _memory_usage / (1024*1024))); \
     return false; \
   }  \
   } while(0)
 
+// Helper function for formatting bytes
+static std::string FormatBytesSimple(uint64_t bytes) {
+  std::stringstream ss;
+  if (bytes >= 1024ull * 1024ull * 1024ull) {
+    ss << std::fixed << std::setprecision(2) 
+       << (double(bytes) / (1024.0 * 1024.0 * 1024.0)) << " GB";
+  } else if (bytes >= 1024ull * 1024ull) {
+    ss << std::fixed << std::setprecision(2) 
+       << (double(bytes) / (1024.0 * 1024.0)) << " MB";
+  } else if (bytes >= 1024ull) {
+    ss << std::fixed << std::setprecision(2) 
+       << (double(bytes) / 1024.0) << " KB";
+  } else {
+    ss << bytes << " B";
+  }
+  return ss.str();
+}
+
 #if 0
 #define REDUCE_MEMORY_USAGE(__nbytes) do { \
   if (_memory_usage >= (__nbytes)) { \
@@ -1007,6 +1042,7 @@ bool AsciiParser::MaybeCustom() {
 }
 
 bool AsciiParser::ParseDict(std::map<std::string, MetaVariable> *out_dict) {
+  TUSDZ_TRACE_TAG("usda-parse", "ParseDict");
   // '{' comment | (type name '=' value)+ '}'
   if (!Expect('{')) {
     return false;
@@ -2059,6 +2095,7 @@ bool AsciiParser::ParseStageMetaOpt() {
 // meta = '(' (comment | metadata_opt)+ ')'
 //      ;
 bool AsciiParser::ParseStageMetas() {
+  TUSDZ_TRACE_TAG("usda-parse", "ParseStageMetas");
   if (!Expect('(')) {
     return false;
   }
@@ -3239,6 +3276,7 @@ AsciiParser::ParsePrimMeta() {
 }
 
 bool AsciiParser::ParsePrimMetas(PrimMetaMap *args) {
+  TUSDZ_TRACE_TAG("usda-parse", "ParsePrimMetas");
   // '(' args ')'
   // args = list of argument, separated by newline.
 

src/ascii-parser.hh

@@ -343,6 +343,13 @@ class AsciiParser {
     _max_memory_limit_bytes = limit_mb * 1024ull * 1024ull;
   }
 
+  ///
+  /// Enable/disable memory operation logging
+  ///
+  void SetMemoryLoggingEnabled(bool enabled) {
+    _enable_memory_logging = enabled;
+  }
+
   ///
   /// Set progress callback function
   /// @param[in] callback Progress callback function
@@ -927,6 +934,7 @@ class AsciiParser {
   // Memory tracking
   uint64_t _max_memory_limit_bytes{128ull * 1024ull * 1024ull * 1024ull}; // Default 128GB
   uint64_t _memory_usage{0};
+  bool _enable_memory_logging{false};
 
   //
   // Callbacks

src/crate-reader.cc

@@ -15,6 +15,7 @@
 #endif
 
 #include "crate-reader.hh"
+#include "logger.hh"
 
 #ifdef __wasi__
 #else
@@ -5981,6 +5982,7 @@ bool CrateReader::ReadSection(crate::Section *s) {
 }
 
 bool CrateReader::ReadTokens() {
+  TUSDZ_TRACE_TAG("usdc-parse", "crate-read");
   TINYUSDZ_PROFILE_SCOPE("crate-reader", "ReadTokens");
   
   // Report progress (20%)
@@ -6343,6 +6345,7 @@ bool CrateReader::ReadFields() {
 }
 
 bool CrateReader::ReadFieldSets() {
+  TUSDZ_TRACE_TAG("usdc-parse", "crate-read");
   // Report progress (50%)
   if (!ReportProgress(0.5f)) {
     PUSH_ERROR("Parsing cancelled by progress callback.");
@@ -6707,6 +6710,7 @@ bool CrateReader::ReadSpecs() {
 }
 
 bool CrateReader::ReadPaths() {
+  TUSDZ_TRACE_TAG("usdc-parse", "crate-read");
   TINYUSDZ_PROFILE_SCOPE("crate-reader", "ReadPaths");
   
   // Report progress (70%)
@@ -6773,6 +6777,7 @@ bool CrateReader::ReadPaths() {
 }
 
 bool CrateReader::ReadBootStrap() {
+  TUSDZ_TRACE_TAG("usdc-parse", "crate-read");
   TINYUSDZ_PROFILE_FUNCTION("crate-reader");
   
   // Report initial progress

src/memory-budget.hh

@@ -8,30 +8,44 @@
 #include <cstdint>
 #include <string>
 #include <limits>
+#include <sstream>
+#include <iomanip>
 
 #include "nonstd/expected.hpp"
+#include "logger.hh"
 
 namespace tinyusdz {
 
 class MemoryBudgetManager {
  public:
   explicit MemoryBudgetManager(uint64_t max_budget = std::numeric_limits<uint32_t>::max())
-      : max_budget_(max_budget), current_usage_(0) {}
+      : max_budget_(max_budget), current_usage_(0), enable_logging_(false) {}
 
-  bool CheckAndReserve(uint64_t requested_bytes) {
+  bool CheckAndReserve(uint64_t requested_bytes, const std::string& tag = "") {
     if (current_usage_ + requested_bytes > max_budget_) {
+      if (enable_logging_) {
+        LogMemoryOperation("REJECT", requested_bytes, tag, false);
+      }
       return false;
     }
     current_usage_ += requested_bytes;
+    if (enable_logging_) {
+      LogMemoryOperation("RESERVE", requested_bytes, tag, true);
+    }
     return true;
   }
 
-  void Release(uint64_t bytes_to_release) {
+  void Release(uint64_t bytes_to_release, const std::string& tag = "") {
+    uint64_t actual_release = bytes_to_release;
     if (current_usage_ >= bytes_to_release) {
       current_usage_ -= bytes_to_release;
     } else {
+      actual_release = current_usage_;
       current_usage_ = 0;
     }
+    if (enable_logging_) {
+      LogMemoryOperation("RELEASE", actual_release, tag, true);
+    }
   }
 
   uint64_t GetCurrentUsage() const { return current_usage_; }
@@ -40,18 +54,27 @@ class MemoryBudgetManager {
   
   size_t GetUsageInMB() const { return size_t(current_usage_ / (1024 * 1024)); }
 
-  void Reset() { current_usage_ = 0; }
+  void Reset() { 
+    uint64_t prev_usage = current_usage_;
+    current_usage_ = 0; 
+    if (enable_logging_ && prev_usage > 0) {
+      LogMemoryOperation("RESET", prev_usage, "", true);
+    }
+  }
+  
+  void SetLoggingEnabled(bool enabled) { enable_logging_ = enabled; }
+  bool IsLoggingEnabled() const { return enable_logging_; }
 
   class ScopedReservation {
    public:
-    ScopedReservation(MemoryBudgetManager& manager, uint64_t bytes)
-        : manager_(manager), bytes_(bytes), reserved_(false) {
-      reserved_ = manager_.CheckAndReserve(bytes);
+    ScopedReservation(MemoryBudgetManager& manager, uint64_t bytes, const std::string& tag = "")
+        : manager_(manager), bytes_(bytes), tag_(tag), reserved_(false) {
+      reserved_ = manager_.CheckAndReserve(bytes, tag);
     }
 
     ~ScopedReservation() {
       if (reserved_) {
-        manager_.Release(bytes_);
+        manager_.Release(bytes_, tag_);
       }
     }
 
@@ -61,7 +84,7 @@ class MemoryBudgetManager {
     ScopedReservation& operator=(const ScopedReservation&) = delete;
 
     ScopedReservation(ScopedReservation&& other) noexcept
-        : manager_(other.manager_), bytes_(other.bytes_), reserved_(other.reserved_) {
+        : manager_(other.manager_), bytes_(other.bytes_), tag_(other.tag_), reserved_(other.reserved_) {
       other.reserved_ = false;
     }
 
@@ -80,16 +103,58 @@ class MemoryBudgetManager {
    private:
     MemoryBudgetManager& manager_;
     uint64_t bytes_;
+    std::string tag_;
     bool reserved_;
   };
 
-  ScopedReservation ReserveScoped(uint64_t bytes) {
-    return ScopedReservation(*this, bytes);
+  ScopedReservation ReserveScoped(uint64_t bytes, const std::string& tag = "") {
+    return ScopedReservation(*this, bytes, tag);
   }
 
  private:
+  void LogMemoryOperation(const std::string& op_type, uint64_t bytes, 
+                          const std::string& tag, bool success) const {
+    if (!logging::Logger::getInstance().shouldLog(logging::LogLevel::Info)) {
+      return;
+    }
+    
+    std::stringstream ss;
+    ss << "[MEM_" << op_type << "]";
+    if (!tag.empty()) {
+      ss << " [" << tag << "]";
+    }
+    ss << " Requested: " << FormatBytes(bytes)
+       << " | Current: " << FormatBytes(current_usage_)
+       << " | Limit: " << FormatBytes(max_budget_)
+       << " | Available: " << FormatBytes(GetRemainingBudget());
+    if (!success && op_type == "REJECT") {
+      ss << " | REJECTED (would exceed limit by " 
+         << FormatBytes((current_usage_ + bytes) - max_budget_) << ")";
+    }
+    
+    TUSDZ_LOG_I(ss.str());
+  }
+  
+  static std::string FormatBytes(uint64_t bytes) {
+    std::stringstream ss;
+    if (bytes >= 1024ull * 1024ull * 1024ull) {
+      ss << std::fixed << std::setprecision(2) 
+         << (double(bytes) / (1024.0 * 1024.0 * 1024.0)) << " GB";
+    } else if (bytes >= 1024ull * 1024ull) {
+      ss << std::fixed << std::setprecision(2) 
+         << (double(bytes) / (1024.0 * 1024.0)) << " MB";
+    } else if (bytes >= 1024ull) {
+      ss << std::fixed << std::setprecision(2) 
+         << (double(bytes) / 1024.0) << " KB";
+    } else {
+      ss << bytes << " B";
+    }
+    return ss.str();
+  }
+
   uint64_t max_budget_;
   uint64_t current_usage_;
+  bool enable_logging_;
 };
 
 template <typename ReturnType>
@@ -97,7 +162,7 @@ class MemoryBudgetGuard {
  public:
   MemoryBudgetGuard(MemoryBudgetManager& manager, uint64_t bytes, 
                     const std::string& error_tag = "")
-      : reservation_(manager.ReserveScoped(bytes)), error_tag_(error_tag) {}
+      : reservation_(manager.ReserveScoped(bytes, error_tag)), error_tag_(error_tag) {}
 
   template <typename T>
   nonstd::expected<T, std::string> CheckAndReturn(T&& value) {
@@ -124,6 +189,14 @@ class MemoryBudgetGuard {
     } \
   } while(0)
 
+// Macro with logging support
+#define MEMORY_BUDGET_CHECK_WITH_LOG(manager, bytes, varname) \
+  do { \
+    if (!(manager).CheckAndReserve(bytes, varname)) { \
+      PUSH_ERROR_AND_RETURN_TAG(varname, "Reached maximum memory budget"); \
+    } \
+  } while(0)
+
 #define MEMORY_BUDGET_CHECK_AND_RETURN(manager, bytes, error_tag, return_type) \
   MemoryBudgetGuard<return_type>(manager, bytes, error_tag)
 

src/pprinter.cc

@@ -7,6 +7,7 @@
 //
 #include "pprinter.hh"
 
+#include "logger.hh"
 #include "prim-pprint.hh"
 #include "prim-types.hh"
 #include "layer.hh"
@@ -4659,6 +4660,7 @@ std::string print_layer(const Layer &layer, const uint32_t indent) {
 namespace prim {
 
 std::string print_prim(const Prim &prim, const uint32_t indent) {
+  TUSDZ_TRACE_TAG("ascii-write", "pprint");
   std::stringstream ss;
 
   // Currently, Prim's elementName is read from name variable in concrete Prim
@@ -4797,6 +4799,7 @@ std::string print_prim(const Prim &prim, const uint32_t indent) {
 }
 
 std::string print_primspec(const PrimSpec &primspec, const uint32_t indent) {
+  TUSDZ_TRACE_TAG("ascii-write", "pprint");
   std::stringstream ss;
 
   ss << pprint::Indent(indent) << to_string(primspec.specifier()) << " ";

src/stage.cc

@@ -23,6 +23,7 @@
 #include <vector>
 
 #include "io-util.hh"
+#include "logger.hh"
 #include "pprinter.hh"
 #include "prim-pprint.hh"
 #include "str-util.hh"
@@ -461,6 +462,7 @@ void PrimPrintRec(std::stringstream &ss, const Prim &prim, uint32_t indent) {
 }  // namespace
 
 std::string Stage::ExportToString(bool relative_path) const {
+  TUSDZ_TRACE("ascii-write");
   (void)relative_path; // TODO
 
   std::stringstream ss;

src/tinyusdz.cc

@@ -756,6 +756,7 @@ bool LoadUSDAFromMemory(const uint8_t *addr, const size_t length,
   config.strict_allowedToken_check = options.strict_allowedToken_check;
   config.allow_unknown_apiSchema = !options.strict_apiSchema_check;
   config.max_memory_limit_in_mb = size_t(options.max_memory_limit_in_mb);
+  config.enable_memory_trace_logging = options.enable_memory_trace_logging;
   reader.set_reader_config(config);
 
   reader.SetBaseDir(base_dir);
@@ -1250,6 +1251,7 @@ bool LoadUSDALayerFromMemory(const uint8_t *addr, const size_t length,
 
   tinyusdz::usda::USDAReaderConfig config;
   config.strict_allowedToken_check = options.strict_allowedToken_check;
+  config.enable_memory_trace_logging = options.enable_memory_trace_logging;
   reader.set_reader_config(config);
 
   uint32_t load_states = static_cast<uint32_t>(tinyusdz::LoadState::Toplevel);

src/tinyusdz.hh

@@ -119,6 +119,12 @@ struct USDLoadOptions {
   std::map<std::string, FileFormatHandler> fileformats;
 
   Axis upAxis{Axis::Y};
+
+  ///
+  /// Enable detailed memory allocation trace logging during loading.
+  /// When enabled, logs memory allocations to the Logger output stream.
+  ///
+  bool enable_memory_trace_logging{false};
 };
 
 

src/usda-reader.cc

@@ -31,6 +31,7 @@
 
 #include "usda-reader.hh"
 #include "layer.hh"
+#include "logger.hh"
 #include "parser-timing.hh"
 
 //
@@ -322,6 +323,7 @@ class USDAReader::Impl {
   void set_reader_config(const USDAReaderConfig &config) {
     _config = config;
     _parser.SetMaxMemoryLimit(config.max_memory_limit_in_mb);
+    _parser.SetMemoryLoggingEnabled(config.enable_memory_trace_logging);
   }
 
   const USDAReaderConfig get_reader_config() const {
@@ -1637,6 +1639,7 @@ bool USDAReader::Impl::ReconstructPrim(
 ///
 
 bool USDAReader::Impl::Read(const uint32_t state_flags, bool as_primspec) {
+  TUSDZ_TRACE("usda-parse");
   TINYUSDZ_PROFILE_FUNCTION("usda-reader");
 
   ///

src/usda-reader.hh

@@ -19,6 +19,7 @@ struct USDAReaderConfig {
   bool allow_unknown_apiSchema{true};
   bool strict_allowedToken_check{false};
   size_t max_memory_limit_in_mb{1024ull*128ull}; // Default 128GB
+  bool enable_memory_trace_logging{false}; // Enable detailed memory allocation trace logging
 };
 
 ///

src/usdc-reader.cc

@@ -19,6 +19,7 @@
 #endif
 
 #include "usdc-reader.hh"
+#include "logger.hh"
 #include "parser-timing.hh"
 
 #if !defined(TINYUSDZ_DISABLE_MODULE_USDC_READER)
@@ -3826,6 +3827,7 @@ bool USDCReader::Impl::ToLayer(Layer *layer) {
 }
 
 bool USDCReader::Impl::ReadUSDC() {
+  TUSDZ_TRACE("usdc-parse");
   TINYUSDZ_PROFILE_FUNCTION("usdc-reader");
   if (crate_reader) {
     delete crate_reader;

src/value-pprint.cc

@@ -6,6 +6,7 @@
 
 #include <sstream>
 
+#include "logger.hh"
 #include "pprinter.hh"
 #include "prim-types.hh"
 #include "str-util.hh"
@@ -868,6 +869,7 @@ std::string pprint_any(const linb::any &v, const uint32_t indent,
 
 std::string pprint_value(const value::Value &v, const uint32_t indent,
                          bool closing_brace) {
+  TUSDZ_TRACE_TAG("ascii-write", "pprint");
 #define BASETYPE_CASE_EXPR(__ty)                           \
   case TypeTraits<__ty>::type_id(): {                      \
     auto p = v.as<__ty>();                                 \