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 <john.hammond@intel.com>
Change-Id: I227d00c97f93a09ac9322213d255102b8a3cf612
Reviewed-on: http://review.whamcloud.com/12042
Tested-by: Jenkins
Tested-by: Maloo <hpdd-maloo@intel.com>
Reviewed-by: James Nunez <james.a.nunez@intel.com>
Reviewed-by: Faccini Bruno <bruno.faccini@intel.com>
Reviewed-by: Nathaniel Clark <nathaniel.l.clark@intel.com>
Reviewed-by: Oleg Drokin <oleg.drokin@intel.com>

diff --git a/lustre/utils/lhsmtool_posix.c b/lustre/utils/lhsmtool_posix.c
index dd85559..0702b9c 100644 (file)
--- a/lustre/utils/lhsmtool_posix.c
+++ b/lustre/utils/lhsmtool_posix.c
@@ -41,7 +41,9 @@
 #include <stdlib.h>
 #include <dirent.h>
 #include <errno.h>
+#include <time.h>
 #include <utime.h>
+#include <sys/time.h>
 #include <sys/xattr.h>
 #include <sys/syscall.h>
 #include <sys/types.h>
@@ -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;
 }