// Copyright 2026 The Tenzr Project Authors
//
// SPDX-License-Identifier: Apache-2.0
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// https://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
#include "tenzr/common/trace.h"
#include <algorithm>
#include <cstdlib>
#include <fstream>
#include <iomanip>
#include <iostream>
#include <sstream>
#include <thread>
namespace tenzr::profiler {
Profiler& Profiler::Instance() {
static Profiler profiler;
return profiler;
}
Profiler::Profiler() {
const char* prof_env = std::getenv("TENZR_PROFILE");
if (prof_env && std::string(prof_env) != "0" && std::string(prof_env) != "false") {
enabled_.store(true, std::memory_order_relaxed);
start_time_ = std::chrono::high_resolution_clock::now();
RecordMetadata("process_name", "Tenzr Accelerated Engine");
RecordMetadata("thread_name", "Main Execution Thread");
}
const char* out_env = std::getenv("TENZR_PROFILE_OUTPUT");
if (out_env && *out_env) {
default_output_path_ = out_env;
} else {
default_output_path_ = "tenzr_profile.trace.json";
}
}
Profiler::~Profiler() {
if (!events_.empty() && !default_output_path_.empty()) {
ExportChromeTrace(default_output_path_);
}
}
void Profiler::Start() {
std::lock_guard<std::mutex> lock(mutex_);
enabled_.store(true, std::memory_order_relaxed);
start_time_ = std::chrono::high_resolution_clock::now();
// Register default process and thread metadata for visualizers (Perfetto / XProf)
TraceEvent p_meta;
p_meta.name = "process_name";
p_meta.cat = "__metadata";
p_meta.ph = 'M';
p_meta.pid = 1;
p_meta.tid = ScopedTrace::GetTid();
p_meta.args["name"] = "Tenzr Accelerated Engine";
events_.push_back(std::move(p_meta));
TraceEvent t_meta;
t_meta.name = "thread_name";
t_meta.cat = "__metadata";
t_meta.ph = 'M';
t_meta.pid = 1;
t_meta.tid = ScopedTrace::GetTid();
t_meta.args["name"] = "Host Dispatch Thread";
events_.push_back(std::move(t_meta));
}
void Profiler::Stop() { enabled_.store(false, std::memory_order_relaxed); }
void Profiler::Reset() {
std::lock_guard<std::mutex> lock(mutex_);
events_.clear();
start_time_ = std::chrono::high_resolution_clock::now();
}
void Profiler::RecordEvent(TraceEvent event) {
std::lock_guard<std::mutex> lock(mutex_);
events_.push_back(std::move(event));
}
void Profiler::RecordInstant(std::string name, std::string cat, char scope) {
if (!IsEnabled()) {
return;
}
TraceEvent ev;
ev.name = std::move(name);
ev.cat = std::move(cat);
ev.ph = 'i';
ev.s = scope;
ev.ts_us = ScopedTrace::CurrentTimeUs();
ev.dur_us = 0;
ev.pid = 1;
ev.tid = ScopedTrace::GetTid();
RecordEvent(std::move(ev));
}
void Profiler::RecordCounter(std::string name, int64_t value, std::string cat) {
if (!IsEnabled()) {
return;
}
TraceEvent ev;
ev.name = name;
ev.cat = std::move(cat);
ev.ph = 'C';
ev.ts_us = ScopedTrace::CurrentTimeUs();
ev.pid = 1;
ev.tid = ScopedTrace::GetTid();
ev.args[std::move(name)] = std::to_string(value);
RecordEvent(std::move(ev));
}
void Profiler::RecordMetadata(std::string name, std::string value) {
TraceEvent ev;
ev.name = std::move(name);
ev.cat = "__metadata";
ev.ph = 'M';
ev.pid = 1;
ev.tid = ScopedTrace::GetTid();
ev.args["name"] = std::move(value);
RecordEvent(std::move(ev));
}
void Profiler::RecordStreamKernel(std::string name, int64_t stream_id, int64_t dur_us, std::string cat, std::unordered_map<std::string, std::string> args) {
if (!IsEnabled()) {
return;
}
TraceEvent ev;
ev.name = std::move(name);
ev.cat = std::move(cat);
ev.ph = 'X';
ev.ts_us = ScopedTrace::CurrentTimeUs() - dur_us;
ev.dur_us = dur_us;
ev.pid = 2; // PID 2 represents accelerator device
ev.tid = static_cast<uint64_t>(stream_id);
ev.args = std::move(args);
ev.args["stream_id"] = std::to_string(stream_id);
RecordEvent(std::move(ev));
}
void Profiler::RecordMemoryTransfer(std::string name, size_t bytes, bool h2d, int64_t dur_us) {
if (!IsEnabled()) {
return;
}
TraceEvent ev;
ev.name = std::move(name);
ev.cat = "transfer";
ev.ph = 'X';
ev.ts_us = ScopedTrace::CurrentTimeUs() - dur_us;
ev.dur_us = dur_us;
ev.pid = 2;
ev.tid = 100; // Dedicated DMA stream TID
ev.args["bytes"] = std::to_string(bytes);
ev.args["direction"] = h2d ? "H2D" : "D2H";
if (dur_us > 0) {
double gb_per_sec = (static_cast<double>(bytes) / 1.0e9) / (static_cast<double>(dur_us) / 1.0e6);
std::ostringstream bss;
bss << std::fixed << std::setprecision(2) << gb_per_sec << " GB/s";
ev.args["bandwidth"] = bss.str();
}
RecordEvent(std::move(ev));
}
void Profiler::RecordCollectiveComm(std::string name, size_t bytes, int64_t dur_us) {
if (!IsEnabled()) {
return;
}
TraceEvent ev;
ev.name = std::move(name);
ev.cat = "collective";
ev.ph = 'X';
ev.ts_us = ScopedTrace::CurrentTimeUs() - dur_us;
ev.dur_us = dur_us;
ev.pid = 2;
ev.tid = 200; // Dedicated Collective stream TID
ev.args["bytes"] = std::to_string(bytes);
RecordEvent(std::move(ev));
}
size_t Profiler::EventCount() const {
std::lock_guard<std::mutex> lock(mutex_);
return events_.size();
}
bool Profiler::ExportChromeTrace(const std::string& path) const {
std::lock_guard<std::mutex> lock(mutex_);
std::ofstream ofs(path);
if (!ofs.is_open()) {
return false;
}
ofs << "{\n \"traceEvents\": [\n";
for (size_t i = 0; i < events_.size(); ++i) {
const auto& ev = events_[i];
ofs << " {\n";
ofs << " \"name\": \"" << ev.name << "\",\n";
ofs << " \"cat\": \"" << ev.cat << "\",\n";
ofs << " \"ph\": \"" << ev.ph << "\",\n";
ofs << " \"ts\": " << ev.ts_us << ",\n";
if (ev.ph == 'X') {
ofs << " \"dur\": " << ev.dur_us << ",\n";
} else if (ev.ph == 'i') {
ofs << " \"s\": \"" << ev.s << "\",\n";
}
ofs << " \"pid\": " << ev.pid << ",\n";
ofs << " \"tid\": " << ev.tid;
if (!ev.args.empty()) {
ofs << ",\n \"args\": {\n";
size_t arg_idx = 0;
for (const auto& [k, v] : ev.args) {
ofs << " \"" << k << "\": ";
if (ev.ph == 'C') {
ofs << v; // Output counter numeric literal
} else {
ofs << "\"" << v << "\"";
}
ofs << (arg_idx + 1 < ev.args.size() ? ",\n" : "\n");
arg_idx++;
}
ofs << " }\n";
} else {
ofs << "\n";
}
ofs << " }" << (i + 1 < events_.size() ? ",\n" : "\n");
}
ofs << " ],\n \"displayTimeUnit\": \"ms\"\n}\n";
return true;
}
ProfileSummary Profiler::AnalyzeTrace() const {
std::lock_guard<std::mutex> lock(mutex_);
ProfileSummary summary;
summary.total_events = events_.size();
if (events_.empty()) {
return summary;
}
int64_t min_ts = std::numeric_limits<int64_t>::max();
int64_t max_ts = 0;
struct Accum {
std::string cat;
int64_t total_us{0};
size_t count{0};
};
std::unordered_map<std::string, Accum> op_accum;
for (const auto& ev : events_) {
if (ev.ph == 'X') {
min_ts = std::min(min_ts, ev.ts_us);
max_ts = std::max(max_ts, ev.ts_us + ev.dur_us);
summary.category_durations_us[ev.cat] += ev.dur_us;
auto& acc = op_accum[ev.name];
acc.cat = ev.cat;
acc.total_us += ev.dur_us;
acc.count++;
}
}
summary.total_duration_us = (max_ts >= min_ts) ? (max_ts - min_ts) : 0;
for (const auto& [name, acc] : op_accum) {
TopOp op;
op.name = name;
op.cat = acc.cat;
op.total_dur_us = acc.total_us;
op.count = acc.count;
op.avg_dur_us = acc.count > 0 ? (static_cast<double>(acc.total_us) / static_cast<double>(acc.count)) : 0.0;
summary.top_ops.push_back(op);
}
std::sort(summary.top_ops.begin(), summary.top_ops.end(), [](const TopOp& a, const TopOp& b) { return a.total_dur_us > b.total_dur_us; });
return summary;
}
std::string ProfileSummary::FormatReport() const {
std::ostringstream oss;
oss << "================================================================================\n";
oss << " TENZR ACCELERATOR EXECUTION PROFILE REPORT \n";
oss << "================================================================================\n";
oss << "Total Trace Duration: " << std::fixed << std::setprecision(2) << (static_cast<double>(total_duration_us) / 1000.0) << " ms\n";
oss << "Total Recorded Events: " << total_events << "\n\n";
oss << "--- Subsystem Category Breakdown ---\n";
oss << std::left << std::setw(18) << "Category" << std::setw(16) << "Total Time (us)" << std::setw(14) << "Time (ms)" << std::setw(12) << "Share (%)"
<< "\n";
oss << std::string(60, '-') << "\n";
for (const auto& [cat, dur_us] : category_durations_us) {
double share = total_duration_us > 0 ? (100.0 * static_cast<double>(dur_us) / static_cast<double>(total_duration_us)) : 0.0;
oss << std::left << std::setw(18) << cat << std::setw(16) << dur_us << std::setw(14) << std::fixed << std::setprecision(3)
<< (static_cast<double>(dur_us) / 1000.0) << std::setw(12) << std::setprecision(1) << share << "%\n";
}
oss << "\n--- Top 10 Most Demanding Operations ---\n";
oss << std::left << std::setw(32) << "Operation Name" << std::setw(14) << "Category" << std::setw(10) << "Count" << std::setw(16) << "Total (us)"
<< std::setw(14) << "Avg (us)" << "\n";
oss << std::string(86, '-') << "\n";
size_t shown = std::min(size_t(10), top_ops.size());
for (size_t i = 0; i < shown; ++i) {
const auto& op = top_ops[i];
oss << std::left << std::setw(32) << op.name << std::setw(14) << op.cat << std::setw(10) << op.count << std::setw(16) << op.total_dur_us << std::setw(14)
<< std::fixed << std::setprecision(2) << op.avg_dur_us << "\n";
}
oss << "\n--- Identified Execution Gaps & Bottlenecks ---\n";
int64_t compiler_us = 0;
int64_t runtime_us = 0;
int64_t transfer_us = 0;
auto c_it = category_durations_us.find("compiler");
if (c_it != category_durations_us.end()) {
compiler_us = c_it->second;
}
auto r_it = category_durations_us.find("runtime");
if (r_it != category_durations_us.end()) {
runtime_us = r_it->second;
}
auto t_it = category_durations_us.find("transfer");
if (t_it != category_durations_us.end()) {
transfer_us = t_it->second;
}
if (compiler_us > runtime_us) {
oss << " [!] High Compilation Overhead: " << (compiler_us / 1000) << " ms spent compiling vs " << (runtime_us / 1000)
<< " ms executing. Ensure tenzr::jit caching is utilized across repetitive iterations.\n";
} else {
oss << " [OK] Steady-State Execution Dominates: JIT compilation overhead successfully amortized.\n";
}
if (transfer_us > (runtime_us / 2) && transfer_us > 100) {
oss << " [!] Device Synchronization Stall: " << (transfer_us / 1000)
<< " ms spent in H2D/D2H transfers. Consider keeping intermediate tensors resident on device.\n";
} else {
oss << " [OK] Device Data Residency: Transfer overhead is low relative to compute execution.\n";
}
oss << "================================================================================\n";
return oss.str();
}
std::string BottleneckReport::Format() const {
std::ostringstream oss;
oss << "=== Hardware Execution Bottleneck Analysis ===\n";
oss << "Primary Bottleneck: " << primary_bottleneck << "\n";
oss << "Compute-to-Comm Ratio: " << std::fixed << std::setprecision(2) << compute_to_comm_ratio << "\n";
oss << "Memory Transfer Share: " << std::fixed << std::setprecision(1) << memory_transfer_pct << "%\n";
oss << "Collective Comm Share: " << std::fixed << std::setprecision(1) << collective_comm_pct << "%\n";
oss << "Device Kernel Time: " << (static_cast<double>(total_device_kernel_us) / 1000.0) << " ms\n";
oss << "Memory Transfer Time: " << (static_cast<double>(total_memory_transfer_us) / 1000.0) << " ms\n";
oss << "Collective Comm Time: " << (static_cast<double>(total_collective_comm_us) / 1000.0) << " ms\n";
if (!recommendations.empty()) {
oss << "\nRecommendations:\n";
for (const auto& rec : recommendations) {
oss << " - " << rec << "\n";
}
}
return oss.str();
}
BottleneckReport ProfileSummary::IdentifyBottlenecks() const {
BottleneckReport report;
for (const auto& [cat, dur] : category_durations_us) {
if (cat == "gpu_kernel" || cat == "kernel" || cat == "device") {
report.total_device_kernel_us += dur;
} else if (cat == "transfer" || cat == "h2d" || cat == "d2h") {
report.total_memory_transfer_us += dur;
} else if (cat == "collective" || cat == "nccl" || cat == "rccl" || cat == "comm") {
report.total_collective_comm_us += dur;
}
}
if (total_duration_us > 0) {
report.memory_transfer_pct = (100.0 * static_cast<double>(report.total_memory_transfer_us)) / static_cast<double>(total_duration_us);
report.collective_comm_pct = (100.0 * static_cast<double>(report.total_collective_comm_us)) / static_cast<double>(total_duration_us);
}
if (report.total_collective_comm_us > 0) {
report.compute_to_comm_ratio = static_cast<double>(report.total_device_kernel_us) / static_cast<double>(report.total_collective_comm_us);
} else {
report.compute_to_comm_ratio = report.total_device_kernel_us > 0 ? 999.0 : 0.0;
}
if (report.total_collective_comm_us > report.total_device_kernel_us && report.total_collective_comm_us > 100) {
report.primary_bottleneck = "Collective Communication Bound";
report.recommendations.push_back(
"Interconnect communication latency dominates. Consider tensor parallelism sharding adjustments or gradient accumulation.");
report.recommendations.push_back("Overlap collective communications with compute streams using non-blocking collectives.");
} else if (report.total_memory_transfer_us > report.total_device_kernel_us && report.total_memory_transfer_us > 100) {
report.primary_bottleneck = "Memory Transfer Bound";
report.recommendations.push_back("Host-device memory transfers exceed kernel execution. Ensure tensors remain device-resident across iterations.");
report.recommendations.push_back("Enable pinned host memory for asynchronous DMA transfers.");
} else if (report.total_device_kernel_us > 0) {
report.primary_bottleneck = "Compute Bound";
report.recommendations.push_back(
"Device compute throughput is fully utilized. Investigate operator kernel fusion or lower-precision arithmetic (FP16/BF16).");
} else {
report.primary_bottleneck = "Host Dispatch Bound";
report.recommendations.push_back("Host Python/C++ dispatch overhead is dominant. Wrap hot loops in tenzr::jit.");
}
return report;
}
bool ProfileSummary::CheckLatencyRegression(int64_t baseline_us, double threshold_pct, std::string* message) const {
if (baseline_us <= 0 || total_duration_us <= 0) {
return false;
}
double delta_pct = 100.0 * static_cast<double>(total_duration_us - baseline_us) / static_cast<double>(baseline_us);
if (delta_pct > threshold_pct) {
if (message) {
std::ostringstream oss;
oss << "LATENCY REGRESSION ALERT: Execution duration increased from " << (static_cast<double>(baseline_us) / 1000.0) << " ms to "
<< (static_cast<double>(total_duration_us) / 1000.0) << " ms (+" << std::fixed << std::setprecision(1) << delta_pct << "% vs threshold "
<< threshold_pct << "%)";
*message = oss.str();
}
return true;
}
return false;
}
int64_t ScopedTrace::CurrentTimeUs() {
auto now = std::chrono::high_resolution_clock::now();
return std::chrono::duration_cast<std::chrono::microseconds>(now.time_since_epoch()).count();
}
uint64_t ScopedTrace::GetTid() { return std::hash<std::thread::id>{}(std::this_thread::get_id()); }
} // namespace tenzr::profiler