GCC Code Coverage Report

Directory: cvmfs/
File: cvmfs/tracer.cc
Date: 2024-04-28 02:33:07
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 #include "cvmfs_config.h"
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 339626 int32_t Tracer::DoTrace(
70 const int event,
71 const PathString &path,
72 const string &msg)
73 {
74 339626 int32_t my_seq_no = atomic_xadd32(&seq_no_, 1);
75 timeval now;
76 364502 gettimeofday(&now, NULL);
77 360557 int pos = my_seq_no % buffer_size_;
78
79
2/2
✓ Branch 1 taken 112978 times.
✓ Branch 2 taken 357353 times.
 479416 while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) {
80 timespec timeout;
81 int retval;
82 112978 GetTimespecRel(25, &timeout);
83 113376 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
84
1/2
✓ Branch 1 taken 120705 times.
✗ Branch 2 not taken.
 120705 retval |= pthread_cond_timedwait(&sig_continue_trace_,
85 &sig_continue_trace_mutex_, &timeout);
86 120705 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
87
2/4
✓ Branch 0 taken 118921 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 118921 times.
 118859 assert(retval == ETIMEDOUT || retval == 0);
88 }
89
90 357353 ring_buffer_[pos].time_stamp = now;
91 357353 ring_buffer_[pos].code = event;
92
1/2
✓ Branch 1 taken 343779 times.
✗ Branch 2 not taken.
 357353 ring_buffer_[pos].path = path;
93
1/2
✓ Branch 1 taken 347274 times.
✗ Branch 2 not taken.
 343779 ring_buffer_[pos].msg = msg;
94 347274 atomic_inc32(&commit_buffer_[pos]);
95
96
2/2
✓ Branch 1 taken 36283 times.
✓ Branch 2 taken 322432 times.
 359035 if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) {
97 36283 MutexLockGuard m(&sig_flush_mutex_);
98 36283 int err_code __attribute__((unused)) = pthread_cond_signal(&sig_flush_);
99
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 36283 times.
 36283 assert(err_code == 0 && "Could not signal flush thread");
100 36283 }
101
102 358624 return my_seq_no;
103 }
104
105
106 1451 void Tracer::Flush() {
107
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1451 times.
 1451 if (!active_) return;
108
109
3/6
✓ Branch 2 taken 1465 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 1476 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 1486 times.
✗ Branch 9 not taken.
 1451 int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6),
110 "flushed ring buffer");
111
2/2
✓ Branch 1 taken 1324 times.
✓ Branch 2 taken 1475 times.
 2814 while (atomic_read32(&flushed_) <= save_seq_no) {
112 timespec timeout;
113 int retval;
114
115 1324 atomic_cas32(&flush_immediately_, 0, 1);
116 {
117 1323 MutexLockGuard m(&sig_flush_mutex_);
118 1336 retval = pthread_cond_signal(&sig_flush_);
119
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 1336 times.
 1336 assert(retval == 0);
120 1336 }
121
122 1334 GetTimespecRel(250, &timeout);
123 1335 retval = pthread_mutex_lock(&sig_continue_trace_mutex_);
124
1/2
✓ Branch 1 taken 1336 times.
✗ Branch 2 not taken.
 1336 retval |= pthread_cond_timedwait(&sig_continue_trace_,
125 &sig_continue_trace_mutex_,
126 &timeout);
127 1336 retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_);
128
3/4
✓ Branch 0 taken 1234 times.
✓ Branch 1 taken 93 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 1234 times.
 1327 assert(retval == ETIMEDOUT || retval == 0);
129 }
130 }
131
132
133 144239 void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) {
134 timeval now;
135 144239 gettimeofday(&now, NULL);
136 144004 int64_t nsecs = now.tv_usec * 1000 + (ms % 1000)*1000*1000;
137 144004 int carry = 0;
138
2/2
✓ Branch 0 taken 380 times.
✓ Branch 1 taken 143624 times.
 144004 if (nsecs >= 1000*1000*1000) {
139 380 carry = 1;
140 380 nsecs -= 1000*1000*1000;
141 }
142 144004 ts->tv_sec = now.tv_sec + ms/1000 + carry;
143 144004 ts->tv_nsec = nsecs;
144 144004 }
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 116655 times.
✓ Branch 2 taken 382 times.
 234088 while ((atomic_read32(&tracer->terminate_flush_thread_) == 0) &&
157
4/4
✓ Branch 0 taken 117037 times.
✓ Branch 1 taken 14 times.
✓ Branch 3 taken 31535 times.
✓ Branch 4 taken 85516 times.
 234088 (atomic_read32(&tracer->flush_immediately_) == 0) &&
158 116655 (atomic_read32(&tracer->seq_no_) -
159 116655 atomic_read32(&tracer->flushed_)
160
2/2
✓ Branch 0 taken 31535 times.
✓ Branch 1 taken 85120 times.
 116655 <= tracer->flush_threshold_))
161 {
162 31535 tracer->GetTimespecRel(2000, &timeout);
163
1/2
✓ Branch 1 taken 31535 times.
✗ Branch 2 not taken.
 31535 retval = pthread_cond_timedwait(&tracer->sig_flush_,
164 &tracer->sig_flush_mutex_,
165 &timeout);
166
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 31535 times.
 31535 assert(retval != EINVAL);
167 }
168
169 85516 int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_;
170 85516 int pos, i = 0;
171
6/6
✓ Branch 0 taken 403269 times.
✓ Branch 1 taken 54876 times.
✓ Branch 2 taken 372629 times.
✓ Branch 3 taken 30640 times.
✓ Branch 4 taken 372629 times.
✓ Branch 5 taken 85516 times.
 861414 while ((i <= tracer->flush_threshold_) &&
172 403269 (atomic_read32(&tracer->commit_buffer_[
173 403269 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 85516 times.
✗ Branch 2 not taken.
 85516 retval = fflush(f);
193
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 85516 times.
 85516 assert(retval == 0);
194 85516 atomic_xadd32(&tracer->flushed_, i);
195 85516 atomic_cas32(&tracer->flush_immediately_, 1, 0);
196
197 {
198 85516 MutexLockGuard l(&tracer->sig_continue_trace_mutex_);
199 85516 retval = pthread_cond_broadcast(&tracer->sig_continue_trace_);
200
1/2
✗ Branch 0 not taken.
✓ Branch 1 taken 85516 times.
 85516 assert(retval == 0);
201 85516 }
202
6/6
✓ Branch 1 taken 16 times.
✓ Branch 2 taken 85500 times.
✓ Branch 3 taken 2 times.
✓ Branch 4 taken 14 times.
✓ Branch 5 taken 85502 times.
✓ Branch 6 taken 14 times.
 85532 } while ((atomic_read32(&tracer->terminate_flush_thread_) == 0) ||
203 16 (atomic_read32(&tracer->flushed_) <
204 16 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