From b23357064aba6022237dd146c33725529069770d Mon Sep 17 00:00:00 2001 From: "John L. Hammond" Date: Wed, 24 Sep 2014 12:33:10 -0500 Subject: [PATCH] LU-5659 hsm: add timestamps to lhsmtool log messages Add epoch timestamps (secs.usecs) to the log messages emitted by lhsmtool_posix. Change the single use of CT_DEBUG() to CT_TRACE(). Remove the unused macro CT_PRINTF(). Signed-off-by: John L. Hammond Change-Id: I227d00c97f93a09ac9322213d255102b8a3cf612 Reviewed-on: http://review.whamcloud.com/12042 Tested-by: Jenkins Tested-by: Maloo Reviewed-by: James Nunez Reviewed-by: Faccini Bruno Reviewed-by: Nathaniel Clark Reviewed-by: Oleg Drokin --- lustre/utils/lhsmtool_posix.c | 48 +++++++++++++++++++++++++++---------------- 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/lustre/utils/lhsmtool_posix.c b/lustre/utils/lhsmtool_posix.c index dd85559..0702b9c 100644 --- a/lustre/utils/lhsmtool_posix.c +++ b/lustre/utils/lhsmtool_posix.c @@ -41,7 +41,9 @@ #include #include #include +#include #include +#include #include #include #include @@ -116,27 +118,34 @@ static char fs_name[MAX_OBD_NAME + 1]; static struct hsm_copytool_private *ctdata; +static inline double ct_now(void) +{ + struct timeval tv; + + gettimeofday(&tv, NULL); -#define CT_ERROR(_rc, _format, ...) \ + return tv.tv_sec + 0.000001 * tv.tv_usec; +} + +#define CT_ERROR(_rc, _format, ...) \ llapi_error(LLAPI_MSG_ERROR, _rc, \ - "%s[%ld]: "_format, \ - cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) -#define CT_DEBUG(_format, ...) \ + "%f %s[%ld]: "_format, \ + ct_now(), cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) + +#define CT_DEBUG(_format, ...) \ llapi_error(LLAPI_MSG_DEBUG | LLAPI_MSG_NO_ERRNO, 0, \ - "%s[%ld]: "_format, \ - cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) + "%f %s[%ld]: "_format, \ + ct_now(), cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) + #define CT_WARN(_format, ...) \ llapi_error(LLAPI_MSG_WARN | LLAPI_MSG_NO_ERRNO, 0, \ - "%s[%ld]: "_format, \ - cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) -#define CT_TRACE(_format, ...) \ + "%f %s[%ld]: "_format, \ + ct_now(), cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) + +#define CT_TRACE(_format, ...) \ llapi_error(LLAPI_MSG_INFO | LLAPI_MSG_NO_ERRNO, 0, \ - "%s[%ld]: "_format, \ - cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) -#define CT_PRINTF(_format, ...) \ - llapi_printf(LLAPI_MSG_NORMAL, \ - "%s[%ld]: "_format, \ - cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) + "%f %s[%ld]: "_format, \ + ct_now(), cmd_name, syscall(SYS_gettid), ## __VA_ARGS__) static void usage(const char *name, int rc) { @@ -540,11 +549,10 @@ static int ct_copy_data(struct hsm_copyaction_private *hcp, const char *src, char *buf = NULL; __u64 write_total = 0; __u64 length; + double start_time = ct_now(); time_t last_print_time = time(NULL); int rc = 0; - CT_TRACE("going to copy data from '%s' to '%s'", src, dst); - if (fstat(src_fd, &src_st) < 0) { rc = -errno; CT_ERROR(rc, "cannot stat '%s'", src); @@ -600,7 +608,8 @@ static int ct_copy_data(struct hsm_copyaction_private *hcp, const char *src, goto out; } - CT_DEBUG("Going to copy "LPU64" bytes %s -> %s\n", length, src, dst); + CT_TRACE("start copy of "LPU64" bytes from '%s' to '%s'", + length, src, dst); while (write_total < length) { ssize_t rsize; @@ -673,6 +682,9 @@ out: if (buf != NULL) free(buf); + CT_TRACE("copied "LPU64" bytes in %f seconds", + length, ct_now() - start_time); + return rc; } -- 1.8.3.1