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