basic test timing + scope tracing ccip

driver/tests/basic/basic.cpp

@@ -2,6 +2,7 @@
 #include <unistd.h>
 #include <string.h>
 #include <vortex.h>
+#include <chrono>
 #include "common.h"
 
 #define RT_CHECK(_expr)                                         \
@@ -68,6 +69,9 @@ uint64_t shuffle(int i, uint64_t value) {
 
 int run_memcopy_test(uint32_t dev_addr, uint64_t value, int num_blocks) {
   int errors = 0;
+  
+  auto time_start = std::chrono::high_resolution_clock::now();
+
   int num_blocks_8 = (64 * num_blocks) / 8;
 
   // update source buffer
@@ -85,7 +89,9 @@ int run_memcopy_test(uint32_t dev_addr, uint64_t value, int num_blocks) {
   
   // write buffer to local memory
   std::cout << "write buffer to local memory" << std::endl;
+  auto t0 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_copy_to_dev(buffer, dev_addr, 64 * num_blocks, 0));
+  auto t1 = std::chrono::high_resolution_clock::now();
 
   // clear destination buffer
   for (int i = 0; i < num_blocks_8; ++i) {
@@ -94,7 +100,9 @@ int run_memcopy_test(uint32_t dev_addr, uint64_t value, int num_blocks) {
 
   // read buffer from local memory
   std::cout << "read buffer from local memory" << std::endl;
+  auto t2 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_copy_from_dev(buffer, dev_addr, 64 * num_blocks, 0));
+  auto t3 = std::chrono::high_resolution_clock::now();
 
   // verify result
   std::cout << "verify result" << std::endl;
@@ -114,6 +122,16 @@ int run_memcopy_test(uint32_t dev_addr, uint64_t value, int num_blocks) {
     return 1;
   }
 
+  auto time_end = std::chrono::high_resolution_clock::now();
+
+  double elapsed;
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count();  
+  printf("upload time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t3 - t2).count();  
+  printf("download time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(time_end - time_start).count();  
+  printf("Total elapsed time: %lg ms\n", elapsed);
+
   return 0;
 }
 
@@ -121,6 +139,8 @@ int run_kernel_test(const kernel_arg_t& kernel_arg,
                     uint32_t buf_size, 
                     uint32_t num_points) {
   int errors = 0; 
+
+  auto time_start = std::chrono::high_resolution_clock::now();
   
   // update source buffer
   {
@@ -130,7 +150,9 @@ int run_kernel_test(const kernel_arg_t& kernel_arg,
     }
   }
   std::cout << "upload source buffer" << std::endl;
+  auto t0 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_copy_to_dev(buffer, kernel_arg.src_ptr, buf_size, 0));
+  auto t1 = std::chrono::high_resolution_clock::now();
 
   // clear destination buffer
   {
@@ -143,21 +165,25 @@ int run_kernel_test(const kernel_arg_t& kernel_arg,
   RT_CHECK(vx_copy_to_dev(buffer, kernel_arg.dst_ptr, buf_size, 0));
 
   // start device
-  std::cout << "start device" << std::endl;
+  std::cout << "start execution" << std::endl;
+  auto t2 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_start(device));
-
-  // wait for completion
-  std::cout << "wait for completion" << std::endl;
   RT_CHECK(vx_ready_wait(device, -1));
+  auto t3 = std::chrono::high_resolution_clock::now();
 
   // flush the caches
   std::cout << "flush the caches" << std::endl;
+  auto t4 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_flush_caches(device, kernel_arg.dst_ptr, buf_size));
+  auto t5 = std::chrono::high_resolution_clock::now();
 
   // read buffer from local memory
   std::cout << "read buffer from local memory" << std::endl;
+  auto t6 = std::chrono::high_resolution_clock::now();
   RT_CHECK(vx_copy_from_dev(buffer, kernel_arg.dst_ptr, buf_size, 0));
+  auto t7 = std::chrono::high_resolution_clock::now();
 
+  
   // verify result
   std::cout << "verify result" << std::endl;
   for (uint32_t i = 0; i < num_points; ++i) {
@@ -176,6 +202,20 @@ int run_kernel_test(const kernel_arg_t& kernel_arg,
     return 1;
   }
 
+  auto time_end = std::chrono::high_resolution_clock::now();
+
+  double elapsed;
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count();  
+  printf("upload time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t3 - t2).count();  
+  printf("execute time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t5 - t4).count();  
+  printf("flush time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t7 - t6).count();  
+  printf("download time: %lg ms\n", elapsed);
+  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(time_end - time_start).count();  
+  printf("Total elapsed time: %lg ms\n", elapsed);
+
   return 0;
 }
 
@@ -196,7 +236,7 @@ int main(int argc, char *argv[]) {
   
   unsigned max_cores;
   RT_CHECK(vx_dev_caps(device, VX_CAPS_MAX_CORES, &max_cores));
-  uint32_t num_points = max_cores * count;
+  uint32_t num_points = 1 * count;
   uint32_t num_blocks = (num_points * sizeof(uint32_t) + 63) / 64;
   uint32_t buf_size = num_blocks * 64;
 
@@ -222,9 +262,7 @@ int main(int argc, char *argv[]) {
   // run tests  
   if (0 == test || -1 == test) {
     std::cout << "run memcopy test" << std::endl;
-    RT_CHECK(run_memcopy_test(kernel_arg.src_ptr, 0x0badf00d00ff00ff, 1));
-    if (num_blocks >= 4) RT_CHECK(run_memcopy_test(kernel_arg.src_ptr, 0x0badf00d00ff00ff, num_blocks/2));
-    if (num_blocks >= 2) RT_CHECK(run_memcopy_test(kernel_arg.src_ptr, 0x0badf00d40ff40ff, num_blocks));
+    RT_CHECK(run_memcopy_test(kernel_arg.src_ptr, 0x0badf00d40ff40ff, num_blocks));
   }
 
   if (1 == test || -1 == test) {
@@ -251,4 +289,4 @@ int main(int argc, char *argv[]) {
   std::cout << "Test PASSED" << std::endl;  
   
   return 0;
-}
+}