Improvements to the log VFD, for helping with SWMR debugging.

2 files changed, 137 insertions, 28 deletions

diff --git a/src/H5FDlog.c b/src/H5FDlog.c
index d0c4647..dae0e4a 100644
--- a/src/H5FDlog.c
+++ b/src/H5FDlog.c
@@ -132,6 +132,7 @@ typedef struct H5FD_log_t {
     double              total_read_time;        /* Total time spent in read operations              */
     double              total_write_time;       /* Total time spent in write operations             */
     double              total_seek_time;        /* Total time spent in seek operations              */
+    double              total_truncate_time;    /* Total time spent in truncate operations              */
     size_t              iosize;                 /* Size of I/O information buffers                  */
     FILE                *logfp;                 /* Log file pointer                                 */
     H5FD_log_fapl_t     fa;                     /* Driver-specific file access properties           */
@@ -170,6 +171,8 @@ static herr_t H5FD_log_close(H5FD_t *_file);
 static int H5FD_log_cmp(const H5FD_t *_f1, const H5FD_t *_f2);
 static herr_t H5FD_log_query(const H5FD_t *_f1, unsigned long *flags);
 static haddr_t H5FD_log_alloc(H5FD_t *_file, H5FD_mem_t type, hid_t dxpl_id, hsize_t size);
+static herr_t H5FD__log_free(H5FD_t *_file, H5FD_mem_t type, hid_t dxpl_id, haddr_t addr,
+            hsize_t size);
 static haddr_t H5FD_log_get_eoa(const H5FD_t *_file, H5FD_mem_t type);
 static herr_t H5FD_log_set_eoa(H5FD_t *_file, H5FD_mem_t type, haddr_t addr);
 static haddr_t H5FD_log_get_eof(const H5FD_t *_file, H5FD_mem_t type);
@@ -203,7 +206,7 @@ static const H5FD_class_t H5FD_log_g = {
     H5FD_log_query,				/*query			*/
     NULL,					/*get_type_map		*/
     H5FD_log_alloc,				/*alloc			*/
-    NULL,					/*free			*/
+    H5FD__log_free,				/*free			*/
     H5FD_log_get_eoa,				/*get_eoa		*/
     H5FD_log_set_eoa, 				/*set_eoa		*/
     H5FD_log_get_eof,				/*get_eof		*/
@@ -735,6 +738,8 @@ H5FD_log_close(H5FD_t *_file)
             HDfprintf(file->logfp, "Total time in write operations: %f s\n", file->total_write_time);
         if(file->fa.flags & H5FD_LOG_TIME_SEEK)
             HDfprintf(file->logfp, "Total time in seek operations: %f s\n", file->total_seek_time);
+        if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE)
+            HDfprintf(file->logfp, "Total time in truncate operations: %f s\n", file->total_truncate_time);
 
         /* Dump the write I/O information */
         if(file->fa.flags & H5FD_LOG_FILE_WRITE) {
@@ -957,6 +962,43 @@ H5FD_log_alloc(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hsi
 
 
 /*-------------------------------------------------------------------------
+ * Function:    H5FD__log_free
+ *
+ * Purpose:     Release file memory.
+ *
+ * Return:      SUCCEED/FAIL
+ *
+ * Programmer:  Quincey Koziol
+ *              Wednesday, September 28, 2016
+ *
+ *-------------------------------------------------------------------------
+ */
+static herr_t
+H5FD__log_free(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id,
+    haddr_t addr, hsize_t size)
+{
+    H5FD_log_t	*file = (H5FD_log_t *)_file;
+
+    FUNC_ENTER_STATIC_NOERR
+
+    if(file->fa.flags != 0) {
+        /* Reset the flavor of the information in the file */
+        if(file->fa.flags & H5FD_LOG_FLAVOR) {
+            HDassert(addr < file->iosize);
+            H5_CHECK_OVERFLOW(size, hsize_t, size_t);
+            HDmemset(&file->flavor[addr], H5FD_MEM_DEFAULT, (size_t)size);
+        } /* end if */
+
+        /* Log the file memory freed */
+        if(file->fa.flags & H5FD_LOG_FREE)
+            HDfprintf(file->logfp, "%10a-%10a (%10Hu bytes) (%s) Freed\n", addr, (addr + size) - 1, size, flavors[type]);
+    } /* end if */
+
+    FUNC_LEAVE_NOAPI(SUCCEED)
+} /* end H5FD__log_free() */
+
+
+/*-------------------------------------------------------------------------
  * Function:    H5FD_log_get_eoa
  *
  * Purpose:     Gets the end-of-address marker for the file. The EOA marker
@@ -1004,6 +1046,7 @@ H5FD_log_set_eoa(H5FD_t *_file, H5FD_mem_t type, haddr_t addr)
     FUNC_ENTER_NOAPI_NOINIT_NOERR
 
     if(file->fa.flags != 0) {
+        /* Check for increasing file size */
         if(H5F_addr_gt(addr, file->eoa) && H5F_addr_gt(addr, 0)) {
             hsize_t size = addr - file->eoa;
 
@@ -1018,6 +1061,22 @@ H5FD_log_set_eoa(H5FD_t *_file, H5FD_mem_t type, haddr_t addr)
             if(file->fa.flags & H5FD_LOG_ALLOC)
                 HDfprintf(file->logfp, "%10a-%10a (%10Hu bytes) (%s) Allocated\n", file->eoa, addr, size, flavors[type]);
         } /* end if */
+
+        /* Check for decreasing file size */
+        if(H5F_addr_lt(addr, file->eoa) && H5F_addr_gt(addr, 0)) {
+            hsize_t size = file->eoa - addr;
+
+            /* Reset the flavor of the space freed by the shrink */
+            if(file->fa.flags & H5FD_LOG_FLAVOR) {
+                HDassert((addr + size) < file->iosize);
+                H5_CHECK_OVERFLOW(size, hsize_t, size_t);
+                HDmemset(&file->flavor[addr], H5FD_MEM_DEFAULT, (size_t)size);
+            } /* end if */
+
+            /* Log the shrink like a free */
+            if(file->fa.flags & H5FD_LOG_FREE)
+                HDfprintf(file->logfp, "%10a-%10a (%10Hu bytes) (%s) Freed\n", file->eoa, addr, size, flavors[type]);
+        } /* end if */
     } /* end if */
 
     file->eoa = addr;
@@ -1167,7 +1226,7 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
                     timeval_diff.tv_sec--;
                 } /* end if */
                 time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f);
