GCC Code Coverage Report

Directory: cvmfs/
File: cvmfs/tracer.cc
Date: 2025-06-22 02:36:02
Exec Total Coverage
Lines: 159 165 96.4%
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 196 void Tracer::Activate(const int buffer_size,
26 const int flush_threshold,
27 const string &trace_file) {
28 196 trace_file_ = trace_file;
29 196 buffer_size_ = buffer_size;
30 196 flush_threshold_ = flush_threshold;
31
3/6
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 196 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 196 times.
✗ Branch 5 not taken.
 196 assert(buffer_size_ > 1 && flush_threshold_ >= 0
32 && flush_threshold_ < buffer_size_);
33
34
4/8
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 58716 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 58716 times.
✓ Branch 7 taken 196 times.
✗ Branch 9 not taken.
✗ Branch 10 not taken.
 58912 ring_buffer_ = new BufferEntry[buffer_size_];
35
1/2
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
 196 commit_buffer_ = new atomic_int32[buffer_size_];
36
2/2
✓ Branch 0 taken 58716 times.
✓ Branch 1 taken 196 times.
 58912 for (int i = 0; i < buffer_size_; i++)
37 58716 atomic_init32(&commit_buffer_[i]);
38
39 int retval;
40 196 retval = pthread_cond_init(&sig_continue_trace_, NULL);
41 196 retval |= pthread_mutex_init(&sig_continue_trace_mutex_, NULL);
42 196 retval |= pthread_cond_init(&sig_flush_, NULL);
43 196 retval |= pthread_mutex_init(&sig_flush_mutex_, NULL);
44
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
45
46 196 active_ = true;
47 196 }
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 4715200 int32_t Tracer::DoTrace(const int event,
68 const PathString &path,
69 const string &msg) {
70 4715200 const int32_t my_seq_no = atomic_xadd32(&seq_no_, 1);
71 timeval now;
72 5003642 gettimeofday(&now, NULL);
73 4966178 const int pos = my_seq_no % buffer_size_;
74
75
2/2
✓ Branch 1 taken 1466332 times.
✓ Branch 2 taken 5012700 times.
 6522768 while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) {
76 timespec timeout;
77 int retval;
78 1466332 GetTimespecRel(25, &timeout);
79 1447684 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
80
1/2
✓ Branch 1 taken 1598072 times.
✗ Branch 2 not taken.
 1598072 retval |= pthread_cond_timedwait(&sig_continue_trace_,
81 &sig_continue_trace_mutex_, &timeout);
82 1598072 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
83
2/4
✓ Branch 0 taken 1558088 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 1558088 times.
 1556590 assert(retval == ETIMEDOUT || retval == 0);
84 }
85
86 5012700 ring_buffer_[pos].time_stamp = now;
87 5012700 ring_buffer_[pos].code = event;
88
1/2
✓ Branch 1 taken 4807754 times.
✗ Branch 2 not taken.
 5012700 ring_buffer_[pos].path = path;
89
1/2
✓ Branch 1 taken 4902590 times.
✗ Branch 2 not taken.
 4807754 ring_buffer_[pos].msg = msg;
