[TOGSim] Fix DMA stat logging and unify stat formatting

Author: YWHyuk

README.md

@@ -154,14 +154,14 @@ Log contains memory & core stats.
 [info] HBM2-CH_0: avg BW utilization 37% (255 reads, 128 writes)
 [info] Row hits: 359, Row misses: 26, Row conflicts: 0
 [info] ========= Core stat =========
-[info] Core [0] : Systolic array [0] Utilization(%) 0.00, active cycle 0, idle cycle 1014
-[info] Core [0] : Systolic array [1] Utilization(%) 12.62, active cycle 128, idle cycle 886
-[info] Core [0] : DMA active cycle 3 DMA idle cycle 1011 DRAM BW 182.000 GB/s (6144)
-[info] Core [0] : Vector Unit Utilization(%) 4.34, active cycle 44, idle_cycle 0
-[info] Core [0] : NUMA local access count : 0, NUMA remote access count : 0
-[info] Core [0] : Total cycle 1014
-[info] Total execution cycle: 1014
-[info] Simulation wall clock time: 0.039296 seconds
+[info] Core [0] : Systolic array [0] Utilization(%) 0.00, active_cycles 0, idle_cycles 1014
+[info] Core [0] : Systolic array [1] Utilization(%) 12.62, active_cycles 128, idle_cycles 886
+[info] Core [0] : DMA active_cycles 3 DMA idle_cycles 1011 DRAM BW 182.000 GB/s (6144)
+[info] Core [0] : Vector Unit Utilization(%) 4.34, active_cycles 44, idle_cycle 0
+[info] Core [0] : NUMA local memory: 34 requests, remote memory: 0 requests
+[info] Core [0] : Total_cycles 1014
+[info] Total execution cycles: 1014
+[info] Wall-clock time for simulation: 0.039296 seconds
 ```
 The log is dumped in `TORCHSIM_DUMP_PATH` and you can set the path as below.
 ```bash

Simulator/simulator.py

@@ -443,12 +443,12 @@ def get_result_from_file(result_path):
             if 'DRAM: AVG BW Util' in line:
                 avg_dram_bw = float(re.search(r'AVG BW Util (\d+\.?\d*)%', line).group(1))
 
-            if 'Total execution cycle' in line:
-                total_cycle = int(re.search(r'Total execution cycle: (\d+)', line).group(1))
+            if 'Total execution cycles' in line:
+                total_cycle = int(re.search(r'Total execution cycles: (\d+)', line).group(1))
 
             # Parse total simulation time
-            if 'Simulation wall clock time' in line:
-                simulation_time = float(re.search(r'Simulation wall clock time: (\d+\.?\d*) seconds', line).group(1))
+            if 'Wall-clock time for simulation' in line:
+                simulation_time = float(re.search(r'Wall-clock time for simulation: (\d+\.?\d*) seconds', line).group(1))
         return core_metrics, dram_channel_bw, avg_dram_bw, simulation_time, total_cycle
 
 if __name__ == "__main__":

TOGSim/include/Core.h