-                HDfprintf(file->logfp, " (%f s)\n", time_diff);
+                HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec);
 
                 /* Add to total seek time */
                 file->total_seek_time += time_diff;
@@ -1241,7 +1300,12 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
     if(file->fa.flags & H5FD_LOG_LOC_READ) {
         HDfprintf(file->logfp, "%10a-%10a (%10Zu bytes) (%s) Read", orig_addr, (orig_addr + orig_size) - 1, orig_size, flavors[type]);
 
-        /* XXX: Verify the flavor information, if we have it? */
+        /* Verify that we are reading in the type of data we allocated in this location */
+        if(file->flavor) {
+            HDassert(type == H5FD_MEM_DEFAULT || type == (H5FD_mem_t)file->flavor[orig_addr] || (H5FD_mem_t)file->flavor[orig_addr] == H5FD_MEM_DEFAULT);
+            HDassert(type == H5FD_MEM_DEFAULT || type == (H5FD_mem_t)file->flavor[(orig_addr + orig_size) - 1] || (H5FD_mem_t)file->flavor[(orig_addr + orig_size) - 1] == H5FD_MEM_DEFAULT);
+        } /* end if */
+
 
 #ifdef H5_HAVE_GETTIMEOFDAY
         if(file->fa.flags & H5FD_LOG_TIME_READ) {
@@ -1256,7 +1320,7 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
                 timeval_diff.tv_sec--;
             } /* end if */
             time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f);
-            HDfprintf(file->logfp, " (%f s)\n", time_diff);
+            HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec);
 
             /* Add to total read time */
             file->total_read_time += time_diff;
@@ -1369,7 +1433,7 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
                     timeval_diff.tv_sec--;
                 } /* end if */
                 time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f);
-                HDfprintf(file->logfp, " (%f s)\n", time_diff);
+                HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec);
 
                 /* Add to total seek time */
                 file->total_seek_time += time_diff;
@@ -1438,8 +1502,10 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
 
         /* Check if this is the first write into a "default" section, grabbed by the metadata agregation algorithm */
         if(file->fa.flags & H5FD_LOG_FLAVOR) {
-            if((H5FD_mem_t)file->flavor[orig_addr] == H5FD_MEM_DEFAULT)
+            if((H5FD_mem_t)file->flavor[orig_addr] == H5FD_MEM_DEFAULT) {
                 HDmemset(&file->flavor[orig_addr], (int)type, orig_size);
+                HDfprintf(file->logfp, " (fresh)");
+            } /* end if */
         } /* end if */
 
 #ifdef H5_HAVE_GETTIMEOFDAY
