Add the log entry report function, also add logs for 'File open','File close' and 'EOT processing time'

4 files changed, 84 insertions, 16 deletions

diff --git a/src/H5FDvfd_swmr_private.h b/src/H5FDvfd_swmr_private.h
index 56cb93e..6a35ec0 100644
--- a/src/H5FDvfd_swmr_private.h
+++ b/src/H5FDvfd_swmr_private.h
@@ -57,15 +57,6 @@ typedef struct eot_queue_entry {
     TAILQ_ENTRY(eot_queue_entry) link;
 } eot_queue_entry_t;
 
-#define TOTAL_TIME_PASSED(X, Y)                                                                              \
-    ((double)((Y.tv_sec - X.tv_sec) * 1000000000 + (Y.tv_nsec - X.tv_nsec))) / 1000000.0
-
-#define TIME_PASSED_MIN(X)        (unsigned int)(X / 60000)
-#define TIME_PASSED_SEC(X, Y)     (unsigned int)((X - Y * 60000) / 1000)
-#define TIME_PASSED_MSEC(X, Y, Z) (unsigned int)(X - Y * 60000 - Z * 1000)
-// H5_DLLVAR extern hbool_t vfd_swmr_log_on;
-// H5_DLLVAR extern FILE *vfd_swmr_log_file_ptr;
-
 H5_DLLVAR unsigned int vfd_swmr_api_entries_g;
 
 /* The head of the EOT queue */
@@ -93,4 +84,19 @@ H5_DLL herr_t H5F_vfd_swmr_insert_entry_eot(struct H5F_t *f);
 H5_DLL void   H5F_vfd_swmr_update_entry_eot(eot_queue_entry_t *);
 H5_DLL herr_t H5F_dump_eot_queue(void);
 
+
+/***************************************/
+/* Log Macros and Functions            */
+/***************************************/
+
+#define TOTAL_TIME_PASSED(X, Y)                                                                              \
+    ((double)((Y.tv_sec - X.tv_sec) * 1000000000 + (Y.tv_nsec - X.tv_nsec))) / 1000000.0
+#define TIME_PASSED_MIN(X)        (unsigned int)(X / 60000)
+#define TIME_PASSED_SEC(X, Y)     (unsigned int)((X - Y * 60000) / 1000)
+#define TIME_PASSED_MSEC(X, Y, Z) (unsigned int)(X - Y * 60000 - Z * 1000)
+
+/* Add more tags */
+static const char *H5Fvfd_swmr_log_tags[] = { "FILE_OPEN", "FILE_CLOSE", "EOT_TRIGGER_TIME",
+                                              "EOT_PROCESSING_TIME", "EOT_META_FILE_INDEX"};
+
 #endif /* H5FDvfd_swmr_private_H */
diff --git a/src/H5Fint.c b/src/H5Fint.c
index 4a88b8c..9d739b7 100644
--- a/src/H5Fint.c
+++ b/src/H5Fint.c
@@ -2014,7 +2014,18 @@ H5F_open(const char *name, unsigned flags, hid_t fcpl_id, hid_t fapl_id)
     /* Short cuts */
     shared = file->shared;
 #if 1 /* Kent*/
-    H5F_post_vfd_swrm_log_entry(file, 0, NULL);
+    if (vfd_swmr_config_ptr->version) {
+
+        if (HDstrlen(vfd_swmr_config_ptr->log_file_path) > 0)
+           shared->vfd_swmr_log_on = TRUE;
+        if (TRUE == shared->vfd_swmr_log_on) {
+            /* Create the log file */
+            if ((shared->vfd_swmr_log_file_ptr = HDfopen(vfd_swmr_config_ptr->log_file_path,"w"))==NULL)
+                HGOTO_ERROR(H5E_FILE, H5E_CANTOPENFILE, NULL, "unable to create the log file")
+            if(HDclock_gettime(CLOCK_MONOTONIC, &(shared->vfd_swmr_log_start_time))<0) 
+                HGOTO_ERROR(H5E_FILE, H5E_CANTGET, NULL, "can't get time via clock_gettime");
+        }
+    }
 #endif
     lf = shared->lf;
 
