log blocking timelines in npy files

scripts plotting figures
comments

.gitignore

@@ -34,3 +34,8 @@ experiments/slurm
 dist/net_rdma
 trace/process
 mk/local.mk
+
+.vscode
+*.log
+*.npy
+experiments/archived_logs
\ No newline at end of file

experiments/parse_timeline.py

+import sys
+import numpy as np
+import matplotlib.pyplot as plt
+
+
+def parse_timeline(file_name):
+    timeline = np.load(file_name)
+
+    # more to be added
+    plot_execution_ratio(timeline, file_name + '_ratio.png')
+
+
+def plot_execution_ratio(timeline, plot_name, num_intervals=100):
+    durations = timeline[1:] - timeline[:-1]
+    time_interval = (timeline[-1] - timeline[0]) / num_intervals
+    time_offset, flag = 0, -2
+    # span[0], span[1]: sum of idle time, sum of execution time
+    span, ratio_list = [0, 0], []
+    for duration in durations:
+        while time_offset + duration > time_interval:
+            remaining = time_interval - time_offset
+            span[flag] = span[flag] + remaining
+            duration = duration - remaining
+            time_offset = 0
+            ratio_list.append(span[1] / sum(span))
+            span = [0, 0]
+        else:
+            time_offset = time_offset + duration
+            span[flag] = span[flag] + duration
+            flag = ~flag
+    fig = plt.figure()
+    plt.plot(ratio_list)
+    plt.xlabel("time intervals")
+    plt.ylabel("ratio of execution (non-blocking)")
+    fig.savefig(plot_name)
+    return ratio_list
+
+
+if __name__ == "__main__":
+    if len(sys.argv) == 2:
+        parse_timeline(sys.argv[1])
+    else:
+        print("usage: python parse_timeline.py log_file")

lib/simbricks/nicbm/nicbm.cc

@@ -35,9 +35,8 @@
 #include <ctime>
 #include <iostream>
 
-#include <fstream>
-#include <iterator>
-#include <chrono>
+#include <unistd.h>
+#include <simbricks/proto/npy.hpp>
 
 extern "C" {
 #include <simbricks/proto/base.h>
@@ -328,11 +327,6 @@ void Runner::EthSend(const void *data, size_t len) {
 
 int64_t rdtsc_cycle() { return __builtin_ia32_rdtsc(); }
 
-int64_t get_time() {
-  using namespace std::chrono;
-  return duration_cast<microseconds>(steady_clock::now().time_since_epoch()).count();
-}
-
 void Runner::PollH2D(std::vector<int64_t> *block_logging) {
   volatile union SimbricksProtoPcieH2D *msg =
       SimbricksNicIfH2DPoll(&nsparams_, main_time);
@@ -551,6 +545,8 @@ int Runner::RunMain(int argc, char *argv[]) {
 
   bool is_sync = nsparams_.sync_pci || nsparams_.sync_eth;
 
+  // to reduce the overhead, replace '*_block_logging' with statically allocated memory and
+  // employ another thread to log data into disks
   std::vector<int64_t> host_block_logging = {rdtsc_cycle()};
   std::vector<int64_t> net_block_logging = {rdtsc_cycle()};
 
@@ -621,19 +617,15 @@ int Runner::RunMain(int argc, char *argv[]) {
       (double)(s_h2d_poll_sync + s_n2d_poll_sync) / (s_h2d_poll_suc + s_n2d_poll_suc));
 #endif
 
-  std::clock_t total = std::clock();
-
-  std::string file_name = std::string(nsparams_.pci_socket_path) + std::string("_nicbm_host_block_logging.txt");
-  std::ofstream output_file(file_name);
-  output_file << "CLOCKS_PER_SEC: " << CLOCKS_PER_SEC << '\n';
-  output_file << "Total clocks: " << total << '\n';
-  std::copy(host_block_logging.begin(), host_block_logging.end(), std::ostream_iterator<int64_t>(output_file, "\n"));
+  std::string pid = std::to_string(getpid());
+  std::string file_name = std::string(nsparams_.pci_socket_path) + pid + std::string("_nicbm_host_block_logging.npy");
+  long unsigned npy_shape[1] = {host_block_logging.size()};
+  npy::SaveArrayAsNumpy(file_name, false, 1, npy_shape, host_block_logging);
 
-  file_name = std::string(nsparams_.pci_socket_path) + std::string("_nicbm_net_block_logging.txt");
+  file_name = std::string(nsparams_.pci_socket_path) + pid + std::string("_nicbm_net_block_logging.npy");
+  npy_shape[0] = net_block_logging.size();
   std::ofstream output_file1(file_name);
-  output_file1 << "CLOCKS_PER_SEC: " << CLOCKS_PER_SEC << '\n';
-  output_file1 << "Total clocks: " << total << '\n';
-  std::copy(net_block_logging.begin(), net_block_logging.end(), std::ostream_iterator<int64_t>(output_file1, "\n"));
+  npy::SaveArrayAsNumpy(file_name, false, 1, npy_shape, net_block_logging);
 
   SimbricksNicIfCleanup();
   return 0;

gem5 @ 4678052b

-Subproject commit 2a38119e6a46e871bb540f51557c3c72edc5a253
+Subproject commit 4678052bc56b5b85fd4f8da4ced48323eff7e4f9

sims/net/switch/net_switch.cc

@@ -37,9 +37,8 @@
 #include <unordered_map>
 #include <vector>
 
-#include <ctime>
-#include <fstream>
-#include <iterator>
+#include <unistd.h>
+#include <simbricks/proto/npy.hpp>
 
 extern "C" {
 #include <simbricks/netif/netif.h>
@@ -339,6 +338,8 @@ int main(int argc, char *argv[]) {
 
 
   printf("start polling\n");
+  // to reduce the overhead, replace 'block_logging' with statically allocated memory and
+  // employ another thread to log data into disks
   std::vector<int64_t> block_logging = {rdtsc_cycle()};
   while (!exiting) {
     // Sync all interfaces
@@ -385,10 +386,10 @@ int main(int argc, char *argv[]) {
           s_d2n_poll_sync, (double)s_d2n_poll_sync / s_d2n_poll_suc);
 #endif
 
-  std::ofstream output_file("./net_switch_block_logging.txt");
-  output_file << "CLOCKS_PER_SEC: " << CLOCKS_PER_SEC << '\n';
-  output_file << "Total clocks: " << std::clock() << '\n';
-  std::copy(block_logging.begin(), block_logging.end(), std::ostream_iterator<int64_t>(output_file, "\n"));
+  std::string pid = std::to_string(getpid());
+  std::string file_name = std::string("net_switch_block_logging_") + pid + std::string(".npy");
+  const long unsigned npy_shape[1] = {block_logging.size()};
+  npy::SaveArrayAsNumpy(file_name, false, 1, npy_shape, block_logging);
 
   return 0;
 }