Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 0 additions & 4 deletions src/a2a3/platform/onboard/aicpu/kernel.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -101,7 +101,6 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a
if (!platform_aicpu_affinity_gate_filter(
runtime->get_aicpu_allowed_cpus(), runtime->get_aicpu_allowed_cpu_count(), runtime->get_aicpu_launch_count()
)) {
LOG_INFO_V0("Thread dropped by filter affinity gate");
return 0;
}

Expand All @@ -113,13 +112,11 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_exec(void *a
set_platform_phase_base(k_args->device_wall_data_base);
AicpuPhaseScope run_wall(AicpuPhase::RunWall);

LOG_INFO_V0("%s", "simpler_aicpu_exec: Calling aicpu_execute with Runtime");
int rc = aicpu_execute(runtime);
if (rc != 0) {
LOG_ERROR("simpler_aicpu_exec: aicpu_execute failed with rc=%d", rc);
return rc;
}
LOG_INFO_V0("%s", "simpler_aicpu_exec: aicpu_execute completed successfully");

// Run-wall end is stamped by run_wall's destructor (covers the early return
// above too); host reduces max(end) - min(start) → ns.
Expand Down Expand Up @@ -154,6 +151,5 @@ extern "C" __attribute__((visibility("default"))) int simpler_aicpu_init(void *a
set_dma_workspace_addr(k, init_args->dma_workspace_addr[k]);
}

LOG_INFO_V0("%s", "simpler_aicpu_init: per-device invariants latched");
return 0;
}
2 changes: 1 addition & 1 deletion src/a2a3/platform/onboard/host/comm_hccl.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -200,7 +200,7 @@ wait_for_rootinfo(const std::string &path, HcclRootInfo *root_info, uint64_t *ru
return true;
}
if (i > 0 && i % (kLogEverySec * 10) == 0) {
LOG_INFO_V0("[comm] wait_for_rootinfo: still waiting (%ds elapsed) path=%s", i / 10, path.c_str());
LOG_DEBUG("[comm] wait_for_rootinfo: still waiting (%ds elapsed) path=%s", i / 10, path.c_str());
}
std::this_thread::sleep_for(std::chrono::milliseconds(100));
}
Expand Down
2 changes: 0 additions & 2 deletions src/a2a3/platform/onboard/host/device_runner.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -378,7 +378,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) {
finalize_collectors();
});

LOG_INFO_V0("=== Initialize runtime args ===");
// Resolve the orchestration SO into a device-resident buffer and refresh
// runtime metadata before the Runtime struct is uploaded to device.
rc = prepare_orch_so(runtime);
Expand Down Expand Up @@ -872,7 +871,6 @@ int DeviceRunner::finalize() {
if (reset_rc == 0) {
device_unusable_ = false;
}
LOG_INFO_V0("DeviceRunner finalized");
return rc != 0 ? rc : reset_rc;
}

Expand Down
8 changes: 2 additions & 6 deletions src/a2a3/platform/onboard/host/host_regs.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -134,8 +134,6 @@ get_aicore_reg_info(std::vector<int64_t> &aic, std::vector<int64_t> &aiv, const
return ret;
}

LOG_INFO_V0("Register base: ptr=0x%llx, len=0x%llx", out_map_para.ptr, out_map_para.len);