@@ -1455,7 +1521,7 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
                 timeval_diff.tv_sec--;
             } /* end if */
             time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f);
-            HDfprintf(file->logfp, " (%f s)\n", time_diff);
+            HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec);
 
             /* Add to total write time */
             file->total_write_time += time_diff;
@@ -1509,6 +1575,14 @@ H5FD_log_truncate(H5FD_t *_file, hid_t H5_ATTR_UNUSED dxpl_id, hbool_t H5_ATTR_U
 
     /* Extend the file to make sure it's large enough */
     if(!H5F_addr_eq(file->eoa, file->eof)) {
+#ifdef H5_HAVE_GETTIMEOFDAY
+        struct timeval timeval_start, timeval_stop;
+#endif /* H5_HAVE_GETTIMEOFDAY */
+
+#ifdef H5_HAVE_GETTIMEOFDAY
+        if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE)
+            HDgettimeofday(&timeval_start, NULL);
+#endif /* H5_HAVE_GETTIMEOFDAY */
 #ifdef H5_HAVE_WIN32_API
         LARGE_INTEGER   li;         /* 64-bit (union) integer for SetFilePointer() call */
         DWORD           dwPtrLow;   /* Low-order pointer bits from SetFilePointer()
@@ -1539,10 +1613,40 @@ H5FD_log_truncate(H5FD_t *_file, hid_t H5_ATTR_UNUSED dxpl_id, hbool_t H5_ATTR_U
         if(-1 == HDftruncate(file->fd, (HDoff_t)file->eoa))
             HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to extend file properly")
 #endif /* H5_HAVE_WIN32_API */
+#ifdef H5_HAVE_GETTIMEOFDAY
+        if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE)
+            HDgettimeofday(&timeval_stop, NULL);
+#endif /* H5_HAVE_GETTIMEOFDAY */
 
         /* Log information about the truncate */
         if(file->fa.flags & H5FD_LOG_NUM_TRUNCATE)
             file->total_truncate_ops++;
+        if(file->fa.flags & H5FD_LOG_TRUNCATE) {
+            HDfprintf(file->logfp, "Truncate: To %10a", file->eoa);
+#ifdef H5_HAVE_GETTIMEOFDAY
+            if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) {
+                struct timeval timeval_diff;
+                double time_diff;
+
+                /* Calculate the elapsed gettimeofday time */
+                timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec;
+                timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec;
+                if(timeval_diff.tv_usec < 0) {
+                    timeval_diff.tv_usec += 1000000;
+                    timeval_diff.tv_sec--;
+                } /* end if */
+                time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f);
+                HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec);
+
+                /* Add to total truncate time */
+                file->total_truncate_time += time_diff;
+            } /* end if */
+            else
+                HDfprintf(file->logfp, "\n");
+#else /* H5_HAVE_GETTIMEOFDAY */
+            HDfprintf(file->logfp, "\n");
+#endif /* H5_HAVE_GETTIMEOFDAY */
+        } /* end if */
 
         /* Update the eof value */
         file->eof = file->eoa;
diff --git a/src/H5FDlog.h b/src/H5FDlog.h
index 2f1544e..11044e2 100644
--- a/src/H5FDlog.h
+++ b/src/H5FDlog.h
@@ -25,34 +25,39 @@
 #define H5FD_LOG	(H5FD_log_init())
 
 /* Flags for H5Pset_fapl_log() */
+/* Flags for tracking 'meta' operations (truncate) */
+#define H5FD_LOG_TRUNCATE   0x00000001
+#define H5FD_LOG_META_IO    (H5FD_LOG_TRUNCATE)
 /* Flags for tracking where reads/writes/seeks occur */
-#define H5FD_LOG_LOC_READ   0x00000001
-#define H5FD_LOG_LOC_WRITE  0x00000002
-#define H5FD_LOG_LOC_SEEK   0x00000004
+#define H5FD_LOG_LOC_READ   0x00000002
+#define H5FD_LOG_LOC_WRITE  0x00000004
+#define H5FD_LOG_LOC_SEEK   0x00000008
 #define H5FD_LOG_LOC_IO     (H5FD_LOG_LOC_READ|H5FD_LOG_LOC_WRITE|H5FD_LOG_LOC_SEEK)
 /* Flags for tracking number of times each byte is read/written */
