GCC Code Coverage Report

Directory: cvmfs/
File: cvmfs/tracer.cc
Date: 2026-10-11 02:40:02
Exec Total Coverage
Lines: 160 166 96.4%
Branches: 105 164 64.0%
Line Branch Exec Source
1 /**
2 * This file is part of the CernVM File System.
3 */
4
5
6 #include "tracer.h"
7
8 #include <pthread.h>
9
10 #include <atomic>
11 #include <cassert>
12 #include <cerrno>
13 #include <cstdio>
14 #include <cstdlib>
15 #include <cstring>
16 #include <string>
17
18 #include "util/concurrency.h"
19 #include "util/posix.h"
20 #include "util/string.h"
21
22 using namespace std; // NOLINT
23
24
25 266 void Tracer::Activate(const int buffer_size,
26 const int flush_threshold,
27 const string &trace_file) {
28 266 trace_file_ = trace_file;
29 266 buffer_size_ = buffer_size;
30 266 flush_threshold_ = flush_threshold;
31
3/6
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 266 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 266 times.
✗ Branch 5 not taken.
 266 assert(buffer_size_ > 1 && flush_threshold_ >= 0
32 && flush_threshold_ < buffer_size_);
33
34
4/8
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 79686 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 79686 times.
✓ Branch 7 taken 266 times.
✗ Branch 9 not taken.
✗ Branch 10 not taken.
 79952 ring_buffer_ = new BufferEntry[buffer_size_];
35
3/4
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 79686 times.
✓ Branch 5 taken 266 times.
 79952 commit_buffer_ = new std::atomic<int32_t>[buffer_size_];
36
2/2
✓ Branch 0 taken 79686 times.
✓ Branch 1 taken 266 times.
 79952 for (int i = 0; i < buffer_size_; i++)
37 79686 commit_buffer_[i].store(0);
38
39 int retval;
40 266 retval = pthread_cond_init(&sig_continue_trace_, NULL);
41 266 retval |= pthread_mutex_init(&sig_continue_trace_mutex_, NULL);
42 266 retval |= pthread_cond_init(&sig_flush_, NULL);
43 266 retval |= pthread_mutex_init(&sig_flush_mutex_, NULL);
44
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
45
46 266 active_ = true;
47 266 }
48
49
50 /**
51 * Trace a message. This is usually a lock-free procedure that just
52 * requires two fetch_and_add operations and a gettimeofday syscall.
53 * There are two exceptions:
54 * -# If the ring buffer is full, the function blocks until the flush
55 * thread made some space. Avoid that by carefully choosing size
56 * and threshold.
57 * -# If this message reaches the threshold, the flush thread gets
58 * signaled.
59 *
60 * \param[in] event Arbitrary code, for consistency applications should use one
61 * of the TraceEvents constants. Negative codes are reserved
62 * for internal use.
63 * \param[in] id Arbitrary id, for example file name or module name which is
64 * doing the trace.
65 * \return The sequence number which was used to trace the record
66 */
67 6452343 int32_t Tracer::DoTrace(const int event,
68 const PathString &path,
69 const string &msg) {
70 6452343 const int32_t my_seq_no = seq_no_.fetch_add(1);
71 timeval now;
72 6452343 gettimeofday(&now, NULL);
73 6712548 const int pos = my_seq_no % buffer_size_;
74
75
2/2
✓ Branch 1 taken 2249847 times.
✓ Branch 2 taken 6584697 times.
 17934062 while (my_seq_no - flushed_.load() >= buffer_size_) {
76 timespec timeout;
77 int retval;
78 2249847 GetTimespecRel(25, &timeout);
79 2223893 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
80
1/2
✓ Branch 1 taken 2447067 times.
✗ Branch 2 not taken.
 2447067 retval |= pthread_cond_timedwait(&sig_continue_trace_,
81 &sig_continue_trace_mutex_, &timeout);
82 2447067 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
83
2/4
✓ Branch 0 taken 2389440 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 2389440 times.
 2386970 assert(retval == ETIMEDOUT || retval == 0);
84 }
85
86 6584697 ring_buffer_[pos].time_stamp = now;
87 6584697 ring_buffer_[pos].code = event;
88
1/2
✓ Branch 1 taken 6455060 times.
✗ Branch 2 not taken.
 6584697 ring_buffer_[pos].path = path;
89
1/2
✓ Branch 1 taken 6561270 times.
✗ Branch 2 not taken.
 6455060 ring_buffer_[pos].msg = msg;
90 6561270 commit_buffer_[pos].fetch_add(1);
91
92
2/2
✓ Branch 1 taken 696217 times.
✓ Branch 2 taken 5960851 times.
 13218338 if (my_seq_no - flushed_.load() == flush_threshold_) {
93 696217 const MutexLockGuard m(&sig_flush_mutex_);
94 const int err_code
95 696236 __attribute__((unused)) = pthread_cond_signal(&sig_flush_);
96
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 696236 times.
 696236 assert(err_code == 0 && "Could not signal flush thread");
97 696236 }
98
99 6655928 return my_seq_no;
100 }
101
102
103 27265 void Tracer::Flush() {
104
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 27265 times.
 27265 if (!active_)
105 ✗ return;
106
107
3/6
✓ Branch 2 taken 27151 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 27740 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 27835 times.
✗ Branch 9 not taken.
 27265 const int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6),
