GCC Code Coverage Report

Directory: cvmfs/
File: cvmfs/tracer.cc
Date: 2025-05-11 02:35:43
Exec Total Coverage
Lines: 159 164 97.0%
Branches: 103 162 63.6%
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 <cassert>
11 #include <cerrno>
12 #include <cstdio>
13 #include <cstdlib>
14 #include <cstring>
15 #include <string>
16
17 #include "util/atomic.h"
18 #include "util/concurrency.h"
19 #include "util/posix.h"
20 #include "util/string.h"
21
22 using namespace std; // NOLINT
23
24
25 14 void Tracer::Activate(
26 const int buffer_size,
27 const int flush_threshold,
28 const string &trace_file)
29 {
30 14 trace_file_ = trace_file;
31 14 buffer_size_ = buffer_size;
32 14 flush_threshold_ = flush_threshold;
33
3/6
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 14 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 14 times.
✗ Branch 5 not taken.
 14 assert(buffer_size_ > 1 && flush_threshold_>= 0
34 && flush_threshold_ < buffer_size_);
35
36
4/8
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 4194 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 4194 times.
✓ Branch 7 taken 14 times.
✗ Branch 9 not taken.
✗ Branch 10 not taken.
 4208 ring_buffer_ = new BufferEntry[buffer_size_];
37
1/2
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
 14 commit_buffer_ = new atomic_int32[buffer_size_];
38
2/2
✓ Branch 0 taken 4194 times.
✓ Branch 1 taken 14 times.
 4208 for (int i = 0; i < buffer_size_; i++)
39 4194 atomic_init32(&commit_buffer_[i]);
40
41 int retval;
42 14 retval = pthread_cond_init(&sig_continue_trace_, NULL);
43 14 retval |= pthread_mutex_init(&sig_continue_trace_mutex_, NULL);
44 14 retval |= pthread_cond_init(&sig_flush_, NULL);
45 14 retval |= pthread_mutex_init(&sig_flush_mutex_, NULL);
46
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
47
48 14 active_ = true;
49 14 }
50
51
52 /**
53 * Trace a message. This is usually a lock-free procedure that just
54 * requires two fetch_and_add operations and a gettimeofday syscall.
55 * There are two exceptions:
56 * -# If the ring buffer is full, the function blocks until the flush
57 * thread made some space. Avoid that by carefully choosing size
58 * and threshold.
59 * -# If this message reaches the threshold, the flush thread gets
60 * signaled.
61 *
62 * \param[in] event Arbitrary code, for consistency applications should use one
63 * of the TraceEvents constants. Negative codes are reserved
64 * for internal use.
65 * \param[in] id Arbitrary id, for example file name or module name which is
66 * doing the trace.
67 * \return The sequence number which was used to trace the record
68 */
69 342012 int32_t Tracer::DoTrace(
70 const int event,
71 const PathString &path,
72 const string &msg)
73 {
74 342012 int32_t my_seq_no = atomic_xadd32(&seq_no_, 1);
75 timeval now;
76 359175 gettimeofday(&now, NULL);
77 358021 int pos = my_seq_no % buffer_size_;
78
79
2/2
✓ Branch 1 taken 107473 times.
✓ Branch 2 taken 360472 times.
 471022 while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) {
80 timespec timeout;
81 int retval;
82 107473 GetTimespecRel(25, &timeout);
83 105950 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
84
1/2
✓ Branch 1 taken 114903 times.
✗ Branch 2 not taken.
 114903 retval |= pthread_cond_timedwait(&sig_continue_trace_,
85 &sig_continue_trace_mutex_, &timeout);
86 114903 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
87
2/4
✓ Branch 0 taken 113092 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 113092 times.
 113001 assert(retval == ETIMEDOUT || retval == 0);
88 }
89
90 360472 ring_buffer_[pos].time_stamp = now;
91 360472 ring_buffer_[pos].code = event;
92
1/2
✓ Branch 1 taken 344794 times.
✗ Branch 2 not taken.
 360472 ring_buffer_[pos].path = path;
93
1/2
✓ Branch 1 taken 349929 times.
✗ Branch 2 not taken.
 344794 ring_buffer_[pos].msg = msg;
94 349929 atomic_inc32(&commit_buffer_[pos]);
95
96
2/2
✓ Branch 1 taken 39667 times.
✓ Branch 2 taken 316128 times.
 358024 if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) {
97 39667 MutexLockGuard m(&sig_flush_mutex_);
98 39667 int err_code __attribute__((unused)) = pthread_cond_signal(&sig_flush_);
99
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 39667 times.
 39667 assert(err_code == 0 && "Could not signal flush thread");
100 39667 }
101
102 355617 return my_seq_no;
103 }
104
105
106 1435 void Tracer::Flush() {
107
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1435 times.
 1435 if (!active_) return;
108
109
3/6
✓ Branch 2 taken 1428 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 1458 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 1470 times.
✗ Branch 9 not taken.
 1435 int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6),