-#define H5FD_LOG_FILE_READ  0x00000008
-#define H5FD_LOG_FILE_WRITE 0x00000010
+#define H5FD_LOG_FILE_READ  0x00000010
+#define H5FD_LOG_FILE_WRITE 0x00000020
 #define H5FD_LOG_FILE_IO    (H5FD_LOG_FILE_READ|H5FD_LOG_FILE_WRITE)
 /* Flag for tracking "flavor" (type) of information stored at each byte */
-#define H5FD_LOG_FLAVOR     0x00000020
+#define H5FD_LOG_FLAVOR     0x00000040
 /* Flags for tracking total number of reads/writes/seeks/truncates */
-#define H5FD_LOG_NUM_READ   0x00000040
-#define H5FD_LOG_NUM_WRITE  0x00000080
-#define H5FD_LOG_NUM_SEEK   0x00000100
-#define H5FD_LOG_NUM_TRUNCATE 0x00000200
+#define H5FD_LOG_NUM_READ   0x00000080
+#define H5FD_LOG_NUM_WRITE  0x00000100
+#define H5FD_LOG_NUM_SEEK   0x00000200
+#define H5FD_LOG_NUM_TRUNCATE 0x00000400
 #define H5FD_LOG_NUM_IO     (H5FD_LOG_NUM_READ|H5FD_LOG_NUM_WRITE|H5FD_LOG_NUM_SEEK|H5FD_LOG_NUM_TRUNCATE)
-/* Flags for tracking time spent in open/stat/read/write/seek/close */
-#define H5FD_LOG_TIME_OPEN  0x00000400
-#define H5FD_LOG_TIME_STAT  0x00000800
-#define H5FD_LOG_TIME_READ  0x00001000
-#define H5FD_LOG_TIME_WRITE 0x00002000
-#define H5FD_LOG_TIME_SEEK  0x00004000
-#define H5FD_LOG_TIME_CLOSE 0x00008000
-#define H5FD_LOG_TIME_IO    (H5FD_LOG_TIME_OPEN|H5FD_LOG_TIME_STAT|H5FD_LOG_TIME_READ|H5FD_LOG_TIME_WRITE|H5FD_LOG_TIME_SEEK|H5FD_LOG_TIME_CLOSE)
-/* Flag for tracking allocation of space in file */
-#define H5FD_LOG_ALLOC      0x00010000
-#define H5FD_LOG_ALL        (H5FD_LOG_ALLOC|H5FD_LOG_TIME_IO|H5FD_LOG_NUM_IO|H5FD_LOG_FLAVOR|H5FD_LOG_FILE_IO|H5FD_LOG_LOC_IO)
+/* Flags for tracking time spent in open/stat/read/write/seek/truncate/close */
+#define H5FD_LOG_TIME_OPEN  0x00000800
+#define H5FD_LOG_TIME_STAT  0x00001000
+#define H5FD_LOG_TIME_READ  0x00002000
+#define H5FD_LOG_TIME_WRITE 0x00004000
+#define H5FD_LOG_TIME_SEEK  0x00008000
+#define H5FD_LOG_TIME_TRUNCATE 0x00010000
+#define H5FD_LOG_TIME_CLOSE 0x00020000
+#define H5FD_LOG_TIME_IO    (H5FD_LOG_TIME_OPEN|H5FD_LOG_TIME_STAT|H5FD_LOG_TIME_READ|H5FD_LOG_TIME_WRITE|H5FD_LOG_TIME_SEEK|H5FD_LOG_TIME_TRUNCATE|H5FD_LOG_TIME_CLOSE)
+/* Flags for tracking allocation/release of space in file */
+#define H5FD_LOG_ALLOC      0x00040000
+#define H5FD_LOG_FREE       0x00080000
+#define H5FD_LOG_ALL        (H5FD_LOG_FREE|H5FD_LOG_ALLOC|H5FD_LOG_TIME_IO|H5FD_LOG_NUM_IO|H5FD_LOG_FLAVOR|H5FD_LOG_FILE_IO|H5FD_LOG_LOC_IO|H5FD_LOG_META_IO)
 
 #ifdef __cplusplus
 extern "C" {