diff --git a/src/a2a3/platform/onboard/aicpu/kernel.cpp b/src/a2a3/platform/onboard/aicpu/kernel.cpp index 4c8795026e..28d13f415d 100644 --- a/src/a2a3/platform/onboard/aicpu/kernel.cpp +++ b/src/a2a3/platform/onboard/aicpu/kernel.cpp @@ -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; } @@ -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. @@ -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; } diff --git a/src/a2a3/platform/onboard/host/comm_hccl.cpp b/src/a2a3/platform/onboard/host/comm_hccl.cpp index 267032abb0..2ce9047d4c 100644 --- a/src/a2a3/platform/onboard/host/comm_hccl.cpp +++ b/src/a2a3/platform/onboard/host/comm_hccl.cpp @@ -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)); } diff --git a/src/a2a3/platform/onboard/host/device_runner.cpp b/src/a2a3/platform/onboard/host/device_runner.cpp index b58ddaf875..00b99291a2 100644 --- a/src/a2a3/platform/onboard/host/device_runner.cpp +++ b/src/a2a3/platform/onboard/host/device_runner.cpp @@ -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); @@ -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; } diff --git a/src/a2a3/platform/onboard/host/host_regs.cpp b/src/a2a3/platform/onboard/host/host_regs.cpp index ba860f0674..80267d2301 100644 --- a/src/a2a3/platform/onboard/host/host_regs.cpp +++ b/src/a2a3/platform/onboard/host/host_regs.cpp @@ -134,8 +134,6 @@ get_aicore_reg_info(std::vector &aic, std::vector &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++) { @@ -175,7 +173,7 @@ static int get_aicore_regs(std::vector ®s, 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() ); @@ -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 host_regs; int rc = get_aicore_regs(host_regs, device_id, kind); if (rc != 0) { @@ -218,7 +214,7 @@ int init_aicore_register_addresses( *runtime_regs_ptr = reinterpret_cast(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 ); diff --git a/src/a2a3/platform/shared/aicpu/pmu_collector_aicpu.cpp b/src/a2a3/platform/shared/aicpu/pmu_collector_aicpu.cpp index e4c47a1a39..89798c9e33 100644 --- a/src/a2a3/platform/shared/aicpu/pmu_collector_aicpu.cpp +++ b/src/a2a3/platform/shared/aicpu/pmu_collector_aicpu.cpp @@ -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(buffer) ); @@ -239,8 +239,6 @@ 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; @@ -248,7 +246,6 @@ void pmu_aicpu_init(const uint32_t *physical_core_ids, int num_cores) { } 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) { @@ -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(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 { diff --git a/src/a2a3/platform/shared/host/pmu_collector.cpp b/src/a2a3/platform/shared/host/pmu_collector.cpp index c9e28d983c..9f23adf79f 100644 --- a/src/a2a3/platform/shared/host/pmu_collector.cpp +++ b/src/a2a3/platform/shared/host/pmu_collector.cpp @@ -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; @@ -469,7 +468,6 @@ void PmuCollector::reconcile_counters() { "stop() — device flush failed", c, static_cast(buf_dev), count ); - leftover_active++; } // Cross-check device-side totals against what we wrote to CSV. @@ -503,10 +501,6 @@ void PmuCollector::reconcile_counters() { static_cast(total_device) ); } - - if (leftover_active > 0) { - LOG_ERROR("PMU reconcile: %d core(s) had un-cleared current_buf_ptr — see prior errors", leftover_active); - } } // --------------------------------------------------------------------------- @@ -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"); } diff --git a/src/a2a3/platform/sim/host/device_runner.cpp b/src/a2a3/platform/sim/host/device_runner.cpp index 614c714b77..8206c7850d 100644 --- a/src/a2a3/platform/sim/host/device_runner.cpp +++ b/src/a2a3/platform/sim/host/device_runner.cpp @@ -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; }; @@ -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) { @@ -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 @@ -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 || @@ -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(); } @@ -724,7 +715,6 @@ int DeviceRunner::finalize() { worker_count_ = 0; last_runtime_ = nullptr; - LOG_INFO_V0("DeviceRunner(sim) finalized"); return 0; } diff --git a/src/a2a3/runtime/host_build_graph/aicpu/aicpu_executor.cpp b/src/a2a3/runtime/host_build_graph/aicpu/aicpu_executor.cpp index b2f7df3572..8ac3a925ad 100644 --- a/src/a2a3/runtime/host_build_graph/aicpu/aicpu_executor.cpp +++ b/src/a2a3/runtime/host_build_graph/aicpu/aicpu_executor.cpp @@ -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 diff --git a/src/a2a3/runtime/host_build_graph/host/runtime_maker.cpp b/src/a2a3/runtime/host_build_graph/host/runtime_maker.cpp index 59f791686a..50d9071a9a 100644 --- a/src/a2a3/runtime/host_build_graph/host/runtime_maker.cpp +++ b/src/a2a3/runtime/host_build_graph/host/runtime_maker.cpp @@ -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; } @@ -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 @@ -925,7 +925,7 @@ 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; } @@ -933,7 +933,7 @@ extern "C" int validate_runtime_impl(Runtime *runtime, const HostApi *api, int e // 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; } @@ -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); } } } diff --git a/src/a2a3/runtime/host_build_graph/runtime/orchestrator_core/pto_orchestrator.cpp b/src/a2a3/runtime/host_build_graph/runtime/orchestrator_core/pto_orchestrator.cpp index df383b8640..31e38e13e9 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/orchestrator_core/pto_orchestrator.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/orchestrator_core/pto_orchestrator.cpp @@ -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); diff --git a/src/a2a3/runtime/host_build_graph/runtime/scheduler/pto_scheduler.cpp b/src/a2a3/runtime/host_build_graph/runtime/scheduler/pto_scheduler.cpp index 4c4cd838c3..8c0a43fcd8 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/scheduler/pto_scheduler.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/scheduler/pto_scheduler.cpp @@ -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("===================="); } diff --git a/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_cold_path.cpp b/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_cold_path.cpp index c7bc14c22c..5014eed289 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_cold_path.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_cold_path.cpp @@ -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; } @@ -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() ); @@ -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"); } // ============================================================================= @@ -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. diff --git a/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_dispatch.cpp b/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_dispatch.cpp index 75b83958e2..17fc4738ed 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_dispatch.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/scheduler/scheduler_dispatch.cpp @@ -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(c->task->task_id.raw) ); @@ -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(header), - static_cast(header->ring.task_descriptors_offset), - static_cast(header->ring.task_window_size) - ); Handshake *hank = static_cast(runtime->workers); - LOG_INFO_V0( - "Thread %d: hank=%p, window_size=%lu", thread_idx, static_cast(hank), - static_cast(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; diff --git a/src/a2a3/runtime/host_build_graph/runtime/shared/pto_shared_memory.cpp b/src/a2a3/runtime/host_build_graph/runtime/shared/pto_shared_memory.cpp index 9b33075a72..fcff0a154c 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/shared/pto_shared_memory.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/shared/pto_shared_memory.cpp @@ -205,28 +205,28 @@ void PTO2SharedMemoryHandle::print_layout() { PTO2SharedMemoryHeader *h = header; - LOG_INFO_V0("=== PTO2 Shared Memory Layout ==="); - LOG_INFO_V0("Base address: %p", sm_base); - LOG_INFO_V0("Total size: %" PRIu64 " bytes", h->total_size); - LOG_INFO_V0("Ring depth: %d", PTO2_MAX_RING_DEPTH); + LOG_DEBUG("=== PTO2 Shared Memory Layout ==="); + LOG_DEBUG("Base address: %p", sm_base); + LOG_DEBUG("Total size: %" PRIu64 " bytes", h->total_size); + LOG_DEBUG("Ring depth: %d", PTO2_MAX_RING_DEPTH); for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { - LOG_INFO_V0("Ring %d:", r); - LOG_INFO_V0(" task_window_size: %" PRIu64, h->ring.task_window_size); - LOG_INFO_V0(" heap_size: %" PRIu64 " bytes", h->ring.heap_size); - LOG_INFO_V0( + LOG_DEBUG("Ring %d:", r); + LOG_DEBUG(" task_window_size: %" PRIu64, h->ring.task_window_size); + LOG_DEBUG(" heap_size: %" PRIu64 " bytes", h->ring.heap_size); + LOG_DEBUG( " descriptors_off: %" PRIu64 " (0x%" PRIx64 ")", h->ring.task_descriptors_offset, h->ring.task_descriptors_offset ); - LOG_INFO_V0(" current_task_idx: %d", h->ring.fc.current_task_index.load(std::memory_order_acquire)); - LOG_INFO_V0(" last_task_alive: %d", h->ring.fc.last_task_alive.load(std::memory_order_acquire)); + LOG_DEBUG(" current_task_idx: %d", h->ring.fc.current_task_index.load(std::memory_order_acquire)); + LOG_DEBUG(" last_task_alive: %d", h->ring.fc.last_task_alive.load(std::memory_order_acquire)); } - LOG_INFO_V0("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); - LOG_INFO_V0("Error state:"); - LOG_INFO_V0(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); - LOG_INFO_V0("================================"); + LOG_DEBUG("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); + LOG_DEBUG("Error state:"); + LOG_DEBUG(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); + LOG_DEBUG("================================"); } bool PTO2SharedMemoryHandle::validate() { diff --git a/src/a2a3/runtime/host_build_graph/runtime/shared/pto_tensormap.cpp b/src/a2a3/runtime/host_build_graph/runtime/shared/pto_tensormap.cpp index 5208c632cc..d10702ef21 100644 --- a/src/a2a3/runtime/host_build_graph/runtime/shared/pto_tensormap.cpp +++ b/src/a2a3/runtime/host_build_graph/runtime/shared/pto_tensormap.cpp @@ -182,18 +182,18 @@ void PTO2TensorMap::print_stats() { } } - LOG_INFO_V0("=== TensorMap Statistics ==="); - LOG_INFO_V0("Pool size: %d", pool_size); - LOG_INFO_V0("Pool next entry idx: %d", next_entry_idx); - LOG_INFO_V0("Pool free_num: %d", free_num); - LOG_INFO_V0("Num buckets: %d", num_buckets); - LOG_INFO_V0("Valid entries: %d", valid); - LOG_INFO_V0("Stale entries: %d", stale); - LOG_INFO_V0("Empty buckets: %d", empty_buckets); - LOG_INFO_V0("Max chain len: %d", max_chain); - LOG_INFO_V0("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); - LOG_INFO_V0("Last task alive: %d", last_task_alive_cached); - LOG_INFO_V0("============================"); + LOG_DEBUG("=== TensorMap Statistics ==="); + LOG_DEBUG("Pool size: %d", pool_size); + LOG_DEBUG("Pool next entry idx: %d", next_entry_idx); + LOG_DEBUG("Pool free_num: %d", free_num); + LOG_DEBUG("Num buckets: %d", num_buckets); + LOG_DEBUG("Valid entries: %d", valid); + LOG_DEBUG("Stale entries: %d", stale); + LOG_DEBUG("Empty buckets: %d", empty_buckets); + LOG_DEBUG("Max chain len: %d", max_chain); + LOG_DEBUG("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); + LOG_DEBUG("Last task alive: %d", last_task_alive_cached); + LOG_DEBUG("============================"); } int32_t PTO2TensorMap::valid_count() { diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp index 1fef4668b9..a1d67375d0 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp @@ -398,7 +398,7 @@ int32_t AicpuExecutor::load_orch_so( continue; } file_created = true; - LOG_INFO_V0("Thread %d: Created SO file at %s (%zu bytes)", thread_idx, so_path, so_size); + LOG_DEBUG("Thread %d: Created SO file at %s (%zu bytes)", thread_idx, so_path, so_size); } if (!file_created) { @@ -414,7 +414,7 @@ int32_t AicpuExecutor::load_orch_so( unlink(so_path); return -1; } - LOG_INFO_V0("Thread %d: dlopen succeeded, handle=%p", thread_idx, handle); + LOG_DEBUG("Thread %d: dlopen succeeded, handle=%p", thread_idx, handle); // The image is mmap'd after dlopen; keeping only the handle avoids stale // libdevice_orch__.so files when worker children exit via os._exit. @@ -494,7 +494,6 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // stamps below would have no valid slot and silently drop. Idempotent // onboard, where the filter gate already set this same value. platform_aicpu_affinity_set_thread_idx(thread_idx); - LOG_INFO_V0("Thread %d: Start (exec_idx=%d)", thread_idx, affinity_exec_idx); // Orchestrator check if (thread_idx >= sched_thread_num_) { @@ -552,7 +551,7 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // Validate arg count on every run against the registered SO. if (*p_config_func != nullptr) { PTO2OrchestrationConfig cfg = (*p_config_func)(orch_args_cached_); - LOG_INFO_V0("Thread %d: Config: expected_args=%d", thread_idx, cfg.expected_arg_count); + LOG_DEBUG("Thread %d: Config: expected_args=%d", thread_idx, cfg.expected_arg_count); if (cfg.expected_arg_count > 0) { const ChipStorageTaskArgs &args_validate = runtime->get_orch_args(); int32_t actual_arg_count = args_validate.tensor_count() + args_validate.scalar_count(); @@ -570,29 +569,11 @@ int32_t AicpuExecutor::run(Runtime *runtime) { return -1; } } - } else { - LOG_INFO_V0("Thread %d: No config function, using defaults", thread_idx); } // sm_handle / rt are bound to *this* run's memory and must be // (re)created every run, regardless of whether the SO itself was // reused above. - const ChipStorageTaskArgs &args = runtime->get_orch_args(); - int32_t arg_count = args.tensor_count() + args.scalar_count(); - LOG_INFO_V0("Thread %d: sm_ptr=%p, arg_count=%d", thread_idx, runtime->get_gm_sm_ptr(), arg_count); - for (int32_t i = 0; i < args.tensor_count() && i < 20; i++) { - const Tensor &t = args.tensor(i); - LOG_INFO_V0( - "Thread %d: orch_args[%d] = TENSOR(data=0x%lx, ndims=%u, dtype=%u)", thread_idx, i, - static_cast(t.buffer.addr), t.ndims, static_cast(t.dtype) - ); - } - for (int32_t i = 0; i < args.scalar_count() && (args.tensor_count() + i) < 20; i++) { - LOG_INFO_V0( - "Thread %d: orch_args[%d] = SCALAR(0x%lx)", thread_idx, args.tensor_count() + i, - static_cast(args.scalar(i)) - ); - } sm_ptr = runtime->get_gm_sm_ptr(); } @@ -615,13 +596,6 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // addresses; we overwrite them with device addresses). runtime_wire_arena_pointers(runtime_arena_, rt->prebuilt_layout, rt); sm_size = PTO2SharedMemoryHandle::calculate_size_per_ring(rt->prebuilt_layout.sizing.task_window_sizes); - for (int r = 0; r < PTO2_MAX_RING_DEPTH; ++r) { - LOG_INFO_V0( - "Thread %d: Ring %d sizes: task_window=%" PRIu64 " heap=%" PRIu64 " dep_pool=%d", thread_idx, r, - rt->prebuilt_layout.sizing.task_window_sizes[r], rt->prebuilt_layout.sizing.heap_sizes[r], - rt->prebuilt_layout.sizing.dep_pool_capacities[r] - ); - } } // Reset SM state. setup_pointers + init_header_per_ring restore diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp index c3f0092781..86e5649873 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp @@ -535,7 +535,7 @@ static bool stage_device_args( 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); out->add_tensor(t); continue; } @@ -588,7 +588,7 @@ static bool stage_device_args( // copying back. bool needs_copy_back = !(signature != nullptr && i < sig_count && signature[i] == ArgDirection::IN); runtime->tensor_leases_.push_back({host_ptr, dev_ptr, size, needs_copy_back, release_kind}); - 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); t.buffer.addr = reinterpret_cast(dev_ptr); out->add_tensor(t); @@ -1011,7 +1011,7 @@ 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 (lease.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; } @@ -1019,7 +1019,7 @@ extern "C" int validate_runtime_impl(Runtime *runtime, const HostApi *api, int e // wrote them — copying them back (potentially ~GB) is pure waste. // They are still released through release_kind below. if (!lease.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; } @@ -1028,7 +1028,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, lease.size); + LOG_DEBUG("Tensor %d: %zu bytes copied to host", i, lease.size); } } } diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp index d5f4bfcd22..1bb18feba8 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp @@ -1262,11 +1262,11 @@ void PTO2OrchestratorState::mark_done() { for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { int32_t total_tasks = orch->rings[r].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); } auto &fanin_pool = orch->rings[r].fanin_pool; if (fanin_pool.top > 1) { - LOG_INFO_V0( + LOG_DEBUG( "=== [FaninPool %d] top=%d tail=%d used=%d high_water=%d capacity=%d ===", r, fanin_pool.top, fanin_pool.tail, fanin_pool.top - fanin_pool.tail, fanin_pool.high_water, fanin_pool.capacity ); diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp index 2f9d96d8a7..c2d5ef62cc 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp @@ -73,14 +73,14 @@ 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_states[r].last_task_alive > 0) { - LOG_INFO_V0("Ring %d:", r); - LOG_INFO_V0(" last_task_alive: %d", sched->ring_sched_states[r].last_task_alive); + LOG_DEBUG("Ring %d:", r); + LOG_DEBUG(" last_task_alive: %d", sched->ring_sched_states[r].last_task_alive); auto &dp = sched->ring_sched_states[r].dep_pool; if (dp.top > 0) { - LOG_INFO_V0( + LOG_DEBUG( " dep_pool: top=%d tail=%d used=%d high_water=%d capacity=%d", dp.top, dp.tail, dp.top - dp.tail, dp.high_water, dp.capacity ); @@ -88,22 +88,22 @@ void PTO2SchedulerState::print_stats() { } } #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("===================="); } diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp index 7d4e1a823e..04ee782d60 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp @@ -657,7 +657,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; } @@ -966,7 +965,6 @@ void SchedulerContext::post_handshake_profiling_init() { } 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_); } if (is_dep_gen_enabled()) { dep_gen_aicpu_init(); @@ -1020,11 +1018,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() ); @@ -1058,7 +1056,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"); } // ============================================================================= @@ -1203,7 +1200,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. diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp index 1b162a61cc..15d2b60cd9 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp @@ -84,7 +84,7 @@ SlotTransition SchedulerContext::decide_slot_transition( // Complete one slot's task: subtask counting, mixed completion, deferred release, profiling. void SchedulerContext::complete_slot_task( PTO2TaskSlotState &slot_state, int32_t expected_reg_task_id, [[maybe_unused]] PTO2SubtaskSlot subslot, - int32_t thread_idx, int32_t core_id, Handshake *hank, int32_t &completed_this_turn, + [[maybe_unused]] int32_t thread_idx, int32_t core_id, Handshake *hank, int32_t &completed_this_turn, PTO2TaskSlotState *deferred_release_slot_states[], int32_t &deferred_release_count #if SIMPLER_DFX , @@ -228,7 +228,6 @@ void SchedulerContext::complete_slot_task( if (deferred_release_count < PTO2_DEFERRED_RELEASE_CAP) { deferred_release_slot_states[deferred_release_count++] = &slot_state; } else { - LOG_INFO_V9("Thread %d: release", thread_idx); while (deferred_release_count > 0) { #if SIMPLER_SCHED_PROFILING // SCHED_PROFILING variant takes thread_idx for the per-thread diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp index c090f94cc9..00bf111d0c 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp @@ -769,7 +769,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(c->task->task_id.raw) ); @@ -864,24 +864,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(header), - static_cast(header->rings[0].task_descriptors_offset), - static_cast(header->rings[0].task_window_size) - ); Handshake *hank = static_cast(runtime->dev.workers); - LOG_INFO_V0( - "Thread %d: hank=%p, window_size=%lu", thread_idx, static_cast(hank), - static_cast(header->rings[0].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; diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp index 2b75c9d621..0b655150a1 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp @@ -188,28 +188,28 @@ void PTO2SharedMemoryHandle::print_layout() { PTO2SharedMemoryHeader *h = header; - LOG_INFO_V0("=== PTO2 Shared Memory Layout ==="); - LOG_INFO_V0("Base address: %p", sm_base); - LOG_INFO_V0("Total size: %" PRIu64 " bytes", h->total_size); - LOG_INFO_V0("Ring depth: %d", PTO2_MAX_RING_DEPTH); + LOG_DEBUG("=== PTO2 Shared Memory Layout ==="); + LOG_DEBUG("Base address: %p", sm_base); + LOG_DEBUG("Total size: %" PRIu64 " bytes", h->total_size); + LOG_DEBUG("Ring depth: %d", PTO2_MAX_RING_DEPTH); for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { - LOG_INFO_V0("Ring %d:", r); - LOG_INFO_V0(" task_window_size: %" PRIu64, h->rings[r].task_window_size); - LOG_INFO_V0(" heap_size: %" PRIu64 " bytes", h->rings[r].heap_size); - LOG_INFO_V0( + LOG_DEBUG("Ring %d:", r); + LOG_DEBUG(" task_window_size: %" PRIu64, h->rings[r].task_window_size); + LOG_DEBUG(" heap_size: %" PRIu64 " bytes", h->rings[r].heap_size); + LOG_DEBUG( " descriptors_off: %" PRIu64 " (0x%" PRIx64 ")", h->rings[r].task_descriptors_offset, h->rings[r].task_descriptors_offset ); - LOG_INFO_V0(" current_task_idx: %d", h->rings[r].fc.current_task_index.load(std::memory_order_acquire)); - LOG_INFO_V0(" last_task_alive: %d", h->rings[r].fc.last_task_alive.load(std::memory_order_acquire)); + LOG_DEBUG(" current_task_idx: %d", h->rings[r].fc.current_task_index.load(std::memory_order_acquire)); + LOG_DEBUG(" last_task_alive: %d", h->rings[r].fc.last_task_alive.load(std::memory_order_acquire)); } - LOG_INFO_V0("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); - LOG_INFO_V0("Error state:"); - LOG_INFO_V0(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); - LOG_INFO_V0("================================"); + LOG_DEBUG("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); + LOG_DEBUG("Error state:"); + LOG_DEBUG(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); + LOG_DEBUG("================================"); } bool PTO2SharedMemoryHandle::validate() { diff --git a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp index 3854099d0e..3cfa357a49 100644 --- a/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp +++ b/src/a2a3/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp @@ -227,20 +227,20 @@ void PTO2TensorMap::print_stats() { } } - LOG_INFO_V0("=== TensorMap Statistics ==="); - LOG_INFO_V0("Pool size: %d", pool_size); - LOG_INFO_V0("Pool next entry idx: %d", next_entry_idx); - LOG_INFO_V0("Pool free_num: %d", free_num); - LOG_INFO_V0("Num buckets: %d", num_buckets); - LOG_INFO_V0("Valid entries: %d", valid); - LOG_INFO_V0("Stale entries: %d", stale); - LOG_INFO_V0("Empty buckets: %d", empty_buckets); - LOG_INFO_V0("Max chain len: %d", max_chain); - LOG_INFO_V0("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); + LOG_DEBUG("=== TensorMap Statistics ==="); + LOG_DEBUG("Pool size: %d", pool_size); + LOG_DEBUG("Pool next entry idx: %d", next_entry_idx); + LOG_DEBUG("Pool free_num: %d", free_num); + LOG_DEBUG("Num buckets: %d", num_buckets); + LOG_DEBUG("Valid entries: %d", valid); + LOG_DEBUG("Stale entries: %d", stale); + LOG_DEBUG("Empty buckets: %d", empty_buckets); + LOG_DEBUG("Max chain len: %d", max_chain); + LOG_DEBUG("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { - LOG_INFO_V0("Last task alive[%d]: %d", r, last_task_alives[r]); + LOG_DEBUG("Last task alive[%d]: %d", r, last_task_alives[r]); } - LOG_INFO_V0("============================"); + LOG_DEBUG("============================"); } int32_t PTO2TensorMap::valid_count() { diff --git a/src/a5/platform/onboard/aicpu/kernel.cpp b/src/a5/platform/onboard/aicpu/kernel.cpp index 90c5f8c060..baa73def97 100644 --- a/src/a5/platform/onboard/aicpu/kernel.cpp +++ b/src/a5/platform/onboard/aicpu/kernel.cpp @@ -112,7 +112,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; } @@ -124,13 +123,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. @@ -165,6 +162,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; } diff --git a/src/a5/platform/onboard/host/comm_hccl.cpp b/src/a5/platform/onboard/host/comm_hccl.cpp index d78e55303b..8214208715 100644 --- a/src/a5/platform/onboard/host/comm_hccl.cpp +++ b/src/a5/platform/onboard/host/comm_hccl.cpp @@ -206,7 +206,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)); } diff --git a/src/a5/platform/onboard/host/device_runner.cpp b/src/a5/platform/onboard/host/device_runner.cpp index a022d73076..fd5c32b518 100644 --- a/src/a5/platform/onboard/host/device_runner.cpp +++ b/src/a5/platform/onboard/host/device_runner.cpp @@ -321,7 +321,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) { finalize_collectors(); }); - LOG_INFO_V0("=== Initialize runtime args ==="); rc = prepare_orch_so(runtime); if (rc != 0) { LOG_ERROR("prepare_orch_so failed: %d", rc); @@ -744,7 +743,6 @@ int DeviceRunner::finalize() { if (reset_rc == 0) { device_unusable_ = false; } - LOG_INFO_V0("DeviceRunner finalized"); return rc != 0 ? rc : reset_rc; } diff --git a/src/a5/platform/onboard/host/host_regs.cpp b/src/a5/platform/onboard/host/host_regs.cpp index 47d54848a3..efd2376b8a 100644 --- a/src/a5/platform/onboard/host/host_regs.cpp +++ b/src/a5/platform/onboard/host/host_regs.cpp @@ -96,7 +96,7 @@ static int get_aicore_regs(std::vector ®s, uint64_t device_id) { LOG_ERROR("get_aicore_reg_info failed: %d", rt); return rt; } - LOG_INFO_V0("get_aicore_regs: Retrieved %zu register addresses", regs.size()); + LOG_DEBUG("get_aicore_regs: Retrieved %zu register addresses", regs.size()); return 0; } @@ -106,8 +106,6 @@ int init_aicore_register_addresses(uint64_t *runtime_regs_ptr, uint64_t device_i return -1; } - LOG_INFO_V0("Retrieving and allocating AICore register addresses..."); - // Step 1: Get register addresses from HAL std::vector host_regs; int rc = get_aicore_regs(host_regs, device_id); @@ -135,7 +133,7 @@ int init_aicore_register_addresses(uint64_t *runtime_regs_ptr, uint64_t device_i // Step 4: Store device pointer in output regs field *runtime_regs_ptr = reinterpret_cast(reg_ptr); - LOG_INFO_V0( + LOG_DEBUG( "Successfully initialized register addresses: %zu addresses at device 0x%llx", host_regs.size(), *runtime_regs_ptr ); diff --git a/src/a5/platform/shared/aicpu/pmu_collector_aicpu.cpp b/src/a5/platform/shared/aicpu/pmu_collector_aicpu.cpp index 7250d48831..3e1cd478d2 100644 --- a/src/a5/platform/shared/aicpu/pmu_collector_aicpu.cpp +++ b/src/a5/platform/shared/aicpu/pmu_collector_aicpu.cpp @@ -157,7 +157,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(buffer) ); @@ -257,15 +257,11 @@ 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; } } - - LOG_INFO_V0("PMU initialized: %d cores, event_type=%u", num_cores, pmu_event_type); } void pmu_aicpu_complete_record( @@ -390,7 +386,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(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 { diff --git a/src/a5/platform/shared/host/pmu_collector.cpp b/src/a5/platform/shared/host/pmu_collector.cpp index 43b66c7b67..835fece4d1 100644 --- a/src/a5/platform/shared/host/pmu_collector.cpp +++ b/src/a5/platform/shared/host/pmu_collector.cpp @@ -496,7 +496,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; @@ -514,11 +513,6 @@ void PmuCollector::reconcile_counters() { "stop() — device flush failed", c, static_cast(buf_dev), count ); - leftover_active++; - } - - if (leftover_active > 0) { - LOG_ERROR("PMU reconcile: %d core(s) had un-cleared current_buf_ptr — see prior errors", leftover_active); } // Cross-check device-side totals against host CSV. PMU is single-kind @@ -672,5 +666,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"); } diff --git a/src/a5/platform/sim/host/device_runner.cpp b/src/a5/platform/sim/host/device_runner.cpp index 0ecd214ffc..d565b86459 100644 --- a/src/a5/platform/sim/host/device_runner.cpp +++ b/src/a5/platform/sim/host/device_runner.cpp @@ -100,9 +100,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; }; @@ -284,7 +281,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) { } kernel_args_.enable_profiling_flag = enable_profiling_flag; - 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) { @@ -391,10 +387,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) { } }); - LOG_INFO_V0( - "Allocated simulated registers: %d cores x 0x%x bytes (sparse: 3 pages)", num_aicore, SIM_REG_TOTAL_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 || @@ -503,7 +495,6 @@ int DeviceRunner::run(Runtime &runtime, const CallConfig &config) { })); } - LOG_INFO_V0("Waiting for threads to complete"); for (auto &t : aicpu_threads) { t.join(); } @@ -683,7 +674,6 @@ int DeviceRunner::finalize() { worker_count_ = 0; last_runtime_ = nullptr; - LOG_INFO_V0("DeviceRunner(sim) finalized"); return 0; } diff --git a/src/a5/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp b/src/a5/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp index 8539ae0f5b..3af262b265 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/aicpu/aicpu_executor.cpp @@ -399,7 +399,7 @@ int32_t AicpuExecutor::load_orch_so( continue; } file_created = true; - LOG_INFO_V0("Thread %d: Created SO file at %s (%zu bytes)", thread_idx, so_path, so_size); + LOG_DEBUG("Thread %d: Created SO file at %s (%zu bytes)", thread_idx, so_path, so_size); } if (!file_created) { @@ -415,7 +415,7 @@ int32_t AicpuExecutor::load_orch_so( unlink(so_path); return -1; } - LOG_INFO_V0("Thread %d: dlopen succeeded, handle=%p", thread_idx, handle); + LOG_DEBUG("Thread %d: dlopen succeeded, handle=%p", thread_idx, handle); unlink(so_path); @@ -491,7 +491,6 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // stamps below would have no valid slot and silently drop. Idempotent // onboard, where the filter gate already set this same value. platform_aicpu_affinity_set_thread_idx(thread_idx); - LOG_INFO_V0("Thread %d: Start (exec_idx=%d)", thread_idx, affinity_exec_idx); // Orchestrator check if (thread_idx >= sched_thread_num_) { @@ -549,7 +548,7 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // Validate arg count on every run against the registered SO. if (*p_config_func != nullptr) { PTO2OrchestrationConfig cfg = (*p_config_func)(orch_args_cached_); - LOG_INFO_V0("Thread %d: Config: expected_args=%d", thread_idx, cfg.expected_arg_count); + LOG_DEBUG("Thread %d: Config: expected_args=%d", thread_idx, cfg.expected_arg_count); if (cfg.expected_arg_count > 0) { const ChipStorageTaskArgs &args_validate = runtime->get_orch_args(); int32_t actual_arg_count = args_validate.tensor_count() + args_validate.scalar_count(); @@ -567,29 +566,11 @@ int32_t AicpuExecutor::run(Runtime *runtime) { return -1; } } - } else { - LOG_INFO_V0("Thread %d: No config function, using defaults", thread_idx); } // sm_handle / rt are bound to *this* run's memory and must be // (re)created every run, regardless of whether the SO itself was // reused above. - const ChipStorageTaskArgs &args = runtime->get_orch_args(); - int32_t arg_count = args.tensor_count() + args.scalar_count(); - LOG_INFO_V0("Thread %d: sm_ptr=%p, arg_count=%d", thread_idx, runtime->get_gm_sm_ptr(), arg_count); - for (int32_t i = 0; i < args.tensor_count() && i < 20; i++) { - const Tensor &t = args.tensor(i); - LOG_INFO_V0( - "Thread %d: orch_args[%d] = TENSOR(data=0x%lx, ndims=%u, dtype=%u)", thread_idx, i, - static_cast(t.buffer.addr), t.ndims, static_cast(t.dtype) - ); - } - for (int32_t i = 0; i < args.scalar_count() && (args.tensor_count() + i) < 20; i++) { - LOG_INFO_V0( - "Thread %d: orch_args[%d] = SCALAR(0x%lx)", thread_idx, args.tensor_count() + i, - static_cast(args.scalar(i)) - ); - } sm_ptr = runtime->get_gm_sm_ptr(); } @@ -612,13 +593,6 @@ int32_t AicpuExecutor::run(Runtime *runtime) { // addresses; we overwrite them with device addresses). runtime_wire_arena_pointers(runtime_arena_, rt->prebuilt_layout, rt); sm_size = PTO2SharedMemoryHandle::calculate_size_per_ring(rt->prebuilt_layout.sizing.task_window_sizes); - for (int r = 0; r < PTO2_MAX_RING_DEPTH; ++r) { - LOG_INFO_V0( - "Thread %d: Ring %d sizes: task_window=%" PRIu64 " heap=%" PRIu64 " dep_pool=%d", thread_idx, r, - rt->prebuilt_layout.sizing.task_window_sizes[r], rt->prebuilt_layout.sizing.heap_sizes[r], - rt->prebuilt_layout.sizing.dep_pool_capacities[r] - ); - } } // Reset SM state. setup_pointers + init_header_per_ring restore diff --git a/src/a5/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp b/src/a5/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp index c355f2e11c..187a66d91f 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/host/runtime_maker.cpp @@ -535,7 +535,7 @@ static bool stage_device_args( 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); out->add_tensor(t); continue; } @@ -588,7 +588,7 @@ static bool stage_device_args( // copying back. bool needs_copy_back = !(signature != nullptr && i < sig_count && signature[i] == ArgDirection::IN); runtime->tensor_leases_.push_back({host_ptr, dev_ptr, size, needs_copy_back, release_kind}); - 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); t.buffer.addr = reinterpret_cast(dev_ptr); out->add_tensor(t); @@ -966,7 +966,7 @@ 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 (lease.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; } @@ -974,7 +974,7 @@ extern "C" int validate_runtime_impl(Runtime *runtime, const HostApi *api, int e // wrote them — copying them back (potentially ~GB) is pure waste. // They are still released through release_kind below. if (!lease.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; } @@ -983,7 +983,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, lease.size); + LOG_DEBUG("Tensor %d: %zu bytes copied to host", i, lease.size); } } } diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp index 9d6dd44b61..b192fdd039 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/pto_orchestrator.cpp @@ -1264,11 +1264,11 @@ void PTO2OrchestratorState::mark_done() { for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { int32_t total_tasks = orch->rings[r].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); } auto &fanin_pool = orch->rings[r].fanin_pool; if (fanin_pool.top > 1) { - LOG_INFO_V0( + LOG_DEBUG( "=== [FaninPool %d] top=%d tail=%d used=%d high_water=%d capacity=%d ===", r, fanin_pool.top, fanin_pool.tail, fanin_pool.top - fanin_pool.tail, fanin_pool.high_water, fanin_pool.capacity ); diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp index 2f9d96d8a7..c2d5ef62cc 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/pto_scheduler.cpp @@ -73,14 +73,14 @@ 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_states[r].last_task_alive > 0) { - LOG_INFO_V0("Ring %d:", r); - LOG_INFO_V0(" last_task_alive: %d", sched->ring_sched_states[r].last_task_alive); + LOG_DEBUG("Ring %d:", r); + LOG_DEBUG(" last_task_alive: %d", sched->ring_sched_states[r].last_task_alive); auto &dp = sched->ring_sched_states[r].dep_pool; if (dp.top > 0) { - LOG_INFO_V0( + LOG_DEBUG( " dep_pool: top=%d tail=%d used=%d high_water=%d capacity=%d", dp.top, dp.tail, dp.top - dp.tail, dp.high_water, dp.capacity ); @@ -88,22 +88,22 @@ void PTO2SchedulerState::print_stats() { } } #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("===================="); } diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp index 4e5ab8ccda..01c1310601 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_cold_path.cpp @@ -661,7 +661,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; } @@ -958,7 +957,6 @@ void SchedulerContext::post_handshake_profiling_init() { } 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_); } if (is_dep_gen_enabled()) { dep_gen_aicpu_init(); @@ -1012,11 +1010,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() ); @@ -1050,7 +1048,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"); } // ============================================================================= @@ -1199,7 +1196,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. diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp index f1d74b9cdb..402956023d 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_completion.cpp @@ -77,7 +77,7 @@ SlotTransition SchedulerContext::decide_slot_transition( // Complete one slot's task: subtask counting, mixed completion, deferred release, profiling. void SchedulerContext::complete_slot_task( PTO2TaskSlotState &slot_state, int32_t expected_reg_task_id, [[maybe_unused]] PTO2SubtaskSlot subslot, - int32_t thread_idx, int32_t core_id, Handshake *hank, int32_t &completed_this_turn, + [[maybe_unused]] int32_t thread_idx, int32_t core_id, Handshake *hank, int32_t &completed_this_turn, PTO2TaskSlotState *deferred_release_slot_states[], int32_t &deferred_release_count #if SIMPLER_DFX , @@ -172,7 +172,6 @@ void SchedulerContext::complete_slot_task( if (deferred_release_count < PTO2_DEFERRED_RELEASE_CAP) { deferred_release_slot_states[deferred_release_count++] = &slot_state; } else { - LOG_INFO_V9("Thread %d: release", thread_idx); while (deferred_release_count > 0) { #if SIMPLER_SCHED_PROFILING // SCHED_PROFILING variant takes thread_idx for the per-thread diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp index ca23c9cb1b..05397cb428 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/scheduler/scheduler_dispatch.cpp @@ -569,7 +569,7 @@ SchedulerContext::early_dispatch_shape(int32_t thread_idx, PTO2ResourceShape sha if (claim == 0) continue; 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(c->task->task_id.raw) ); @@ -725,24 +725,14 @@ void SchedulerContext::dispatch_ready_tasks( int32_t SchedulerContext::resolve_and_dispatch(Runtime *runtime, int32_t thread_idx) { 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(header), - static_cast(header->rings[0].task_descriptors_offset), - static_cast(header->rings[0].task_window_size) - ); Handshake *hank = static_cast(runtime->dev.workers); - LOG_INFO_V0( - "Thread %d: hank=%p, window_size=%lu", thread_idx, static_cast(hank), - static_cast(header->rings[0].task_window_size) - ); LOG_INFO_V0("Thread %d: PTO2 dispatch starting with %d cores", thread_idx, tracker.core_num()); int32_t cur_thread_completed = 0; diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp index 2b75c9d621..0b655150a1 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_shared_memory.cpp @@ -188,28 +188,28 @@ void PTO2SharedMemoryHandle::print_layout() { PTO2SharedMemoryHeader *h = header; - LOG_INFO_V0("=== PTO2 Shared Memory Layout ==="); - LOG_INFO_V0("Base address: %p", sm_base); - LOG_INFO_V0("Total size: %" PRIu64 " bytes", h->total_size); - LOG_INFO_V0("Ring depth: %d", PTO2_MAX_RING_DEPTH); + LOG_DEBUG("=== PTO2 Shared Memory Layout ==="); + LOG_DEBUG("Base address: %p", sm_base); + LOG_DEBUG("Total size: %" PRIu64 " bytes", h->total_size); + LOG_DEBUG("Ring depth: %d", PTO2_MAX_RING_DEPTH); for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { - LOG_INFO_V0("Ring %d:", r); - LOG_INFO_V0(" task_window_size: %" PRIu64, h->rings[r].task_window_size); - LOG_INFO_V0(" heap_size: %" PRIu64 " bytes", h->rings[r].heap_size); - LOG_INFO_V0( + LOG_DEBUG("Ring %d:", r); + LOG_DEBUG(" task_window_size: %" PRIu64, h->rings[r].task_window_size); + LOG_DEBUG(" heap_size: %" PRIu64 " bytes", h->rings[r].heap_size); + LOG_DEBUG( " descriptors_off: %" PRIu64 " (0x%" PRIx64 ")", h->rings[r].task_descriptors_offset, h->rings[r].task_descriptors_offset ); - LOG_INFO_V0(" current_task_idx: %d", h->rings[r].fc.current_task_index.load(std::memory_order_acquire)); - LOG_INFO_V0(" last_task_alive: %d", h->rings[r].fc.last_task_alive.load(std::memory_order_acquire)); + LOG_DEBUG(" current_task_idx: %d", h->rings[r].fc.current_task_index.load(std::memory_order_acquire)); + LOG_DEBUG(" last_task_alive: %d", h->rings[r].fc.last_task_alive.load(std::memory_order_acquire)); } - LOG_INFO_V0("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); - LOG_INFO_V0("Error state:"); - LOG_INFO_V0(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); - LOG_INFO_V0(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); - LOG_INFO_V0("================================"); + LOG_DEBUG("orchestrator_done: %d", h->orchestrator_done.load(std::memory_order_acquire)); + LOG_DEBUG("Error state:"); + LOG_DEBUG(" orch_error_code: %d", h->orch_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_bitmap: 0x%x", h->sched_error_bitmap.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_code: %d", h->sched_error_code.load(std::memory_order_relaxed)); + LOG_DEBUG(" sched_error_thread: %d", h->sched_error_thread.load(std::memory_order_relaxed)); + LOG_DEBUG("================================"); } bool PTO2SharedMemoryHandle::validate() { diff --git a/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp b/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp index 3854099d0e..3cfa357a49 100644 --- a/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp +++ b/src/a5/runtime/tensormap_and_ringbuffer/runtime/shared/pto_tensormap.cpp @@ -227,20 +227,20 @@ void PTO2TensorMap::print_stats() { } } - LOG_INFO_V0("=== TensorMap Statistics ==="); - LOG_INFO_V0("Pool size: %d", pool_size); - LOG_INFO_V0("Pool next entry idx: %d", next_entry_idx); - LOG_INFO_V0("Pool free_num: %d", free_num); - LOG_INFO_V0("Num buckets: %d", num_buckets); - LOG_INFO_V0("Valid entries: %d", valid); - LOG_INFO_V0("Stale entries: %d", stale); - LOG_INFO_V0("Empty buckets: %d", empty_buckets); - LOG_INFO_V0("Max chain len: %d", max_chain); - LOG_INFO_V0("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); + LOG_DEBUG("=== TensorMap Statistics ==="); + LOG_DEBUG("Pool size: %d", pool_size); + LOG_DEBUG("Pool next entry idx: %d", next_entry_idx); + LOG_DEBUG("Pool free_num: %d", free_num); + LOG_DEBUG("Num buckets: %d", num_buckets); + LOG_DEBUG("Valid entries: %d", valid); + LOG_DEBUG("Stale entries: %d", stale); + LOG_DEBUG("Empty buckets: %d", empty_buckets); + LOG_DEBUG("Max chain len: %d", max_chain); + LOG_DEBUG("Avg chain len: %.2f", non_empty_buckets > 0 ? (float)total_chain / non_empty_buckets : 0); for (int r = 0; r < PTO2_MAX_RING_DEPTH; r++) { - LOG_INFO_V0("Last task alive[%d]: %d", r, last_task_alives[r]); + LOG_DEBUG("Last task alive[%d]: %d", r, last_task_alives[r]); } - LOG_INFO_V0("============================"); + LOG_DEBUG("============================"); } int32_t PTO2TensorMap::valid_count() { diff --git a/src/common/platform/onboard/host/device_runner_base.cpp b/src/common/platform/onboard/host/device_runner_base.cpp index dc89003253..89d4a16609 100644 --- a/src/common/platform/onboard/host/device_runner_base.cpp +++ b/src/common/platform/onboard/host/device_runner_base.cpp @@ -1254,7 +1254,6 @@ int DeviceRunnerBase::prepare_runtime_for_launch(Runtime &runtime, int block_dim // a CoreCallable device address; the binary code address is one // compile-time offset further in. The dispatch path then reads // resolved_addr_ from the on-device CoreCallable header. - LOG_DEBUG("Setting function_bin_addr for Tasks"); for (int i = 0; i < runtime.get_task_count(); i++) { Task *task = runtime.get_task(i); if (task != nullptr) { @@ -1263,7 +1262,6 @@ int DeviceRunnerBase::prepare_runtime_for_launch(Runtime &runtime, int block_dim LOG_DEBUG("Task %d (func_id=%d) -> function_bin_addr=0x%lx", i, task->func_id, task->function_bin_addr); } } - LOG_DEBUG(""); return 0; }