From ae2155e3d4bbcc170dace133c32a4cc0af8b9697 Mon Sep 17 00:00:00 2001 From: Alexandre Ioffe Date: Wed, 23 Feb 2022 13:09:34 -0800 Subject: [PATCH] EX-4865 lipe: add timestamps to lamigo and lpurge log messages Added optional timestamp to log messages; Added command line option --timestamps to lamigo/lpurge and 'timestamps' keyword to lpurge config. Added timestamps to log files to hot-pools test frame by default. Test-Parameters: trivial testlist=hot-pools Signed-off-by: Alexandre Ioffe Change-Id: If58f20eed31c6df30a70f0cb1c93430040f8fe62 Reviewed-on: https://review.whamcloud.com/46599 Tested-by: jenkins Tested-by: Maloo Reviewed-by: John L. Hammond Reviewed-by: Jian Yu --- lipe/src/lamigo.c | 7 +++++++ lipe/src/lpurge.c | 7 +++++++ lipe/src/lx_log.h | 29 ++++++++++++++++++++++++----- lustre/tests/hot-pools.sh | 22 ++++++++++++++-------- 4 files changed, 52 insertions(+), 13 deletions(-) diff --git a/lipe/src/lamigo.c b/lipe/src/lamigo.c index e4b18b3..9cb9005 100644 --- a/lipe/src/lamigo.c +++ b/lipe/src/lamigo.c @@ -96,6 +96,7 @@ enum llapi_message_level lx_log_level = LLAPI_MSG_INFO; char *lx_log_prefix = "NONE"; +bool lx_log_timestamps; /* Add timestamps to debug log */ static char *lamigo_changelog_user; static LIPE_LIST_HEAD(lamigo_rule_list); @@ -143,6 +144,7 @@ static void usage(void) "\t--slow-pool=POOL (default '%s')\n" "\t--slow-pool-max-used=MAX stop mirroring to POOL when %% used reaches MAX (default %d)\n" "\t--ssh-log-verbosity=V, set SSH_OPTIONS_LOG_VERBOSITY to V (default: 0)\n" + "\t--timestamps, add timestamp to log messages (default: no)\n" "\t--version, print version information and exit\n", program_invocation_short_name, DEF_MIN_AGE, @@ -1778,6 +1780,7 @@ enum { LAMIGO_OPT_SSH_LOG_VERBOSITY, LAMIGO_OPT_STATFS_REFRESH, LAMIGO_OPT_TGT_FREE, /* == LAMIGO_OPT_SLOW_POOL_MAX_USED + math + warning */ + LAMIGO_OPT_LOG_TIMESTAMPS, LAMIGO_OPT_VERSION, }; @@ -1822,6 +1825,7 @@ static struct option options[] = { { "tgt", required_argument, NULL, 't'}, { "tgt-free", required_argument, NULL, LAMIGO_OPT_TGT_FREE}, { "thread-number", required_argument, NULL, 'n' }, + { "timestamps", no_argument, NULL, LAMIGO_OPT_LOG_TIMESTAMPS}, { "user", required_argument, 0, 'u'}, { "verbose", no_argument, NULL, 'v'}, { "version", no_argument, NULL, LAMIGO_OPT_VERSION }, @@ -2008,6 +2012,9 @@ static void lamigo_process_opt(int c, char *optarg) case LAMIGO_OPT_IGNORE_READS: opt.o_alr_ignore_reads = 1; break; + case LAMIGO_OPT_LOG_TIMESTAMPS: + lx_log_timestamps = 1; + break; case LAMIGO_OPT_IGNORE_WRITES: opt.o_alr_ignore_writes = 1; break; diff --git a/lipe/src/lpurge.c b/lipe/src/lpurge.c index 7904c5a..bbf49b8 100644 --- a/lipe/src/lpurge.c +++ b/lipe/src/lpurge.c @@ -153,6 +153,7 @@ static struct options opt = { enum llapi_message_level lx_log_level = LLAPI_MSG_INFO; char *lx_log_prefix; /* To print device name in log messages */ +bool lx_log_timestamps; static struct lipe_instance instance; static unsigned long long lpurge_max_used_kb; /* kbtotal - freelo */ @@ -263,6 +264,7 @@ static void usage(void) "\t-R, --scan_rate, slow scanning rate, objs/sec (default: %u)\n" "\t-S, --slot_size, objects to store in memory (default: %u)\n" "\t-t, --scan_threads, scanning threads (default: %u)\n" + "\t--timestamps, add timestamp to log messages (default: no)\n" "\t-w, --dump, stats file (via USR1 signal, default: %s)\n" "\t--version, print version information and exit\n", program_invocation_short_name, @@ -1371,6 +1373,7 @@ static void parse_mountpoint(char *name) #define LPURGE_INTERNAL_DUMP_FIDS 1 #define LPURGE_OPT_VERSION 2 +#define LPURGE_OPT_LOG_TIMESTAMPS 3 static struct option options[] = { { "device", required_argument, NULL, 'D'}, @@ -1389,6 +1392,7 @@ static struct option options[] = { { "scan_rate", required_argument, NULL, 'R'}, { "scan_threads", required_argument, NULL, 't'}, { "slot_size", required_argument, NULL, 'S'}, + { "timestamps", no_argument, NULL, LPURGE_OPT_LOG_TIMESTAMPS}, { "version", no_argument, NULL, LPURGE_OPT_VERSION}, { NULL } }; @@ -1493,6 +1497,9 @@ static void lpurge_process_opt(int c, char *optarg) opt.o_scan_threads = value; break; + case LPURGE_OPT_LOG_TIMESTAMPS: + lx_log_timestamps = 1; + break; case 'w': opt.o_dumpfile = xstrdup(optarg); break; diff --git a/lipe/src/lx_log.h b/lipe/src/lx_log.h index cfb0a38..391480d 100644 --- a/lipe/src/lx_log.h +++ b/lipe/src/lx_log.h @@ -3,12 +3,23 @@ #include #include +#include #include #include #include extern enum llapi_message_level lx_log_level; extern char *lx_log_prefix; /* Device name the message is related to */ +extern bool lx_log_timestamps; + +static inline double lx_now(void) +{ + struct timeval tv; + + gettimeofday(&tv, NULL); + + return tv.tv_sec + 0.000001 * tv.tv_usec; +} /* lamigo/lpurge runs as a systemd service. So whatever it prints to stderr * (or stdout) will be collected by journald and added to the @@ -21,11 +32,19 @@ extern char *lx_log_prefix; /* Device name the message is related to */ #define LX_PRINT(level, fmt, args...) \ do { \ int _lx_print_saved_errno = errno; \ - if (level <= lx_log_level) \ - fprintf(stderr, "%s%s" fmt, \ - lx_log_prefix ? lx_log_prefix : "", \ - lx_log_prefix ? ": " : "", \ - ##args); \ + if (level <= lx_log_level) { \ + if (lx_log_timestamps) \ + fprintf(stderr, "%f %s%s" fmt, \ + lx_now(), \ + lx_log_prefix ? lx_log_prefix : "", \ + lx_log_prefix ? ": " : "", \ + ##args); \ + else \ + fprintf(stderr, "%s%s" fmt, \ + lx_log_prefix ? lx_log_prefix : "", \ + lx_log_prefix ? ": " : "", \ + ##args); \ + } \ errno = _lx_print_saved_errno; \ } while (0) diff --git a/lustre/tests/hot-pools.sh b/lustre/tests/hot-pools.sh index 0ec9bc1..caf4194 100755 --- a/lustre/tests/hot-pools.sh +++ b/lustre/tests/hot-pools.sh @@ -54,6 +54,7 @@ LAMIGO_CACHE=${LAMIGO_CACHE:-""} LAMIGO_MIRROR_CMD=${LAMIGO_MIRROR_CMD:-""} LAMIGO_DEBUG=${LAMIGO_DEBUG:-true} LAMIGO_RESCAN=${LAMIGO_RESCAN:-false} +LAMIGO_TIMESTAMPS=${LAMIGO_TIMESTAMPS:-true} LAMIGO_VERBOSE=${LAMIGO_VERBOSE:-false} LAMIGO_DUMP=${LAMIGO_DUMP:-""} LAMIGO_EXTRA=${LAMIGO_EXTRA:-""} @@ -79,6 +80,7 @@ LPURGE_SCAN_THREADS=${LPURGE_SCAN_THREADS:-""} LPURGE_INTV=${LPURGE_INTV:-"30"} LPURGE_SLOT_SIZE=${LPURGE_SLOT_SIZE:-""} LPURGE_DEBUG=${LPURGE_DEBUG:-true} +LPURGE_TIMESTAMPS=${LPURGE_TIMESTAMPS:-true} LPURGE_DUMP=${LPURGE_DUMP:-""} LPURGE_DUMP_FIDS=${LPURGE_DUMP_FIDS:-""} LPURGE_EXTRA=${LPURGE_EXTRA:-""} @@ -272,6 +274,7 @@ start_one_lamigo_cmd() { ! $LAMIGO_DEBUG || cmd+=" --debug" ! $LAMIGO_RESCAN || cmd+=" --rescan" + ! $LAMIGO_TIMESTAMPS || cmd+=" --timestamps" ! $LAMIGO_VERBOSE || cmd+=" --verbose" cmd+=" $LAMIGO_EXTRA_OPT" @@ -357,6 +360,7 @@ create_one_lamigo_cfg() { echo dump=\\\"${LAMIGO_DUMP}.$mdt\\\" >> $cfg_file; ! $LAMIGO_DEBUG || echo debug >> $cfg_file; ! $LAMIGO_RESCAN || echo rescan >> $cfg_file; + ! $LAMIGO_TIMESTAMPS || echo timestamps >> $cfg_file; ! $LAMIGO_VERBOSE || echo verbose >> $cfg_file;" echo "lamigo configuration file $cfg_file:" @@ -649,6 +653,7 @@ start_one_lpurge_cmd() { cmd+=${LPURGE_DUMP:+" -w ${LPURGE_DUMP}.$dev"} ! $LPURGE_DEBUG || cmd+=" -b" + ! $LPURGE_TIMESTAMPS || cmd+=" --timestamps" echo "Start lpurge on OSS $(facet_active_host $facet): $cmd" do_facet $facet "$cmd &> $(lpurge_logfile $facet)" & @@ -725,7 +730,8 @@ create_one_lpurge_cfg() { echo \\\"$LPURGE_EXTRA\\\" >> $cfg_file; [[ -z \\\"$LPURGE_DUMP\\\" ]] || echo dump=\\\"${LPURGE_DUMP}.$dev\\\" >> $cfg_file; - ! $LPURGE_DEBUG || echo debug >> $cfg_file;" + ! $LPURGE_DEBUG || echo debug >> $cfg_file; + ! $LPURGE_TIMESTAMPS || echo timestamps >> $cfg_file;" for j in ${!LPURGE_MDS[@]}; do mds=${LPURGE_MDS[j]} @@ -2115,10 +2121,10 @@ check_entry() { local facet=${LAMIGO_MDT_FACET[$mdt_indx]} local log_file=$(lamigo_logfile $facet) - # 1 2 3 4 5 6 7 8 9 10 11 12 13 - # DEBUG: ALRUPG: H: 'oss' FID RW: w O: 1 IO: 8192 P: Pool f/s + # 1 2 3 4 5 6 7 8 9 10 11 12 + # DEBUG: ALRUPG: H: 'oss' FID RW: w O: 1 IO: 8192 P: Pool f/s local awk_string="awk -v fid=$fid \ - '\\\$2 == \\\"DEBUG:\\\" && \\\$3 == \\\"ALRUPD:\\\" && \\\$6 == fid { print; }'\ + '\\\$3 == \\\"DEBUG:\\\" && \\\$4 == \\\"ALRUPD:\\\" && \\\$7 == fid { print; }'\ ${log_file}" for ((j = 0; j < $wait_alr_duration; j++)); do @@ -2139,11 +2145,11 @@ check_entry() { local entry=($e) - [[ "${entry[7]}" == "w" ]] || - error "alr: '${entry[*]}' has invalid operation '${entry[7]}', expected 'w'" + [[ "${entry[8]}" == "w" ]] || + error "alr: '${entry[*]}' has invalid operation '${entry[8]}', expected 'w'" - ((${entry[11]} == size)) || - error "alr: '${entry[*]}' has invalid io size '${entry[11]}', expected ${size}" + ((${entry[12]} == size)) || + error "alr: '${entry[*]}' has invalid io size '${entry[12]}', expected ${size}" } test_72() { -- 1.8.3.1