diff options
Diffstat (limited to 'src/H5FDlog.c')
-rw-r--r-- | src/H5FDlog.c | 436 |
1 files changed, 197 insertions, 239 deletions
diff --git a/src/H5FDlog.c b/src/H5FDlog.c index f649bc4..78b7742 100644 --- a/src/H5FDlog.c +++ b/src/H5FDlog.c @@ -487,11 +487,8 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr) #ifdef H5_HAVE_WIN32_API struct _BY_HANDLE_FILE_INFORMATION fileinfo; #endif -#ifdef H5_HAVE_GETTIMEOFDAY - struct timeval timeval_start; - struct timeval open_timeval_diff; - struct timeval stat_timeval_diff; -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_t open_timer; /* Timer for open() call */ + H5_timer_t stat_timer; /* Timer for stat() call */ h5_stat_t sb; H5FD_t *ret_value = NULL; /* Return value */ @@ -523,54 +520,36 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr) if(NULL == (fa = (const H5FD_log_fapl_t *)H5P_peek_driver_info(plist))) HGOTO_ERROR(H5E_PLIST, H5E_BADVALUE, NULL, "bad VFL driver info") -#ifdef H5_HAVE_GETTIMEOFDAY - if(fa->flags & H5FD_LOG_TIME_OPEN) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Start timer for open() call */ + if(fa->flags & H5FD_LOG_TIME_OPEN) { + H5_timer_init(&open_timer); + H5_timer_start(&open_timer); + } /* end if */ + /* Open the file */ if((fd = HDopen(name, o_flags, H5_POSIX_CREATE_MODE_RW)) < 0) { int myerrno = errno; HGOTO_ERROR(H5E_FILE, H5E_CANTOPENFILE, NULL, "unable to open file: name = '%s', errno = %d, error message = '%s', flags = %x, o_flags = %x", name, myerrno, HDstrerror(myerrno), flags, (unsigned)o_flags); } /* end if */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(fa->flags & H5FD_LOG_TIME_OPEN) { - struct timeval timeval_stop; - HDgettimeofday(&timeval_stop, NULL); + /* Stop timer for open() call */ + if(fa->flags & H5FD_LOG_TIME_OPEN) + H5_timer_stop(&open_timer); - /* Calculate the elapsed gettimeofday time */ - open_timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - open_timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(open_timeval_diff.tv_usec < 0) { - open_timeval_diff.tv_usec += 1000000; - open_timeval_diff.tv_sec--; - } /* end if */ + /* Start timer for stat() call */ + if(fa->flags & H5FD_LOG_TIME_STAT) { + H5_timer_init(&stat_timer); + H5_timer_start(&stat_timer); } /* end if */ -#endif /* H5_HAVE_GETTIMEOFDAY */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(fa->flags & H5FD_LOG_TIME_STAT) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ /* Get the file stats */ if(HDfstat(fd, &sb) < 0) HSYS_GOTO_ERROR(H5E_FILE, H5E_BADFILE, NULL, "unable to fstat file") -#ifdef H5_HAVE_GETTIMEOFDAY - if(fa->flags & H5FD_LOG_TIME_STAT) { - struct timeval timeval_stop; - HDgettimeofday(&timeval_stop, NULL); - - /* Calculate the elapsed gettimeofday time */ - stat_timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - stat_timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(stat_timeval_diff.tv_usec < 0) { - stat_timeval_diff.tv_usec += 1000000; - stat_timeval_diff.tv_sec--; - } /* end if */ - } /* end if */ -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Stop timer for stat() call */ + if(fa->flags & H5FD_LOG_TIME_STAT) + H5_timer_stop(&stat_timer); /* Create the new file struct */ if(NULL == (file = H5FL_CALLOC(H5FD_log_t))) @@ -631,13 +610,19 @@ H5FD_log_open(const char *name, unsigned flags, hid_t fapl_id, haddr_t maxaddr) else file->logfp = stderr; -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_OPEN) - HDfprintf(file->logfp, "Open took: (%f s)\n", (double)open_timeval_diff.tv_sec + ((double)open_timeval_diff.tv_usec / (double)1000000.0f)); - if(file->fa.flags & H5FD_LOG_TIME_STAT) - HDfprintf(file->logfp, "Stat took: (%f s)\n", (double)stat_timeval_diff.tv_sec + ((double)stat_timeval_diff.tv_usec / (double)1000000.0f)); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Log the timer values */ + if(file->fa.flags & H5FD_LOG_TIME_OPEN) { + H5_timevals_t open_times; /* Elapsed time for open() call */ + H5_timer_get_times(open_timer, &open_times); + HDfprintf(file->logfp, "Open took: (%f s)\n", open_times.elapsed); + } /* end if */ + if(file->fa.flags & H5FD_LOG_TIME_STAT) { + H5_timevals_t stat_times; /* Elapsed time for stat() call */ + + H5_timer_get_times(stat_timer, &stat_times); + HDfprintf(file->logfp, "Stat took: (%f s)\n", stat_times.elapsed); + } /* end if */ } /* end if */ /* Check for non-default FAPL */ @@ -684,27 +669,27 @@ static herr_t H5FD_log_close(H5FD_t *_file) { H5FD_log_t *file = (H5FD_log_t *)_file; -#ifdef H5_HAVE_GETTIMEOFDAY - struct timeval timeval_start, timeval_stop; -#endif /* H5_HAVE_GETTIMEOFDAY */ - herr_t ret_value = SUCCEED; /* Return value */ + H5_timer_t close_timer; /* Timer for close() call */ + herr_t ret_value = SUCCEED; /* Return value */ FUNC_ENTER_NOAPI_NOINIT /* Sanity check */ HDassert(file); -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags&H5FD_LOG_TIME_CLOSE) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Start timer for close() call */ + if(file->fa.flags & H5FD_LOG_TIME_CLOSE) { + H5_timer_init(&close_timer); + H5_timer_start(&close_timer); + } /* end if */ + /* Close the underlying file */ if(HDclose(file->fd) < 0) HSYS_GOTO_ERROR(H5E_IO, H5E_CANTCLOSEFILE, FAIL, "unable to close file") -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for close() call */ if(file->fa.flags&H5FD_LOG_TIME_CLOSE) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&close_timer); /* Dump I/O information */ if(file->fa.flags != 0) { @@ -712,20 +697,12 @@ H5FD_log_close(H5FD_t *_file) haddr_t last_addr; unsigned char last_val; -#ifdef H5_HAVE_GETTIMEOFDAY if(file->fa.flags & H5FD_LOG_TIME_CLOSE) { - struct timeval timeval_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - HDfprintf(file->logfp, "Close took: (%f s)\n", (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f)); + H5_timevals_t close_times; /* Elapsed time for close() call */ + + H5_timer_get_times(close_timer, &close_times); + HDfprintf(file->logfp, "Close took: (%f s)\n", close_times.elapsed); } /* end if */ -#endif /* H5_HAVE_GETTIMEOFDAY */ /* Dump the total number of seek/read/write operations */ if(file->fa.flags & H5FD_LOG_NUM_READ) @@ -1168,11 +1145,14 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd H5FD_log_t *file = (H5FD_log_t *)_file; size_t orig_size = size; /* Save the original size for later */ haddr_t orig_addr = addr; -#ifdef H5_HAVE_GETTIMEOFDAY - struct timeval timeval_start, timeval_stop; -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_t read_timer; /* Timer for read operation */ + H5_timevals_t read_times; /* Elapsed time for read operation */ +#ifndef H5_HAVE_PREADWRITE + H5_timer_t seek_timer; /* Timer for seek operation */ + H5_timevals_t seek_times; /* Elapsed time for seek operation */ +#endif /* H5_HAVE_PREADWRITE */ HDoff_t offset = (HDoff_t)addr; - herr_t ret_value = SUCCEED; /* Return value */ + herr_t ret_value = SUCCEED; /* Return value */ FUNC_ENTER_NOAPI_NOINIT @@ -1201,59 +1181,56 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd #ifndef H5_HAVE_PREADWRITE /* Seek to the correct location (if we don't have pread) */ if(addr != file->pos || OP_READ != file->op) { -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_SEEK) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Start timer for seek() call */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) { + H5_timer_init(&seek_timer); + H5_timer_start(&seek_timer); + } /* end if */ + if(HDlseek(file->fd, (HDoff_t)addr, SEEK_SET) < 0) HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to seek to proper position") -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for seek() call */ if(file->fa.flags & H5FD_LOG_TIME_SEEK) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&seek_timer); - /* Log information about the seek */ + /* Add to the number of seeks, when tracking that */ if(file->fa.flags & H5FD_LOG_NUM_SEEK) file->total_seek_ops++; + + /* Add to the total seek time, when tracking that */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) { + H5_timer_get_times(seek_timer, &seek_times); + file->total_seek_time += seek_times.elapsed; + } /* end if */ + + /* Emit log string if we're tracking individual seek events. */ if(file->fa.flags & H5FD_LOG_LOC_SEEK) { HDfprintf(file->logfp, "Seek: From %10a To %10a", file->pos, addr); -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_SEEK) { - struct timeval timeval_diff; - double time_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f); - HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec); - /* Add to total seek time */ - file->total_seek_time += time_diff; - } /* end if */ - else - HDfprintf(file->logfp, "\n"); -#else /* H5_HAVE_GETTIMEOFDAY */ - HDfprintf(file->logfp, "\n"); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Add the seek time, if we're tracking that. + * Note that the seek time is NOT emitted for when just H5FD_LOG_TIME_SEEK + * is set. + */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) + HDfprintf(file->logfp, " (%fs @ %f)\n", seek_times.elapsed, seek_timer.initial.elapsed); + else + HDfprintf(file->logfp, "\n"); } /* end if */ } /* end if */ #endif /* H5_HAVE_PREADWRITE */ + /* Start timer for read operation */ + if(file->fa.flags & H5FD_LOG_TIME_READ) { + H5_timer_init(&read_timer); + H5_timer_start(&read_timer); + } /* end if */ + /* * Read data, being careful of interrupted system calls, partial results, * and the end of the file. */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_READ) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ while(size > 0) { - h5_posix_io_t bytes_in = 0; /* # of bytes to read */ h5_posix_io_ret_t bytes_read = -1; /* # of bytes actually read */ @@ -1301,14 +1278,22 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd buf = (char *)buf + bytes_read; } /* end while */ -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for read operation */ if(file->fa.flags & H5FD_LOG_TIME_READ) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&read_timer); - /* Log information about the read */ + /* Add to the number of reads, when tracking that */ if(file->fa.flags & H5FD_LOG_NUM_READ) file->total_read_ops++; + + /* Add to the total read time, when tracking that */ + if(file->fa.flags & H5FD_LOG_TIME_READ) { + H5_timer_get_times(read_timer, &read_times); + file->total_read_time += read_times.elapsed; + } /* end if */ + + /* Log information about the read */ if(file->fa.flags & H5FD_LOG_LOC_READ) { HDfprintf(file->logfp, "%10a-%10a (%10Zu bytes) (%s) Read", orig_addr, (orig_addr + orig_size) - 1, orig_size, flavors[type]); @@ -1318,30 +1303,14 @@ H5FD_log_read(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, hadd HDassert(type == H5FD_MEM_DEFAULT || type == (H5FD_mem_t)file->flavor[(orig_addr + orig_size) - 1] || (H5FD_mem_t)file->flavor[(orig_addr + orig_size) - 1] == H5FD_MEM_DEFAULT); } /* end if */ - -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_READ) { - struct timeval timeval_diff; - double time_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f); - HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec); - - /* Add to total read time */ - file->total_read_time += time_diff; - } /* end if */ + /* Add the read time, if we're tracking that. + * Note that the read time is NOT emitted for when just H5FD_LOG_TIME_READ + * is set. + */ + if(file->fa.flags & H5FD_LOG_TIME_READ) + HDfprintf(file->logfp, " (%fs @ %f)\n", read_times.elapsed, read_timer.initial.elapsed); else HDfprintf(file->logfp, "\n"); -#else /* H5_HAVE_GETTIMEOFDAY */ - HDfprintf(file->logfp, "\n"); -#endif /* H5_HAVE_GETTIMEOFDAY */ } /* end if */ /* Update current position */ @@ -1380,11 +1349,14 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had H5FD_log_t *file = (H5FD_log_t *)_file; size_t orig_size = size; /* Save the original size for later */ haddr_t orig_addr = addr; -#ifdef H5_HAVE_GETTIMEOFDAY - struct timeval timeval_start, timeval_stop; -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_t write_timer; /* Timer for write operation */ + H5_timevals_t write_times; /* Elapsed time for write operation */ +#ifndef H5_HAVE_PREADWRITE + H5_timer_t seek_timer; /* Timer for seek operation */ + H5_timevals_t seek_times; /* Elapsed time for seek operation */ +#endif /* H5_HAVE_PREADWRITE */ HDoff_t offset = (HDoff_t)addr; - herr_t ret_value = SUCCEED; /* Return value */ + herr_t ret_value = SUCCEED; /* Return value */ FUNC_ENTER_NOAPI_NOINIT @@ -1418,59 +1390,56 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had #ifndef H5_HAVE_PREADWRITE /* Seek to the correct location (if we don't have pwrite) */ if(addr != file->pos || OP_WRITE != file->op) { -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_SEEK) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Start timer for seek() call */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) { + H5_timer_init(&seek_timer); + H5_timer_start(&seek_timer); + } /* end if */ + if(HDlseek(file->fd, (HDoff_t)addr, SEEK_SET) < 0) HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to seek to proper position") -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for seek() call */ if(file->fa.flags & H5FD_LOG_TIME_SEEK) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&seek_timer); - /* Log information about the seek */ + /* Add to the number of seeks, when tracking that */ if(file->fa.flags & H5FD_LOG_NUM_SEEK) file->total_seek_ops++; + + /* Add to the total seek time, when tracking that */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) { + H5_timer_get_times(seek_timer, &seek_times); + file->total_seek_time += seek_times.elapsed; + } /* end if */ + + /* Emit log string if we're tracking individual seek events. */ if(file->fa.flags & H5FD_LOG_LOC_SEEK) { HDfprintf(file->logfp, "Seek: From %10a To %10a", file->pos, addr); -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_SEEK) { - struct timeval timeval_diff; - double time_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f); - HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec); - /* Add to total seek time */ - file->total_seek_time += time_diff; - } /* end if */ - else - HDfprintf(file->logfp, "\n"); -#else /* H5_HAVE_GETTIMEOFDAY */ - HDfprintf(file->logfp, "\n"); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Add the seek time, if we're tracking that. + * Note that the seek time is NOT emitted for when just H5FD_LOG_TIME_SEEK + * is set. + */ + if(file->fa.flags & H5FD_LOG_TIME_SEEK) + HDfprintf(file->logfp, " (%fs @ %f)\n", seek_times.elapsed, seek_timer.initial.elapsed); + else + HDfprintf(file->logfp, "\n"); } /* end if */ } /* end if */ #endif /* H5_HAVE_PREADWRITE */ + /* Start timer for write operation */ + if(file->fa.flags&H5FD_LOG_TIME_WRITE) { + H5_timer_init(&write_timer); + H5_timer_start(&write_timer); + } /* end if */ + /* * Write the data, being careful of interrupted system calls and partial * results */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags&H5FD_LOG_TIME_WRITE) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ while(size > 0) { - h5_posix_io_t bytes_in = 0; /* # of bytes to write */ h5_posix_io_ret_t bytes_wrote = -1; /* # of bytes written */ @@ -1511,14 +1480,22 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had addr += (haddr_t)bytes_wrote; buf = (const char *)buf + bytes_wrote; } /* end while */ -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for write operation */ if(file->fa.flags & H5FD_LOG_TIME_WRITE) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&write_timer); - /* Log information about the write */ + /* Add to the number of writes, when tracking that */ if(file->fa.flags & H5FD_LOG_NUM_WRITE) file->total_write_ops++; + + /* Add to the total write time, when tracking that */ + if(file->fa.flags & H5FD_LOG_TIME_WRITE) { + H5_timer_get_times(write_timer, &write_times); + file->total_write_time += write_times.elapsed; + } /* end if */ + + /* Log information about the write */ if(file->fa.flags & H5FD_LOG_LOC_WRITE) { HDfprintf(file->logfp, "%10a-%10a (%10Zu bytes) (%s) Written", orig_addr, (orig_addr + orig_size) - 1, orig_size, flavors[type]); @@ -1530,29 +1507,14 @@ H5FD_log_write(H5FD_t *_file, H5FD_mem_t type, hid_t H5_ATTR_UNUSED dxpl_id, had } /* end if */ } /* end if */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_WRITE) { - struct timeval timeval_diff; - double time_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f); - HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec); - - /* Add to total write time */ - file->total_write_time += time_diff; - } /* end if */ - else - HDfprintf(file->logfp, "\n"); -#else /* H5_HAVE_GETTIMEOFDAY */ - HDfprintf(file->logfp, "\n"); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Add the write time, if we're tracking that. + * Note that the write time is NOT emitted for when just H5FD_LOG_TIME_WRITE + * is set. + */ + if(file->fa.flags & H5FD_LOG_TIME_WRITE) + HDfprintf(file->logfp, " (%fs @ %f)\n", write_times.elapsed, write_timer.initial.elapsed); + else + HDfprintf(file->logfp, "\n"); } /* end if */ /* Update current position and eof */ @@ -1597,23 +1559,22 @@ H5FD_log_truncate(H5FD_t *_file, hid_t H5_ATTR_UNUSED dxpl_id, hbool_t H5_ATTR_U /* Extend the file to make sure it's large enough */ if(!H5F_addr_eq(file->eoa, file->eof)) { -#ifdef H5_HAVE_GETTIMEOFDAY - struct timeval timeval_start, timeval_stop; -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_t trunc_timer; /* Timer for truncate operation */ + H5_timevals_t trunc_times; /* Elapsed time for truncate operation */ + + /* Start timer for truncate operation */ + if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) { + H5_timer_init(&trunc_timer); + H5_timer_start(&trunc_timer); + } /* end if */ + #ifdef H5_HAVE_WIN32_API +{ LARGE_INTEGER li; /* 64-bit (union) integer for SetFilePointer() call */ DWORD dwPtrLow; /* Low-order pointer bits from SetFilePointer() * Only used as an error code here. */ - DWORD dwError; /* DWORD error code from GetLastError() */ - BOOL bError; /* Boolean error flag */ -#endif /* H5_HAVE_WIN32_API */ -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) - HDgettimeofday(&timeval_start, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ -#ifdef H5_HAVE_WIN32_API /* Windows uses this odd QuadPart union for 32/64-bit portability */ li.QuadPart = (__int64)file->eoa; @@ -1624,51 +1585,48 @@ H5FD_log_truncate(H5FD_t *_file, hid_t H5_ATTR_UNUSED dxpl_id, hbool_t H5_ATTR_U */ dwPtrLow = SetFilePointer(file->hFile, li.LowPart, &li.HighPart, FILE_BEGIN); if(INVALID_SET_FILE_POINTER == dwPtrLow) { + DWORD dwError; /* DWORD error code from GetLastError() */ + dwError = GetLastError(); if(dwError != NO_ERROR ) HGOTO_ERROR(H5E_FILE, H5E_FILEOPEN, FAIL, "unable to set file pointer") - } + } /* end if */ - bError = SetEndOfFile(file->hFile); - if(0 == bError) + if(0 == SetEndOfFile(file->hFile)) HGOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to extend file properly") +} #else /* H5_HAVE_WIN32_API */ + /* Truncate/extend the file */ if(-1 == HDftruncate(file->fd, (HDoff_t)file->eoa)) HSYS_GOTO_ERROR(H5E_IO, H5E_SEEKERROR, FAIL, "unable to extend file properly") #endif /* H5_HAVE_WIN32_API */ -#ifdef H5_HAVE_GETTIMEOFDAY + + /* Stop timer for truncate operation */ if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) - HDgettimeofday(&timeval_stop, NULL); -#endif /* H5_HAVE_GETTIMEOFDAY */ + H5_timer_stop(&trunc_timer); - /* Log information about the truncate */ + /* Add to the number of truncates, when tracking that */ if(file->fa.flags & H5FD_LOG_NUM_TRUNCATE) file->total_truncate_ops++; + + /* Add to the total truncate time, when tracking that */ + if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) { + H5_timer_get_times(trunc_timer, &trunc_times); + file->total_truncate_time += trunc_times.elapsed; + } /* end if */ + + /* Emit log string if we're tracking individual truncate events. */ if(file->fa.flags & H5FD_LOG_TRUNCATE) { HDfprintf(file->logfp, "Truncate: To %10a", file->eoa); -#ifdef H5_HAVE_GETTIMEOFDAY - if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) { - struct timeval timeval_diff; - double time_diff; - - /* Calculate the elapsed gettimeofday time */ - timeval_diff.tv_usec = timeval_stop.tv_usec - timeval_start.tv_usec; - timeval_diff.tv_sec = timeval_stop.tv_sec - timeval_start.tv_sec; - if(timeval_diff.tv_usec < 0) { - timeval_diff.tv_usec += 1000000; - timeval_diff.tv_sec--; - } /* end if */ - time_diff = (double)timeval_diff.tv_sec + ((double)timeval_diff.tv_usec / (double)1000000.0f); - HDfprintf(file->logfp, " (%fs @ %.6lu.%.6llu)\n", time_diff, (unsigned long long)timeval_start.tv_sec, (unsigned long long)timeval_start.tv_usec); - /* Add to total truncate time */ - file->total_truncate_time += time_diff; - } /* end if */ - else - HDfprintf(file->logfp, "\n"); -#else /* H5_HAVE_GETTIMEOFDAY */ - HDfprintf(file->logfp, "\n"); -#endif /* H5_HAVE_GETTIMEOFDAY */ + /* Add the truncate time, if we're tracking that. + * Note that the truncate time is NOT emitted for when just H5FD_LOG_TIME_TRUNCATE + * is set. + */ + if(file->fa.flags & H5FD_LOG_TIME_TRUNCATE) + HDfprintf(file->logfp, " (%fs @ %f)\n", trunc_times.elapsed, trunc_timer.initial.elapsed); + else + HDfprintf(file->logfp, "\n"); } /* end if */ /* Update the eof value */ |