108 "flushed ring buffer");
109
2/2
✓ Branch 1 taken 23370 times.
✓ Branch 2 taken 27550 times.
 102638 while (flushed_.load() <= save_seq_no) {
110 timespec timeout;
111 int retval;
112
113 23370 int32_t expected_val = 0;
114 23370 flush_immediately_.compare_exchange_strong(expected_val, 1);
115 {
116 23256 const MutexLockGuard m(&sig_flush_mutex_);
117 24092 retval = pthread_cond_signal(&sig_flush_);
118
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 24092 times.
 24092 assert(retval == 0);
119 24092 }
120
121 24035 GetTimespecRel(250, &timeout);
122 24035 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
123
1/2
✓ Branch 1 taken 24092 times.
✗ Branch 2 not taken.
 24092 retval |= pthread_cond_timedwait(&sig_continue_trace_,
124 &sig_continue_trace_mutex_, &timeout);
125 24092 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
126
3/4
✓ Branch 0 taken 21869 times.
✓ Branch 1 taken 1710 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 21869 times.
 23579 assert(retval == ETIMEDOUT || retval == 0);
127 }
128 }
129
130
131 2819790 void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) {
132 timeval now;
133 2819790 gettimeofday(&now, NULL);
134 2822963 int64_t nsecs = now.tv_usec * 1000 + (ms % 1000) * 1000 * 1000;
135 2822963 int carry = 0;
136
2/2
✓ Branch 0 taken 95570 times.
✓ Branch 1 taken 2727393 times.
 2822963 if (nsecs >= 1000 * 1000 * 1000) {
137 95570 carry = 1;
138 95570 nsecs -= 1000 * 1000 * 1000;
139 }
140 2822963 ts->tv_sec = now.tv_sec + ms / 1000 + carry;
141 2822963 ts->tv_nsec = nsecs;
142 2822963 }
143
144
145 266 void *Tracer::MainFlush(void *data) {
146 266 Tracer *tracer = reinterpret_cast<Tracer *>(data);
147 int retval;
148 266 const MutexLockGuard m(&tracer->sig_flush_mutex_);
149
1/2
✓ Branch 2 taken 266 times.
✗ Branch 3 not taken.
 266 FILE *f = fopen(tracer->trace_file_.c_str(), "a");
150
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(f != NULL && "Could not open trace file");
151 struct timespec timeout;
152
153 do {
154 2248859 while ((tracer->terminate_flush_thread_.load() == 0)
155
2/2
✓ Branch 1 taken 2242228 times.
✓ Branch 2 taken 6365 times.
 4497186 && (tracer->flush_immediately_.load() == 0)
156
4/4
✓ Branch 0 taken 2248593 times.
✓ Branch 1 taken 266 times.
✓ Branch 4 taken 593503 times.
✓ Branch 5 taken 1655356 times.
 8981908 && ((tracer->seq_no_).load() - (tracer->flushed_).load()
157
2/2
✓ Branch 0 taken 593503 times.
✓ Branch 1 taken 1648725 times.
 2242228 <= tracer->flush_threshold_)) {
158 593503 tracer->GetTimespecRel(2000, &timeout);
159
1/2
✓ Branch 1 taken 593503 times.
✗ Branch 2 not taken.
 593503 retval = pthread_cond_timedwait(&tracer->sig_flush_,
160 &tracer->sig_flush_mutex_, &timeout);
161
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 593503 times.
 593503 assert(retval != EINVAL);
162 }
163
164 1655356 const int base = tracer->flushed_.load() % tracer->buffer_size_;
165 1655356 int pos, i = 0;
166 1655356 while (
167 8735307 (i <= tracer->flush_threshold_)
168
4/4
✓ Branch 0 taken 7683752 times.
✓ Branch 1 taken 1051555 times.
✓ Branch 2 taken 7079951 times.
✓ Branch 3 taken 1655356 times.
 16419059 && ((tracer->commit_buffer_[pos = ((base + i) % tracer->buffer_size_)])
169
2/2
✓ Branch 1 taken 7079951 times.
✓ Branch 2 taken 603801 times.
 15367504 .load()
170 == 1)) {
171 7079951 string tmp;
172
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 tmp = StringifyTimeval(tracer->ring_buffer_[pos].time_stamp);
173
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval = tracer->WriteCsvFile(f, tmp);
174
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval |= fputc(',', f) - ',';
175
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 tmp = StringifyInt(tracer->ring_buffer_[pos].code);
176
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval = tracer->WriteCsvFile(f, tmp);
177
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval |= fputc(',', f) - ',';
178
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval |= tracer->WriteCsvFile(f,
179
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 14159902 tracer->ring_buffer_[pos].path.ToString());
180
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval |= fputc(',', f) - ',';
181
1/2
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
 7079951 retval |= tracer->WriteCsvFile(f, tracer->ring_buffer_[pos].msg);
182
2/4
✓ Branch 1 taken 7079951 times.
✗ Branch 2 not taken.
✓ Branch 4 taken 7079951 times.
✗ Branch 5 not taken.
 7079951 retval |= (fputc(13, f) - 13) | (fputc(10, f) - 10);
183
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 7079951 times.
 7079951 assert(retval == 0);
184
185 7079951 tracer->commit_buffer_[pos].fetch_sub(1);
186 7079951 ++i;
187 7079951 }
188
1/2
✓ Branch 1 taken 1655356 times.
✗ Branch 2 not taken.
 1655356 retval = fflush(f);
189
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1655356 times.
 1655356 assert(retval == 0);
190 1655356 tracer->flushed_.fetch_add(i);
191 1655356 int32_t expected_val = 1;
192 1655356 tracer->flush_immediately_.compare_exchange_strong(expected_val, 0);
193
194 {
195 1655356 const MutexLockGuard l(&tracer->sig_continue_trace_mutex_);
196 1655356 retval = pthread_cond_broadcast(&tracer->sig_continue_trace_);
197
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1655356 times.
 1655356 assert(retval == 0);
198 1655356 }
199 1655356 } while ((tracer->terminate_flush_thread_.load() == 0)
200
6/6
✓ Branch 0 taken 323 times.
✓ Branch 1 taken 1655033 times.
✓ Branch 4 taken 57 times.
✓ Branch 5 taken 266 times.
✓ Branch 6 taken 1655090 times.
✓ Branch 7 taken 266 times.
 1656002 || ((tracer->flushed_).load() < (tracer->seq_no_).load()));
201
202
1/2
✓ Branch 1 taken 266 times.
✗ Branch 2 not taken.
 266 retval = fclose(f);
203
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
204 266 return NULL;
205 266 }
206
207
208 285 void Tracer::Spawn() {
209
2/2
✓ Branch 0 taken 266 times.
✓ Branch 1 taken 19 times.
 285 if (active_) {
210 266 const int retval = pthread_create(&thread_flush_, NULL, MainFlush, this);
211
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
212
213 266 spawned_ = true;
214
3/6
✓ Branch 2 taken 266 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 266 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 266 times.
✗ Branch 9 not taken.
 266 DoTrace(kEventStart, PathString("Tracer", 6), "Trace buffer created");
215 }
216 285 }
217
218
219 842 Tracer::Tracer()
220 842 : active_(false)
221 842 , spawned_(false)
222 842 , buffer_size_(0)
223 842 , flush_threshold_(0)
224 842 , ring_buffer_(NULL)
225 842 , commit_buffer_(NULL) {
226 842 memset(&thread_flush_, 0, sizeof(thread_flush_));
227 842 seq_no_.store(0);
228 842 flushed_.store(0);
229 842 terminate_flush_thread_.store(0);
230 842 flush_immediately_.store(0);
231 842 }
232
233
234 1108 Tracer::~Tracer() {
235
2/2
✓ Branch 0 taken 576 times.
✓ Branch 1 taken 266 times.
 842 if (!active_)
236 576 return;
237 int retval;
238
239
1/2
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
 266 if (spawned_) {
240 266 DoTrace(kEventStop, PathString("Tracer", 6), "Destroying trace buffer...");
241
242 // Trigger flushing and wait for it
243 266 terminate_flush_thread_.fetch_add(1);
244 {
245 266 const MutexLockGuard m(&sig_flush_mutex_);
246 266 retval = pthread_cond_signal(&sig_flush_);
247
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
248 266 }
249 266 retval = pthread_join(thread_flush_, NULL);
250
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
251 }
252
253 266 retval = pthread_cond_destroy(&sig_continue_trace_);
254 266 retval |= pthread_mutex_destroy(&sig_continue_trace_mutex_);
255 266 retval |= pthread_cond_destroy(&sig_flush_);
256 266 retval |= pthread_mutex_destroy(&sig_flush_mutex_);
257
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 266 times.
 266 assert(retval == 0);
258
259
3/4
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 79686 times.
✓ Branch 3 taken 266 times.
 79952 delete[] ring_buffer_;
260
1/2
✓ Branch 0 taken 266 times.
✗ Branch 1 not taken.
 266 delete[] commit_buffer_;
261
2/2
✓ Branch 1 taken 266 times.
✓ Branch 2 taken 576 times.
 842 }
262
263
264 28319804 int Tracer::WriteCsvFile(FILE *fp, const string &field) {
265
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 28319804 times.
 28319804 if (fp == NULL)
266 ✗ return 0;
267
268 int retval;
269
270
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 28319804 times.
 28319804 if ((retval = fputc('"', fp)) != '"')
271 ✗ return retval;
272
273
2/2
✓ Branch 1 taken 408300272 times.
✓ Branch 2 taken 28319804 times.
 436620076 for (unsigned i = 0, l = field.length(); i < l; ++i) {
274
2/2
✓ Branch 1 taken 4959000 times.
✓ Branch 2 taken 403341272 times.
 408300272 if (field[i] == '"') {
275
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 4959000 times.
 4959000 if ((retval = fputc('"', fp)) != '"')
276 ✗ return retval;
277 }
278
1/2
✗ Branch 3 not taken.
✓ Branch 4 taken 408300272 times.
 408300272 if ((retval = fputc(field[i], fp)) != field[i])
279 ✗ return retval;
280 }
281
282
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 28319804 times.
 28319804 if ((retval = fputc('"', fp)) != '"')
283 ✗ return retval;
284
285 28319804 return 0;
286 }
287
288