// Iterate over all cores and subcores
for (uint32_t i = 0; i < DAV_2201::PLATFORM_MAX_PHYSICAL_CORES; i++) {
for (uint32_t j = 0; j < PLATFORM_SUB_CORES_PER_AICORE; j++) {
Expand Down Expand Up @@ -175,7 +173,7 @@ static int get_aicore_regs(std::vector<int64_t> &regs, uint64_t device_id, Aicor
regs.insert(regs.end(), aic.begin(), aic.end());
regs.insert(regs.end(), aiv.begin(), aiv.end());

LOG_INFO_V0(
LOG_DEBUG(
"get_aicore_regs(%s): Retrieved %zu AIC and %zu AIV register addresses", kind_to_name(kind), aic.size(),
aiv.size()
);
Expand All @@ -190,8 +188,6 @@ int init_aicore_register_addresses(
return -1;
}

LOG_INFO_V0("Retrieving and allocating AICore %s register addresses...", kind_to_name(kind));

std::vector<int64_t> host_regs;
int rc = get_aicore_regs(host_regs, device_id, kind);
if (rc != 0) {
Expand All @@ -218,7 +214,7 @@ int init_aicore_register_addresses(

*runtime_regs_ptr = reinterpret_cast<uint64_t>(reg_ptr);

LOG_INFO_V0(
LOG_DEBUG(
"Successfully initialized %s register addresses: %zu addresses at device 0x%llx", kind_to_name(kind),
host_regs.size(), *runtime_regs_ptr
);
Expand Down
6 changes: 1 addition & 5 deletions src/a2a3/platform/shared/aicpu/pmu_collector_aicpu.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -151,7 +151,7 @@ struct PmuDeviceModule {
}
static void on_switch_complete(Context ctx, State *, Buffer *buffer) {
if (buffer != nullptr) {
LOG_INFO_V0(
LOG_DEBUG(
"Thread %d: Core %d switched to new PMU buffer (addr=0x%lx)", ctx.thread_idx, ctx.core_id,
reinterpret_cast<uint64_t>(buffer)
);
Expand Down Expand Up @@ -239,16 +239,13 @@ void pmu_aicpu_init(const uint32_t *physical_core_ids, int num_cores) {

if (head != tail) {
(void)try_pop_pmu_buffer(i, state, 0);
uint64_t buf_ptr = state->current_buf_ptr;
LOG_DEBUG("Core %d: popped initial PMU buffer (addr=0x%lx)", i, buf_ptr);
} else {
LOG_ERROR("Core %d: PMU free_queue is empty during init!", i);
state->current_buf_ptr = 0;
}
}

wmb();
LOG_INFO_V0("PMU initialized: %d cores, event_type=%u", num_cores, pmu_event_type);
}

void pmu_aicpu_record_task(int core_id, int thread_idx, uint64_t task_id, uint32_t func_id, CoreType core_type) {
Expand Down Expand Up @@ -353,7 +350,6 @@ void pmu_aicpu_flush_buffers(int thread_idx, const int *cur_thread_cores, int co
uint32_t seq = state->current_buf_seq;
int rc = enqueue_pmu_ready_buffer(thread_idx, static_cast<uint32_t>(core_id), buf_ptr, seq);
if (rc == 0) {
LOG_INFO_V0("Thread %d: Core %d flushed PMU buffer with %u records", thread_idx, core_id, buf->count);
state->current_buf_ptr = 0;
wmb();
} else {
Expand Down
7 changes: 0 additions & 7 deletions src/a2a3/platform/shared/host/pmu_collector.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -452,7 +452,6 @@ void PmuCollector::reconcile_counters() {
// active buffer (success → current_buf_ptr=0) or counted it as dropped
// and cleared it. A non-zero pointer with non-zero count means records
// AICPU neither delivered nor accounted for — a device-side flush bug.
int leftover_active = 0;
for (int c = 0; c < num_cores_; c++) {
PmuBufferState *state = pmu_state(c);
uint64_t buf_dev = state->current_buf_ptr;
Expand All @@ -469,7 +468,6 @@ void PmuCollector::reconcile_counters() {
"stop() — device flush failed",
c, static_cast<unsigned long>(buf_dev), count
);
leftover_active++;
}

// Cross-check device-side totals against what we wrote to CSV.
Expand Down Expand Up @@ -503,10 +501,6 @@ void PmuCollector::reconcile_counters() {
static_cast<unsigned long>(total_device)
);
}

if (leftover_active > 0) {
LOG_ERROR("PMU reconcile: %d core(s) had un-cleared current_buf_ptr — see prior errors", leftover_active);
}
}

// ---------------------------------------------------------------------------
Expand Down Expand Up @@ -578,5 +572,4 @@ void PmuCollector::finalize(PmuUnregisterCallback unregister_cb, const PmuFreeCa
collector_counters_.shrink_to_fit();
csv_shards_finalized_ = false;
clear_memory_context();
LOG_INFO_V0("PMU collector finalized");
}
10 changes: 0 additions & 10 deletions src/a2a3/platform/sim/host/device_runner.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -89,9 +89,6 @@ int DeviceRunner::ensure_binaries_loaded() {
auto load_optional_sym = [this](const char *name, void **out) {
dlerror();
void *sym = dlsym(aicpu_so_handle_, name);
if (sym == nullptr) {
LOG_DEBUG("Optional dlsym skipped for %s: %s", name, dlerror());
}
*out = sym;
};

Expand Down Expand Up @@ -284,7 +281,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) {
workers[i].core_type = (i < num_aic) ? CoreType::AIC : CoreType::AIV;
}

LOG_DEBUG("Setting function_bin_addr for Tasks (Simulation)");
for (int i = 0; i < runtime.get_task_count(); i++) {
Task *task = runtime.get_task(i);
if (task != nullptr) {
Expand Down Expand Up @@ -387,8 +383,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) {
}
});

LOG_INFO_V0("Allocated simulated registers: %d cores x 0x%x bytes", num_aicore, SIM_REG_BLOCK_SIZE);

// Allocate simulated PMU register blocks. PMU MMIO is a separate address
// region from the general AICore regs on hardware, so sim mirrors that with
// its own backing memory; otherwise the AICPU PMU collector would early-out
Expand Down Expand Up @@ -423,8 +417,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) {
}
});

LOG_INFO_V0("Allocated simulated PMU registers: %d cores x 0x%x bytes", num_aicore, SIM_REG_BLOCK_SIZE);

if (aicpu_execute_func_ == nullptr || aicore_execute_func_ == nullptr || set_platform_regs_func_ == nullptr ||
set_platform_dump_base_func_ == nullptr || set_platform_phase_base_func_ == nullptr ||
set_dump_args_enabled_func_ == nullptr || set_platform_pmu_base_func_ == nullptr ||
Expand Down Expand Up @@ -535,7 +527,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) {
}));
}

LOG_INFO_V0("Waiting for threads to complete");
for (auto &t : aicpu_threads) {
t.join();
}
Expand Down Expand Up @@ -724,7 +715,6 @@ int DeviceRunner::finalize() {
worker_count_ = 0;
last_runtime_ = nullptr;

LOG_INFO_V0("DeviceRunner(sim) finalized");
return 0;
}

Expand Down
1 change: 0 additions & 1 deletion src/a2a3/runtime/host_build_graph/aicpu/aicpu_executor.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -223,7 +223,6 @@ int32_t AicpuExecutor::run(Runtime *runtime) {
return -1;
}
int32_t run_rc = 0;
LOG_INFO_V0("Thread %d: Start (exec_idx=%d)", thread_idx, affinity_exec_idx);

// Boot thread (thread N-1): host_build_graph host-orch boot. The
// orchestrator already ran on the host, which also relocated every
Expand Down
10 changes: 5 additions & 5 deletions src/a2a3/runtime/host_build_graph/host/runtime_maker.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -660,7 +660,7 @@ extern "C" int bind_callable_to_runtime_impl(
Tensor t = orch_args->tensor(i);

if (t.is_child_memory()) {
LOG_INFO_V0(" Tensor %d: child memory, pass-through (0x%" PRIx64 ")", i, t.buffer.addr);
LOG_DEBUG(" Tensor %d: child memory, pass-through (0x%" PRIx64 ")", i, t.buffer.addr);
device_args.add_tensor(t);
continue;
}
Expand Down Expand Up @@ -695,7 +695,7 @@ extern "C" int bind_callable_to_runtime_impl(
// copying back.
bool needs_copy_back = !(signature != nullptr && i < sig_count && signature[i] == ArgDirection::IN);
runtime->tensor_pairs_.push_back({host_ptr, dev_ptr, size, needs_copy_back});
LOG_INFO_V0(" Tensor %d: %zu bytes at %p", i, size, dev_ptr);
LOG_DEBUG(" Tensor %d: %zu bytes at %p", i, size, dev_ptr);

// host_build_graph runs the orchestrator on the host, which may read
// control tensors (e.g. paged_attention's context_lens/block_table) via
Expand Down Expand Up @@ -925,15 +925,15 @@ extern "C" int validate_runtime_impl(Runtime *runtime, const HostApi *api, int e

// If host pointer is null, this is a device-only allocation (no copy-back)
if (pair.host_ptr == nullptr) {
LOG_INFO_V0("Tensor %d: device-only allocation (no copy-back)", i);
LOG_DEBUG("Tensor %d: device-only allocation (no copy-back)", i);
continue;
}

// Read-only INPUT tensors were uploaded H2D but the kernel never
// wrote them — copying them back (potentially ~GB) is pure waste.
// They are still device_free'd in the cleanup loop below.
if (!pair.needs_copy_back) {
LOG_INFO_V0("Tensor %d: read-only input, skipping copy-back", i);
LOG_DEBUG("Tensor %d: read-only input, skipping copy-back", i);
continue;
}

Expand All @@ -942,7 +942,7 @@ extern "C" int validate_runtime_impl(Runtime *runtime, const HostApi *api, int e
LOG_ERROR("Failed to copy tensor %d from device: %d", i, copy_rc);
rc = copy_rc;
} else {
LOG_INFO_V0("Tensor %d: %zu bytes copied to host", i, pair.size);
LOG_DEBUG("Tensor %d: %zu bytes copied to host", i, pair.size);
}
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -1091,7 +1091,7 @@ void PTO2OrchestratorState::mark_done() {
for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) {
int32_t total_tasks = orch->ring.task_allocator.active_count();
if (total_tasks > 0) {
LOG_INFO_V0("=== [Orchestrator] ring %d: total_tasks=%d ===", r, total_tasks);
LOG_DEBUG("=== [Orchestrator] ring %d: total_tasks=%d ===", r, total_tasks);
}
}
orch->sm_header->orchestrator_done.store(1, std::memory_order_release);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -73,30 +73,30 @@ PTO2SchedProfilingData scheduler_get_profiling(int thread_idx) {

void PTO2SchedulerState::print_stats() {
PTO2SchedulerState *sched = this;
LOG_INFO_V0("=== Scheduler Statistics ===");
LOG_DEBUG("=== Scheduler Statistics ===");
for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) {
if (sched->ring_sched_state.last_task_alive > 0) {
LOG_INFO_V0("Ring %d:", r);
LOG_INFO_V0(" last_task_alive: %d", sched->ring_sched_state.last_task_alive);
LOG_DEBUG("Ring %d:", r);
LOG_DEBUG(" last_task_alive: %d", sched->ring_sched_state.last_task_alive);
}
}
#if SIMPLER_SCHED_PROFILING
LOG_INFO_V0("tasks_completed: %lld", (long long)sched->tasks_completed.load(std::memory_order_relaxed));
LOG_INFO_V0("tasks_consumed: %lld", (long long)sched->tasks_consumed.load(std::memory_order_relaxed));
LOG_DEBUG("tasks_completed: %lld", (long long)sched->tasks_completed.load(std::memory_order_relaxed));
LOG_DEBUG("tasks_consumed: %lld", (long long)sched->tasks_consumed.load(std::memory_order_relaxed));
#endif
LOG_INFO_V0("============================");
LOG_DEBUG("============================");
}

void PTO2SchedulerState::print_queues() {
PTO2SchedulerState *sched = this;
LOG_INFO_V0("=== Ready Queues ===");
LOG_DEBUG("=== Ready Queues ===");

const char *shape_names[] = {"AIC", "AIV", "MIX"};

for (int i = 0; i < PTO2_NUM_RESOURCE_SHAPES; i++) {
LOG_INFO_V0(" %s: count=%" PRIu64, shape_names[i], sched->ready_queues[i].size());
LOG_DEBUG(" %s: count=%" PRIu64, shape_names[i], sched->ready_queues[i].size());
}
LOG_INFO_V0(" DUMMY: count=%" PRIu64, sched->dummy_ready_queue.size());
LOG_DEBUG(" DUMMY: count=%" PRIu64, sched->dummy_ready_queue.size());

LOG_INFO_V0("====================");
LOG_DEBUG("====================");
}
Original file line number Diff line number Diff line change
Expand Up @@ -564,7 +564,6 @@ int32_t SchedulerContext::shutdown(int32_t thread_idx) {
LOG_ERROR("Thread %d: Core %d has invalid register address", thread_idx, core_id);
}
}
LOG_INFO_V0("Thread %d: Shutdown complete", thread_idx);
return rc;
}

Expand Down Expand Up @@ -742,11 +741,11 @@ bool SchedulerContext::assign_cores_to_threads() {

core_trackers_[t].set_cluster(cluster_idx_per_thread[t]++, aic_wid, aiv0_wid, aiv1_wid);

LOG_INFO_V0("Thread %d: cluster %d (AIC=%d, AIV0=%d, AIV1=%d)", t, ci, aic_wid, aiv0_wid, aiv1_wid);
LOG_DEBUG("Thread %d: cluster %d (AIC=%d, AIV0=%d, AIV1=%d)", t, ci, aic_wid, aiv0_wid, aiv1_wid);
}

for (int32_t t = 0; t < aicpu_thread_num_; t++) {
LOG_INFO_V0(
LOG_DEBUG(
"Thread %d: total %d cores (%d clusters)", t, core_trackers_[t].core_num(),
core_trackers_[t].get_cluster_count()
);
Expand Down Expand Up @@ -780,7 +779,6 @@ void SchedulerContext::emergency_shutdown(Runtime *runtime) {
if (timeout_count > 0) {
LOG_ERROR("Emergency shutdown: %d cores did not acknowledge exit", timeout_count);
}
LOG_WARN("Emergency shutdown complete");
}

// =============================================================================
Expand Down Expand Up @@ -888,7 +886,6 @@ int32_t SchedulerContext::post_handshake_init(Runtime *runtime) {
}
if (is_pmu_enabled()) {
pmu_aicpu_init(physical_core_ids_, cores_total_num_);
LOG_INFO_V0("PMU profiling started on %d cores", cores_total_num_);
}
// dep_gen is host-driven (SubmitTrace) — runtime-gated by the host flag —
// and compiles out with the other profiling subsystems at SIMPLER_DFX=0.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -766,7 +766,7 @@ SchedulerContext::early_dispatch_shape(int32_t thread_idx, PTO2ResourceShape sha
// Re-push for concurrent peers BEFORE the expensive staging.
if (start + claim < c->logical_block_num) {
if (!sched_->early_dispatch_queues[s].push_tagged(c, task_id_snapshots[bi]))
LOG_INFO_V9(
LOG_DEBUG(
"[EARLY_DISPATCH] queue full on re-push, consumer=%" PRId64,
static_cast<int64_t>(c->task->task_id.raw)
);
Expand Down Expand Up @@ -861,24 +861,14 @@ int32_t SchedulerContext::try_early_dispatch(
int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_idx) {
always_assert(sched_ != nullptr);
CoreTracker &tracker = core_trackers_[thread_idx];
LOG_INFO_V0("Thread %d: resolve_and_dispatch entry", thread_idx);

PTO2SharedMemoryHeader *header = sched_->sm_header;
if (!header) {
LOG_ERROR("PTO2 dispatch: header is null");
return -1;
}
LOG_INFO_V0(
"Thread %d: header=%p, task_desc_offset[0]=%lu, window_size=%lu", thread_idx, static_cast<void *>(header),
static_cast<uint64_t>(header->ring.task_descriptors_offset),
static_cast<uint64_t>(header->ring.task_window_size)
);

Handshake *hank = static_cast<Handshake *>(runtime->workers);
LOG_INFO_V0(
"Thread %d: hank=%p, window_size=%lu", thread_idx, static_cast<void *>(hank),
static_cast<uint64_t>(header->ring.task_window_size)
);

LOG_INFO_V0("Thread %d: PTO2 dispatch starting with %d cores", thread_idx, core_trackers_[thread_idx].core_num());
int32_t cur_thread_completed = 0;
Expand Down
Loading
Loading