90 4902590 atomic_inc32(&commit_buffer_[pos]);
91
92
2/2
✓ Branch 1 taken 573986 times.
✓ Branch 2 taken 4358116 times.
 5009116 if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) {
93 573986 const MutexLockGuard m(&sig_flush_mutex_);
94 const int err_code __attribute__((unused)) =
95 574000 pthread_cond_signal(&sig_flush_);
96
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 574000 times.
 574000 assert(err_code == 0 && "Could not signal flush thread");
97 574000 }
98
99 4930436 return my_seq_no;
100 }
101
102
103 20412 void Tracer::Flush() {
104
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 20412 times.
 20412 if (!active_)
105 ✗ return;
106
107 const int32_t save_seq_no =
108
3/6
✓ Branch 2 taken 20510 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 20720 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 20720 times.
✗ Branch 9 not taken.
 20412 DoTrace(kEventFlush, PathString("Tracer", 6), "flushed ring buffer");
109
2/2
✓ Branch 1 taken 17794 times.
✓ Branch 2 taken 20804 times.
 38738 while (atomic_read32(&flushed_) <= save_seq_no) {
110 timespec timeout;
111 int retval;
112
113 17794 atomic_cas32(&flush_immediately_, 0, 1);
114 {
115 17794 const MutexLockGuard m(&sig_flush_mutex_);
116 18102 retval = pthread_cond_signal(&sig_flush_);
117
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 18102 times.
 18102 assert(retval == 0);
118 18102 }
119
120 18102 GetTimespecRel(250, &timeout);
121 18060 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
122
1/2
✓ Branch 1 taken 18102 times.
✗ Branch 2 not taken.
 18102 retval |= pthread_cond_timedwait(
123 &sig_continue_trace_, &sig_continue_trace_mutex_, &timeout);
124 18102 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
125
3/4
✓ Branch 0 taken 16086 times.
✓ Branch 1 taken 1932 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 16086 times.
 18018 assert(retval == ETIMEDOUT || retval == 0);
126 }
127 }
128
129
130 1929172 void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) {
131 timeval now;
132 1929172 gettimeofday(&now, NULL);
133 1923698 int64_t nsecs = now.tv_usec * 1000 + (ms % 1000) * 1000 * 1000;
134 1923698 int carry = 0;
135
2/2
✓ Branch 0 taken 64932 times.
✓ Branch 1 taken 1858766 times.
 1923698 if (nsecs >= 1000 * 1000 * 1000) {
136 64932 carry = 1;
137 64932 nsecs -= 1000 * 1000 * 1000;
138 }
139 1923698 ts->tv_sec = now.tv_sec + ms / 1000 + carry;
140 1923698 ts->tv_nsec = nsecs;
141 1923698 }
142
143
144 196 void *Tracer::MainFlush(void *data) {
145 196 Tracer *tracer = reinterpret_cast<Tracer *>(data);
146 int retval;
147 196 const MutexLockGuard m(&tracer->sig_flush_mutex_);
148
1/2
✓ Branch 2 taken 196 times.
✗ Branch 3 not taken.
 196 FILE *f = fopen(tracer->trace_file_.c_str(), "a");
149
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(f != NULL && "Could not open trace file");
150 struct timespec timeout;
151
152 do {
153 1300740 while (
154 1779862 (atomic_read32(&tracer->terminate_flush_thread_) == 0)
155
2/2
✓ Branch 1 taken 1773030 times.
✓ Branch 2 taken 6636 times.
 1779666 && (atomic_read32(&tracer->flush_immediately_) == 0)
156
4/4
✓ Branch 0 taken 1779666 times.
✓ Branch 1 taken 196 times.
✓ Branch 4 taken 479122 times.
✓ Branch 5 taken 1300740 times.
 5332558 && (atomic_read32(&tracer->seq_no_) - atomic_read32(&tracer->flushed_)
157
2/2
✓ Branch 0 taken 479122 times.
✓ Branch 1 taken 1293908 times.
 1773030 <= tracer->flush_threshold_)) {
158 479122 tracer->GetTimespecRel(2000, &timeout);
159
1/2
✓ Branch 1 taken 479122 times.
✗ Branch 2 not taken.
 479122 retval = pthread_cond_timedwait(
160 &tracer->sig_flush_, &tracer->sig_flush_mutex_, &timeout);
161
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 479122 times.
 479122 assert(retval != EINVAL);
162 }
163
164 1300740 const int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_;
165 1300740 int pos, i = 0;
166 1300740 while ((i <= tracer->flush_threshold_)
167
6/6
✓ Branch 0 taken 5748232 times.
✓ Branch 1 taken 769314 times.
✓ Branch 2 taken 5216806 times.
✓ Branch 3 taken 531426 times.
✓ Branch 4 taken 5216806 times.
✓ Branch 5 taken 1300740 times.
 12265778 && (atomic_read32(
168 5748232 &tracer->commit_buffer_[pos = ((base + i)
169 5748232 % tracer->buffer_size_)])
170 == 1)) {
171 5216806 string tmp;
172
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 tmp = StringifyTimeval(tracer->ring_buffer_[pos].time_stamp);
173
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval = tracer->WriteCsvFile(f, tmp);
174
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval |= fputc(',', f) - ',';
175
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 tmp = StringifyInt(tracer->ring_buffer_[pos].code);
176
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval = tracer->WriteCsvFile(f, tmp);
177
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval |= fputc(',', f) - ',';
178
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval |= tracer->WriteCsvFile(f,
179
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 10433612 tracer->ring_buffer_[pos].path.ToString());
180
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval |= fputc(',', f) - ',';
181
1/2
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
 5216806 retval |= tracer->WriteCsvFile(f, tracer->ring_buffer_[pos].msg);
182
2/4
✓ Branch 1 taken 5216806 times.
✗ Branch 2 not taken.
✓ Branch 4 taken 5216806 times.
✗ Branch 5 not taken.
 5216806 retval |= (fputc(13, f) - 13) | (fputc(10, f) - 10);
183
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 5216806 times.
 5216806 assert(retval == 0);
184
185 5216806 atomic_dec32(&tracer->commit_buffer_[pos]);
186 5216806 ++i;
187 5216806 }
188
1/2
✓ Branch 1 taken 1300740 times.
✗ Branch 2 not taken.
 1300740 retval = fflush(f);
189
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1300740 times.
 1300740 assert(retval == 0);
190 1300740 atomic_xadd32(&tracer->flushed_, i);
191 1300740 atomic_cas32(&tracer->flush_immediately_, 1, 0);
192
193 {
194 1300740 const MutexLockGuard l(&tracer->sig_continue_trace_mutex_);
195 1300740 retval = pthread_cond_broadcast(&tracer->sig_continue_trace_);
196
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1300740 times.
 1300740 assert(retval == 0);
197 1300740 }
198 } while (
199 1300740 (atomic_read32(&tracer->terminate_flush_thread_) == 0)
200
6/6
✓ Branch 0 taken 224 times.
✓ Branch 1 taken 1300516 times.
✓ Branch 4 taken 28 times.
✓ Branch 5 taken 196 times.
✓ Branch 6 taken 1300544 times.
✓ Branch 7 taken 196 times.
 1300740 || (atomic_read32(&tracer->flushed_) < atomic_read32(&tracer->seq_no_)));
201
202
1/2
✓ Branch 1 taken 196 times.
✗ Branch 2 not taken.
 196 retval = fclose(f);
203
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
204 196 return NULL;
205 196 }
206
207
208 210 void Tracer::Spawn() {
209
2/2
✓ Branch 0 taken 196 times.
✓ Branch 1 taken 14 times.
 210 if (active_) {
210 196 const int retval = pthread_create(&thread_flush_, NULL, MainFlush, this);
211
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
212
213 196 spawned_ = true;
214
3/6
✓ Branch 2 taken 196 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 196 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 196 times.
✗ Branch 9 not taken.
 196 DoTrace(kEventStart, PathString("Tracer", 6), "Trace buffer created");
215 }
216 210 }
217
218
219 1281 Tracer::Tracer()
220 1281 : active_(false)
221 1281 , spawned_(false)
222 1281 , buffer_size_(0)
223 1281 , flush_threshold_(0)
224 1281 , ring_buffer_(NULL)
225 1281 , commit_buffer_(NULL) {
226 1281 memset(&thread_flush_, 0, sizeof(thread_flush_));
227 1281 atomic_init32(&seq_no_);
228 1281 atomic_init32(&flushed_);
229 1281 atomic_init32(&terminate_flush_thread_);
230 1281 atomic_init32(&flush_immediately_);
231 1281 }
232
233
234 1477 Tracer::~Tracer() {
235
2/2
✓ Branch 0 taken 1085 times.
✓ Branch 1 taken 196 times.
 1281 if (!active_)
236 1085 return;
237 int retval;
238
239
1/2
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
 196 if (spawned_) {
240 196 DoTrace(kEventStop, PathString("Tracer", 6), "Destroying trace buffer...");
241
242 // Trigger flushing and wait for it
243 196 atomic_inc32(&terminate_flush_thread_);
244 {
245 196 const MutexLockGuard m(&sig_flush_mutex_);
246 196 retval = pthread_cond_signal(&sig_flush_);
247
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
248 196 }
249 196 retval = pthread_join(thread_flush_, NULL);
250
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
251 }
252
253 196 retval = pthread_cond_destroy(&sig_continue_trace_);
254 196 retval |= pthread_mutex_destroy(&sig_continue_trace_mutex_);
255 196 retval |= pthread_cond_destroy(&sig_flush_);
256 196 retval |= pthread_mutex_destroy(&sig_flush_mutex_);
257
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 196 times.
 196 assert(retval == 0);
258
259
3/4
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 58716 times.
✓ Branch 3 taken 196 times.
 58912 delete[] ring_buffer_;
260
1/2
✓ Branch 0 taken 196 times.
✗ Branch 1 not taken.
 196 delete[] commit_buffer_;
261
2/2
✓ Branch 1 taken 196 times.
✓ Branch 2 taken 1085 times.
 1281 }
262
263
264 20867224 int Tracer::WriteCsvFile(FILE *fp, const string &field) {
265
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 20867224 times.
 20867224 if (fp == NULL)
266 ✗ return 0;
267
268 int retval;
269
270
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 20867224 times.
 20867224 if ((retval = fputc('"', fp)) != '"')
271 ✗ return retval;
272
273
2/2
✓ Branch 1 taken 300852832 times.
✓ Branch 2 taken 20867224 times.
 321720056 for (unsigned i = 0, l = field.length(); i < l; ++i) {
274
2/2
✓ Branch 1 taken 3654000 times.
✓ Branch 2 taken 297198832 times.
 300852832 if (field[i] == '"') {
275
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 3654000 times.
 3654000 if ((retval = fputc('"', fp)) != '"')
276 ✗ return retval;
277 }
278
1/2
✗ Branch 3 not taken.
✓ Branch 4 taken 300852832 times.
 300852832 if ((retval = fputc(field[i], fp)) != field[i])
279 ✗ return retval;
280 }
281
282
1/2
✗ Branch 1 not taken.
✓ Branch 2 taken 20867224 times.
 20867224 if ((retval = fputc('"', fp)) != '"')
283 ✗ return retval;
284
285 20867224 return 0;
286 }
287