added printf early flushing

Author: zibai.wang

include/acl_types.h

@@ -922,7 +922,10 @@ typedef struct _cl_kernel {
   // Eventually this should be an array of ACLDeviceBinaries similar
   // to how cl_program contains an array of dev_prog.
   const acl_device_binary_t *dev_bin;
-  size_t processed_buffer_size;
+
+  // In ACL_HAL_DEBUG mode, printf buffer could be dumped before Kernel ends
+  // Therefore, we need to keep track of how much data has been processed.
+  size_t processed_printf_buffer_size;
 } _cl_kernel;
 
 ACL_DECLARE_CL_OBJECT_ALLOC_FUNCTIONS(cl_kernel);
@@ -1347,7 +1350,10 @@ typedef struct {
   // it sees the CL_COMPLETE status for the first time, but it won't
   // change after that.
   cl_uint num_printf_bytes_pending;
-  int debug_dump = 0; // TODO, initialize to 0, somewhere
+
+  // Indicate whether this operation is dumping printf buffer before the Kernel
+  // for debug purpose
+  int debug_dump_printf = 0;
 } acl_device_op_info_t;
 
 // An operation to be performed on a device.

src/acl_hal_mmd.cpp

@@ -919,7 +919,6 @@ void acl_hal_mmd_get_device_status(cl_uint num_devices,
     assert(devices[idevice]->opened_count > 0);
 
     physical_device_id = devices[idevice]->def.physical_device_id;
-    printf("Zibai Added, going to check kernel status! \n");
     acl_kernel_if_check_kernel_status(&kern[physical_device_id]);
   }
 }

src/acl_kernel.cpp

