GCC Code Coverage Report

Directory: cvmfs/
File: cvmfs/tracer.cc
Date: 2025-02-09 02:34:19
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 345535 int32_t Tracer::DoTrace(
70 const int event,
71 const PathString &path,
72 const string &msg)
73 {
74 345535 int32_t my_seq_no = atomic_xadd32(&seq_no_, 1);
75 timeval now;
76 360571 gettimeofday(&now, NULL);
77 360383 int pos = my_seq_no % buffer_size_;
78
79
2/2
✓ Branch 1 taken 119351 times.
✓ Branch 2 taken 357143 times.
 482477 while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) {
80 timespec timeout;
81 int retval;
82 119351 GetTimespecRel(25, &timeout);
83 117370 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
84
1/2
✓ Branch 1 taken 124589 times.
✗ Branch 2 not taken.
 124589 retval |= pthread_cond_timedwait(&sig_continue_trace_,
85 &sig_continue_trace_mutex_, &timeout);
86 124589 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
87
2/4
✓ Branch 0 taken 122288 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 122288 times.
 122094 assert(retval == ETIMEDOUT || retval == 0);
88 }
89
90 357143 ring_buffer_[pos].time_stamp = now;
91 357143 ring_buffer_[pos].code = event;
92
1/2
✓ Branch 1 taken 344774 times.
✗ Branch 2 not taken.
 357143 ring_buffer_[pos].path = path;
93
1/2
✓ Branch 1 taken 356486 times.
✗ Branch 2 not taken.
 344774 ring_buffer_[pos].msg = msg;
94 356486 atomic_inc32(&commit_buffer_[pos]);
95
96
2/2
✓ Branch 1 taken 36539 times.
✓ Branch 2 taken 319492 times.
 358388 if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) {
97 36539 MutexLockGuard m(&sig_flush_mutex_);
98 36541 int err_code __attribute__((unused)) = pthread_cond_signal(&sig_flush_);
99
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 36541 times.
 36541 assert(err_code == 0 && "Could not signal flush thread");
100 36541 }
101
102 355926 return my_seq_no;
103 }
104
105
106 1453 void Tracer::Flush() {
107
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1453 times.
 1453 if (!active_) return;
108
109
3/6
✓ Branch 2 taken 1442 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 1468 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 1468 times.
✗ Branch 9 not taken.
 1453 int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6),
110 "flushed ring buffer");
111
2/2
✓ Branch 1 taken 1265 times.
✓ Branch 2 taken 1450 times.
 2744 while (atomic_read32(&flushed_) <= save_seq_no) {
112 timespec timeout;
113 int retval;
114
115 1265 atomic_cas32(&flush_immediately_, 0, 1);
116 {
117 1267 MutexLockGuard m(&sig_flush_mutex_);
118 1296 retval = pthread_cond_signal(&sig_flush_);
119
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1296 times.
 1296 assert(retval == 0);
120 1296 }
121
122 1293 GetTimespecRel(250, &timeout);
123 1293 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
124
1/2
✓ Branch 1 taken 1296 times.
✗ Branch 2 not taken.
 1296 retval |= pthread_cond_timedwait(&sig_continue_trace_,
125 &sig_continue_trace_mutex_,
126 &timeout);
127 1296 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
128
3/4
✓ Branch 0 taken 1236 times.
✓ Branch 1 taken 44 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 1236 times.
 1280 assert(retval == ETIMEDOUT || retval == 0);
129 }
130 }
131
132
133 149813 void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) {
134 timeval now;
135 149813 gettimeofday(&now, NULL);
136 149600 int64_t nsecs = now.tv_usec * 1000 + (ms % 1000)*1000*1000;
137 149600 int carry = 0;
138
2/2
✓ Branch 0 taken 4168 times.
✓ Branch 1 taken 145432 times.
 149600 if (nsecs >= 1000*1000*1000) {
139 4168 carry = 1;
140 4168 nsecs -= 1000*1000*1000;
141 }
142 149600 ts->tv_sec = now.tv_sec + ms/1000 + carry;
143 149600 ts->tv_nsec = nsecs;
144 149600 }
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 124535 times.
✓ Branch 2 taken 394 times.
 249872 while ((atomic_read32(&tracer->terminate_flush_thread_) == 0) &&
157
4/4
✓ Branch 0 taken 124929 times.
✓ Branch 1 taken 14 times.
✓ Branch 3 taken 30598 times.
✓ Branch 4 taken 94345 times.
 249872 (atomic_read32(&tracer->flush_immediately_) == 0) &&
158 124535 (atomic_read32(&tracer->seq_no_) -
159 124535 atomic_read32(&tracer->flushed_)
160
2/2
✓ Branch 0 taken 30598 times.
✓ Branch 1 taken 93937 times.
 124535 <= tracer->flush_threshold_))
161 {
162 30598 tracer->GetTimespecRel(2000, &timeout);
163
1/2
✓ Branch 1 taken 30598 times.
✗ Branch 2 not taken.
 30598 retval = pthread_cond_timedwait(&tracer->sig_flush_,
164 &tracer->sig_flush_mutex_,
165 &timeout);
166
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 30598 times.
 30598 assert(retval != EINVAL);
167 }
168
169 94345 int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_;
170 94345 int pos, i = 0;
171
6/6
✓ Branch 0 taken 412083 times.
✓ Branch 1 taken 54891 times.
✓ Branch 2 taken 372629 times.
✓ Branch 3 taken 39454 times.
✓ Branch 4 taken 372629 times.
✓ Branch 5 taken 94345 times.
 879057 while ((i <= tracer->flush_threshold_) &&
172 412083 (atomic_read32(&tracer->commit_buffer_[
173 412083 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 94345 times.
✗ Branch 2 not taken.
 94345 retval = fflush(f);
193
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 94345 times.
 94345 assert(retval == 0);
194 94345 atomic_xadd32(&tracer->flushed_, i);
195 94345 atomic_cas32(&tracer->flush_immediately_, 1, 0);
196
197 {
198 94345 MutexLockGuard l(&tracer->sig_continue_trace_mutex_);
199 94345 retval = pthread_cond_broadcast(&tracer->sig_continue_trace_);
200
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 94345 times.
 94345 assert(retval == 0);
201 94345 }
202
6/6
✓ Branch 1 taken 17 times.
✓ Branch 2 taken 94328 times.
✓ Branch 3 taken 3 times.
✓ Branch 4 taken 14 times.
✓ Branch 5 taken 94331 times.
✓ Branch 6 taken 14 times.
 94362 } 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