summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorLeon Arber <larber@ncsa.uiuc.edu>2006-01-26 22:45:51 (GMT)
committerLeon Arber <larber@ncsa.uiuc.edu>2006-01-26 22:45:51 (GMT)
commitd61b6875876f33c2e5ceecc8267dedeba4fa0102 (patch)
treeeed734ca7cf7e39c9f54c8b50eb8cfeac8bcc808
parent25f2ebda39e5a2932853668b88f821a5bd0faf32 (diff)
downloadhdf5-d61b6875876f33c2e5ceecc8267dedeba4fa0102.zip
hdf5-d61b6875876f33c2e5ceecc8267dedeba4fa0102.tar.gz
hdf5-d61b6875876f33c2e5ceecc8267dedeba4fa0102.tar.bz2
[svn-r11894] Purpose:
Feature, address bug #426 Description: The h5perf test now also keeps track of the time it takes to: open a file: Time between start of open and start first read/write close a file: Time between end of last read/write and end of close. This information is only displayed if debug output printing is enabled (level 3 or higher) Solution: The test actually has all of the data necessary to compute the time it takes to open and close a file; it just wasn't recording it. Added 4 new timers: HDF5_FILE_READ_OPEN HDF5_FILE_READ_CLOSE HDF5_FILE_WRITE_OPEN HDF5_FILE_WRITE_CLOSE that keep track of the time to open/close a file opened for reading/writing. Platforms tested: heping and mir Misc. update:
-rw-r--r--perform/pio_perf.c96
-rw-r--r--perform/pio_timer.c49
-rw-r--r--perform/pio_timer.h4
3 files changed, 137 insertions, 12 deletions
diff --git a/perform/pio_perf.c b/perform/pio_perf.c
index d436e5c..f19afa7 100644
--- a/perform/pio_perf.c
+++ b/perform/pio_perf.c
@@ -532,6 +532,10 @@ run_test(iotype iot, parameters parms, struct options *opts)
minmax *read_mm_table=NULL;
minmax *read_gross_mm_table=NULL;
minmax *read_raw_mm_table=NULL;
+ minmax *read_open_mm_table=NULL;
+ minmax *read_close_mm_table=NULL;
+ minmax *write_open_mm_table=NULL;
+ minmax *write_close_mm_table=NULL;
minmax write_mpi_mm = {0.0, 0.0, 0.0, 0};
minmax write_mm = {0.0, 0.0, 0.0, 0};
minmax write_gross_mm = {0.0, 0.0, 0.0, 0};
@@ -540,6 +544,10 @@ run_test(iotype iot, parameters parms, struct options *opts)
minmax read_mm = {0.0, 0.0, 0.0, 0};
minmax read_gross_mm = {0.0, 0.0, 0.0, 0};
minmax read_raw_mm = {0.0, 0.0, 0.0, 0};
+ minmax read_open_mm = {0.0, 0.0, 0.0, 0};
+ minmax read_close_mm = {0.0, 0.0, 0.0, 0};
+ minmax write_open_mm = {0.0, 0.0, 0.0, 0};
+ minmax write_close_mm = {0.0, 0.0, 0.0, 0};
raw_size = (off_t)parms.num_dsets * (off_t)parms.num_bytes;
parms.io_type = iot;
@@ -569,13 +577,18 @@ run_test(iotype iot, parameters parms, struct options *opts)
write_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
write_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
write_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ write_open_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ write_close_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
if (!parms.h5_write_only) {
- read_mpi_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
- read_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
- read_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
- read_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
- }
+ read_mpi_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ read_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ read_gross_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ read_raw_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ read_open_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+ read_close_mm_table = calloc((size_t)parms.num_iters , sizeof(minmax));
+
+ }
/* Do IO iteration times, collecting statistics each time */
for (i = 0; i < parms.num_iters; ++i) {
@@ -603,10 +616,22 @@ run_test(iotype iot, parameters parms, struct options *opts)
write_gross_mm_table[i] = write_gross_mm;
/* gather all of the raw "write" times */
- t = get_time(res.timers, HDF5_RAW_WRITE_FIXED_DIMS);
+ t = get_time(res.timers, HDF5_RAW_WRITE_FIXED_DIMS);
get_minmax(&write_raw_mm, t);
- write_raw_mm_table[i] = write_raw_mm;
+ write_raw_mm_table[i] = write_raw_mm;
+
+ /* gather all of the file open times (time from open to first write) */
+ t = get_time(res.timers, HDF5_FILE_WRITE_OPEN);
+ get_minmax(&write_open_mm, t);
+
+ write_open_mm_table[i] = write_open_mm;
+
+ /* gather all of the file close times (time from last write to close) */
+ t = get_time(res.timers, HDF5_FILE_WRITE_CLOSE);
+ get_minmax(&write_close_mm, t);
+
+ write_close_mm_table[i] = write_close_mm;
if (!parms.h5_write_only) {
/* gather all of the "mpi read" times */
@@ -632,6 +657,19 @@ run_test(iotype iot, parameters parms, struct options *opts)
get_minmax(&read_raw_mm, t);
read_raw_mm_table[i] = read_raw_mm;
+
+ /* gather all of the file open times (time from open to first read) */
+ t = get_time(res.timers, HDF5_FILE_READ_OPEN);
+ get_minmax(&read_open_mm, t);
+
+ read_open_mm_table[i] = read_open_mm;
+
+ /* gather all of the file close times (time from last read to close) */
+ t = get_time(res.timers, HDF5_FILE_READ_CLOSE);
+ get_minmax(&read_close_mm, t);
+
+ read_close_mm_table[i] = read_close_mm;
+
}
pio_time_destroy(res.timers);
@@ -684,6 +722,24 @@ run_test(iotype iot, parameters parms, struct options *opts)
output_results(opts,"Write Open-Close",write_gross_mm_table,parms.num_iters,raw_size);
+ /* Print out time from open to first write */
+ if (pio_debug_level >= 3) {
+ /* output all of the times for all iterations */
+ print_indent(3);
+ output_report("Write file open details:\n");
+ output_all_info(write_open_mm_table, parms.num_iters, 4);
+ }
+
+ /* Print out time from last write to close */
+ if (pio_debug_level >= 3) {
+ /* output all of the times for all iterations */
+ print_indent(3);
+ output_report("Write file close details:\n");
+ output_all_info(write_close_mm_table, parms.num_iters, 4);
+ }
+
+
+
if (!parms.h5_write_only) {
/* Read statistics */
/* Print the raw data throughput if desired */
@@ -728,8 +784,26 @@ run_test(iotype iot, parameters parms, struct options *opts)
output_all_info(read_gross_mm_table, parms.num_iters, 4);
}
- output_results(opts, "Read Open-Close", read_gross_mm_table,
- parms.num_iters, raw_size);
+ output_results(opts, "Read Open-Close", read_gross_mm_table,
+ parms.num_iters, raw_size);
+
+
+ /* Print out time from open to first read */
+ if (pio_debug_level >= 3) {
+ /* output all of the times for all iterations */
+ print_indent(3);
+ output_report("Read file open details:\n");
+ output_all_info(read_open_mm_table, parms.num_iters, 4);
+ }
+
+ /* Print out time from last read to close */
+ if (pio_debug_level >= 3) {
+ /* output all of the times for all iterations */
+ print_indent(3);
+ output_report("Read file close details:\n");
+ output_all_info(read_close_mm_table, parms.num_iters, 4);
+ }
+
}
/* clean up our mess */
@@ -737,12 +811,16 @@ run_test(iotype iot, parameters parms, struct options *opts)
free(write_mm_table);
free(write_gross_mm_table);
free(write_raw_mm_table);
+ free(write_open_mm_table);
+ free(write_close_mm_table);
if (!parms.h5_write_only) {
free(read_mpi_mm_table);
free(read_mm_table);
free(read_gross_mm_table);
free(read_raw_mm_table);
+ free(read_open_mm_table);
+ free(read_close_mm_table);
}
return ret_value;
diff --git a/perform/pio_timer.c b/perform/pio_timer.c
index 10e0ff4..027b536 100644
--- a/perform/pio_timer.c
+++ b/perform/pio_timer.c
@@ -119,21 +119,55 @@ set_time(pio_time *pt, timer_type t, int start_stop)
if (pt->type == MPI_TIMER) {
if (start_stop == START) {
pt->mpi_timer[t] = MPI_Wtime();
+
+ /* When we start the timer for HDF5_FINE_WRITE_FIXED_DIMS or HDF5_FINE_READ_FIXED_DIMS
+ * we compute the time it took to only open the file */
+ if(t == HDF5_FINE_WRITE_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_WRITE_OPEN] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_GROSS_WRITE_FIXED_DIMS];
+ else if(t == HDF5_FINE_READ_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_READ_OPEN] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_GROSS_READ_FIXED_DIMS];
+
} else {
pt->total_time[t] += MPI_Wtime() - pt->mpi_timer[t];
+ pt->mpi_timer[t] = MPI_Wtime();
+
+ /* When we stop the timer for HDF5_GROSS_WRITE_FIXED_DIMS or HDF5_GROSS_READ_FIXED_DIMS
+ * we compute the time it took to close the file after the last read/write finished */
+ if(t == HDF5_GROSS_WRITE_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_WRITE_CLOSE] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_FINE_WRITE_FIXED_DIMS];
+ else if(t == HDF5_GROSS_READ_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_READ_CLOSE] += pt->mpi_timer[t] - pt->mpi_timer[HDF5_FINE_READ_FIXED_DIMS];
}
} else {
if (start_stop == START) {
gettimeofday(&pt->sys_timer[t], NULL);
+
+ /* When we start the timer for HDF5_FINE_WRITE_FIXED_DIMS or HDF5_FINE_READ_FIXED_DIMS
+ * we compute the time it took to only open the file */
+ if(t == HDF5_FINE_WRITE_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_WRITE_OPEN] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_GROSS_WRITE_FIXED_DIMS]));
+ else if(t == HDF5_FINE_READ_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_READ_OPEN] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_GROSS_READ_FIXED_DIMS]));
+
+
} else {
struct timeval sys_t;
gettimeofday(&sys_t, NULL);
- pt->total_time[t] +=
- ((double)sys_t.tv_sec +
+ pt->total_time[t] += sub_time(&sys_t, &(pt->sys_timer[t]));
+
+/* ((double)sys_t.tv_sec +
((double)sys_t.tv_usec) / MICROSECOND) -
((double)pt->sys_timer[t].tv_sec +
- ((double)pt->sys_timer[t].tv_usec) / MICROSECOND);
+ ((double)pt->sys_timer[t].tv_usec) / MICROSECOND);*/
+
+ /* When we stop the timer for HDF5_GROSS_WRITE_FIXED_DIMS or HDF5_GROSS_READ_FIXED_DIMS
+ * we compute the time it took to close the file after the last read/write finished */
+ if(t == HDF5_GROSS_WRITE_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_WRITE_CLOSE] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_FINE_WRITE_FIXED_DIMS]));
+ else if(t == HDF5_GROSS_READ_FIXED_DIMS)
+ pt->total_time[HDF5_FILE_READ_CLOSE] += sub_time(&(pt->sys_timer[t]), &(pt->sys_timer[HDF5_FINE_READ_FIXED_DIMS]));
+
}
}
@@ -201,6 +235,15 @@ get_time(pio_time *pt, timer_type t)
return pt->total_time[t];
}
+/* Assumes that a > b */
+static inline double sub_time(struct timeval* a, struct timeval* b)
+{
+ ((double)a->tv_sec +
+ ((double)a->tv_usec) / MICROSECOND) -
+ ((double)b->tv_sec +
+ ((double)b->tv_usec) / MICROSECOND);
+}
+
#endif /* H5_HAVE_PARALLEL */
#ifdef STANDALONE
#include "pio_standalone.c"
diff --git a/perform/pio_timer.h b/perform/pio_timer.h
index 3094997..ca942a3 100644
--- a/perform/pio_timer.h
+++ b/perform/pio_timer.h
@@ -32,6 +32,10 @@ typedef enum timer_type_ {
HDF5_DATASET_CREATE,
HDF5_MPI_WRITE,
HDF5_MPI_READ,
+ HDF5_FILE_READ_OPEN,
+ HDF5_FILE_READ_CLOSE,
+ HDF5_FILE_WRITE_OPEN,
+ HDF5_FILE_WRITE_CLOSE,
HDF5_FINE_WRITE_FIXED_DIMS,
HDF5_FINE_READ_FIXED_DIMS,
HDF5_GROSS_WRITE_FIXED_DIMS,