110 "flushed ring buffer");
111
2/2
✓ Branch 1 taken 1251 times.
✓ Branch 2 taken 1475 times.
 2726 while (atomic_read32(&flushed_) <= save_seq_no) {
112 timespec timeout;
113 int retval;
114
115 1251 atomic_cas32(&flush_immediately_, 0, 1);
116 {
117 1252 MutexLockGuard m(&sig_flush_mutex_);
118 1285 retval = pthread_cond_signal(&sig_flush_);
119
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1285 times.
 1285 assert(retval == 0);
120 1285 }
121
122 1285 GetTimespecRel(250, &timeout);
123 1278 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
124
1/2
✓ Branch 1 taken 1285 times.
✗ Branch 2 not taken.
 1285 retval |= pthread_cond_timedwait(&sig_continue_trace_,
125 &sig_continue_trace_mutex_,
126 &timeout);
127 1285 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
128
3/4
✓ Branch 0 taken 1179 times.
✓ Branch 1 taken 79 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 1179 times.
 1258 assert(retval == ETIMEDOUT || retval == 0);
129 }
130 }
131
132
133 139088 void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) {
134 timeval now;
135 139088 gettimeofday(&now, NULL);
136 138988 int64_t nsecs = now.tv_usec * 1000 + (ms % 1000)*1000*1000;
137 138988 int carry = 0;
138
2/2
✓ Branch 0 taken 915 times.
✓ Branch 1 taken 138073 times.
 138988 if (nsecs >= 1000*1000*1000) {
139 915 carry = 1;
140 915 nsecs -= 1000*1000*1000;
141 }
142 138988 ts->tv_sec = now.tv_sec + ms/1000 + carry;
143 138988 ts->tv_nsec = nsecs;
144 138988 }
145
146
147 14 void *Tracer::MainFlush(void *data) {
148 14 Tracer *tracer = reinterpret_cast<Tracer *>(data);
149 int retval;
150 14 MutexLockGuard m(&tracer->sig_flush_mutex_);
151
1/2
✓ Branch 2 taken 14 times.
✗ Branch 3 not taken.
 14 FILE *f = fopen(tracer->trace_file_.c_str(), "a");
152
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(f != NULL && "Could not open trace file");
153 struct timespec timeout;
154
155 do {
156
2/2
✓ Branch 1 taken 148493 times.
✓ Branch 2 taken 361 times.
 297722 while ((atomic_read32(&tracer->terminate_flush_thread_) == 0) &&
157
4/4
✓ Branch 0 taken 148854 times.
✓ Branch 1 taken 14 times.
✓ Branch 3 taken 32149 times.
✓ Branch 4 taken 116719 times.
 297722 (atomic_read32(&tracer->flush_immediately_) == 0) &&
158 148493 (atomic_read32(&tracer->seq_no_) -
159 148493 atomic_read32(&tracer->flushed_)
160
2/2
✓ Branch 0 taken 32149 times.
✓ Branch 1 taken 116344 times.
 148493 <= tracer->flush_threshold_))
161 {
162 32149 tracer->GetTimespecRel(2000, &timeout);
163
1/2
✓ Branch 1 taken 32149 times.
✗ Branch 2 not taken.
 32149 retval = pthread_cond_timedwait(&tracer->sig_flush_,
164 &tracer->sig_flush_mutex_,
165 &timeout);
166
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 32149 times.
 32149 assert(retval != EINVAL);
167 }
168
169 116719 int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_;
170 116719 int pos, i = 0;
171
6/6
✓ Branch 0 taken 433867 times.
✓ Branch 1 taken 55481 times.
✓ Branch 2 taken 372629 times.
✓ Branch 3 taken 61238 times.
✓ Branch 4 taken 372629 times.
✓ Branch 5 taken 116719 times.
 923215 while ((i <= tracer->flush_threshold_) &&
172 433867 (atomic_read32(&tracer->commit_buffer_[
173 433867 pos = ((base + i) % tracer->buffer_size_)]) == 1))
174 {
175 372629 string tmp;
176
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 tmp = StringifyTimeval(tracer->ring_buffer_[pos].time_stamp);
177
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval = tracer->WriteCsvFile(f, tmp);
178
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval |= fputc(',', f) - ',';
179
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 tmp = StringifyInt(tracer->ring_buffer_[pos].code);
180
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval = tracer->WriteCsvFile(f, tmp);
181
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval |= fputc(',', f) - ',';
182
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval |= tracer->WriteCsvFile(
183
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 745258 f, tracer->ring_buffer_[pos].path.ToString());
184
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval |= fputc(',', f) - ',';
185
1/2
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
 372629 retval |= tracer->WriteCsvFile(f, tracer->ring_buffer_[pos].msg);
186
2/4
✓ Branch 1 taken 372629 times.
✗ Branch 2 not taken.
✓ Branch 4 taken 372629 times.
✗ Branch 5 not taken.
 372629 retval |= (fputc(13, f) - 13) | (fputc(10, f) - 10);
187
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 372629 times.
 372629 assert(retval == 0);
188
189 372629 atomic_dec32(&tracer->commit_buffer_[pos]);
190 372629 ++i;
191 372629 }
192
1/2
✓ Branch 1 taken 116719 times.
✗ Branch 2 not taken.
 116719 retval = fflush(f);
193
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 116719 times.
 116719 assert(retval == 0);
194 116719 atomic_xadd32(&tracer->flushed_, i);
195 116719 atomic_cas32(&tracer->flush_immediately_, 1, 0);
196
197 {
198 116719 MutexLockGuard l(&tracer->sig_continue_trace_mutex_);
199 116719 retval = pthread_cond_broadcast(&tracer->sig_continue_trace_);
200
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 116719 times.
 116719 assert(retval == 0);
201 116719 }
202
6/6
✓ Branch 1 taken 17 times.
✓ Branch 2 taken 116702 times.
✓ Branch 3 taken 3 times.
✓ Branch 4 taken 14 times.
✓ Branch 5 taken 116705 times.
✓ Branch 6 taken 14 times.
 116736 } while ((atomic_read32(&tracer->terminate_flush_thread_) == 0) ||
203 17 (atomic_read32(&tracer->flushed_) <
204 17 atomic_read32(&tracer->seq_no_)));
205
206
1/2
✓ Branch 1 taken 14 times.
✗ Branch 2 not taken.
 14 retval = fclose(f);
207
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
208 14 return NULL;
209 14 }
210
211
212 15 void Tracer::Spawn() {
213
2/2
✓ Branch 0 taken 14 times.
✓ Branch 1 taken 1 times.
 15 if (active_) {
214 14 int retval = pthread_create(&thread_flush_, NULL, MainFlush, this);
215
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
216
217 14 spawned_ = true;
218
3/6
✓ Branch 2 taken 14 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 14 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 14 times.
✗ Branch 9 not taken.
 14 DoTrace(kEventStart, PathString("Tracer", 6), "Trace buffer created");
219 }
220 15 }
221
222
223 38 Tracer::Tracer()
224 38 : active_(false)
225 38 , spawned_(false)
226 38 , buffer_size_(0)
227 38 , flush_threshold_(0)
228 38 , ring_buffer_(NULL)
229 38 , commit_buffer_(NULL)
230 {
231 38 memset(&thread_flush_, 0, sizeof(thread_flush_));
232 38 atomic_init32(&seq_no_);
233 38 atomic_init32(&flushed_);
234 38 atomic_init32(&terminate_flush_thread_);
235 38 atomic_init32(&flush_immediately_);
236 38 }
237
238
239 52 Tracer::~Tracer() {
240
2/2
✓ Branch 0 taken 24 times.
✓ Branch 1 taken 14 times.
 38 if (!active_)
241 24 return;
242 int retval;
243
244
1/2
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
 14 if (spawned_) {
245 14 DoTrace(kEventStop, PathString("Tracer", 6), "Destroying trace buffer...");
246
247 // Trigger flushing and wait for it
248 14 atomic_inc32(&terminate_flush_thread_);
249 {
250 14 MutexLockGuard m(&sig_flush_mutex_);
251 14 retval = pthread_cond_signal(&sig_flush_);
252
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
253 14 }
254 14 retval = pthread_join(thread_flush_, NULL);
255
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
256 }
257
258 14 retval = pthread_cond_destroy(&sig_continue_trace_);
259 14 retval |= pthread_mutex_destroy(&sig_continue_trace_mutex_);
260 14 retval |= pthread_cond_destroy(&sig_flush_);
261 14 retval |= pthread_mutex_destroy(&sig_flush_mutex_);
262
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 14 times.
 14 assert(retval == 0);
263
264
3/4
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 4194 times.
✓ Branch 3 taken 14 times.
 4208 delete[] ring_buffer_;
265
1/2
✓ Branch 0 taken 14 times.
✗ Branch 1 not taken.
 14 delete[] commit_buffer_;
266
2/2
✓ Branch 1 taken 14 times.
✓ Branch 2 taken 24 times.
 38 }
267
268
269 1490516 int Tracer::WriteCsvFile(FILE *fp, const string &field) {
270
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1490516 times.
 1490516 if (fp == NULL)
271 ✗ return 0;
272
273 int retval;
274
275
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 1490516 times.
 1490516 if ((retval = fputc('"', fp)) != '"')
276 ✗ return retval;
277
278
2/2
✓ Branch 1 taken 21489488 times.
✓ Branch 2 taken 1490516 times.
 22980004 for (unsigned i = 0, l = field.length(); i < l; ++i) {
279
2/2
✓ Branch 1 taken 261000 times.
✓ Branch 2 taken 21228488 times.
 21489488 if (field[i] == '"') {
280
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 261000 times.
 261000 if ((retval = fputc('"', fp)) != '"')
281 ✗ return retval;
282 }
283
1/2
✗ Branch 3 not taken.
✓ Branch 4 taken 21489488 times.
 21489488 if ((retval = fputc(field[i], fp)) != field[i])
284 ✗ return retval;
285 }
286
287
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 1490516 times.
 1490516 if ((retval = fputc('"', fp)) != '"')
288 ✗ return retval;
289
290 1490516 return 0;
291 }
292