1 /* SPDX-License-Identifier: BSD-3-Clause */ 2 3 #include <limits.h> 4 #include <stdarg.h> 5 #include <stdbool.h> 6 #include <stdint.h> 7 #include <stdio.h> 8 #include <stdlib.h> 9 #include <string.h> 10 #include <time.h> 11 12 #include <rte_common.h> 13 #include <rte_stdatomic.h> 14 #include <rte_time.h> 15 16 #ifdef RTE_EXEC_ENV_WINDOWS 17 #include <rte_os_shim.h> 18 #endif 19 20 #include "log_internal.h" 21 #include "log_private.h" 22 23 #ifndef NS_PER_SEC 24 #define NS_PER_SEC 1E9 25 #endif 26 27 static enum { 28 LOG_TIMESTAMP_NONE = 0, 29 LOG_TIMESTAMP_TIME, /* time since start */ 30 LOG_TIMESTAMP_DELTA, /* time since last message */ 31 LOG_TIMESTAMP_RELTIME, /* relative time since last message */ 32 LOG_TIMESTAMP_CTIME, /* Unix standard time format */ 33 LOG_TIMESTAMP_ISO, /* ISO8601 time format */ 34 } log_time_format; 35 36 static struct { 37 struct timespec started; /* when log was initialized */ 38 RTE_ATOMIC(uint64_t) last_monotonic; 39 RTE_ATOMIC(uint64_t) last_realtime; 40 } log_time; 41 42 /* Set the log timestamp format */ 43 int 44 eal_log_timestamp(const char *str) 45 { 46 if (str == NULL) 47 log_time_format = LOG_TIMESTAMP_TIME; 48 else if (strcmp(str, "notime") == 0) 49 log_time_format = LOG_TIMESTAMP_NONE; 50 else if (strcmp(str, "reltime") == 0) 51 log_time_format = LOG_TIMESTAMP_RELTIME; 52 else if (strcmp(str, "delta") == 0) 53 log_time_format = LOG_TIMESTAMP_DELTA; 54 else if (strcmp(str, "ctime") == 0) 55 log_time_format = LOG_TIMESTAMP_CTIME; 56 else if (strcmp(str, "iso") == 0) 57 log_time_format = LOG_TIMESTAMP_ISO; 58 else 59 return -1; 60 61 return 0; 62 } 63 64 bool 65 log_timestamp_enabled(void) 66 { 67 return log_time_format != LOG_TIMESTAMP_NONE; 68 } 69 70 /* Subtract two timespec values and handle wraparound */ 71 static struct timespec 72 timespec_sub(const struct timespec *t0, const struct timespec *t1) 73 { 74 struct timespec ts; 75 76 ts.tv_sec = t0->tv_sec - t1->tv_sec; 77 ts.tv_nsec = t0->tv_nsec - t1->tv_nsec; 78 if (ts.tv_nsec < 0) { 79 ts.tv_sec--; 80 ts.tv_nsec += 1000000000L; 81 } 82 return ts; 83 } 84 85 /* 86 * Format current timespec into ISO8601 format. 87 * Surprisingly, can't just use strftime() for this; 88 * since want microseconds and the timezone offset format differs. 89 */ 90 static ssize_t 91 format_iso8601(char *tsbuf, size_t tsbuflen, const struct timespec *now) 92 { 93 struct tm *tm, tbuf; 94 char dbuf[64]; /* "2024-05-01T22:11:00" */ 95 char zbuf[16] = { }; /* "+0800" */ 96 97 tm = localtime_r(&now->tv_sec, &tbuf); 98 99 /* make "2024-05-01T22:11:00,123456+0100" */ 100 if (strftime(dbuf, sizeof(dbuf), "%Y-%m-%dT%H:%M:%S", tm) == 0) 101 return 0; 102 103 /* convert timezone to +hhmm */ 104 if (strftime(zbuf, sizeof(zbuf), "%z", tm) == 0) 105 return 0; 106 107 /* the result for strftime is "+hhmm" but ISO wants "+hh:mm" */ 108 return snprintf(tsbuf, tsbuflen, "%s,%06lu%.3s:%.2s", 109 dbuf, now->tv_nsec / 1000u, 110 zbuf, zbuf + 3); 111 } 112 113 /* 114 * Format a timestamp which shows time between messages. 115 */ 116 static ssize_t 117 format_delta(char *tsbuf, size_t tsbuflen, const struct timespec *now) 118 { 119 struct timespec delta; 120 uint64_t ns = rte_timespec_to_ns(now); 121 uint64_t previous; 122 123 previous = rte_atomic_exchange_explicit(&log_time.last_monotonic, 124 ns, rte_memory_order_seq_cst); 125 delta = rte_ns_to_timespec(ns - previous); 126 127 return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>", 128 (unsigned long)delta.tv_sec, 129 (unsigned long)delta.tv_nsec / 1000u); 130 } 131 132 /* 133 * Make a timestamp where if the minute, hour or day has 134 * changed from the last message, then print abbreviated 135 * "Month day hour:minute" format. 136 * Otherwise print delta from last printed message as +sec.usec 137 */ 138 static ssize_t 139 format_reltime(char *tsbuf, size_t tsbuflen, const struct timespec *now) 140 { 141 struct tm *tm, *last_tm, tbuf1, tbuf2; 142 time_t last_sec; 143 uint64_t ns = rte_timespec_to_ns(now); 144 uint64_t previous; 145 146 tm = localtime_r(&now->tv_sec, &tbuf1); 147 148 previous = rte_atomic_exchange_explicit(&log_time.last_realtime, 149 ns, rte_memory_order_seq_cst); 150 last_sec = previous / NS_PER_SEC; 151 last_tm = localtime_r(&last_sec, &tbuf2); 152 if (tm->tm_min == last_tm->tm_min && 153 tm->tm_hour == last_tm->tm_hour && 154 tm->tm_yday == last_tm->tm_yday) { 155 struct timespec elapsed; 156 157 elapsed = rte_ns_to_timespec(ns - previous); 158 159 return snprintf(tsbuf, tsbuflen, "+%3lu.%06lu", 160 (unsigned long)elapsed.tv_sec, 161 (unsigned long)elapsed.tv_nsec / 1000u); 162 } else { 163 return strftime(tsbuf, tsbuflen, "%b%d %H:%M", tm); 164 } 165 } 166 167 /* Format up a timestamp based on current format */ 168 ssize_t 169 log_timestamp(char *tsbuf, size_t tsbuflen) 170 { 171 struct timespec now, delta; 172 173 switch (log_time_format) { 174 case LOG_TIMESTAMP_NONE: 175 return 0; 176 177 case LOG_TIMESTAMP_TIME: 178 if (clock_gettime(CLOCK_MONOTONIC, &now) < 0) 179 return 0; 180 181 delta = timespec_sub(&now, &log_time.started); 182 183 return snprintf(tsbuf, tsbuflen, "%6lu.%06lu", 184 (unsigned long)delta.tv_sec, 185 (unsigned long)delta.tv_nsec / 1000u); 186 187 case LOG_TIMESTAMP_DELTA: 188 if (clock_gettime(CLOCK_MONOTONIC, &now) < 0) 189 return 0; 190 191 return format_delta(tsbuf, tsbuflen, &now); 192 193 case LOG_TIMESTAMP_RELTIME: 194 if (clock_gettime(CLOCK_REALTIME, &now) < 0) 195 return 0; 196 197 return format_reltime(tsbuf, tsbuflen, &now); 198 199 case LOG_TIMESTAMP_CTIME: 200 if (clock_gettime(CLOCK_REALTIME, &now) < 0) 201 return 0; 202 203 /* trncate to remove newline from ctime result */ 204 return snprintf(tsbuf, tsbuflen, "%.24s", ctime(&now.tv_sec)); 205 206 case LOG_TIMESTAMP_ISO: 207 if (clock_gettime(CLOCK_REALTIME, &now) < 0) 208 return 0; 209 210 return format_iso8601(tsbuf, tsbuflen, &now); 211 } 212 213 return 0; 214 } 215 216 /* print timestamp before message */ 217 int 218 log_print_with_timestamp(FILE *f, const char *format, va_list ap) 219 { 220 char tsbuf[128]; 221 char msgbuf[LINE_MAX]; 222 223 if (log_timestamp(tsbuf, sizeof(tsbuf)) > 0) { 224 vsnprintf(msgbuf, sizeof(msgbuf), format, ap); 225 return fprintf(f, "[%s] %s", tsbuf, msgbuf); 226 } 227 228 /* fall back when timestamp is unavailable */ 229 return vfprintf(f, format, ap); 230 } 231 232 RTE_INIT_PRIO(log_timestamp_init, LOG) 233 { 234 struct timespec now; 235 236 clock_gettime(CLOCK_MONOTONIC, &now); 237 log_time.started = now; 238 rte_atomic_store_explicit(&log_time.last_monotonic, rte_timespec_to_ns(&now), 239 rte_memory_order_seq_cst); 240 } 241