@@ -28,8 +28,8 @@ class Core {
   virtual mem_fetch* top_memory_request() { return _request_queue.front(); }
   virtual void push_memory_response(mem_fetch* response);
   void check_tag() { _dma.check_table(); }
-  void inc_numa_hit() { _stat_numa_hit++; }
-  void inc_numa_miss() { _stat_numa_miss++; }
+  void inc_numa_local_access() { _stat_numa_local_access++; }
+  void inc_numa_remote_access() { _stat_numa_remote_access++; }
 
   std::queue<std::shared_ptr<Instruction>>& get_compute_pipeline(int compute_type);
   enum {
@@ -69,8 +69,8 @@ class Core {
   uint64_t _stat_tot_mem_response = 0;
   uint64_t _stat_gemm_inst = 0;
   uint64_t _stat_skip_dma = 0;
-  uint64_t _stat_numa_hit = 0;
-  uint64_t _stat_numa_miss = 0;
+  uint64_t _stat_numa_local_access = 0;
+  uint64_t _stat_numa_remote_access = 0;
 
   cycle_type _stat_vu_compute_cycle = 0;
   std::vector<cycle_type> _stat_sa_compute_cycle;

TOGSim/include/DMA.h

@@ -3,6 +3,7 @@
 
 #include <cstdint>
 #include <memory>
+#include <queue>
 #include <map>
 #include <vector>
 #include "Instruction.h"
@@ -114,7 +115,7 @@ class DMA {
   }
 
   std::shared_ptr<Instruction>& get_current_inst() { return _current_inst; }
-  std::shared_ptr<std::vector<mem_fetch*>> get_memory_access(cycle_type core_cycle);
+  std::shared_ptr<std::vector<mem_fetch*>> get_memory_access(cycle_type core_cycle, int nr_req);
   uint32_t generate_mem_access_id();
   const uint32_t get_max_dim() { return _max_dim; }
 
@@ -130,5 +131,7 @@ class DMA {
   bool _finished=true;
   std::map<int, std::map<std::vector<int>, uint32_t>> tag_table;
   std::map<int, std::map<std::vector<int>, std::vector<std::shared_ptr<Instruction>>>> waiters;
+  std::queue<mem_fetch*> _pending_accesses;
+  bool _generated_once = false;
 };
 #endif

TOGSim/include/SimulationConfig.h

@@ -27,6 +27,7 @@ struct SimulationConfig {
   /* DRAM config */
   DramType dram_type;
   uint32_t dram_num_partitions = 1;
+  uint32_t dram_channels_per_partitions = 0;
   uint32_t dram_freq_mhz;
   uint32_t dram_channels;
   uint32_t dram_req_size;

TOGSim/src/Common.cc

@@ -74,8 +74,15 @@ SimulationConfig initialize_config(json config) {
     parsed_config.dram_print_interval = config["dram_stats_print_period_cycles"];
   if(config.contains("dram_num_burst_length"))
     parsed_config.dram_nbl = config["dram_num_burst_length"];
-  if (config.contains("dram_num_partitions"))
+  if (config.contains("dram_num_partitions")) {
     parsed_config.dram_num_partitions = config["dram_num_partitions"];
+    if (parsed_config.dram_channels % parsed_config.dram_num_partitions != 0) {
+      throw std::runtime_error("[Config] DRAM channels must be divisible by dram_num_partitions");
+    }
+  }
+  parsed_config.dram_channels_per_partitions =
+    parsed_config.dram_channels / parsed_config.dram_num_partitions;
+
 
    /* L2D config */
   if (config.contains("l2d_type")) {

TOGSim/src/Core.cc

@@ -175,7 +175,7 @@ void Core::dma_cycle() {
     }
   }
   /* Generate memfetch */
-  auto access_vec = _dma.get_memory_access(_core_cycle);
+  auto access_vec = _dma.get_memory_access(_core_cycle, _config.icnt_injection_ports_per_core);
   for (auto access : *access_vec) {
     access->set_start_cycle(_core_cycle);
     _request_queue.push(access);
@@ -411,24 +411,43 @@ void Core::print_stats() {
   std::vector<float> sa_utilization;
   update_stats();
   spdlog::info("===== Instructions count =====");
-  for (int i=0; i < static_cast<size_t>(Opcode::COUNT); i++) {
-    if (i == static_cast<size_t>(Opcode::COMP))
-      spdlog::info("Core [{}] : {} inst count {} (GEMM: {}, Vector: {}), skipped inst count {}", _id, opcode_to_string(static_cast<Opcode>(i)), _stat_inst_count.at(i), _stat_gemm_inst, _stat_inst_count.at(i) - _stat_gemm_inst, _stat_tot_skipped_inst.at(i));
-    else
-      spdlog::info("Core [{}] : {} inst count {}, skipped inst count {}", _id, opcode_to_string(static_cast<Opcode>(i)), _stat_inst_count.at(i), _stat_tot_skipped_inst.at(i));
+  for (int i = 0; i < static_cast<size_t>(Opcode::COUNT); i++) {
+    auto opcode  = static_cast<Opcode>(i);
+    auto inst = _stat_inst_count.at(i);
+    auto skipped = _stat_tot_skipped_inst.at(i);
+    auto name = opcode_to_string(opcode);
+
+    if (opcode == Opcode::COMP) {
+      auto gemm   = _stat_gemm_inst;
+      auto vector = inst - gemm;
+      if (skipped)
+        spdlog::info("Core [{}] : {:8} inst_count {} (GEMM: {}, Vector: {}), skipped inst_count {}",
+            _id, name, inst, gemm, vector, skipped);
+      else
+        spdlog::info("Core [{}] : {:8} inst_count {} (GEMM: {}, Vector: {})",
+            _id, name, inst, gemm, vector);
+    }
+    else {
+      if (skipped)
+        spdlog::info("Core [{}] : {:8} inst_count {}, skipped inst_count {}",
+            _id, name, inst, skipped);
+      else
+        spdlog::info("Core [{}] : {:8} inst_count {}",
+            _id, name, inst);
+    }
   }
   spdlog::info("========= Core stat =========");
   for (int i=0; i<_num_systolic_array_per_core; i++)
     sa_utilization.push_back(static_cast<float>(_stat_tot_sa_compute_cycle.at(i) * 100) / _core_cycle);
   for (int i=0; i<_num_systolic_array_per_core; i++)
-    spdlog::info("Core [{}] : Systolic array [{}] Utilization(%) {:.2f}, active cycle {}, idle cycle {}", _id, i, sa_utilization.at(i),
+    spdlog::info("Core [{}] : Systolic array [{}] utilization(%) {:.2f}, active_cycles {}, idle_cycles {}", _id, i, sa_utilization.at(i),
       _stat_tot_sa_compute_cycle.at(i), _stat_tot_sa_compute_idle_cycle.at(i));
   float dram_bw = _config.dram_req_size * _stat_tot_mem_response * _config.core_freq_mhz / (_core_cycle * 1000); // B/cycle
-  spdlog::info("Core [{}] : DMA active cycle {} DMA idle cycle {} DRAM BW {:.3f} GB/s ({})", _id, _stat_tot_dma_cycle, _stat_tot_dma_idle_cycle, dram_bw, _stat_tot_mem_response);
-  spdlog::info("Core [{}] : Vector Unit utilization(%) {:.2f}, active cycle {}, idle_cycle {}", _id,
+  spdlog::info("Core [{}] : DMA active_cycles, {} DMA idle_cycles {}, DRAM BW {:.3f} GB/s ({} responses)", _id, _stat_tot_dma_cycle, _stat_tot_dma_idle_cycle, dram_bw, _stat_tot_mem_response);
+  spdlog::info("Core [{}] : Vector unit utilization(%) {:.2f}, active cycle {}, idle_cycle {}", _id,
     static_cast<float>(_stat_tot_vu_compute_cycle * 100) / _core_cycle, _stat_tot_vu_compute_cycle, _stat_tot_vu_compute_idle_cycle);
-  spdlog::info("Core [{}] : NUMA local access count : {}, NUMA remote access count : {}", _id, _stat_numa_hit, _stat_numa_miss);
-  spdlog::info("Core [{}] : Total cycle {}", _id, _core_cycle);
+  spdlog::info("Core [{}] : NUMA local memory: {} requests, remote memory: {} requests", _id, _stat_numa_local_access, _stat_numa_remote_access);
+  spdlog::info("Core [{}] : Total_cycles {}", _id, _core_cycle);
 }
 
 void Core::print_current_stats() {
@@ -442,12 +461,12 @@ void Core::print_current_stats() {
 
   spdlog::info("========= Core stat =========");
   for (int i=0; i<_num_systolic_array_per_core; i++)
-    spdlog::info("Core [{}] : Systolic array [{}] Utilization(%) {:.2f}, active cycle {}, idle cycle {}", _id, i, sa_utilization.at(i),
+    spdlog::info("Core [{}] : Systolic array [{}] utilization(%) {:.2f}, active_cycles {}, idle_cycles {}", _id, i, sa_utilization.at(i),
       _stat_sa_compute_cycle.at(i), _stat_sa_compute_idle_cycle.at(i));
-  spdlog::info("Core [{}] : DMA active cycle {} DMA idle cycle {} DRAM BW {:.3f} GB/s ({})", _id, _stat_dma_cycle, _stat_dma_idle_cycle, dram_bw, _stat_mem_response);
-  spdlog::info("Core [{}] : Vector Unit Utilization(%) {:.2f}, active cycle {}, idle_cycle {}", _id,
+  spdlog::info("Core [{}] : DMA active_cycles {}, DMA idle_cycles {}, DRAM BW {:.3f} GB/s ({} responses)", _id, _stat_dma_cycle, _stat_dma_idle_cycle, dram_bw, _stat_mem_response);
+  spdlog::info("Core [{}] : Vector unit Utilization(%) {:.2f}, active_cycles {}, idle_cycles {}", _id,
     static_cast<float>(_stat_vu_compute_cycle * 100) / _config.core_print_interval, _stat_vu_compute_cycle, _stat_vu_compute_idle_cycle);
-  spdlog::info("Core [{}] : Total cycle {}", _id, _core_cycle);
+  spdlog::info("Core [{}] : Total_cycles {}", _id, _core_cycle);
   update_stats();
 }
 

TOGSim/src/DMA.cc

@@ -18,27 +18,62 @@ void DMA::issue_tile(std::shared_ptr<Instruction> inst) {
   _finished = false;
 }
 
-std::shared_ptr<std::vector<mem_fetch*>> DMA::get_memory_access(cycle_type core_cycle) {
-  auto addr_set = _current_inst->get_dram_address(_dram_req_size);
+std::shared_ptr<std::vector<mem_fetch*>> DMA::get_memory_access(cycle_type core_cycle, int nr_req) {
+
+  if (!_generated_once) {
+    std::shared_ptr<std::set<addr_type>> addr_set =
+      _current_inst->get_dram_address(_dram_req_size);
+
+    Tile* owner = (Tile*)_current_inst->get_owner();
+    std::shared_ptr<TileSubGraph> owner_subgraph = owner->get_owner();
+    unsigned long long base_daddr = _current_inst->get_base_dram_address();
+
+    bool is_cacheable =
+      owner_subgraph->is_cacheable(base_daddr, base_daddr + _dram_req_size);
+
+    spdlog::trace("[{}][Core {}][SRAM] Address: 0x{:016x}, Is_cacheable: {}",
+                    core_cycle, _id, base_daddr, is_cacheable);
+    spdlog::trace("[{}][Core {}][NUMA] Subgraph id: {} , Numa id: {}, Arg: {} is_write: {}",
+                    core_cycle, _id, owner_subgraph->get_core_id(),
+                    _current_inst->get_numa_id(), _current_inst->get_addr_name(),
+                    _current_inst->is_dma_write());
+    for (const auto& addr : *addr_set) {
+      mem_access_type acc_type =
+        _current_inst->is_dma_write() ? mem_access_type::GLOBAL_ACC_W
+                                          : mem_access_type::GLOBAL_ACC_R;
+      mf_type type =
+        _current_inst->is_dma_write() ? mf_type::WRITE_REQUEST
+                                          : mf_type::READ_REQUEST;
+
+      mem_fetch* access = new mem_fetch(
+          addr, acc_type, type, _dram_req_size,
+          _current_inst->get_numa_id(),
+          static_cast<void*>(_current_inst.get()));
+
+      access->set_cacheable(is_cacheable);
+      _current_inst->inc_waiting_request();
+      _pending_accesses.push(access);
+    }
+    _generated_once = true;
+  }
+
+  if (nr_req == -1)
+    nr_req = _pending_accesses.size();
+
+  // Return pending accesses up to nr_req
   auto access_vec = std::make_shared<std::vector<mem_fetch *>>();
-  Tile* owner = (Tile*)_current_inst->get_owner();
-  std::shared_ptr<TileSubGraph> owner_subgraph = owner->get_owner();
-  unsigned long long base_daddr = _current_inst->get_base_dram_address();
-  // Todo. We use a ternsor level buffer allocation, so we don't need to check all memfetch
-  bool is_cacheable = owner_subgraph->is_cacheable(base_daddr, base_daddr + _dram_req_size);
-  spdlog::trace("[{}][Core {}][SRAM] Address: 0x{:016x}, Is_cacheable: {}", core_cycle, _id, base_daddr, is_cacheable);
-  spdlog::trace("[{}][Core {}][NUMA] Subgraph id: {} , Numa id: {}, Arg: {} is_write: {}",
-    core_cycle, _id, owner_subgraph->get_core_id(), _current_inst->get_numa_id(), _current_inst->get_addr_name(), _current_inst->is_dma_write());
-
-  for (auto addr: *addr_set) {
-    mem_access_type acc_type = _current_inst->is_dma_write() ? mem_access_type::GLOBAL_ACC_W : mem_access_type::GLOBAL_ACC_R;
-    mf_type type = _current_inst->is_dma_write() ? mf_type::WRITE_REQUEST : mf_type::READ_REQUEST;
-    mem_fetch* access = new mem_fetch(addr, acc_type, type, _dram_req_size, _current_inst->get_numa_id(), static_cast<void*>(_current_inst.get()));
-    access->set_cacheable(is_cacheable);
-    _current_inst->inc_waiting_request();
-    access_vec->push_back(access);
+  for (int i = 0; i < nr_req; i++) {
+      if (_pending_accesses.empty())
+        break;
+      access_vec->push_back(_pending_accesses.front());
+      _pending_accesses.pop();
   }
-  _finished = true;
+
+  if (_pending_accesses.empty()) {
+    _finished = true;
+    _generated_once = false;
+  }
+
   return access_vec;
 }
 

TOGSim/src/Dram.cc

@@ -17,7 +17,7 @@ Dram::Dram(SimulationConfig config, cycle_type* core_cycle) {
   _n_bl = config.dram_nbl;
   _req_size = config.dram_req_size;
   _n_partitions = config.dram_num_partitions;
-  _n_ch_per_partition = _n_ch / _n_partitions;
+  _n_ch_per_partition = config.dram_channels_per_partitions;
   _config = config;
 
   spdlog::info("[Config/DRAM] DRAM Bandwidth {} GB/s, Freq: {} MHz, Channels: {}, Request_size: {}B", config.max_dram_bandwidth(), config.dram_freq_mhz, _n_ch, _req_size);

TOGSim/src/Simulator.cc

@@ -117,11 +117,11 @@ void Simulator::icnt_cycle() {
         mem_fetch *front = _cores[core_id]->top_memory_request();
         front->set_core_id(core_id);
         if (!_icnt->is_full(port_id, front)) {
-          //int node_id = _dram->get_channel_id(front) / 16;
-          //if (core_id == node_id)
-          //  _cores[core_id]->inc_numa_hit();
-          //else
-          //  _cores[core_id]->inc_numa_miss();
+          int node_id = _dram->get_channel_id(front) / _config.dram_channels_per_partitions;
+          if (core_id == node_id)
+            _cores[core_id]->inc_numa_local_access();
+          else
+            _cores[core_id]->inc_numa_remote_access();
           _icnt->push(port_id , get_dest_node(front), front);
           _cores[core_id]->pop_memory_request();
           _nr_from_core++;
@@ -291,5 +291,5 @@ void Simulator::print_core_stat()
   for (int core_id = 0; core_id < _n_cores; core_id++) {
     _cores[core_id]->print_stats();
   }
-  spdlog::info("Total execution cycle: {}", _core_cycles);
+  spdlog::info("Total execution cycles: {}", _core_cycles);
 }