@@ -2420,7 +2420,7 @@ static int l_init_kernel(cl_kernel kernel, cl_program program,
   kernel->printf_device_buffer = 0; // Default is none.
   kernel->printf_device_ptr = 0;    // Default is none.
   // Zibai Testing
-  kernel->processed_buffer_size = 0;
+  kernel->processed_printf_buffer_size = 0;
   if (!accel_def->printf_format_info.empty()) {
     auto gmem_idx = static_cast<size_t>(
         acl_get_default_memory(kernel->dev_bin->get_devdef()));

src/acl_kernel_if.cpp

@@ -1369,7 +1369,7 @@ void acl_kernel_if_update_status(acl_kernel_if *kern) {
                                 ":: Calling acl_process_printf_buffer_fn with "
                                 "activation_id=%d and printf_size=%u.\n",
                                 activation_id, printf_size);
-        // update status, which will dump the printf buffer, set debug_dump = 0
+        // update status, which will dump the printf buffer, set debug_dump_printf = 0
         acl_process_printf_buffer_fn(activation_id, (int)printf_size, 0);
 
         ACL_KERNEL_IF_DEBUG_MSG(
@@ -1378,7 +1378,6 @@ void acl_kernel_if_update_status(acl_kernel_if *kern) {
 
         acl_kernel_cra_write(kern, k, KERNEL_OFFSET_CSR, new_csr);
         continue;
-        // ZIBAI TODO FIGURE OUT: Why Doesn't printf buffer need to be cleared, after this? Probably Handled outside of runtime?
       }
     }
 
@@ -1433,7 +1432,6 @@ void acl_kernel_if_update_status(acl_kernel_if *kern) {
       kern->accel_job_ids[k][next_queue_back] = -1;
 
 #ifdef TEST_PROFILING_HARDWARE
-      // ZIBAI TODO: What is this doing?
       // Test readback of fake profile data using the acl_hal_mmd function that
       // would be called from the acl runtime.
       ACL_KERNEL_IF_DEBUG_MSG(
@@ -1496,12 +1494,41 @@ void acl_kernel_if_update_status(acl_kernel_if *kern) {
   }
 }
 
+void acl_kernel_if_debug_dump_printf(acl_kernel_if *kern, unsigned k){
+  acl_assert_locked();
+  unsigned int printf_size = 0; // Do I have to initialize it to 0?
+  int activation_id;
+  unsigned int next_queue_back;
+
+  if (kern->accel_queue_back[k] == (int)kern->accel_invoc_queue_depth[k] - 1)
+    next_queue_back = 0;
+  else
+    next_queue_back = kern->accel_queue_back[k] + 1;
+
+  if (kern->accel_num_printfs[k] > 0) {
+    acl_kernel_cra_read(kern, k, KERNEL_OFFSET_PRINTF_BUFFER_SIZE,
+                        &printf_size);
+    assert(printf_size <= ACL_PRINTF_BUFFER_TOTAL_SIZE);
+    ACL_KERNEL_IF_DEBUG_MSG(kern,
+                            ":: Accelerator %d printf buffer size is %d.\n",
+                            k, printf_size);
+    activation_id = kern->accel_job_ids[k][next_queue_back];
+    ACL_KERNEL_IF_DEBUG_MSG(kern,
+                      ":: Calling acl_process_printf_buffer_fn with "
+                      "activation_id=%d and printf_size=%u.\n",
+                      activation_id, printf_size);
+
+    // set debug_dump_printf to 1
+    acl_process_printf_buffer_fn(activation_id, (int)printf_size, 1);
+  }
+  
+}
+
 void acl_kernel_if_dump_status(acl_kernel_if *kern) {
   int expect_kernel = 0;
   unsigned k, i;
   acl_assert_locked();
 
-  kern->io.printf(" Zibai Added, kernel may be hung?\n");
   for (k = 0; k < kern->num_accel; ++k) {
     for (i = 0; i < kern->accel_invoc_queue_depth[k]; ++i) {
       if (kern->accel_job_ids[k][i] >= 0) {
@@ -1513,10 +1540,6 @@ void acl_kernel_if_dump_status(acl_kernel_if *kern) {
   if (!expect_kernel)
     return;
 
-  kern->io.printf("No kernel updates in approximately 10 seconds for device %u",
-                  kern->physical_device_id);
-  kern->io.printf(" ... a kernel may be hung?\n");
-
   for (k = 0; k < kern->num_accel; ++k) {
     unsigned int csr;
 
@@ -1542,37 +1565,8 @@ void acl_kernel_if_dump_status(acl_kernel_if *kern) {
     if (ACL_KERNEL_READ_BIT(csr, KERNEL_CSR_LMEM_INVALID_BANK))
       kern->io.printf(" lm_bank_exception");
 
-    //Testing start Zibai
-    unsigned int printf_size = 0; // Do I have to initialize it to 0?
-    int activation_id;
-
-    int next_queue_back2;
-
-    if (kern->accel_queue_back[k] == (int)kern->accel_invoc_queue_depth[k] - 1)
-      next_queue_back2 = 0;
-    else
-      next_queue_back2 = kern->accel_queue_back[k] + 1;
-
-    if (kern->accel_num_printfs[k] > 0) {
-      acl_kernel_cra_read(kern, k, KERNEL_OFFSET_PRINTF_BUFFER_SIZE,
-                          &printf_size);
-      assert(printf_size <= ACL_PRINTF_BUFFER_TOTAL_SIZE);
-      ACL_KERNEL_IF_DEBUG_MSG(kern,
-                              ":: Accelerator %d printf buffer size is %d.\n",
-                              k, printf_size);
-      activation_id = kern->accel_job_ids[k][next_queue_back2];
-      ACL_KERNEL_IF_DEBUG_MSG(kern,
-                        ":: Calling acl_process_printf_buffer_fn with "
-                        "activation_id=%d and printf_size=%u.\n",
-                        activation_id, printf_size);
-
-      // set debug_dump to 1
-      acl_process_printf_buffer_fn(activation_id, (int)printf_size, 1);
-      //acl_process_printf_buffer_fn(activation_id, 64, 0);
-    }
-
-    //Testing end Zibai
-    // Zibai TODO: What is the below code this doing?
+    //Dump the printf buffer to stdout
+    acl_kernel_if_debug_dump_printf(kern, k);
 
     unsigned buffered_kernel_invocation = 0;
     for (i = 0; i < kern->accel_invoc_queue_depth[k]; ++i) {
@@ -1611,15 +1605,18 @@ void acl_kernel_if_check_kernel_status(acl_kernel_if *kern) {
 #endif
   acl_assert_locked();
 
-  // Print kernel status if it hasn't done anything in a while
-  // If multiple thread calls this, only one will print every 10 seconds
-  kern->io.printf("Zibai Added, Are we calling acl_kernel_if_dump_status? \n");
   if (kern->last_kern_update != 0 &&
-      (acl_kernel_if_get_time_us(kern) - kern->last_kern_update >
-       10 * 1000000)) {
-    kern->last_kern_update = acl_kernel_if_get_time_us(kern);
-    if (kern->io.debug_verbosity > 0)
-      kern->io.printf("Zibai Added, calling acl_kernel_if_dump_status! \n");
+        (acl_kernel_if_get_time_us(kern) - kern->last_kern_update >
+        10 * 1000000)) {
+      kern->last_kern_update = acl_kernel_if_get_time_us(kern);
+      kern->io.printf("No kernel updates in approximately 10 seconds for device %u",
+                kern->physical_device_id);
+      kern->io.printf(" ... a kernel may be hung?\n");
+      acl_kernel_if_dump_status(kern);
+  } else if (kern->io.debug_verbosity >= 3) {
+      // If ACL_HAL_DEBUG >= 3, the status will be printed even the server isn't hang.
+      // If there are spare cycles, it will be called at most every 5 seconds to dump the status and flush the printf buffer
+      // 5 seconds is configured in acl_thread->acl_wait_for_device_update()
       acl_kernel_if_dump_status(kern);
   }
 

src/acl_printf.cpp

@@ -770,29 +770,25 @@ static size_t l_dump_printf_buffer(cl_event event, cl_kernel kernel,
     hal_dma_fn = acl_get_hal()->copy_globalmem_to_hostmem;
   }
 
-  // void* b = (void*)((char*)kernel->printf_device_buffer->block_allocation->range.begin + kernel->processed_buffer_size);
-  // // hal_dma_fn(NULL, b, buffer, size - 64);
-
-  //hal_dma_fn(NULL, b, buffer, size - 64);
-  // test is giving segfault if I use size - 64, because test doesn't have that much data
-  // What if I don't use -64
-  printf("total size is %d \n", size);
-  printf("kernel prcessed buffer size is %d \n", kernel->processed_buffer_size);
-
-  void* unprocessed_begin = (void*)((char*)kernel->printf_device_buffer->block_allocation->range.begin + kernel->processed_buffer_size);
-  printf("Hang may begin here?? \n");
-  if (size > (unsigned int) kernel->processed_buffer_size){
-    printf("ZIBAI has something to print! \n");
-    hal_dma_fn(NULL, unprocessed_begin, buffer, size - kernel->processed_buffer_size);
-    dumped_buffer_size = size - kernel->processed_buffer_size;
+  // It needs the context from ACL_HAL_DEBUG instead of ACL_DEBUG
+  if (acl_get_hal()->get_debug_verbosity &&
+      acl_get_hal()->get_debug_verbosity() > 0) {
+    printf("Previously processed buffer size is %d \n", kernel->processed_printf_buffer_size);
+  }
+
+  // Check if we have already processed all the printf buffer
+  if (size > (unsigned int) kernel->processed_printf_buffer_size){
+    void* unprocessed_begin = (void*)((char*)kernel->printf_device_buffer->block_allocation->range.begin + kernel->processed_printf_buffer_size);
+    hal_dma_fn(NULL, unprocessed_begin, buffer, size - kernel->processed_printf_buffer_size);
+    dumped_buffer_size = size - kernel->processed_printf_buffer_size;
   } else{
-    printf("Zibai Added, nothing to print \n");
+      if (acl_get_hal()->get_debug_verbosity &&
+        acl_get_hal()->get_debug_verbosity() > 0) {
+      printf("All Printf() buffer has already been dumped \n");
+  }
     return dumped_buffer_size;
   }
 
-
-  //hal_dma_fn(NULL, kernel->printf_device_buffer->block_allocation->range.begin, buffer, size);
-
 #ifdef DEBUG
   if (debug_mode > 0) {
     printf("acl_dump_printf_buffer at %p size=%d\n", buffer, size);
@@ -987,7 +983,7 @@ static size_t l_dump_printf_buffer(cl_event event, cl_kernel kernel,
 //
 // Schedule enqueue read buffer to read printf buffer
 // The activation ID is the device op ID.
-void acl_schedule_printf_buffer_pickup(int activation_id, int size, int debug_dump) {
+void acl_schedule_printf_buffer_pickup(int activation_id, int size, int debug_dump_printf) {
   acl_device_op_queue_t *doq = &(acl_platform.device_op_queue);
 
   // This function can potentially be called by a HAL that does not use the
@@ -1010,10 +1006,11 @@ void acl_schedule_printf_buffer_pickup(int activation_id, int size, int debug_du
     acl_device_op_t *op = doq->op + activation_id;
     op->info.num_printf_bytes_pending = (cl_uint)size;
 
-    if (debug_dump == 1){
-      op->info.debug_dump = 1;
+    // Propagate the operation info
+    if (debug_dump_printf == 1){
+      op->info.debug_dump_printf = 1;
     }else {
-      op->info.debug_dump = 0;
+      op->info.debug_dump_printf = 0;
     }
   }
   // Signal all waiters.
@@ -1035,16 +1032,17 @@ void acl_process_printf_buffer(void *user_data, acl_device_op_t *op) {
     cl_uint num_bytes = op->info.num_printf_bytes_pending;
     size_t dumped_buffer_size = l_dump_printf_buffer(event, kernel, num_bytes);
 
+    if (op->info.debug_dump_printf == 1){
+      // Update the already processed buffer size
+      kernel->processed_printf_buffer_size += dumped_buffer_size;
+    } else{
+      // Full dump, reset this variable
+      kernel->processed_printf_buffer_size = 0;
+    }
+
     // Mark this printf work as done.  Must do this *before* unstalling
     // the kernel, to avoid a race against the kernel filling up the
     // buffer again.
-    // Zibai Testing
-    if (op->info.debug_dump == 1){
-      kernel->processed_buffer_size += dumped_buffer_size;
-    } else{
-      // Full dump, clear this global var
-      kernel->processed_buffer_size = 0;
-    }
     op->info.num_printf_bytes_pending = 0;
 
     // Ensure kernel IRQ doesn't race with us to update the
@@ -1053,7 +1051,7 @@ void acl_process_printf_buffer(void *user_data, acl_device_op_t *op) {
 
     // Allow the kernel to continue running.
     // We don't need to unstall the kernel during the early flushing during debug.
-    if (op->info.debug_dump == 0){
+    if (op->info.debug_dump_printf == 0){
       acl_get_hal()->unstall_kernel(
           event->cmd.info.ndrange_kernel.device->def.physical_device_id, op->id);
     }