diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/H5Eprivate.h | 2 | ||||
| -rw-r--r-- | src/H5FDlog.c | 432 | ||||
| -rw-r--r-- | src/H5T.c | 35 | ||||
| -rw-r--r-- | src/H5Tdbg.c | 25 | ||||
| -rw-r--r-- | src/H5Tpkg.h | 2 | ||||
| -rw-r--r-- | src/H5Z.c | 195 | ||||
| -rw-r--r-- | src/H5private.h | 37 | ||||
| -rw-r--r-- | src/H5system.c | 117 | ||||
| -rw-r--r-- | src/H5timer.c | 608 | ||||
| -rw-r--r-- | src/H5trace.c | 51 |
10 files changed, 991 insertions, 513 deletions
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 */ @@ -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 */ @@ -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, ×); + 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, ×); + 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() */ |