summaryrefslogtreecommitdiffstats
path: root/src
diff options
context:
space:
mode:
authorQuincey Koziol <koziol@lbl.gov>2020-07-02 15:36:44 (GMT)
committerQuincey Koziol <koziol@lbl.gov>2020-07-02 15:36:44 (GMT)
commitd05b58b5d4806d694f16d0fc698c5e1c057a411b (patch)
tree1931c3ebb10d98d90b694adb1588945d9519c394 /src
parent7cbb5fe2d177e49417401e1dc0b2a4c9d618cc67 (diff)
parent7371c83f9777b34b31909e99e052398b93c31bed (diff)
downloadhdf5-d05b58b5d4806d694f16d0fc698c5e1c057a411b.zip
hdf5-d05b58b5d4806d694f16d0fc698c5e1c057a411b.tar.gz
hdf5-d05b58b5d4806d694f16d0fc698c5e1c057a411b.tar.bz2
Merge pull request #2668 in HDFFV/hdf5 from monotonic_timer to develop
* commit '7371c83f9777b34b31909e99e052398b93c31bed': Remove non-existent example Add new source files to CMake build Clean up warnings va_arg -> HDva_arg Refactor code to remove remaining checks for H5_HAVE_GETTIMEOFDAY scattered around in various places. Also clean up iopipe.c. Correct mistake in H5_now_usec calculation for clock_gettime. Remove detection for mach/mach/time.h, since we're no longer using the time routines from that header. Update H5_now_usec to prefer using clock_gettime. Changes to make timers within the library monotonic.
Diffstat (limited to 'src')
-rw-r--r--src/H5Eprivate.h2
-rw-r--r--src/H5FDlog.c436
-rw-r--r--src/H5T.c21
-rw-r--r--src/H5Tdbg.c55
-rw-r--r--src/H5Tpkg.h2
-rw-r--r--src/H5Z.c239
-rw-r--r--src/H5private.h37
-rw-r--r--src/H5system.c149
-rw-r--r--src/H5timer.c640
-rw-r--r--src/H5trace.c51
10 files changed, 1064 insertions, 568 deletions
diff --git a/src/H5Eprivate.h b/src/H5Eprivate.h
index 19ab729..130a8fd 100644
--- a/src/H5Eprivate.h
+++ b/src/H5Eprivate.h
@@ -180,7 +180,7 @@ extern int H5E_mpi_error_str_len;
/* Library-private functions defined in H5E package */
H5_DLL herr_t H5E_init(void);
H5_DLL herr_t H5E_printf_stack(H5E_t *estack, const char *file, const char *func,
- unsigned line, hid_t cls_id, hid_t maj_id, hid_t min_id, const char *fmt, ...)H5_ATTR_FORMAT(printf, 8, 9);
+ unsigned line, hid_t cls_id, hid_t maj_id, hid_t min_id, const char *fmt, ...) H5_ATTR_FORMAT(printf, 8, 9);
H5_DLL herr_t H5E_clear_stack(H5E_t *estack);
H5_DLL herr_t H5E_dump_api_stack(hbool_t is_api);
diff --git a/src/H5FDlog.c b/src/H5FDlog.c
index f649bc4..78b7742 100644
--- a/src/H5FDlog.c
+++ b/src/H5FDlog.c
@@ -487,11 +487,8 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr)
#ifdef H5_HAVE_WIN32_API
struct _BY_HANDLE_FILE_INFORMATION fileinfo;
#endif
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval timeval_start;
- struct timeval open_timeval_diff;
- struct timeval stat_timeval_diff;
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_t open_timer; /* Timer for open() call */
+ H5_timer_t stat_timer; /* Timer for stat() call */
h5_stat_t sb;
H5FD_t *ret_value = NULL; /* Return value */
@@ -523,54 +520,36 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr)
if(NULL == (fa = (const H5FD_log_fapl_t *)H5P_peek_driver_info(plist)))
HGOTO_ERROR(H5E_PLIST, H5E_BADVALUE, NULL, "bad VFL driver info")
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(fa->flags & H5FD_LOG_TIME_OPEN)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Start timer for open() call */
+ if(fa->flags & H5FD_LOG_TIME_OPEN) {
+ H5_timer_init(&open_timer);
+ H5_timer_start(&open_timer);
+ } /* end if */
+
/* Open the file */
if((fd = HDopen(name, o_flags, H5_POSIX_CREATE_MODE_RW)) < 0) {
int myerrno = errno;
HGOTO_ERROR(H5E_FILE, H5E_CANTOPENFILE, NULL, "unable to open file: name = '%s', errno = %d, error message = '%s', flags = %x, o_flags = %x", name, myerrno, HDstrerror(myerrno), flags, (unsigned)o_flags);
} /* end if */
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(fa->flags & H5FD_LOG_TIME_OPEN) {
- struct timeval timeval_stop;
- HDgettimeofday(&timeval_stop, NULL);
+ /* Stop timer for open() call */
+ if(fa->flags & H5FD_LOG_TIME_OPEN)
+ H5_timer_stop(&open_timer);
- /* Calculate the elapsed gettimeofday time */
- open_timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec;
- open_timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec;
- if(open_timeval_diff.tv_usec < 0) {
- open_timeval_diff.tv_usec += 1000000;
- open_timeval_diff.tv_sec--;
- } /* end if */
+ /* Start timer for stat() call */
+ if(fa->flags & H5FD_LOG_TIME_STAT) {
+ H5_timer_init(&stat_timer);
+ H5_timer_start(&stat_timer);
} /* end if */
-#endif /* H5_HAVE_GETTIMEOFDAY */
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(fa->flags & H5FD_LOG_TIME_STAT)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
/* Get the file stats */
if(HDfstat(fd, &sb) < 0)
HSYS_GOTO_ERROR(H5E_FILE, H5E_BADFILE, NULL, "unable to fstat file")
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(fa->flags & H5FD_LOG_TIME_STAT) {
- struct timeval timeval_stop;
- HDgettimeofday(&timeval_stop, NULL);
-
- /* Calculate the elapsed gettimeofday time */
- stat_timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec;
- stat_timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec;
- if(stat_timeval_diff.tv_usec < 0) {
- stat_timeval_diff.tv_usec += 1000000;
- stat_timeval_diff.tv_sec--;
- } /* end if */
- } /* end if */
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Stop timer for stat() call */
+ if(fa->flags & H5FD_LOG_TIME_STAT)
+ H5_timer_stop(&stat_timer);
/* Create the new file struct */
if(NULL == (file = H5FL_CALLOC(H5FD_log_t)))
@@ -631,13 +610,19 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr)
else
file->logfp = stderr;
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_OPEN)
- HDfprintf(file->logfp, "Open took: (%f s)\n", (double)open_timeval_diff.tv_sec + ((double)open_timeval_diff.tv_usec / (double)1000000.0f));
- if(file->fa.flags & H5FD_LOG_TIME_STAT)
- HDfprintf(file->logfp, "Stat took: (%f s)\n", (double)stat_timeval_diff.tv_sec + ((double)stat_timeval_diff.tv_usec / (double)1000000.0f));
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Log the timer values */
+ if(file->fa.flags & H5FD_LOG_TIME_OPEN) {
+ H5_timevals_t open_times; /* Elapsed time for open() call */
+ H5_timer_get_times(open_timer, &open_times);
+ HDfprintf(file->logfp, "Open took: (%f s)\n", open_times.elapsed);
+ } /* end if */
+ if(file->fa.flags & H5FD_LOG_TIME_STAT) {
+ H5_timevals_t stat_times; /* Elapsed time for stat() call */
+
+ H5_timer_get_times(stat_timer, &stat_times);
+ HDfprintf(file->logfp, "Stat took: (%f s)\n", stat_times.elapsed);
+ } /* end if */
} /* end if */
/* Check for non-default FAPL */
@@ -684,27 +669,27 @@ static herr_t
H5FD_log_close(H5FD_t *_file)
{
H5FD_log_t *file = (H5FD_log_t *)_file;
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval timeval_start, timeval_stop;
-#endif /* H5_HAVE_GETTIMEOFDAY */
- herr_t ret_value = SUCCEED; /* Return value */
+ H5_timer_t close_timer; /* Timer for close() call */
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI_NOINIT
/* Sanity check */
HDassert(file);
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags&H5FD_LOG_TIME_CLOSE)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Start timer for close() call */
+ if(file->fa.flags & H5FD_LOG_TIME_CLOSE) {
+ H5_timer_init(&close_timer);
+ H5_timer_start(&close_timer);
+ } /* end if */
+
/* Close the underlying file */
if(HDclose(file->fd) < 0)
HSYS_GOTO_ERROR(H5E_IO, H5E_CANTCLOSEFILE, FAIL, "unable to close file")
-#ifdef H5_HAVE_GETTIMEOFDAY
+
+ /* Stop timer for close() call */
if(file->fa.flags&H5FD_LOG_TIME_CLOSE)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&close_timer);
/* Dump I/O information */
if(file->fa.flags != 0) {
@@ -712,20 +697,12 @@ H5FD_log_close(H5FD_t *_file)
haddr_t last_addr;
unsigned char last_val;
-#ifdef H5_HAVE_GETTIMEOFDAY
if(file->fa.flags & H5FD_LOG_TIME_CLOSE) {
- struct timeval timeval_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 */
- HDfprintf(file->logfp, "Close took: (%f s)\n", (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f));
+ H5_timevals_t close_times; /* Elapsed time for close() call */
+
+ H5_timer_get_times(close_timer, &close_times);
+ HDfprintf(file->logfp, "Close took: (%f s)\n", close_times.elapsed);
} /* end if */
-#endif /* H5_HAVE_GETTIMEOFDAY */
/* Dump the total number of seek/read/write operations */
if(file->fa.flags & H5FD_LOG_NUM_READ)
@@ -1168,11 +1145,14 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
H5FD_log_t *file = (H5FD_log_t *)_file;
size_t orig_size = size; /* Save the original size for later */
haddr_t orig_addr = addr;
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval timeval_start, timeval_stop;
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_t read_timer; /* Timer for read operation */
+ H5_timevals_t read_times; /* Elapsed time for read operation */
+#ifndef H5_HAVE_PREADWRITE
+ H5_timer_t seek_timer; /* Timer for seek operation */
+ H5_timevals_t seek_times; /* Elapsed time for seek operation */
+#endif /* H5_HAVE_PREADWRITE */
HDoff_t offset = (HDoff_t)addr;
- herr_t ret_value = SUCCEED; /* Return value */
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI_NOINIT
@@ -1201,59 +1181,56 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
#ifndef H5_HAVE_PREADWRITE
/* Seek to the correct location (if we don't have pread) */
if(addr != file->pos || OP_READ != file->op) {
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_SEEK)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Start timer for seek() call */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
+ H5_timer_init(&seek_timer);
+ H5_timer_start(&seek_timer);
+ } /* end if */
+
if(HDlseek(file->fd, (HDoff_t)addr, SEEK_SET) < 0)
HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to seek to proper position")
-#ifdef H5_HAVE_GETTIMEOFDAY
+
+ /* Stop timer for seek() call */
if(file->fa.flags & H5FD_LOG_TIME_SEEK)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&seek_timer);
- /* Log information about the seek */
+ /* Add to the number of seeks, when tracking that */
if(file->fa.flags & H5FD_LOG_NUM_SEEK)
file->total_seek_ops++;
+
+ /* Add to the total seek time, when tracking that */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
+ H5_timer_get_times(seek_timer, &seek_times);
+ file->total_seek_time += seek_times.elapsed;
+ } /* end if */
+
+ /* Emit log string if we're tracking individual seek events. */
if(file->fa.flags & H5FD_LOG_LOC_SEEK) {
HDfprintf(file->logfp, "Seek: From %10a To %10a", file->pos, addr);
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
- 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 seek time */
- file->total_seek_time += time_diff;
- } /* end if */
- else
- HDfprintf(file->logfp, "\n");
-#else /* H5_HAVE_GETTIMEOFDAY */
- HDfprintf(file->logfp, "\n");
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Add the seek time, if we're tracking that.
+ * Note that the seek time is NOT emitted for when just H5FD_LOG_TIME_SEEK
+ * is set.
+ */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK)
+ HDfprintf(file->logfp, " (%fs @ %f)\n", seek_times.elapsed, seek_timer.initial.elapsed);
+ else
+ HDfprintf(file->logfp, "\n");
} /* end if */
} /* end if */
#endif /* H5_HAVE_PREADWRITE */
+ /* Start timer for read operation */
+ if(file->fa.flags & H5FD_LOG_TIME_READ) {
+ H5_timer_init(&read_timer);
+ H5_timer_start(&read_timer);
+ } /* end if */
+
/*
* Read data, being careful of interrupted system calls, partial results,
* and the end of the file.
*/
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_READ)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
while(size > 0) {
-
h5_posix_io_t bytes_in = 0; /* # of bytes to read */
h5_posix_io_ret_t bytes_read = -1; /* # of bytes actually read */
@@ -1301,14 +1278,22 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
buf = (char *)buf + bytes_read;
} /* end while */
-#ifdef H5_HAVE_GETTIMEOFDAY
+
+ /* Stop timer for read operation */
if(file->fa.flags & H5FD_LOG_TIME_READ)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&read_timer);
- /* Log information about the read */
+ /* Add to the number of reads, when tracking that */
if(file->fa.flags & H5FD_LOG_NUM_READ)
file->total_read_ops++;
+
+ /* Add to the total read time, when tracking that */
+ if(file->fa.flags & H5FD_LOG_TIME_READ) {
+ H5_timer_get_times(read_timer, &read_times);
+ file->total_read_time += read_times.elapsed;
+ } /* end if */
+
+ /* Log information about the read */
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]);
@@ -1318,30 +1303,14 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
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) {
- 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 read time */
- file->total_read_time += time_diff;
- } /* end if */
+ /* Add the read time, if we're tracking that.
+ * Note that the read time is NOT emitted for when just H5FD_LOG_TIME_READ
+ * is set.
+ */
+ if(file->fa.flags & H5FD_LOG_TIME_READ)
+ HDfprintf(file->logfp, " (%fs @ %f)\n", read_times.elapsed, read_timer.initial.elapsed);
else
HDfprintf(file->logfp, "\n");
-#else /* H5_HAVE_GETTIMEOFDAY */
- HDfprintf(file->logfp, "\n");
-#endif /* H5_HAVE_GETTIMEOFDAY */
} /* end if */
/* Update current position */
@@ -1380,11 +1349,14 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
H5FD_log_t *file = (H5FD_log_t *)_file;
size_t orig_size = size; /* Save the original size for later */
haddr_t orig_addr = addr;
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval timeval_start, timeval_stop;
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_t write_timer; /* Timer for write operation */
+ H5_timevals_t write_times; /* Elapsed time for write operation */
+#ifndef H5_HAVE_PREADWRITE
+ H5_timer_t seek_timer; /* Timer for seek operation */
+ H5_timevals_t seek_times; /* Elapsed time for seek operation */
+#endif /* H5_HAVE_PREADWRITE */
HDoff_t offset = (HDoff_t)addr;
- herr_t ret_value = SUCCEED; /* Return value */
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI_NOINIT
@@ -1418,59 +1390,56 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
#ifndef H5_HAVE_PREADWRITE
/* Seek to the correct location (if we don't have pwrite) */
if(addr != file->pos || OP_WRITE != file->op) {
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_SEEK)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Start timer for seek() call */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
+ H5_timer_init(&seek_timer);
+ H5_timer_start(&seek_timer);
+ } /* end if */
+
if(HDlseek(file->fd, (HDoff_t)addr, SEEK_SET) < 0)
HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to seek to proper position")
-#ifdef H5_HAVE_GETTIMEOFDAY
+
+ /* Stop timer for seek() call */
if(file->fa.flags & H5FD_LOG_TIME_SEEK)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&seek_timer);
- /* Log information about the seek */
+ /* Add to the number of seeks, when tracking that */
if(file->fa.flags & H5FD_LOG_NUM_SEEK)
file->total_seek_ops++;
+
+ /* Add to the total seek time, when tracking that */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
+ H5_timer_get_times(seek_timer, &seek_times);
+ file->total_seek_time += seek_times.elapsed;
+ } /* end if */
+
+ /* Emit log string if we're tracking individual seek events. */
if(file->fa.flags & H5FD_LOG_LOC_SEEK) {
HDfprintf(file->logfp, "Seek: From %10a To %10a", file->pos, addr);
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_SEEK) {
- 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 seek time */
- file->total_seek_time += time_diff;
- } /* end if */
- else
- HDfprintf(file->logfp, "\n");
-#else /* H5_HAVE_GETTIMEOFDAY */
- HDfprintf(file->logfp, "\n");
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Add the seek time, if we're tracking that.
+ * Note that the seek time is NOT emitted for when just H5FD_LOG_TIME_SEEK
+ * is set.
+ */
+ if(file->fa.flags & H5FD_LOG_TIME_SEEK)
+ HDfprintf(file->logfp, " (%fs @ %f)\n", seek_times.elapsed, seek_timer.initial.elapsed);
+ else
+ HDfprintf(file->logfp, "\n");
} /* end if */
} /* end if */
#endif /* H5_HAVE_PREADWRITE */
+ /* Start timer for write operation */
+ if(file->fa.flags&H5FD_LOG_TIME_WRITE) {
+ H5_timer_init(&write_timer);
+ H5_timer_start(&write_timer);
+ } /* end if */
+
/*
* Write the data, being careful of interrupted system calls and partial
* results
*/
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags&H5FD_LOG_TIME_WRITE)
- HDgettimeofday(&timeval_start, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
while(size > 0) {
-
h5_posix_io_t bytes_in = 0; /* # of bytes to write */
h5_posix_io_ret_t bytes_wrote = -1; /* # of bytes written */
@@ -1511,14 +1480,22 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
addr += (haddr_t)bytes_wrote;
buf = (const char *)buf + bytes_wrote;
} /* end while */
-#ifdef H5_HAVE_GETTIMEOFDAY
+
+ /* Stop timer for write operation */
if(file->fa.flags & H5FD_LOG_TIME_WRITE)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&write_timer);
- /* Log information about the write */
+ /* Add to the number of writes, when tracking that */
if(file->fa.flags & H5FD_LOG_NUM_WRITE)
file->total_write_ops++;
+
+ /* Add to the total write time, when tracking that */
+ if(file->fa.flags & H5FD_LOG_TIME_WRITE) {
+ H5_timer_get_times(write_timer, &write_times);
+ file->total_write_time += write_times.elapsed;
+ } /* end if */
+
+ /* Log information about the write */
if(file->fa.flags & H5FD_LOG_LOC_WRITE) {
HDfprintf(file->logfp, "%10a-%10a (%10Zu bytes) (%s) Written", orig_addr, (orig_addr + orig_size) - 1, orig_size, flavors[type]);
@@ -1530,29 +1507,14 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
} /* end if */
} /* end if */
-#ifdef H5_HAVE_GETTIMEOFDAY
- if(file->fa.flags & H5FD_LOG_TIME_WRITE) {
- 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 write time */
- file->total_write_time += time_diff;
- } /* end if */
- else
- HDfprintf(file->logfp, "\n");
-#else /* H5_HAVE_GETTIMEOFDAY */
- HDfprintf(file->logfp, "\n");
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ /* Add the write time, if we're tracking that.
+ * Note that the write time is NOT emitted for when just H5FD_LOG_TIME_WRITE
+ * is set.
+ */
+ if(file->fa.flags & H5FD_LOG_TIME_WRITE)
+ HDfprintf(file->logfp, " (%fs @ %f)\n", write_times.elapsed, write_timer.initial.elapsed);
+ else
+ HDfprintf(file->logfp, "\n");
} /* end if */
/* Update current position and eof */
@@ -1597,23 +1559,22 @@ 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 */
+ H5_timer_t trunc_timer; /* Timer for truncate operation */
+ H5_timevals_t trunc_times; /* Elapsed time for truncate operation */
+
+ /* Start timer for truncate operation */
+ if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) {
+ H5_timer_init(&trunc_timer);
+ H5_timer_start(&trunc_timer);
+ } /* end if */
+
#ifdef H5_HAVE_WIN32_API
+{
LARGE_INTEGER li; /* 64-bit (union) integer for SetFilePointer() call */
DWORD dwPtrLow; /* Low-order pointer bits from SetFilePointer()
* Only used as an error code here.
*/
- DWORD dwError; /* DWORD error code from GetLastError() */
- BOOL bError; /* Boolean error flag */
-#endif /* H5_HAVE_WIN32_API */
-#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
/* Windows uses this odd QuadPart union for 32/64-bit portability */
li.QuadPart = (__int64)file->eoa;
@@ -1624,51 +1585,48 @@ H5FD_log_truncate(H5FD_t *_file, hid_t H5_ATTR_UNUSED dxpl_id, hbool_t H5_ATTR_U
*/
dwPtrLow = SetFilePointer(file->hFile, li.LowPart, &li.HighPart, FILE_BEGIN);
if(INVALID_SET_FILE_POINTER == dwPtrLow) {
+ DWORD dwError; /* DWORD error code from GetLastError() */
+
dwError = GetLastError();
if(dwError != NO_ERROR )
HGOTO_ERROR(H5E_FILE, H5E_FILEOPEN, FAIL, "unable to set file pointer")
- }
+ } /* end if */
- bError = SetEndOfFile(file->hFile);
- if(0 == bError)
+ if(0 == SetEndOfFile(file->hFile))
HGOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to extend file properly")
+}
#else /* H5_HAVE_WIN32_API */
+ /* Truncate/extend the file */
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
+
+ /* Stop timer for truncate operation */
if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE)
- HDgettimeofday(&timeval_stop, NULL);
-#endif /* H5_HAVE_GETTIMEOFDAY */
+ H5_timer_stop(&trunc_timer);
- /* Log information about the truncate */
+ /* Add to the number of truncates, when tracking that */
if(file->fa.flags & H5FD_LOG_NUM_TRUNCATE)
file->total_truncate_ops++;
+
+ /* Add to the total truncate time, when tracking that */
+ if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) {
+ H5_timer_get_times(trunc_timer, &trunc_times);
+ file->total_truncate_time += trunc_times.elapsed;
+ } /* end if */
+
+ /* Emit log string if we're tracking individual truncate events. */
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 */
+ /* Add the truncate time, if we're tracking that.
+ * Note that the truncate time is NOT emitted for when just H5FD_LOG_TIME_TRUNCATE
+ * is set.
+ */
+ if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE)
+ HDfprintf(file->logfp, " (%fs @ %f)\n", trunc_times.elapsed, trunc_timer.initial.elapsed);
+ else
+ HDfprintf(file->logfp, "\n");
} /* end if */
/* Update the eof value */
diff --git a/src/H5T.c b/src/H5T.c
index 47c4e4e..25c1f75 100644
--- a/src/H5T.c
+++ b/src/H5T.c
@@ -5272,16 +5272,21 @@ H5T_convert(H5T_path_t *tpath, hid_t src_id, hid_t dst_id, size_t nelmts,
size_t buf_stride, size_t bkg_stride, void *buf, void *bkg)
{
#ifdef H5T_DEBUG
- H5_timer_t timer;
+ H5_timer_t timer; /* Timer for conversion */
#endif
herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI(FAIL)
#ifdef H5T_DEBUG
- if(H5DEBUG(T))
- H5_timer_begin(&timer);
+ if(H5DEBUG(T)) {
+ /* Initialize and start timer */
+ H5_timer_init(&timer);
+ H5_timer_start(&timer);
+ } /* end if */
#endif
+
+ /* Call the appropriate conversion callback */
tpath->cdata.command = H5T_CONV_CONV;
if(tpath->conv.is_app) {
if((tpath->conv.u.app_func)(src_id, dst_id, &(tpath->cdata), nelmts, buf_stride, bkg_stride, buf, bkg, H5CX_get_dxpl()) < 0)
@@ -5292,10 +5297,16 @@ H5T_convert(H5T_path_t *tpath, hid_t src_id, hid_t dst_id, size_t nelmts,
HGOTO_ERROR(H5E_DATATYPE, H5E_CANTCONVERT, FAIL, "datatype conversion failed")
#ifdef H5T_DEBUG
if(H5DEBUG(T)) {
- H5_timer_end(&(tpath->stats.timer), &timer);
+ /* Stop timer */
+ H5_timer_stop(&timer);
+
+ /* Record elapsed timer info */
+ H5_timer_get_times(timer, &tpath->stats.times);
+
+ /* Increment # of calls and # of elements converted */
tpath->stats.ncalls++;
tpath->stats.nelmts += nelmts;
- }
+ } /* end if */
#endif
done:
diff --git a/src/H5Tdbg.c b/src/H5Tdbg.c
index 605310a..693174a 100644
--- a/src/H5Tdbg.c
+++ b/src/H5Tdbg.c
@@ -95,25 +95,24 @@
herr_t
H5T__print_stats(H5T_path_t H5_ATTR_UNUSED * path, int H5_ATTR_UNUSED * nprint/*in,out*/)
{
-#ifdef H5T_DEBUG
- hsize_t nbytes;
- char bandwidth[32];
-#endif
-
FUNC_ENTER_PACKAGE_NOERR
#ifdef H5T_DEBUG
- if (H5DEBUG(T) && path->stats.ncalls > 0) {
- if (nprint && 0 == (*nprint)++) {
- HDfprintf(H5DEBUG(T), "H5T: type conversion statistics:\n");
- HDfprintf(H5DEBUG(T), " %-16s %10s %10s %8s %8s %8s %10s\n",
- "Conversion", "Elmts", "Calls", "User",
- "System", "Elapsed", "Bandwidth");
- HDfprintf(H5DEBUG(T), " %-16s %10s %10s %8s %8s %8s %10s\n",
- "----------", "-----", "-----", "----",
- "------", "-------", "---------");
- }
- if (path->src && path->dst)
+ if(H5DEBUG(T) && path->stats.ncalls > 0) {
+ hsize_t nbytes;
+ char bandwidth[32];
+
+ if(nprint && 0 == (*nprint)++) {
+ HDfprintf(H5DEBUG(T), "H5T: type conversion statistics:\n");
+ HDfprintf(H5DEBUG(T), " %-16s %10s %10s %8s %8s %8s %10s\n",
+ "Conversion", "Elmts", "Calls", "User",
+ "System", "Elapsed", "Bandwidth");
+ HDfprintf(H5DEBUG(T), " %-16s %10s %10s %8s %8s %8s %10s\n",
+ "----------", "-----", "-----", "----",
+ "------", "-------", "---------");
+ } /* end if */
+
+ if(path->src && path->dst)
nbytes = MAX(H5T_get_size(path->src), H5T_get_size(path->dst));
else if (path->src)
nbytes = H5T_get_size(path->src);
@@ -121,18 +120,20 @@ H5T__print_stats(H5T_path_t H5_ATTR_UNUSED * path, int H5_ATTR_UNUSED * nprint/*
nbytes = H5T_get_size(path->dst);
else
nbytes = 0;
- nbytes *= path->stats.nelmts;
- H5_bandwidth(bandwidth, (double)nbytes, path->stats.timer.etime);
- HDfprintf(H5DEBUG(T), " %-16s %10Hd %10d %8.2f %8.2f %8.2f %10s\n",
- path->name,
- path->stats.nelmts,
- path->stats.ncalls,
- path->stats.timer.utime,
- path->stats.timer.stime,
- path->stats.timer.etime,
- bandwidth);
- }
+
+ nbytes *= path->stats.nelmts;
+ H5_bandwidth(bandwidth, (double)nbytes, path->stats.times.elapsed);
+ HDfprintf(H5DEBUG(T), " %-16s %10Hd %10d %8T %8T %8T %10s\n",
+ path->name,
+ path->stats.nelmts,
+ path->stats.ncalls,
+ path->stats.times.user,
+ path->stats.times.system,
+ path->stats.times.elapsed,
+ bandwidth);
+ } /* end if */
#endif
+
FUNC_LEAVE_NOAPI(SUCCEED)
} /* end H5T__print_stats() */
diff --git a/src/H5Tpkg.h b/src/H5Tpkg.h
index 39bff15..600d7aa 100644
--- a/src/H5Tpkg.h
+++ b/src/H5Tpkg.h
@@ -152,7 +152,7 @@
struct H5T_stats_t {
unsigned ncalls; /*num calls to conversion function */
hsize_t nelmts; /*total data points converted */
- H5_timer_t timer; /*total time for conversion */
+ H5_timevals_t times; /*total time for conversion */
};
/* Library internal datatype conversion functions are... */
diff --git a/src/H5Z.c b/src/H5Z.c
index 2f477a3..af5b888 100644
--- a/src/H5Z.c
+++ b/src/H5Z.c
@@ -35,10 +35,10 @@
#ifdef H5Z_DEBUG
typedef struct H5Z_stats_t {
struct {
- hsize_t total; /* total number of bytes processed */
- hsize_t errors; /* bytes of total attributable to errors */
- H5_timer_t timer; /* execution time including errors */
- } stats[2]; /* 0=output, 1=input */
+ hsize_t total; /* total number of bytes processed */
+ hsize_t errors; /* bytes of total attributable to errors */
+ H5_timevals_t times; /* execution time including errors */
+ } stats[2]; /* 0 = output, 1 = input */
} H5Z_stats_t;
#endif /* H5Z_DEBUG */
@@ -132,9 +132,9 @@ H5Z_term_package(void)
if(H5_PKG_INIT_VAR) {
#ifdef H5Z_DEBUG
- char comment[16], bandwidth[32];
- int dir, nprint = 0;
- size_t i;
+ char comment[16], bandwidth[32];
+ int dir, nprint = 0;
+ size_t i;
if(H5DEBUG(Z)) {
for(i = 0; i < H5Z_table_used_g; i++) {
@@ -142,50 +142,50 @@ H5Z_term_package(void)
if(0 == H5Z_stat_table_g[i].stats[dir].total)
continue;
- if(0 == nprint++) {
- /* Print column headers */
- HDfprintf(H5DEBUG(Z), "H5Z: filter statistics "
- "accumulated over life of library:\n");
- HDfprintf(H5DEBUG(Z),
- " %-16s %10s %10s %8s %8s %8s %10s\n",
- "Filter", "Total", "Errors", "User",
- "System", "Elapsed", "Bandwidth");
- HDfprintf(H5DEBUG(Z),
- " %-16s %10s %10s %8s %8s %8s %10s\n",
- "------", "-----", "------", "----",
- "------", "-------", "---------");
- } /* end if */
-
- /* Truncate the comment to fit in the field */
- HDstrncpy(comment, H5Z_table_g[i].name, sizeof comment);
- comment[sizeof(comment) - 1] = '\0';
-
- /*
- * Format bandwidth to have four significant digits and
- * units of `B/s', `kB/s', `MB/s', `GB/s', or `TB/s' or
- * the word `Inf' if the elapsed time is zero.
- */
- H5_bandwidth(bandwidth,
- (double)(H5Z_stat_table_g[i].stats[dir].total),
- H5Z_stat_table_g[i].stats[dir].timer.etime);
-
- /* Print the statistics */
- HDfprintf(H5DEBUG(Z),
- " %s%-15s %10Hd %10Hd %8.2f %8.2f %8.2f "
- "%10s\n", dir?"<":">", comment,
+ if(0 == nprint++) {
+ /* Print column headers */
+ HDfprintf(H5DEBUG(Z), "H5Z: filter statistics "
+ "accumulated over life of library:\n");
+ HDfprintf(H5DEBUG(Z),
+ " %-16s %10s %10s %8s %8s %8s %10s\n",
+ "Filter", "Total", "Errors", "User",
+ "System", "Elapsed", "Bandwidth");
+ HDfprintf(H5DEBUG(Z),
+ " %-16s %10s %10s %8s %8s %8s %10s\n",
+ "------", "-----", "------", "----",
+ "------", "-------", "---------");
+ } /* end if */
+
+ /* Truncate the comment to fit in the field */
+ HDstrncpy(comment, H5Z_table_g[i].name, sizeof comment);
+ comment[sizeof(comment) - 1] = '\0';
+
+ /*
+ * Format bandwidth to have four significant digits and
+ * units of `B/s', `kB/s', `MB/s', `GB/s', or `TB/s' or
+ * the word `Inf' if the elapsed time is zero.
+ */
+ H5_bandwidth(bandwidth, (double)(H5Z_stat_table_g[i].stats[dir].total),
+ H5Z_stat_table_g[i].stats[dir].times.elapsed);
+
+ /* Print the statistics */
+ HDfprintf(H5DEBUG(Z), " %s%-15s %10Hd %10Hd %8T %8T %8T %10s\n",
+ (dir ? "<" : ">"), comment,
H5Z_stat_table_g[i].stats[dir].total,
H5Z_stat_table_g[i].stats[dir].errors,
- H5Z_stat_table_g[i].stats[dir].timer.utime,
- H5Z_stat_table_g[i].stats[dir].timer.stime,
- H5Z_stat_table_g[i].stats[dir].timer.etime,
+ H5Z_stat_table_g[i].stats[dir].times.user,
+ H5Z_stat_table_g[i].stats[dir].times.system,
+ H5Z_stat_table_g[i].stats[dir].times.elapsed,
bandwidth);
- } /* end for */
- } /* end for */
- } /* end if */
+ } /* end for */
+ } /* end for */
+ } /* end if */
#endif /* H5Z_DEBUG */
- /* Free the table of filters */
- if (H5Z_table_g) {
+
+ /* Free the table of filters */
+ if(H5Z_table_g) {
H5Z_table_g = (H5Z_class2_t *)H5MM_xfree(H5Z_table_g);
+
#ifdef H5Z_DEBUG
H5Z_stat_table_g = (H5Z_stats_t *)H5MM_xfree(H5Z_stat_table_g);
#endif /* H5Z_DEBUG */
@@ -1248,20 +1248,22 @@ done:
*/
herr_t
H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
- unsigned *filter_mask/*in,out*/, H5Z_EDC_t edc_read,
- H5Z_cb_t cb_struct, size_t *nbytes/*in,out*/,
- size_t *buf_size/*in,out*/, void **buf/*in,out*/)
+ unsigned *filter_mask/*in,out*/, H5Z_EDC_t edc_read, H5Z_cb_t cb_struct,
+ size_t *nbytes/*in,out*/, size_t *buf_size/*in,out*/, void **buf/*in,out*/)
{
- size_t i, idx, new_nbytes;
- int fclass_idx; /* Index of filter class in global table */
- H5Z_class2_t *fclass=NULL; /* Filter class pointer */
+ size_t idx;
+ size_t new_nbytes;
+ int fclass_idx; /* Index of filter class in global table */
+ H5Z_class2_t *fclass = NULL; /* Filter class pointer */
#ifdef H5Z_DEBUG
- H5Z_stats_t *fstats=NULL; /* Filter stats pointer */
- H5_timer_t timer;
+ H5Z_stats_t *fstats = NULL; /* Filter stats pointer */
+ H5_timer_t timer; /* Timer for filter operations */
+ H5_timevals_t times; /* Elapsed time for each operation */
#endif
- unsigned failed = 0;
- unsigned tmp_flags;
- herr_t ret_value = SUCCEED; /* Return value */
+ unsigned failed = 0;
+ unsigned tmp_flags;
+ size_t i;
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI(FAIL)
@@ -1272,23 +1274,25 @@ H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
HDassert(buf && *buf);
HDassert(!pline || pline->nused < H5Z_MAX_NFILTERS);
- if (pline && (flags & H5Z_FLAG_REVERSE)) { /* Read */
- for (i = pline->nused; i > 0; --i) {
- idx = i-1;
-
- if (*filter_mask & ((unsigned)1 << idx)) {
- failed |= (unsigned)1 << idx;
- continue; /* filter excluded */
- }
+#ifdef H5Z_DEBUG
+ H5_timer_init(&timer);
+#endif
+ if(pline && (flags & H5Z_FLAG_REVERSE)) { /* Read */
+ for(i = pline->nused; i > 0; --i) {
+ idx = i - 1;
+ if(*filter_mask & ((unsigned)1 << idx)) {
+ failed |= (unsigned)1 << idx;
+ continue; /* filter excluded */
+ } /* end if */
/* If the filter isn't registered and the application doesn't
* indicate no plugin through HDF5_PRELOAD_PLUG (using the symbol "::"),
* try to load it dynamically and register it. Otherwise, return failure
*/
if ((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0) {
- hbool_t issue_error = FALSE;
H5PL_key_t key;
const H5Z_class2_t *filter_info;
+ hbool_t issue_error = FALSE;
/* Try loading the filter */
key.id = (int)(pline->filter[idx].id);
@@ -1298,9 +1302,9 @@ H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
HGOTO_ERROR(H5E_PLINE, H5E_CANTINIT, FAIL, "unable to register filter")
/* Search in the table of registered filters again to find the dynamic filter just loaded and registered */
- if ((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0)
+ if((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0)
issue_error = TRUE;
- }
+ } /* end if */
else
issue_error = TRUE;
@@ -1316,76 +1320,95 @@ H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
} /* end if */
fclass = &H5Z_table_g[fclass_idx];
+
#ifdef H5Z_DEBUG
fstats = &H5Z_stat_table_g[fclass_idx];
- H5_timer_begin (&timer);
+ H5_timer_start(&timer);
#endif
+
tmp_flags = flags | (pline->filter[idx].flags);
- tmp_flags |= (edc_read== H5Z_DISABLE_EDC) ? H5Z_FLAG_SKIP_EDC : 0;
- new_nbytes = (fclass->filter)(tmp_flags, pline->filter[idx].cd_nelmts,
- pline->filter[idx].cd_values, *nbytes, buf_size, buf);
+ tmp_flags |= (edc_read == H5Z_DISABLE_EDC) ? H5Z_FLAG_SKIP_EDC : 0;
+ new_nbytes = (fclass->filter)(tmp_flags,
+ pline->filter[idx].cd_nelmts, pline->filter[idx].cd_values,
+ *nbytes, buf_size, buf);
#ifdef H5Z_DEBUG
- H5_timer_end (&(fstats->stats[1].timer), &timer);
- fstats->stats[1].total += MAX(*nbytes, new_nbytes);
- if (0 == new_nbytes)
+ H5_timer_stop(&timer);
+ H5_timer_get_times(timer, &times);
+ fstats->stats[1].times.elapsed += times.elapsed;
+ fstats->stats[1].times.system += times.system;
+ fstats->stats[1].times.user += times.user;
+
+ fstats->stats[1].total += MAX(*nbytes, new_nbytes);
+ if(0 == new_nbytes)
fstats->stats[1].errors += *nbytes;
#endif
- if (0 == new_nbytes) {
- if ((cb_struct.func && (H5Z_CB_FAIL == cb_struct.func(pline->filter[idx].id, *buf, *buf_size, cb_struct.op_data))) || !cb_struct.func)
+ if(0 == new_nbytes) {
+ if((cb_struct.func
+ && (H5Z_CB_FAIL == cb_struct.func(pline->filter[idx].id, *buf, *buf_size, cb_struct.op_data)))
+ || !cb_struct.func)
HGOTO_ERROR(H5E_PLINE, H5E_READERROR, FAIL, "filter returned failure during read")
*nbytes = *buf_size;
failed |= (unsigned)1 << idx;
- H5E_clear_stack (NULL);
- }
+ H5E_clear_stack(NULL);
+ } /* end if */
else
*nbytes = new_nbytes;
- }
- }
- else if (pline) { /* Write */
- for (idx = 0; idx < pline->nused; idx++) {
- if (*filter_mask & ((unsigned)1 << idx)) {
- failed |= (unsigned)1 << idx;
- continue; /*filter excluded*/
- }
- if ((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0) {
+ } /* end for */
+ } else if (pline) { /* Write */
+ for(idx = 0; idx < pline->nused; idx++) {
+ if(*filter_mask & ((unsigned)1 << idx)) {
+ failed |= (unsigned)1 << idx;
+ continue; /* filter excluded */
+ } /* end if */
+ if((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0) {
/* Check if filter is optional -- If it isn't, then error */
- if ((pline->filter[idx].flags & H5Z_FLAG_OPTIONAL) == 0)
- HGOTO_ERROR(H5E_PLINE, H5E_WRITEERROR, FAIL, "required filter is not registered")
+ if((pline->filter[idx].flags & H5Z_FLAG_OPTIONAL) == 0)
+ HGOTO_ERROR(H5E_PLINE, H5E_WRITEERROR, FAIL, "required filter is not registered")
+ failed |= (unsigned)1 << idx;
+ H5E_clear_stack(NULL);
+ continue; /* filter excluded */
+ } /* end if */
- failed |= (unsigned)1 << idx;
- H5E_clear_stack (NULL);
- continue; /*filter excluded*/
- }
fclass = &H5Z_table_g[fclass_idx];
+
#ifdef H5Z_DEBUG
fstats = &H5Z_stat_table_g[fclass_idx];
- H5_timer_begin (&timer);
+ H5_timer_start(&timer);
#endif
- new_nbytes = (fclass->filter)(flags | (pline->filter[idx].flags), pline->filter[idx].cd_nelmts,
- pline->filter[idx].cd_values, *nbytes, buf_size, buf);
+
+ new_nbytes = (fclass->filter)(flags | (pline->filter[idx].flags),
+ pline->filter[idx].cd_nelmts, pline->filter[idx].cd_values,
+ *nbytes, buf_size, buf);
+
#ifdef H5Z_DEBUG
- H5_timer_end (&(fstats->stats[0].timer), &timer);
- fstats->stats[0].total += MAX(*nbytes, new_nbytes);
- if (0 == new_nbytes)
+ H5_timer_stop(&timer);
+ H5_timer_get_times(timer, &times);
+ fstats->stats[0].times.elapsed += times.elapsed;
+ fstats->stats[0].times.system += times.system;
+ fstats->stats[0].times.user += times.user;
+
+ fstats->stats[0].total += MAX(*nbytes, new_nbytes);
+ if(0 == new_nbytes)
fstats->stats[0].errors += *nbytes;
#endif
- if (0 == new_nbytes) {
- if (0 == (pline->filter[idx].flags & H5Z_FLAG_OPTIONAL)) {
- if ((cb_struct.func && (H5Z_CB_FAIL == cb_struct.func (pline->filter[idx].id, *buf, *nbytes, cb_struct.op_data))) || !cb_struct.func)
+
+ if(0 == new_nbytes) {
+ if(0 == (pline->filter[idx].flags & H5Z_FLAG_OPTIONAL)) {
+ if((cb_struct.func && (H5Z_CB_FAIL==cb_struct.func(pline->filter[idx].id, *buf, *nbytes, cb_struct.op_data)))
+ || !cb_struct.func)
HGOTO_ERROR(H5E_PLINE, H5E_WRITEERROR, FAIL, "filter returned failure")
*nbytes = *buf_size;
- }
-
+ } /* end if */
failed |= (unsigned)1 << idx;
- H5E_clear_stack (NULL);
- }
+ H5E_clear_stack(NULL);
+ } /* end if */
else
*nbytes = new_nbytes;
- }
+ } /* end for */
}
*filter_mask = failed;
diff --git a/src/H5private.h b/src/H5private.h
index dc7ca57..836d7d5 100644
--- a/src/H5private.h
+++ b/src/H5private.h
@@ -614,21 +614,37 @@
#define LOCK_UN 0x08
#endif /* H5_HAVE_FLOCK */
-/*
- * Data types and functions for timing certain parts of the library.
+/* Typedefs and functions for timing certain parts of the library. */
+
+/* A set of elapsed/user/system times emitted as a time point by the
+ * platform-independent timers.
*/
typedef struct {
- double utime; /*user time */
- double stime; /*system time */
- double etime; /*elapsed wall-clock time */
+ double user; /* User time in seconds */
+ double system; /* System time in seconds */
+ double elapsed; /* Elapsed (wall clock) time in seconds */
+} H5_timevals_t;
+
+/* Timer structure for platform-independent timers */
+typedef struct {
+ H5_timevals_t initial; /* Current interval start time */
+ H5_timevals_t final_interval; /* Last interval elapsed time */
+ H5_timevals_t total; /* Total elapsed time for all intervals */
+ hbool_t is_running; /* Whether timer is running */
} H5_timer_t;
-H5_DLL void H5_timer_reset (H5_timer_t *timer);
-H5_DLL void H5_timer_begin (H5_timer_t *timer);
-H5_DLL void H5_timer_end (H5_timer_t *sum/*in,out*/,
- H5_timer_t *timer/*in,out*/);
+/* Returns library bandwidth as a pretty string */
H5_DLL void H5_bandwidth(char *buf/*out*/, double nbytes, double nseconds);
+
+/* Timer functionality */
H5_DLL time_t H5_now(void);
+H5_DLL uint64_t H5_now_usec(void);
+H5_DLL herr_t H5_timer_init(H5_timer_t *timer /*in,out*/);
+H5_DLL herr_t H5_timer_start(H5_timer_t *timer /*in,out*/);
+H5_DLL herr_t H5_timer_stop(H5_timer_t *timer /*in,out*/);
+H5_DLL herr_t H5_timer_get_times(H5_timer_t timer, H5_timevals_t *times /*in,out*/);
+H5_DLL herr_t H5_timer_get_total_times(H5_timer_t timer, H5_timevals_t *times /*in,out*/);
+H5_DLL char *H5_timer_get_time_string(double seconds);
/* Depth of object copy */
typedef enum {
@@ -750,6 +766,9 @@ typedef struct {
#ifndef HDclock
#define HDclock() clock()
#endif /* HDclock */
+#ifndef HDclock_gettime
+ #define HDclock_gettime(CID, TS) clock_gettime(CID, TS)
+#endif /* HDclock_gettime */
#ifndef HDclose
#define HDclose(F) close(F)
#endif /* HDclose */
diff --git a/src/H5system.c b/src/H5system.c
index ca0c6bf..b3db39c 100644
--- a/src/H5system.c
+++ b/src/H5system.c
@@ -13,11 +13,11 @@
/*-------------------------------------------------------------------------
*
- * Created: H5system.c
- * Aug 21 2006
- * Quincey Koziol <koziol@hdfgroup.org>
+ * Created: H5system.c
+ * Aug 21 2006
+ * Quincey Koziol <koziol@hdfgroup.org>
*
- * Purpose: System call wrapper implementations.
+ * Purpose: System call wrapper implementations.
*
*-------------------------------------------------------------------------
*/
@@ -30,10 +30,10 @@
/***********/
/* Headers */
/***********/
-#include "H5private.h" /* Generic Functions */
-#include "H5Eprivate.h" /* Error handling */
-#include "H5Fprivate.h" /* File access */
-#include "H5MMprivate.h" /* Memory management */
+#include "H5private.h" /* Generic Functions */
+#include "H5Eprivate.h" /* Error handling */
+#include "H5Fprivate.h" /* File access */
+#include "H5MMprivate.h" /* Memory management */
/****************/
@@ -379,7 +379,7 @@ HDfprintf(FILE *stream, const char *fmt, ...)
if(fwidth)
len += HDsnprintf(format_templ + len, (sizeof(format_templ) - (size_t)(len + 1)), "%d", fwidth);
HDstrncat(format_templ, "s", (sizeof(format_templ) - (size_t)(len + 1)));
- fprintf(stream, format_templ, "UNDEF");
+ n = fprintf(stream, format_templ, "UNDEF");
}
}
break;
@@ -409,11 +409,25 @@ HDfprintf(FILE *stream, const char *fmt, ...)
htri_t tri_var = HDva_arg(ap, htri_t);
if(tri_var > 0)
- fprintf(stream, "TRUE");
+ n = fprintf(stream, "TRUE");
else if(!tri_var)
- fprintf(stream, "FALSE");
+ n = fprintf(stream, "FALSE");
else
- fprintf(stream, "FAIL(%d)", (int)tri_var);
+ n = fprintf(stream, "FAIL(%d)", (int)tri_var);
+ }
+ break;
+
+ case 'T': /* Elapsed time, in seconds */
+ {
+ double seconds = HDva_arg(ap, double);
+ char *time_string = H5_timer_get_time_string(seconds);
+
+ if(time_string) {
+ n = fprintf(stream, format_templ, time_string);
+ HDfree(time_string);
+ } /* end if */
+ else
+ n = fprintf(stream, format_templ, "(error)");
}
break;
@@ -861,11 +875,88 @@ Wsetenv(const char *name, const char *value, int overwrite)
#pragma comment(lib, "advapi32.lib")
#endif
+
+/*-------------------------------------------------------------------------
+ * Function: H5_get_win32_times
+ *
+ * Purpose: Gets the elapsed, system and user times on Windows platforms.
+ * All time values are in seconds.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifdef H5_HAVE_WIN32_API
+int
+H5_get_win32_times(H5_timevals_t *tvs /*in,out*/)
+{
+ static HANDLE process_handle;
+ ULARGE_INTEGER kernel_start;
+ ULARGE_INTEGER user_start;
+ FILETIME KernelTime;
+ FILETIME UserTime;
+ FILETIME CreationTime;
+ FILETIME ExitTime;
+ LARGE_INTEGER counts_start;
+ static LARGE_INTEGER counts_freq;
+ static hbool_t is_initialized = FALSE;
+ BOOL err;
+
+ HDassert(tvs);
+
+ if(!is_initialized) {
+ /* NOTE: This is just a pseudo handle and does not need to be closed. */
+ process_handle = GetCurrentProcess();
+ err = QueryPerformanceFrequency(&counts_freq);
+ if(0 == err)
+ return -1;
+ is_initialized = TRUE;
+ } /* end if */
+
+ /*************************
+ * System and user times *
+ *************************/
+
+ err = GetProcessTimes(process_handle, &CreationTime, &ExitTime, &KernelTime,
+ &UserTime);
+ if(0 == err)
+ return -1;
+
+ /* The 1.0E7 factor seems strange but it's due to the clock
+ * ticking in 100 ns increments.
+ */
+ kernel_start.HighPart = KernelTime.dwHighDateTime;
+ kernel_start.LowPart = KernelTime.dwLowDateTime;
+ tvs->system = (double)(kernel_start.QuadPart / 1.0E7F);
+
+ user_start.HighPart = UserTime.dwHighDateTime;
+ user_start.LowPart = UserTime.dwLowDateTime;
+ tvs->user = (double)(user_start.QuadPart / 1.0E7F);
+
+ /****************
+ * Elapsed time *
+ ****************/
+
+ err = QueryPerformanceCounter(&counts_start);
+ if(0 == err)
+ return -1;
+
+ tvs->elapsed = (double)(counts_start.QuadPart) / (double)counts_freq.QuadPart;
+
+ return 0;
+} /* end H5_get_win32_times() */
+#endif
+
#define WloginBuffer_count 256
static char Wlogin_buffer[WloginBuffer_count];
+
char*
-Wgetlogin()
+Wgetlogin(void)
{
#ifdef H5_HAVE_WINSOCK2_H
@@ -1370,38 +1461,6 @@ H5_nanosleep(uint64_t nanosec)
FUNC_LEAVE_NOAPI_VOID
} /* end H5_nanosleep() */
-
-/*--------------------------------------------------------------------------
- * Function: H5_get_time
- *
- * Purpose: Get the current time, as the time of seconds after the UNIX epoch
- *
- * Return: SUCCEED/FAIL
- *
- * Programmer: Quincey Koziol
- * October 05, 2016
- *--------------------------------------------------------------------------
- */
-double
-H5_get_time(void)
-{
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval curr_time;
-#endif /* H5_HAVE_GETTIMEOFDAY */
- double ret_value = (double)0.0f;
-
- FUNC_ENTER_NOAPI_NOINIT_NOERR
-
-#ifdef H5_HAVE_GETTIMEOFDAY
- HDgettimeofday(&curr_time, NULL);
-
- ret_value = (double)curr_time.tv_sec + ((double)curr_time.tv_usec / (double)1000000.0f);
-#endif /* H5_HAVE_GETTIMEOFDAY */
-
- FUNC_LEAVE_NOAPI(ret_value)
-} /* end H5_get_time() */
-
-
#ifdef H5_HAVE_WIN32_API
#define H5_WIN32_ENV_VAR_BUFFER_SIZE 32767
diff --git a/src/H5timer.c b/src/H5timer.c
index 4b1ec06..8f3d305 100644
--- a/src/H5timer.c
+++ b/src/H5timer.c
@@ -12,12 +12,11 @@
* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */
/*-------------------------------------------------------------------------
- *
* Created: H5timer.c
* Aug 21 2006
* Quincey Koziol <koziol@hdfgroup.org>
*
- * Purpose: Internal 'timer' routines & support routines.
+ * Purpose: Internal, platform-independent 'timer' support routines.
*
*-------------------------------------------------------------------------
*/
@@ -32,20 +31,22 @@
/***********/
#include "H5private.h" /* Generic Functions */
-/* We need this for the struct rusage declaration */
-#if defined(H5_HAVE_GETRUSAGE) && defined(H5_HAVE_SYS_RESOURCE_H)
-# include <sys/resource.h>
-#endif
-
-#if defined(H5_HAVE_GETTIMEOFDAY) && defined(H5_HAVE_SYS_TIME_H)
-#include <sys/time.h>
-#endif
-
/****************/
/* Local Macros */
/****************/
+/* Size of a generated time string.
+ * Most time strings should be < 20 or so characters (max!) so this should be a
+ * safe size. Dynamically allocating the correct size would be painful.
+ */
+#define H5TIMER_TIME_STRING_LEN 1536
+
+/* Conversion factors */
+#define H5_SEC_PER_DAY (double)(24.0F * 60.0F * 60.0F)
+#define H5_SEC_PER_HOUR (double)(60.0F * 60.0F)
+#define H5_SEC_PER_MIN (double)(60.0F)
+
/******************/
/* Local Typedefs */
@@ -76,104 +77,6 @@
/* Local Variables */
/*******************/
-
-/*-------------------------------------------------------------------------
- * Function: H5_timer_reset
- *
- * Purpose: Resets the timer struct to zero. Use this to reset a timer
- * that's being used as an accumulator for summing times.
- *
- * Return: void
- *
- * Programmer: Robb Matzke
- * Thursday, April 16, 1998
- *
- *-------------------------------------------------------------------------
- */
-void
-H5_timer_reset (H5_timer_t *timer)
-{
- HDassert(timer);
- HDmemset(timer, 0, sizeof *timer);
-} /* end H5_timer_reset() */
-
-
-/*-------------------------------------------------------------------------
- * Function: H5_timer_begin
- *
- * Purpose: Initialize a timer to time something.
- *
- * Return: void
- *
- * Programmer: Robb Matzke
- * Thursday, April 16, 1998
- *
- *-------------------------------------------------------------------------
- */
-void
-H5_timer_begin (H5_timer_t *timer)
-{
-#ifdef H5_HAVE_GETRUSAGE
- struct rusage rusage;
-#endif
-#ifdef H5_HAVE_GETTIMEOFDAY
- struct timeval etime;
-#endif
-
- HDassert(timer);
-
-#ifdef H5_HAVE_GETRUSAGE
- HDgetrusage (RUSAGE_SELF, &rusage);
- timer->utime = (double)rusage.ru_utime.tv_sec +
- ((double)rusage.ru_utime.tv_usec / (double)1e6F);
- timer->stime = (double)rusage.ru_stime.tv_sec +
- ((double)rusage.ru_stime.tv_usec / (double)1e6F);
-#else
- timer->utime = 0.0F;
- timer->stime = 0.0F;
-#endif
-#ifdef H5_HAVE_GETTIMEOFDAY
- HDgettimeofday (&etime, NULL);
- timer->etime = (double)etime.tv_sec + ((double)etime.tv_usec / (double)1e6F);
-#else
- timer->etime = 0.0F;
-#endif
-} /* end H5_timer_begin() */
-
-
-/*-------------------------------------------------------------------------
- * Function: H5_timer_end
- *
- * Purpose: This function should be called at the end of a timed region.
- * The SUM is an optional pointer which will accumulate times.
- * TMS is the same struct that was passed to H5_timer_start().
- * On return, TMS will contain total times for the timed region.
- *
- * Return: void
- *
- * Programmer: Robb Matzke
- * Thursday, April 16, 1998
- *
- *-------------------------------------------------------------------------
- */
-void
-H5_timer_end (H5_timer_t *sum/*in,out*/, H5_timer_t *timer/*in,out*/)
-{
- H5_timer_t now;
-
- HDassert(timer);
- H5_timer_begin(&now);
-
- timer->utime = MAX((double)0.0F, now.utime - timer->utime);
- timer->stime = MAX((double)0.0F, now.stime - timer->stime);
- timer->etime = MAX((double)0.0F, now.etime - timer->etime);
-
- if (sum) {
- sum->utime += timer->utime;
- sum->stime += timer->stime;
- sum->etime += timer->etime;
- }
-} /* end H5_timer_end() */
/*-------------------------------------------------------------------------
@@ -209,32 +112,35 @@ H5_bandwidth(char *buf/*out*/, double nbytes, double nseconds)
if(nseconds <= (double)0.0F)
HDstrcpy(buf, " NaN");
else {
- bw = nbytes/nseconds;
+ bw = nbytes / nseconds;
if(H5_DBL_ABS_EQUAL(bw, (double)0.0F))
HDstrcpy(buf, "0.000 B/s");
else if(bw < (double)1.0F)
HDsprintf(buf, "%10.4e", bw);
else if(bw < (double)H5_KB) {
HDsprintf(buf, "%05.4f", bw);
- HDstrcpy(buf+5, " B/s");
+ HDstrcpy(buf + 5, " B/s");
} else if(bw < (double)H5_MB) {
HDsprintf(buf, "%05.4f", bw / (double)H5_KB);
- HDstrcpy(buf+5, " kB/s");
+ HDstrcpy(buf + 5, " kB/s");
} else if(bw < (double)H5_GB) {
HDsprintf(buf, "%05.4f", bw / (double)H5_MB);
- HDstrcpy(buf+5, " MB/s");
+ HDstrcpy(buf + 5, " MB/s");
} else if(bw < (double)H5_TB) {
HDsprintf(buf, "%05.4f", bw / (double)H5_GB);
- HDstrcpy(buf+5, " GB/s");
+ HDstrcpy(buf + 5, " GB/s");
} else if(bw < (double)H5_PB) {
HDsprintf(buf, "%05.4f", bw / (double)H5_TB);
- HDstrcpy(buf+5, " TB/s");
+ HDstrcpy(buf + 5, " TB/s");
+ } else if(bw < (double)H5_EB) {
+ HDsprintf(buf, "%05.4f", bw / (double)H5_PB);
+ HDstrcpy(buf + 5, " PB/s");
} else {
HDsprintf(buf, "%10.4e", bw);
if(HDstrlen(buf) > 10)
HDsprintf(buf, "%10.3e", bw);
- }
- }
+ } /* end else-if */
+ } /* end else */
} /* end H5_bandwidth() */
@@ -269,3 +175,503 @@ H5_now(void)
return(now);
} /* end H5_now() */
+
+/*-------------------------------------------------------------------------
+ * Function: H5_now_usec
+ *
+ * Purpose: Retrieves the current time, as microseconds after the UNIX epoch.
+ *
+ * Return: # of microseconds from the epoch (can't fail)
+ *
+ * Programmer: Quincey Koziol
+ * Tuesday, November 28, 2006
+ *
+ *-------------------------------------------------------------------------
+ */
+uint64_t
+H5_now_usec(void)
+{
+ uint64_t now; /* Current time, in microseconds */
+
+#if defined(H5_HAVE_CLOCK_GETTIME)
+ {
+ struct timespec ts;
+
+ HDclock_gettime(CLOCK_MONOTONIC, &ts);
+ now = (uint64_t)(ts.tv_sec * (1000 * 1000)) + (uint64_t)(ts.tv_nsec / 1000);
+ }
+#elif defined(H5_HAVE_GETTIMEOFDAY)
+ {
+ struct timeval now_tv;
+
+ HDgettimeofday(&now_tv, NULL);
+ now = (uint64_t)(now_tv.tv_sec * (1000 * 1000)) + (uint64_t)now_tv.tv_usec;
+ }
+#else /* H5_HAVE_GETTIMEOFDAY */
+ now = (uint64_t)(HDtime(NULL) * (1000 * 1000));
+#endif /* H5_HAVE_GETTIMEOFDAY */
+
+ return(now);
+} /* end H5_now_usec() */
+
+
+/*--------------------------------------------------------------------------
+ * Function: H5_get_time
+ *
+ * Purpose: Get the current time, as the time of seconds after the UNIX epoch
+ *
+ * Return: SUCCEED/FAIL
+ *
+ * Programmer: Quincey Koziol
+ * October 05, 2016
+ *--------------------------------------------------------------------------
+ */
+double
+H5_get_time(void)
+{
+ double ret_value = (double)0.0f;
+
+ FUNC_ENTER_NOAPI_NOINIT_NOERR
+
+#if defined(H5_HAVE_CLOCK_GETTIME)
+ {
+ struct timespec ts;
+
+ HDclock_gettime(CLOCK_MONOTONIC, &ts);
+ ret_value = (double)ts.tv_sec + ((double)ts.tv_nsec / (double)1000000000.0f);
+ }
+#elif defined(H5_HAVE_GETTIMEOFDAY)
+ {
+ struct timeval now_tv;
+
+ HDgettimeofday(&now_tv, NULL);
+ ret_value = (double)now_tv.tv_sec + ((double)now_tv.tv_usec / (double)1000000.0f);
+ }
+#else /* H5_HAVE_GETTIMEOFDAY */
+ ret_value = (double)HDtime(NULL);
+#endif /* H5_HAVE_GETTIMEOFDAY */
+
+ FUNC_LEAVE_NOAPI(ret_value)
+} /* end H5_get_time() */
+
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5__timer_get_timevals
+ *
+ * Purpose: Internal platform-specific function to get time system,
+ * user and elapsed time values.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+static herr_t
+H5__timer_get_timevals(H5_timevals_t *times /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(times);
+
+ /* Windows call handles both system/user and elapsed times */
+#ifdef H5_HAVE_WIN32_API
+ if(H5_get_win32_times(times) < 0) {
+ times->elapsed = -1;
+ times->system = -1;
+ times->user = -1;
+
+ return -1;
+ } /* end if */
+#else /* H5_HAVE_WIN32_API */
+
+ /*************************
+ * System and user times *
+ *************************/
+#if defined(H5_HAVE_GETRUSAGE)
+{
+ struct rusage res;
+
+ if(HDgetrusage(RUSAGE_SELF, &res) < 0)
+ return -1;
+ times->system = (double)res.ru_stime.tv_sec + ((double)res.ru_stime.tv_usec / (double)1.0E6F);
+ times->user = (double)res.ru_utime.tv_sec + ((double)res.ru_utime.tv_usec / (double)1.0E6F);
+}
+#else
+ /* No suitable way to get system/user times */
+ /* This is not an error condition, they just won't be available */
+ times->system = -1.0;
+ times->user = -1.0;
+#endif
+
+ /****************
+ * Elapsed time *
+ ****************/
+
+ /* NOTE: Not having a way to get elapsed time IS an error, unlike
+ * the system and user times.
+ */
+
+#if defined(H5_HAVE_CLOCK_GETTIME)
+{
+ struct timespec ts;
+
+ if(HDclock_gettime(CLOCK_MONOTONIC, &ts) != 0)
+ return -1;
+ times->elapsed = (double)ts.tv_sec + ((double)ts.tv_nsec / (double)1.0E9F);
+}
+#else
+ /* Die here. We'd like to know about this so we can support some
+ * other time functionality.
+ */
+ HDassert(0);
+#endif
+#endif /* H5_HAVE_WIN32_API */
+
+ return 0;
+} /* end H5__timer_get_timevals() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_init
+ *
+ * Purpose: Initialize a platform-independent timer.
+ *
+ * Timer usage is as follows:
+ *
+ * 1) Call H5_timer_init(), passing in a timer struct, to set
+ * up the timer.
+ *
+ * 2) Wrap any code you'd like to time with calls to
+ * H5_timer_start/stop(). For accurate timing, place these
+ * calls as close to the code of interest as possible. You
+ * can call start/stop multiple times on the same timer -
+ * when you do this, H5_timer_get_times() will return time
+ * values for the current/last session and
+ * H5_timer_get_total_times() will return the summed times
+ * of all sessions (see #3 and #4, below).
+ *
+ * 3) Use H5_timer_get_times() to get the current system, user
+ * and elapsed times from a running timer. If called on a
+ * stopped timer, this will return the time recorded at the
+ * stop point.
+ *
+ * 4) Call H5_timer_get_total_times() to get the total system,
+ * user and elapsed times recorded across multiple start/stop
+ * sessions. If called on a running timer, it will return the
+ * time recorded up to that point. On a stopped timer, it
+ * will return the time recorded at the stop point.
+ *
+ * NOTE: Obtaining a time point is not free! Keep in mind that
+ * the time functions make system calls and can have
+ * non-trivial overhead. If you call one of the get_time
+ * functions on a running timer, that overhead will be
+ * added to the reported times.
+ *
+ * 5) All times recorded will be in seconds. These can be
+ * converted into human-readable strings with the
+ * H5_timer_get_time_string() function.
+ *
+ * 6) A timer can be reset using by calling H5_timer_init() on
+ * it. This will set its state to 'stopped' and reset all
+ * accumulated times to zero.
+ *
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+herr_t
+H5_timer_init(H5_timer_t *timer /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(timer);
+
+ /* Initialize everything */
+ HDmemset(timer, 0, sizeof(H5_timer_t));
+
+ return 0;
+} /* end H5_timer_init() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_start
+ *
+ * Purpose: Start tracking time in a platform-independent timer.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+herr_t
+H5_timer_start(H5_timer_t *timer /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(timer);
+
+ /* Start the timer
+ * This sets the "initial" times to the system-defined start times.
+ */
+ if(H5__timer_get_timevals(&(timer->initial)) < 0)
+ return -1;
+
+ timer->is_running = TRUE;
+
+ return 0;
+} /* end H5_timer_start() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_stop
+ *
+ * Purpose: Stop tracking time in a platform-independent timer.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+herr_t
+H5_timer_stop(H5_timer_t *timer /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(timer);
+
+ /* Stop the timer */
+ if(H5__timer_get_timevals(&(timer->final_interval)) < 0)
+ return -1;
+
+ /* The "final" times are stored as intervals (final - initial)
+ * for more useful reporting to the user.
+ */
+ timer->final_interval.elapsed = timer->final_interval.elapsed - timer->initial.elapsed;
+ timer->final_interval.system = timer->final_interval.system - timer->initial.system;
+ timer->final_interval.user = timer->final_interval.user - timer->initial.user;
+
+ /* Add the intervals to the elapsed time */
+ timer->total.elapsed += timer->final_interval.elapsed;
+ timer->total.system += timer->final_interval.system;
+ timer->total.user += timer->final_interval.user;
+
+ timer->is_running = FALSE;
+
+ return 0;
+} /* end H5_timer_stop() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_get_times
+ *
+ * Purpose: Get the system, user and elapsed times from a timer. These
+ * are the times since the timer was last started and will be
+ * 0.0 in a timer that has not been started since it was
+ * initialized.
+ *
+ * This function can be called either before or after
+ * H5_timer_stop() has been called. If it is called before the
+ * stop function, the timer will continue to run.
+ *
+ * The system and user times will be -1.0 if those times cannot
+ * be computed on a particular platform. The elapsed time will
+ * always be present.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+herr_t
+H5_timer_get_times(H5_timer_t timer, H5_timevals_t *times /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(times);
+
+ if(timer.is_running) {
+ H5_timevals_t now;
+
+ /* Get the current times and report the current intervals without
+ * stopping the timer.
+ */
+ if(H5__timer_get_timevals(&now) < 0)
+ return -1;
+
+ times->elapsed = now.elapsed - timer.initial.elapsed;
+ times->system = now.system - timer.initial.system;
+ times->user = now.user - timer.initial.user;
+ } /* end if */
+ else {
+ times->elapsed = timer.final_interval.elapsed;
+ times->system = timer.final_interval.system;
+ times->user = timer.final_interval.user;
+ } /* end else */
+
+ return 0;
+} /* end H5_timer_get_times() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_get_total_times
+ *
+ * Purpose: Get the TOTAL system, user and elapsed times recorded by
+ * the timer since its initialization. This is the sum of all
+ * times recorded while the timer was running.
+ *
+ * These will be 0.0 in a timer that has not been started
+ * since it was initialized. Calling H5_timer_init() on a
+ * timer will reset these values to 0.0.
+ *
+ * This function can be called either before or after
+ * H5_timer_stop() has been called. If it is called before the
+ * stop function, the timer will continue to run.
+ *
+ * The system and user times will be -1.0 if those times cannot
+ * be computed on a particular platform. The elapsed time will
+ * always be present.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+herr_t
+H5_timer_get_total_times(H5_timer_t timer, H5_timevals_t *times /*in,out*/)
+{
+ /* Sanity check */
+ HDassert(times);
+
+ if(timer.is_running) {
+ H5_timevals_t now;
+
+ /* Get the current times and report the current totals without
+ * stopping the timer.
+ */
+ if(H5__timer_get_timevals(&now) < 0)
+ return -1;
+
+ times->elapsed = timer.total.elapsed + (now.elapsed - timer.initial.elapsed);
+ times->system = timer.total.system + (now.system - timer.initial.system);
+ times->user = timer.total.user + (now.user - timer.initial.user);
+ } /* end if */
+ else {
+ times->elapsed = timer.total.elapsed;
+ times->system = timer.total.system;
+ times->user = timer.total.user;
+ } /* end else */
+
+ return 0;
+} /* end H5_timer_get_total_times() */
+
+
+/*-------------------------------------------------------------------------
+ * Function: H5_timer_get_time_string
+ *
+ * Purpose: Converts a time (in seconds) into a human-readable string
+ * suitable for log messages.
+ *
+ * Return: Success: The time string.
+ *
+ * The general format of the time string is:
+ *
+ * "N/A" time < 0 (invalid time)
+ * "%.f ns" time < 1 microsecond
+ * "%.1f us" time < 1 millisecond
+ * "%.1f ms" time < 1 second
+ * "%.2f s" time < 1 minute
+ * "%.f m %.f s" time < 1 hour
+ * "%.f h %.f m %.f s" longer times
+ *
+ * Failure: NULL
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+char *
+H5_timer_get_time_string(double seconds)
+{
+ char *s; /* output string */
+
+ /* Used when the time is greater than 59 seconds */
+ double days;
+ double hours;
+ double minutes;
+ double remainder_sec;
+
+ /* Extract larger time units from count of seconds */
+ if(seconds > (double)60.0F) {
+ /* Set initial # of seconds */
+ remainder_sec = seconds;
+
+ /* Extract days */
+ days = HDfloor(remainder_sec / H5_SEC_PER_DAY);
+ remainder_sec -= (days * H5_SEC_PER_DAY);
+
+ /* Extract hours */
+ hours = HDfloor(remainder_sec / H5_SEC_PER_HOUR);
+ remainder_sec -= (hours * H5_SEC_PER_HOUR);
+
+ /* Extract minutes */
+ minutes = HDfloor(remainder_sec / H5_SEC_PER_MIN);
+ remainder_sec -= (minutes * H5_SEC_PER_MIN);
+
+ /* The # of seconds left is in remainder_sec */
+ } /* end if */
+
+ /* Allocate */
+ if(NULL == (s = (char *)HDcalloc(H5TIMER_TIME_STRING_LEN, sizeof(char))))
+ return NULL;
+
+ /* Do we need a format string? Some people might like a certain
+ * number of milliseconds or s before spilling to the next highest
+ * time unit. Perhaps this could be passed as an integer.
+ * (name? round_up_size? ?)
+ */
+ if(seconds < (double)0.0F)
+ HDsprintf(s, "N/A");
+ else if(H5_DBL_ABS_EQUAL((double)0.0F, seconds))
+ HDsprintf(s, "0.0 s");
+ else if(seconds < (double)1.0E-6F)
+ /* t < 1 us, Print time in ns */
+ HDsprintf(s, "%.f ns", seconds * (double)1.0E9F);
+ else if(seconds < (double)1.0E-3F)
+ /* t < 1 ms, Print time in us */
+ HDsprintf(s, "%.1f us", seconds * (double)1.0E6F);
+ else if(seconds < (double)1.0F)
+ /* t < 1 s, Print time in ms */
+ HDsprintf(s, "%.1f ms", seconds * (double)1.0E3F);
+ else if(seconds < H5_SEC_PER_MIN)
+ /* t < 1 m, Print time in s */
+ HDsprintf(s, "%.2f s", seconds);
+ else if(seconds < H5_SEC_PER_HOUR)
+ /* t < 1 h, Print time in m and s */
+ HDsprintf(s, "%.f m %.f s", minutes, remainder_sec);
+ else if(seconds < H5_SEC_PER_DAY)
+ /* t < 1 d, Print time in h, m and s */
+ HDsprintf(s, "%.f h %.f m %.f s", hours, minutes, remainder_sec);
+ else
+ /* Print time in d, h, m and s */
+ HDsprintf(s, "%.f d %.f h %.f m %.f s", days, hours, minutes, remainder_sec);
+
+ return s;
+} /* end H5_timer_get_time_string() */
+
diff --git a/src/H5trace.c b/src/H5trace.c
index f9f96e2..91019a4 100644
--- a/src/H5trace.c
+++ b/src/H5trace.c
@@ -127,8 +127,11 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
hssize_t i;
void *vp = NULL;
FILE *out = H5_debug_g.trace;
- H5_timer_t event_time;
- static H5_timer_t first_time = {0.0F, 0.0F, 0.0F};
+ static hbool_t is_first_invocation = TRUE;
+ H5_timer_t function_timer;
+ H5_timevals_t function_times;
+ static H5_timer_t running_timer;
+ H5_timevals_t running_times;
static int current_depth = 0;
static int last_call_depth = 0;
@@ -154,13 +157,18 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
} /* end else */
} /* end if */
- /* Get time for event */
- if(H5_DBL_ABS_EQUAL(first_time.etime, (double)0.0f))
- H5_timer_begin(&first_time);
- if(H5_debug_g.ttimes)
- H5_timer_begin(&event_time);
- else
- HDmemset(&event_time, 0, sizeof event_time);
+ /* Get time for event if the trace times flag is set */
+ if(is_first_invocation && H5_debug_g.ttimes) {
+ /* start the library-wide timer */
+ is_first_invocation = FALSE;
+ H5_timer_init(&running_timer);
+ H5_timer_start(&running_timer);
+ } /* end if */
+ if(H5_debug_g.ttimes) {
+ /* start the timer for this function */
+ H5_timer_init(&function_timer);
+ H5_timer_start(&function_timer);
+ } /* end if */
/* Print the first part of the line. This is the indication of the
* nesting depth followed by the function name and either start of
@@ -176,7 +184,9 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
if(H5_debug_g.ttimes) {
char tmp[320];
- HDsprintf(tmp, "%.6f", event_time.etime-first_time.etime);
+ H5_timer_get_times(function_timer, &function_times);
+ H5_timer_get_times(running_timer, &running_times);
+ HDsprintf(tmp, "%.6f", (function_times.elapsed - running_times.elapsed));
HDfprintf(out, " %*s ", (int)HDstrlen(tmp), "");
} /* end if */
for(i = 0; i < current_depth; i++)
@@ -191,8 +201,11 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
else {
if(current_depth>last_call_depth)
HDfputs(" = <delayed>\n", out);
- if(H5_debug_g.ttimes)
- HDfprintf(out, "@%.6f ", event_time.etime - first_time.etime);
+ if(H5_debug_g.ttimes) {
+ H5_timer_get_times(function_timer, &function_times);
+ H5_timer_get_times(running_timer, &running_times);
+ HDfprintf(out, "@%.6f ", (function_times.elapsed - running_times.elapsed));
+ } /* end if */
for(i = 0; i < current_depth; i++)
HDfputc('+', out);
HDfprintf(out, "%*s%s(", 2*current_depth, "", func);
@@ -3686,9 +3699,12 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
} /* end for */
/* Display event time for return */
- if(returning && H5_debug_g.ttimes)
- HDfprintf(out, " @%.6f [dt=%.6f]", (event_time.etime - first_time.etime),
- (event_time.etime - *returning));
+ if(returning && H5_debug_g.ttimes) {
+ H5_timer_get_times(function_timer, &function_times);
+ H5_timer_get_times(running_timer, &running_times);
+ HDfprintf(out, " @%.6f [dt=%.6f]", (function_times.elapsed - running_times.elapsed),
+ (function_times.elapsed - *returning));
+ } /* end if */
error:
HDva_end(ap);
@@ -3700,6 +3716,9 @@ error:
} /* end else */
HDfflush(out);
- return event_time.etime;
+ if(H5_debug_g.ttimes)
+ return function_times.elapsed;
+ else
+ return 0.0F;
} /* end H5_trace() */