summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorQuincey Koziol <koziol@hdfgroup.org>2017-09-03 07:53:28 (GMT)
committerQuincey Koziol <koziol@hdfgroup.org>2017-09-03 07:53:28 (GMT)
commitd5c3ec8b93296987b443efb45fe1d7726c268183 (patch)
tree7e6b7de16903266fe72de9fbcb3b194714432653
parent289007567e6ab5e0893af787b1870f27f10644c7 (diff)
downloadhdf5-d5c3ec8b93296987b443efb45fe1d7726c268183.zip
hdf5-d5c3ec8b93296987b443efb45fe1d7726c268183.tar.gz
hdf5-d5c3ec8b93296987b443efb45fe1d7726c268183.tar.bz2
Changes to make timers within the library monotonic.
-rw-r--r--examples/Makefile.am12
-rw-r--r--examples/h5_debug_trace.c144
-rw-r--r--examples/run-c-ex.sh.in5
-rw-r--r--src/H5Eprivate.h2
-rw-r--r--src/H5FDlog.c432
-rw-r--r--src/H5T.c35
-rw-r--r--src/H5Tdbg.c25
-rw-r--r--src/H5Tpkg.h2
-rw-r--r--src/H5Z.c195
-rw-r--r--src/H5private.h37
-rw-r--r--src/H5system.c117
-rw-r--r--src/H5timer.c608
-rw-r--r--src/H5trace.c51
-rw-r--r--test/Makefile.am3
-rw-r--r--test/timer.c415
15 files changed, 1563 insertions, 520 deletions
diff --git a/examples/Makefile.am b/examples/Makefile.am
index 8c6540f..6665574 100644
--- a/examples/Makefile.am
+++ b/examples/Makefile.am
@@ -35,9 +35,9 @@ EXAMPLE_PROG = h5_write h5_read h5_extend_write h5_chunk_read h5_compound \
h5_crtgrpd h5_subset h5_cmprss h5_rdwt h5_crtgrpar h5_extend \
h5_crtatt h5_crtgrp h5_crtdat \
h5_group h5_select h5_attribute h5_mount h5_reference h5_drivers \
- h5_ref2reg h5_extlink h5_elink_unix2win h5_shared_mesg h5_vds h5_vds-exc \
- h5_vds-exclim h5_vds-eiger h5_vds-simpleIO h5_vds-percival \
- h5_vds-percival-unlim h5_vds-percival-unlim-maxmin
+ h5_ref2reg h5_extlink h5_elink_unix2win h5_shared_mesg h5_debug_trace \
+ h5_vds h5_vds-exc h5_vds-exclim h5_vds-eiger h5_vds-simpleIO \
+ h5_vds-percival h5_vds-percival-unlim h5_vds-percival-unlim-maxmin
TEST_SCRIPT=testh5cc.sh
TEST_EXAMPLES_SCRIPT=$(INSTALL_SCRIPT_FILES)
@@ -48,9 +48,9 @@ INSTALL_FILES = h5_write.c h5_read.c h5_extend_write.c h5_chunk_read.c \
h5_extend.c h5_crtatt.c h5_crtgrp.c h5_crtdat.c \
h5_compound.c h5_group.c h5_select.c h5_attribute.c h5_mount.c \
h5_reference.c h5_drivers.c h5_extlink.c h5_elink_unix2win.c \
- h5_ref2reg.c h5_shared_mesg.c ph5example.c h5_vds.c h5_vds-exc.c \
- h5_vds-exclim.c h5_vds-eiger.c h5_vds-simpleIO.c h5_vds-percival.c \
- h5_vds-percival-unlim.c h5_vds-percival-unlim-maxmin.c
+ h5_ref2reg.c h5_shared_mesg.c h5_debug_trace.c ph5example.c \
+ h5_vds.c h5_vds-exc.c h5_vds-exclim.c h5_vds-eiger.c h5_vds-simpleIO.c \
+ h5_vds-percival.c h5_vds-percival-unlim.c h5_vds-percival-unlim-maxmin.c
diff --git a/examples/h5_debug_trace.c b/examples/h5_debug_trace.c
new file mode 100644
index 0000000..3d89ba4
--- /dev/null
+++ b/examples/h5_debug_trace.c
@@ -0,0 +1,144 @@
+/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *
+ * Copyright by The HDF Group. *
+ * Copyright by the Board of Trustees of the University of Illinois. *
+ * All rights reserved. *
+ * *
+ * This file is part of HDF5. The full HDF5 copyright notice, including *
+ * terms governing use, modification, and redistribution, is contained in *
+ * the files COPYING and Copyright.html. COPYING can be found at the root *
+ * of the source code distribution tree; Copyright.html can be found at the *
+ * root level of an installed copy of the electronic HDF5 document set and *
+ * is linked from the top-level documents page. It can also be found at *
+ * http://hdfgroup.org/HDF5/doc/Copyright.html. If you do not have *
+ * access to either file, you may request a copy from help@hdfgroup.org. *
+ * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */
+
+/* This example demonstrates debug trace output.
+ *
+ * Debug/trace/performance output is not tested as a regular part of our
+ * testing so this program gives a quick check that it's all working.
+ *
+ * Preconditions:
+ *
+ * You need to set an environment variable named HDF5_DEBUG to have a value
+ * of "+all trace ttimes". In the bash shell, you'd use:
+ *
+ * export HDF5_DEBUG="+all trace ttimes"
+ *
+ * When you are done with this test program, you can set the variable back
+ * to "-all" to suppress trace output.
+ *
+ * Usage:
+ *
+ * Compile and run the test program, then inspect the output. You should see
+ * trace information for each HDF5 function call that increase over time.
+ * Each time stamp is in seconds and designated with an '@' sign. The
+ * elapsed time for the function call is given in seconds in the [dt= ]
+ * part.
+ *
+ * You will also get summary output for the shuffle filter performance and
+ * data type conversion performance. These will include the elapsed time
+ * (always) and the system and user times (if available on your system). On
+ * fast machines, these numbers may be 0.0. Adjust the loop variables in
+ * the program as needed to generate reasonable output.
+ */
+
+#include <stdio.h>
+#include <stdlib.h>
+
+#include "hdf5.h"
+
+#define BUF_SIZE 1048576
+#define N_LOOPS 64
+
+#define TESTFILE "h5_debug_trace_out.h5"
+
+int
+main(int argc, char **argv)
+{
+ int i, j;
+ int *data;
+
+ hid_t fid;
+ hid_t pid;
+ hid_t did;
+ hid_t sid;
+
+ hsize_t dims[1] = { BUF_SIZE };
+ hsize_t chunk_sizes[1] = { 1024 };
+
+ herr_t err;
+
+ /*************************************************************************/
+
+ /* Warn the user about trace deluge to come */
+
+ printf("Testing debug/trace/performance data generation\n");
+ printf("\n");
+ printf("This test should generate a large amount of trace data\n");
+ printf("\n");
+ printf("*** BEGIN TRACE OUTPUT ***\n");
+ printf("\n");
+ fflush(stdout);
+
+ /* This will emit H5Tconvert() performance information */
+
+ for(i = 0; i < N_LOOPS; i++) {
+
+ /* The buffer has to be large enough to hold the conversion output */
+ data = (int *)malloc(BUF_SIZE * sizeof(double));
+
+ for(j = 0; j < BUF_SIZE; j++) {
+ data[j] = j;
+ }
+
+ err = H5Tconvert(H5T_NATIVE_INT, H5T_NATIVE_DOUBLE, BUF_SIZE, data,
+ NULL, H5P_DEFAULT);
+
+ if(err < 0) {
+ fprintf(stderr, "ERROR: Conversion failed\n");
+ free(data);
+ return err;
+ }
+
+ free(data);
+
+ }
+
+
+ /* This will emit H5Z performance information */
+
+ data = (int *)malloc(BUF_SIZE * sizeof(int));
+
+ for(i = 0; i < BUF_SIZE; i++) {
+ data[i] = i;
+ }
+
+ fid = H5Fcreate(TESTFILE, H5F_ACC_TRUNC, H5P_DEFAULT, H5P_DEFAULT);
+
+ pid = H5Pcreate(H5P_DATASET_CREATE);
+ err = H5Pset_chunk(pid, 1, chunk_sizes);
+ err = H5Pset_shuffle(pid);
+
+ sid = H5Screate_simple(1, dims, dims);
+ did = H5Dcreate(fid, "somedata", H5T_NATIVE_INT, sid, H5P_DEFAULT, pid, H5P_DEFAULT);
+ err = H5Dwrite(did, H5T_NATIVE_INT, sid, sid, H5P_DEFAULT, data);
+
+ H5Sclose(sid);
+ H5Dclose(did);
+ H5Pclose(pid);
+ H5Fclose(fid);
+
+ free(data);
+
+ /* Finished */
+ fflush(stdout);
+ printf("\n");
+ printf("*** END TRACE OUTPUT ***\n");
+ printf("\n");
+
+ remove(TESTFILE);
+
+ return 0;
+}
+
diff --git a/examples/run-c-ex.sh.in b/examples/run-c-ex.sh.in
index 4d5d594..f550992 100644
--- a/examples/run-c-ex.sh.in
+++ b/examples/run-c-ex.sh.in
@@ -122,6 +122,11 @@ then
rm h5_extlink &&\
RunTest h5_elink_unix2win &&\
rm h5_elink_unix2win &&\
+ OLD_DEBUG_STRING=$HDF5_DEBUG &&\
+ export HDF5_DEBUG="+all +trace +ttimes" &&\
+ RunTest h5_debug_trace &&\
+ HDF5_DEBUG=$OLD_DEBUG_STRING &&\
+ rm h5_debug_trace &&\
RunTest h5_shared_mesg &&\
rm h5_shared_mesg &&\
RunTest h5_vds-eiger &&\
diff --git a/src/H5Eprivate.h b/src/H5Eprivate.h
index 57e7485..d75c43d 100644
--- a/src/H5Eprivate.h
+++ b/src/H5Eprivate.h
@@ -184,7 +184,7 @@ H5_DLL herr_t H5E_init(void);
H5_DLL herr_t H5E_push_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 *desc);
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 7c2297a..b7b2421 100644
--- a/src/H5FDlog.c
+++ b/src/H5FDlog.c
@@ -479,11 +479,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 */
@@ -515,54 +512,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)))
@@ -623,13 +602,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 */
@@ -676,27 +661,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) {
@@ -704,20 +689,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)
@@ -1160,10 +1137,11 @@ 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 */
- herr_t ret_value = SUCCEED; /* Return value */
+ H5_timer_t read_timer; /* Timer for read operation */
+ H5_timer_t seek_timer; /* Timer for seek operation */
+ H5_timevals_t read_times; /* Elapsed time for read operation */
+ H5_timevals_t seek_times; /* Elapsed time for seek operation */
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI_NOINIT
@@ -1191,58 +1169,55 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd
/* Seek to the correct location */
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 */
+ /* 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 */
@@ -1283,14 +1258,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]);
@@ -1300,30 +1283,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 */
@@ -1362,10 +1329,11 @@ 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 */
- herr_t ret_value = SUCCEED; /* Return value */
+ H5_timer_t write_timer; /* Timer for write operation */
+ H5_timer_t seek_timer; /* Timer for seek operation */
+ H5_timevals_t write_times; /* Elapsed time for write operation */
+ H5_timevals_t seek_times; /* Elapsed time for seek operation */
+ herr_t ret_value = SUCCEED; /* Return value */
FUNC_ENTER_NOAPI_NOINIT
@@ -1398,58 +1366,55 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had
/* Seek to the correct location */
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 */
+ /* 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 */
@@ -1483,14 +1448,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]);
@@ -1502,29 +1475,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 */
@@ -1569,23 +1527,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;
@@ -1596,51 +1553,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 a525cd5..4f0c700 100644
--- a/src/H5T.c
+++ b/src/H5T.c
@@ -4806,34 +4806,47 @@ done:
*/
herr_t
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,
- hid_t dset_xfer_plist)
+ size_t buf_stride, size_t bkg_stride, void *buf, void *bkg,
+ hid_t dset_xfer_plist)
{
#ifdef H5T_DEBUG
- H5_timer_t timer;
+ H5_timer_t timer; /* Timer for conversion */
#endif
- herr_t ret_value=SUCCEED; /* Return value */
+ 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->func)(src_id, dst_id, &(tpath->cdata), nelmts, buf_stride,
- bkg_stride, buf, bkg, dset_xfer_plist)<0)
+ if((tpath->func)(src_id, dst_id, &(tpath->cdata), nelmts, buf_stride,
+ bkg_stride, buf, bkg, dset_xfer_plist) < 0)
HGOTO_ERROR(H5E_ATTR, H5E_CANTENCODE, FAIL, "data type conversion failed");
+
#ifdef H5T_DEBUG
- if (H5DEBUG(T)) {
- H5_timer_end(&(tpath->stats.timer), &timer);
+ if(H5DEBUG(T)) {
+ /* 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:
FUNC_LEAVE_NOAPI(ret_value)
-}
+} /* end H5T_convert() */
/*-------------------------------------------------------------------------
diff --git a/src/H5Tdbg.c b/src/H5Tdbg.c
index f434543..e20113e 100644
--- a/src/H5Tdbg.c
+++ b/src/H5Tdbg.c
@@ -102,15 +102,13 @@
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) {
+ 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",
@@ -119,7 +117,8 @@ H5T__print_stats(H5T_path_t H5_ATTR_UNUSED * path, int H5_ATTR_UNUSED * nprint/*
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)
@@ -128,18 +127,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",
+ 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.timer.utime,
- path->stats.timer.stime,
- path->stats.timer.etime,
+ 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 d075127..fe54ce1 100644
--- a/src/H5Tpkg.h
+++ b/src/H5Tpkg.h
@@ -146,7 +146,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 */
};
/* The datatype conversion database */
diff --git a/src/H5Z.c b/src/H5Z.c
index ef34d7c..04624a6 100644
--- a/src/H5Z.c
+++ b/src/H5Z.c
@@ -34,10 +34,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 */
@@ -136,9 +136,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++) {
@@ -169,27 +169,27 @@ H5Z_term_package(void)
* 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);
+ 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 %8.2f %8.2f %8.2f "
- "%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,
- bandwidth);
+ 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].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 */
#endif /* H5Z_DEBUG */
+
/* 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 */
@@ -1281,26 +1281,26 @@ done:
* Programmer: Robb Matzke
* Tuesday, August 4, 1998
*
- * Modifications:
- *
*-------------------------------------------------------------------------
*/
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)
@@ -1311,14 +1311,17 @@ 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;
+#ifdef H5Z_DEBUG
+ H5_timer_init(&timer);
+#endif
- if (*filter_mask & ((unsigned)1<<idx)) {
+ 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*/
- }
+ 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 "::"),
@@ -1326,20 +1329,20 @@ H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
*/
if((fclass_idx = H5Z_find_idx(pline->filter[idx].id)) < 0) {
hbool_t issue_error = FALSE;
- const H5Z_class2_t *filter_info;
+ const H5Z_class2_t *filter_info;
- /* Try loading the filter */
- if(NULL != (filter_info = (const H5Z_class2_t *)H5PL_load(H5PL_TYPE_FILTER, (int)(pline->filter[idx].id)))) {
- /* Register the filter we loaded */
- if(H5Z_register(filter_info) < 0)
- HGOTO_ERROR(H5E_PLINE, H5E_CANTINIT, FAIL, "unable to register filter")
+ /* Try loading the filter */
+ if(NULL != (filter_info = (const H5Z_class2_t *)H5PL_load(H5PL_TYPE_FILTER, (int)(pline->filter[idx].id)))) {
+ /* Register the filter we loaded */
+ if(H5Z_register(filter_info) < 0)
+ 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)
- issue_error = TRUE;
- } /* end if */
- else
- issue_error = TRUE;
+ /* 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)
+ issue_error = TRUE;
+ } /* end if */
+ else
+ issue_error = TRUE;
/* Check for error */
if(issue_error) {
@@ -1352,76 +1355,96 @@ H5Z_pipeline(const H5O_pline_t *pline, unsigned flags,
} /* end if */
} /* end if */
- fclass=&H5Z_table_g[fclass_idx];
+ fclass = &H5Z_table_g[fclass_idx];
+
#ifdef H5Z_DEBUG
- fstats=&H5Z_stat_table_g[fclass_idx];
- H5_timer_begin(&timer);
+ fstats = &H5Z_stat_table_g[fclass_idx];
+ 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);
+ 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);
+ 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;
+ 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)
- HGOTO_ERROR(H5E_PLINE, H5E_READERROR, FAIL, "filter returned failure during read")
+ 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);
- } else {
+ } /* end if */
+ else
*nbytes = new_nbytes;
- }
- }
+ } /* end for */
} else if (pline) { /* Write */
- for (idx=0; idx<pline->nused; idx++) {
- if (*filter_mask & ((unsigned)1<<idx)) {
+ 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) {
+ 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)
+ 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*/
- }
- fclass=&H5Z_table_g[fclass_idx];
+ continue; /* filter excluded */
+ } /* end if */
+
+ fclass = &H5Z_table_g[fclass_idx];
+
#ifdef H5Z_DEBUG
- fstats=&H5Z_stat_table_g[fclass_idx];
- H5_timer_begin(&timer);
+ fstats = &H5Z_stat_table_g[fclass_idx];
+ 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);
+ 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;
+ if(0 == new_nbytes)
+ fstats->stats[0].errors += *nbytes;
#endif
- if(0==new_nbytes) {
- if (0==(pline->filter[idx].flags & H5Z_FLAG_OPTIONAL)) {
+
+ 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);
- } else {
+ } /* end if */
+ else
*nbytes = new_nbytes;
- }
- }
+ } /* end for */
}
*filter_mask = failed;
diff --git a/src/H5private.h b/src/H5private.h
index ca4ebcf..557eeba 100644
--- a/src/H5private.h
+++ b/src/H5private.h
@@ -573,21 +573,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 {
@@ -703,6 +719,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 a1cdf19..cff2d71 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 */
/****************/
@@ -372,7 +372,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;
@@ -402,11 +402,25 @@ HDfprintf(FILE *stream, const char *fmt, ...)
htri_t tri_var = va_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 = va_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;
@@ -822,11 +836,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
diff --git a/src/H5timer.c b/src/H5timer.c
index 0ba8bd1..2cb8cea 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 256
+
+/* 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)
- sprintf(buf, "%10.4e", bw);
+ HDsprintf(buf, "%10.4e", bw);
else if(bw < (double)H5_KB) {
- sprintf(buf, "%05.4f", bw);
- HDstrcpy(buf+5, " B/s");
+ HDsprintf(buf, "%05.4f", bw);
+ HDstrcpy(buf + 5, " B/s");
} else if(bw < (double)H5_MB) {
- sprintf(buf, "%05.4f", bw / (double)H5_KB);
- HDstrcpy(buf+5, " kB/s");
+ HDsprintf(buf, "%05.4f", bw / (double)H5_KB);
+ HDstrcpy(buf + 5, " kB/s");
} else if(bw < (double)H5_GB) {
- sprintf(buf, "%05.4f", bw / (double)H5_MB);
- HDstrcpy(buf+5, " MB/s");
+ HDsprintf(buf, "%05.4f", bw / (double)H5_MB);
+ HDstrcpy(buf + 5, " MB/s");
} else if(bw < (double)H5_TB) {
- sprintf(buf, "%05.4f", bw / (double)H5_GB);
- HDstrcpy(buf+5, " GB/s");
+ HDsprintf(buf, "%05.4f", bw / (double)H5_GB);
+ HDstrcpy(buf + 5, " GB/s");
} else if(bw < (double)H5_PB) {
- sprintf(buf, "%05.4f", bw / (double)H5_TB);
- HDstrcpy(buf+5, " TB/s");
+ HDsprintf(buf, "%05.4f", bw / (double)H5_TB);
+ 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 {
- sprintf(buf, "%10.4e", bw);
+ HDsprintf(buf, "%10.4e", bw);
if(HDstrlen(buf) > 10)
- sprintf(buf, "%10.3e", bw);
- }
- }
+ HDsprintf(buf, "%10.3e", bw);
+ } /* end else-if */
+ } /* end else */
} /* end H5_bandwidth() */
@@ -269,3 +175,455 @@ 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 */
+
+#ifdef 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__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 9fb8a72..c21aa6f 100644
--- a/src/H5trace.c
+++ b/src/H5trace.c
@@ -125,8 +125,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;
@@ -152,13 +155,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, H5_DOUBLE(0.0)))
- 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
@@ -174,7 +182,9 @@ H5_trace(const double *returning, const char *func, const char *type, ...)
if(H5_debug_g.ttimes) {
char tmp[128];
- sprintf(tmp, "%.6f", event_time.etime-first_time.etime);
+ H5_timer_get_times(function_timer, &function_times);
+ H5_timer_get_times(running_timer, &running_times);
+ sprintf(tmp, "%.6f", (function_times.elapsed - running_times.elapsed));
fprintf(out, " %*s ", (int)HDstrlen(tmp), "");
} /* end if */
for(i = 0; i < current_depth; i++)
@@ -189,8 +199,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)
- fprintf(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);
+ fprintf(out, "@%.6f ", (function_times.elapsed - running_times.elapsed));
+ } /* end if */
for(i = 0; i < current_depth; i++)
HDfputc('+', out);
fprintf(out, "%*s%s(", 2*current_depth, "", func);
@@ -2639,9 +2652,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)
- fprintf(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);
+ fprintf(out, " @%.6f [dt=%.6f]", (function_times.elapsed - running_times.elapsed),
+ (function_times.elapsed - *returning));
+ } /* end if */
error:
va_end(ap);
@@ -2653,6 +2669,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() */
diff --git a/test/Makefile.am b/test/Makefile.am
index 53dbf0d..610c619 100644
--- a/test/Makefile.am
+++ b/test/Makefile.am
@@ -58,7 +58,8 @@ TEST_PROG= testhdf5 \
twriteorder big mtime fillval mount flush1 flush2 app_ref enum \
set_extent ttsafe enc_dec_plist enc_dec_plist_cross_platform\
getname vfd ntypes dangle dtransform reserved cross_read \
- freespace mf vds file_image unregister cache_logging cork swmr
+ freespace mf vds file_image unregister cache_logging cork swmr \
+ timer
# List programs to be built when testing here.
# error_test and err_compat are built at the same time as the other tests, but executed by testerror.sh.
diff --git a/test/timer.c b/test/timer.c
new file mode 100644
index 0000000..3a82b82
--- /dev/null
+++ b/test/timer.c
@@ -0,0 +1,415 @@
+/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *
+ * Copyright by The HDF Group. *
+ * Copyright by the Board of Trustees of the University of Illinois. *
+ * All rights reserved. *
+ * *
+ * This file is part of HDF5. The full HDF5 copyright notice, including *
+ * terms governing use, modification, and redistribution, is contained in *
+ * the files COPYING and Copyright.html. COPYING can be found at the root *
+ * of the source code distribution tree; Copyright.html can be found at the *
+ * root level of an installed copy of the electronic HDF5 document set and *
+ * is linked from the top-level documents page. It can also be found at *
+ * http://hdfgroup.org/HDF5/doc/Copyright.html. If you do not have *
+ * access to either file, you may request a copy from help@hdfgroup.org. *
+ * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */
+
+/*
+ * Programmer: Dana Robinson
+ * May, 2011
+ *
+ * Purpose: Tests the operation of the platform-independent timers.
+ */
+
+#include "h5test.h"
+
+
+
+
+/*-------------------------------------------------------------------------
+ * Function: test_time_formatting
+ *
+ * Purpose: Tests time string creation.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+static herr_t
+test_time_formatting(void)
+{
+ char *s = NULL;
+
+ TESTING("Time string formats");
+
+ /* < 0, N/A */
+ s = H5_timer_get_time_string(-1.0F);
+ if(NULL == s || HDstrcmp(s, "N/A") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* 0 0 */
+ s = H5_timer_get_time_string(0.0F);
+ if(NULL == s || HDstrcmp(s, "0.0 s") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 us nanoseconds */
+ s = H5_timer_get_time_string(123.0E-9F);
+ if(NULL == s || HDstrcmp(s, "123 ns") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 ms microseconds */
+ s = H5_timer_get_time_string(23.456E-6F);
+ if(NULL == s || HDstrcmp(s, "23.5 us") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 s milliseconds */
+ s = H5_timer_get_time_string(4.56789E-3);
+ if(NULL == s || HDstrcmp(s, "4.6 ms") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 min seconds */
+ s = H5_timer_get_time_string(3.14);
+ if(NULL == s || HDstrcmp(s, "3.14 s") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 hr mins, secs */
+ s = H5_timer_get_time_string(2521.0F);
+ if(NULL == s || HDstrcmp(s, "42 m 1 s") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* < 1 d hrs, mins, secs */
+ s = H5_timer_get_time_string(9756.0F);
+ if(NULL == s || HDstrcmp(s, "2 h 42 m 36 s") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ /* > 1 d days, hrs, mins, secs */
+ s = H5_timer_get_time_string(280802.0F);
+ if(NULL == s || HDstrcmp(s, "3 d 6 h 0 m 2 s") != 0)
+ TEST_ERROR;
+ HDfree(s);
+
+ PASSED();
+ return 0;
+
+error:
+ if(s)
+ HDfree(s);
+ return -1;
+
+}
+
+
+/*-------------------------------------------------------------------------
+ * Function: test_timer_system_user
+ *
+ * Purpose: Tests the ability to get system and user times from the
+ * timers.
+ * Some platforms may require special code to get system and
+ * user times. If we do not support that particular platform
+ * dependent functionality, this test is skipped.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+static herr_t
+test_timer_system_user(void)
+{
+ int i;
+ char *buf = NULL;
+ H5_timer_t timer;
+ H5_timevals_t times;
+ herr_t err;
+
+ TESTING("system/user times");
+
+ err = H5_timer_init(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ err = H5_timer_start(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ /* The system and user times may not be present on some systems. They
+ * will be -1.0 if they are not.
+ */
+ if(timer.initial.system < 0.0 || timer.initial.user < 0.0) {
+ SKIPPED();
+ printf("NOTE: No suitable way to get system/user times on this platform.\n");
+ return 0;
+ }
+
+ /* Do some fake work */
+ for(i=0; i < 1024; i++) {
+ buf = (char *)HDmalloc(1024 * i * sizeof(char));
+ HDfree(buf);
+ }
+
+ err = H5_timer_stop(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0)
+ TEST_ERROR;
+
+ /* System and user times should be non-negative. */
+ if(times.system < 0.0 || times.user < 0.0)
+ TEST_ERROR;
+
+ PASSED();
+ return 0;
+
+error:
+ return -1;
+}
+
+
+/*-------------------------------------------------------------------------
+ * Function: test_timer_elapsed
+ *
+ * Purpose: Tests the ability to get elapsed times from the timers.
+ * We should always be able to get an elapsed time,
+ * regardless of the time libraries or platform.
+ *
+ * Return: Success: 0
+ * Failure: -1
+ *
+ * Programmer: Dana Robinson
+ * May 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+static herr_t
+test_timer_elapsed(void)
+{
+ int i;
+ char *buf = NULL;
+ H5_timer_t timer;
+ H5_timevals_t times;
+ herr_t err;
+
+ TESTING("elapsed times");
+
+ err = H5_timer_init(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ err = H5_timer_start(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ /* Do some fake work */
+ for(i=0; i < 1024; i++) {
+ buf = (char *)HDmalloc(1024 * i * sizeof(char));
+ HDfree(buf);
+ }
+
+ err = H5_timer_stop(&timer);
+ if(err < 0)
+ TEST_ERROR;
+
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0)
+ TEST_ERROR;
+
+ /* Elapsed time should be non-negative. */
+ if(times.elapsed < 0.0)
+ TEST_ERROR;
+
+ PASSED();
+ return 0;
+
+error:
+ return -1;
+}
+
+
+
+static herr_t
+test_timer_functionality(void)
+{
+ int i;
+ char *buf = NULL;
+ H5_timer_t timer;
+
+ H5_timevals_t times;
+ double prev_etime;
+ double prev_total_etime;
+
+ herr_t err;
+
+ TESTING("timer functionality");
+
+ /*****************
+ * CHECK STARTUP *
+ *****************/
+
+ /* Timer should be running after start */
+ err = H5_timer_init(&timer);
+ if(err < 0 || timer.is_running)
+ TEST_ERROR;
+
+ /* Times should be initialized to zero */
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0 || !H5_DBL_ABS_EQUAL(times.elapsed, 0.0))
+ TEST_ERROR;
+
+ err = H5_timer_get_total_times(timer, &times);
+ if(err < 0 || !H5_DBL_ABS_EQUAL(times.elapsed, 0.0))
+ TEST_ERROR;
+
+
+ /********************
+ * CHECK START/STOP *
+ ********************/
+
+ /* Running state should change after start */
+ err = H5_timer_start(&timer);
+ if(err < 0 || !timer.is_running)
+ TEST_ERROR;
+
+ /* Do some fake work */
+ for(i=0; i < 1024; i++) {
+ buf = (char *)HDmalloc(1024 * i * sizeof(char));
+ HDfree(buf);
+ }
+
+ /* Running state should change after stop */
+ err = H5_timer_stop(&timer);
+ if(err < 0 || timer.is_running)
+ TEST_ERROR;
+
+ /* Times should be positive and non-negative */
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0 || times.elapsed < 0.0)
+ TEST_ERROR;
+
+ err = H5_timer_get_total_times(timer, &times);
+ if(err < 0 || times.elapsed < 0.0)
+ TEST_ERROR;
+
+
+ /**********************
+ * CHECK INTERRUPTING *
+ **********************/
+
+ /* Timer should change stat and refresh to 0s */
+ err = H5_timer_init(&timer);
+ if(err < 0 || timer.is_running)
+ TEST_ERROR;
+
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0 || !H5_DBL_ABS_EQUAL(times.elapsed, 0.0))
+ TEST_ERROR;
+
+ err = H5_timer_get_total_times(timer, &times);
+ if(err < 0 || !H5_DBL_ABS_EQUAL(times.elapsed, 0.0))
+ TEST_ERROR;
+
+ /* Timer state should flip */
+ err = H5_timer_start(&timer);
+ if(err < 0 || !timer.is_running)
+ TEST_ERROR;
+
+ /* Do some fake work */
+ for(i=0; i < 1024; i++) {
+ buf = (char *)HDmalloc(1024 * i * sizeof(char));
+ HDfree(buf);
+ }
+
+ /* Times should be non-negative */
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0 || times.elapsed < 0.0)
+ TEST_ERROR;
+ prev_etime = times.elapsed;
+
+ err = H5_timer_get_total_times(timer, &times);
+ if(err < 0 || times.elapsed < 0.0)
+ TEST_ERROR;
+ prev_total_etime = times.elapsed;
+
+ /* Do some fake work */
+ for(i=0; i < 1024; i++) {
+ buf = (char *)HDmalloc(1024 * i * sizeof(char));
+ HDfree(buf);
+ }
+
+ /* State should flip on stop */
+ err = H5_timer_stop(&timer);
+ if(err < 0 || timer.is_running)
+ TEST_ERROR;
+
+ /* Times should be >= than the cached intermediate times */
+ err = H5_timer_get_times(timer, &times);
+ if(err < 0 || times.elapsed < prev_etime)
+ TEST_ERROR;
+
+ err = H5_timer_get_total_times(timer, &times);
+ if(err < 0 || times.elapsed < prev_total_etime)
+ TEST_ERROR;
+
+
+ PASSED();
+ return 0;
+
+error:
+ return -1;
+}
+
+
+/*-------------------------------------------------------------------------
+ * Function: main
+ *
+ * Purpose: Tests the basic functionality of the platform-independent
+ * timers
+ *
+ * Return: Success: 0
+ * Failure: 1
+ *
+ * Programmer: Dana Robinson
+ * May, 2011
+ *
+ *-------------------------------------------------------------------------
+ */
+int
+main(void)
+{
+ int nerrors = 0;
+
+ h5_reset();
+
+ printf("Testing platform-independent timer functionality.\n");
+
+ nerrors += test_time_formatting() < 0 ? 1 : 0;
+ nerrors += test_timer_system_user() < 0 ? 1 : 0;
+ nerrors += test_timer_elapsed() < 0 ? 1 : 0;
+ nerrors += test_timer_functionality() < 0 ? 1 : 0;
+
+
+ if(nerrors) {
+ printf("***** %d platform-independent timer TEST%s FAILED! *****\n",
+ nerrors, nerrors > 1 ? "S" : "");
+ return 1;
+ } else {
+ printf("All platform-independent timer tests passed.\n");
+ return 0;
+ }
+}
+