Branch data Line data Source code
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 : 3 : eal_log_timestamp(const char *str)
45 : : {
46 [ + + ]: 3 : if (str == NULL)
47 : 1 : log_time_format = LOG_TIMESTAMP_TIME;
48 [ - + ]: 2 : else if (strcmp(str, "notime") == 0)
49 : 0 : log_time_format = LOG_TIMESTAMP_NONE;
50 [ - + ]: 2 : else if (strcmp(str, "reltime") == 0)
51 : 0 : log_time_format = LOG_TIMESTAMP_RELTIME;
52 [ - + ]: 2 : else if (strcmp(str, "delta") == 0)
53 : 0 : log_time_format = LOG_TIMESTAMP_DELTA;
54 [ - + ]: 2 : else if (strcmp(str, "ctime") == 0)
55 : 0 : log_time_format = LOG_TIMESTAMP_CTIME;
56 [ + + ]: 2 : else if (strcmp(str, "iso") == 0)
57 : 1 : log_time_format = LOG_TIMESTAMP_ISO;
58 : : else
59 : : return -1;
60 : :
61 : : return 0;
62 : : }
63 : :
64 : : bool
65 : 248 : log_timestamp_enabled(void)
66 : : {
67 : 248 : 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 : 6 : ts.tv_sec = t0->tv_sec - t1->tv_sec;
77 : 6 : ts.tv_nsec = t0->tv_nsec - t1->tv_nsec;
78 [ - + ]: 6 : if (ts.tv_nsec < 0) {
79 : 0 : ts.tv_sec--;
80 : 0 : 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 : 6 : 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 : 6 : char zbuf[16] = { }; /* "+0800" */
96 : :
97 : 6 : tm = localtime_r(&now->tv_sec, &tbuf);
98 : :
99 : : /* make "2024-05-01T22:11:00,123456+0100" */
100 [ + - ]: 6 : if (strftime(dbuf, sizeof(dbuf), "%Y-%m-%dT%H:%M:%S", tm) == 0)
101 : : return 0;
102 : :
103 : : /* convert timezone to +hhmm */
104 [ + - ]: 6 : 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 : 6 : return snprintf(tsbuf, tsbuflen, "%s,%06lu%.3s:%.2s",
109 : 6 : 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 [ # # ]: 0 : 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 : 0 : previous = rte_atomic_exchange_explicit(&log_time.last_monotonic,
124 : : ns, rte_memory_order_seq_cst);
125 [ # # ]: 0 : delta = rte_ns_to_timespec(ns - previous);
126 : :
127 : 0 : return snprintf(tsbuf, tsbuflen, "<%6lu.%06lu>",
128 : : (unsigned long)delta.tv_sec,
129 : 0 : (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 : 0 : 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 : 0 : tm = localtime_r(&now->tv_sec, &tbuf1);
147 : :
148 : 0 : previous = rte_atomic_exchange_explicit(&log_time.last_realtime,
149 : : ns, rte_memory_order_seq_cst);
150 : 0 : last_sec = previous / NS_PER_SEC;
151 : 0 : last_tm = localtime_r(&last_sec, &tbuf2);
152 [ # # ]: 0 : if (tm->tm_min == last_tm->tm_min &&
153 [ # # ]: 0 : tm->tm_hour == last_tm->tm_hour &&
154 [ # # ]: 0 : tm->tm_yday == last_tm->tm_yday) {
155 : : struct timespec elapsed;
156 : :
157 [ # # ]: 0 : elapsed = rte_ns_to_timespec(ns - previous);
158 : :
159 : 0 : return snprintf(tsbuf, tsbuflen, "+%3lu.%06lu",
160 : : (unsigned long)elapsed.tv_sec,
161 : 0 : (unsigned long)elapsed.tv_nsec / 1000u);
162 : : } else {
163 : 0 : 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 : 12 : log_timestamp(char *tsbuf, size_t tsbuflen)
170 : : {
171 : : struct timespec now, delta;
172 : :
173 [ + - - - : 12 : switch (log_time_format) {
+ - ]
174 : : case LOG_TIMESTAMP_NONE:
175 : : return 0;
176 : :
177 : 6 : case LOG_TIMESTAMP_TIME:
178 [ + - ]: 6 : if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
179 : : return 0;
180 : :
181 : : delta = timespec_sub(&now, &log_time.started);
182 : :
183 : 6 : return snprintf(tsbuf, tsbuflen, "%6lu.%06lu",
184 : : (unsigned long)delta.tv_sec,
185 : 6 : (unsigned long)delta.tv_nsec / 1000u);
186 : :
187 : 0 : case LOG_TIMESTAMP_DELTA:
188 [ # # ]: 0 : if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
189 : : return 0;
190 : :
191 : 0 : return format_delta(tsbuf, tsbuflen, &now);
192 : :
193 : 0 : case LOG_TIMESTAMP_RELTIME:
194 [ # # ]: 0 : if (clock_gettime(CLOCK_REALTIME, &now) < 0)
195 : : return 0;
196 : :
197 : 0 : return format_reltime(tsbuf, tsbuflen, &now);
198 : :
199 : 0 : case LOG_TIMESTAMP_CTIME:
200 [ # # ]: 0 : if (clock_gettime(CLOCK_REALTIME, &now) < 0)
201 : : return 0;
202 : :
203 : : /* trncate to remove newline from ctime result */
204 : 0 : return snprintf(tsbuf, tsbuflen, "%.24s", ctime(&now.tv_sec));
205 : :
206 : 6 : case LOG_TIMESTAMP_ISO:
207 [ + - ]: 6 : if (clock_gettime(CLOCK_REALTIME, &now) < 0)
208 : : return 0;
209 : :
210 : 6 : return format_iso8601(tsbuf, tsbuflen, &now);
211 : : }
212 : :
213 : : return 0;
214 : : }
215 : :
216 : : /* print timestamp before message */
217 : : int
218 : 12 : log_print_with_timestamp(FILE *f, const char *format, va_list ap)
219 : : {
220 : : char tsbuf[128];
221 : : char msgbuf[LINE_MAX];
222 : :
223 [ + - ]: 12 : if (log_timestamp(tsbuf, sizeof(tsbuf)) > 0) {
224 : : vsnprintf(msgbuf, sizeof(msgbuf), format, ap);
225 : 12 : return fprintf(f, "[%s] %s", tsbuf, msgbuf);
226 : : }
227 : :
228 : : /* fall back when timestamp is unavailable */
229 : 0 : return vfprintf(f, format, ap);
230 : : }
231 : :
232 : 251 : RTE_INIT_PRIO(log_timestamp_init, LOG)
233 : : {
234 : : struct timespec now;
235 : :
236 : 251 : clock_gettime(CLOCK_MONOTONIC, &now);
237 : 251 : log_time.started = now;
238 : 251 : rte_atomic_store_explicit(&log_time.last_monotonic, rte_timespec_to_ns(&now),
239 : : rte_memory_order_seq_cst);
240 : 251 : }
|