@@ -2224,6 +2235,9 @@ done:
         if (H5F__dest(file, FALSE) < 0)
             HDONE_ERROR(H5E_FILE, H5E_CANTCLOSEFILE, NULL, "problems closing file")
     }
+#if 1 /*KENT*/
+    H5F_post_vfd_swrm_log_entry(file, 0, "File open ends");
+#endif 
     if (vfd_swmr_config_ptr)
         H5MM_free(vfd_swmr_config_ptr);
 
diff --git a/src/H5Fpkg.h b/src/H5Fpkg.h
index ae9c037..3ab0cd3 100644
--- a/src/H5Fpkg.h
+++ b/src/H5Fpkg.h
@@ -469,9 +469,9 @@ struct H5F_shared_t {
                                  * manager
                                  */
 
-    int     vfd_swmr_log_fd;
-    hbool_t use_vfd_swmr_log;
-    double  vfd_swmr_log_time_elapsed;
+    FILE*     vfd_swmr_log_file_ptr;
+    hbool_t vfd_swmr_log_on;
+    struct timespec  vfd_swmr_log_start_time;
 
     /* Delayed free space release doubly linked list */
     shadow_defree_queue_t shadow_defrees;
@@ -612,5 +612,5 @@ H5_DLL htri_t H5F__same_file_test(hid_t file_id1, hid_t file_id2);
 H5_DLL herr_t H5F__reparse_file_lock_variable_test(void);
 #endif /* H5F_TESTING */
 
-H5_DLL void *H5F_post_vfd_swrm_log_entry(H5F_t *f, int entry_type_code, char *body);
+H5_DLL herr_t H5F_post_vfd_swrm_log_entry(H5F_t *f, int entry_type_code,  char *body);
 #endif /* H5Fpkg_H */
diff --git a/src/H5Fvfd_swmr.c b/src/H5Fvfd_swmr.c
index 5ef8260..b549eeb 100644
--- a/src/H5Fvfd_swmr.c
+++ b/src/H5Fvfd_swmr.c
@@ -157,7 +157,6 @@ H5F_vfd_swmr_init(H5F_t *f, hbool_t file_create)
         /* Create the metadata file */
         if (((shared->vfd_swmr_md_fd = HDopen(shared->vfd_swmr_config.md_file_path, O_CREAT | O_RDWR,
                                               H5_POSIX_CREATE_MODE_RW))) < 0)
-
             HGOTO_ERROR(H5E_FILE, H5E_CANTOPENFILE, FAIL, "unable to create the metadata file")
 
         md_size = (hsize_t)shared->vfd_swmr_config.md_pages_reserved * shared->fs_page_size;
@@ -277,6 +276,7 @@ H5F_vfd_swmr_close_or_flush(H5F_t *f, hbool_t closing)
 
     FUNC_ENTER_NOAPI(FAIL)
 
+
     HDassert(shared->vfd_swmr_writer);
     HDassert(shared->vfd_swmr_md_fd >= 0);
 
@@ -320,6 +320,12 @@ H5F_vfd_swmr_close_or_flush(H5F_t *f, hbool_t closing)
             HDONE_ERROR(H5E_FILE, H5E_CANTSET, FAIL, "unable to update end of tick");
     }
 done:
+     
+    H5F_post_vfd_swrm_log_entry(f, 1, "File close ends");
+
+    if (shared->vfd_swmr_log_on) {
+       HDfclose(shared->vfd_swmr_log_file_ptr); 
+    }
     FUNC_LEAVE_NOAPI(ret_value)
 }
 
@@ -628,10 +634,13 @@ H5F_vfd_swmr_writer__prep_for_flush_or_close(H5F_t *f)
 
     FUNC_ENTER_NOAPI(FAIL)
 
+
     HDassert(shared->vfd_swmr);
     HDassert(shared->vfd_swmr_writer);
     HDassert(shared->page_buf);
 
+    H5F_post_vfd_swrm_log_entry(f, 1, "File close starts");
+
     /* since we are about to flush the page buffer, force and end of
      * tick so as to avoid attempts to flush entries on the page buffer
      * tick list that were modified during the current tick.
@@ -755,12 +764,21 @@ H5F_vfd_swmr_writer_end_of_tick(H5F_t *f, hbool_t wait_for_reader)
     herr_t        ret_value                 = SUCCEED; /* Return value */
     hbool_t       incr_tick                 = FALSE;
 
+    struct timespec start_time,end_time;
+    unsigned int temp_time;
+    char*  log_msg;
+
     FUNC_ENTER_NOAPI(FAIL)
 
     HDassert(shared);
     HDassert(shared->page_buf);
     HDassert(shared->vfd_swmr_writer);
 
+    if(f->shared->vfd_swmr_log_on == true) {
+        H5F_post_vfd_swrm_log_entry(f, 3, "EOT gets started"); 
+        if(HDclock_gettime(CLOCK_MONOTONIC, &start_time)<0) 
+            HGOTO_ERROR(H5E_FILE, H5E_CANTGET, FAIL, "can't get time via clock_gettime");
+    }
     if (!vfd_swmr_writer_may_increase_tick_to(shared->tick_num + 1, wait_for_reader))
         goto update_eot;
 
@@ -883,6 +901,15 @@ update_eot:
         HGOTO_ERROR(H5E_FILE, H5E_CANTSET, FAIL, "unable to insert entry into the EOT queue")
 
 done:
+    if(f->shared->vfd_swmr_log_on == true) {
+        if(HDclock_gettime(CLOCK_MONOTONIC, &end_time)<0) 
+            HGOTO_ERROR(H5E_FILE, H5E_CANTGET, FAIL, "can't get time via clock_gettime");
+        log_msg = HDmalloc(48);
+        temp_time = (unsigned int) (TOTAL_TIME_PASSED(start_time, end_time));
+        HDsprintf(log_msg,"Writer time is %u milliseconds",temp_time);
+        H5F_post_vfd_swrm_log_entry(f, 3, log_msg); 
+        HDfree(log_msg);
+    }
     FUNC_LEAVE_NOAPI(ret_value)
 }
 
@@ -1887,7 +1914,28 @@ done:
     FUNC_LEAVE_NOAPI(ret_value)
 }
 
-void *
+herr_t 
 H5F_post_vfd_swrm_log_entry(H5F_t *f, int entry_type_code, char *body)
 {
+    herr_t ret_value = SUCCEED;
+    double temp_time;
+    struct timespec  current_time;
+    unsigned int    elap_min, elap_sec, elap_msec;
+
+    FUNC_ENTER_NOAPI(FAIL)
+    if(f->shared->vfd_swmr_log_on == false)
+        HGOTO_DONE(TRUE)
+    if(HDclock_gettime(CLOCK_MONOTONIC, &current_time)<0) 
+        HGOTO_ERROR(H5E_FILE, H5E_CANTGET, FAIL, "can't get time via clock_gettime");
+    temp_time = TOTAL_TIME_PASSED(f->shared->vfd_swmr_log_start_time, current_time);
+    elap_min  = TIME_PASSED_MIN(temp_time);
+    elap_sec  = TIME_PASSED_SEC(temp_time, elap_min);
+    elap_msec = TIME_PASSED_MSEC(temp_time, elap_min, elap_sec);
+
+    /* TODO: add a check for the range of entry_type_code to separate debug mode from the production mode.*/
+    HDfprintf(f->shared->vfd_swmr_log_file_ptr, "%s: %u m %u s %u ms, Content -  %s\n", 
+              H5Fvfd_swmr_log_tags[entry_type_code],elap_min,elap_sec, elap_msec, body);
+
+done:
+    FUNC_LEAVE_NOAPI(ret_value)
 }