Directory: | cvmfs/ |
---|---|
File: | cvmfs/tracer.cc |
Date: | 2025-07-13 02:35:07 |
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 | 98 | void Tracer::Activate(const int buffer_size, | |
26 | const int flush_threshold, | ||
27 | const string &trace_file) { | ||
28 | 98 | trace_file_ = trace_file; | |
29 | 98 | buffer_size_ = buffer_size; | |
30 | 98 | flush_threshold_ = flush_threshold; | |
31 |
3/6✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 98 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 98 times.
✗ Branch 5 not taken.
|
98 | assert(buffer_size_ > 1 && flush_threshold_ >= 0 |
32 | && flush_threshold_ < buffer_size_); | ||
33 | |||
34 |
4/8✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 29358 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 29358 times.
✓ Branch 7 taken 98 times.
✗ Branch 9 not taken.
✗ Branch 10 not taken.
|
29456 | ring_buffer_ = new BufferEntry[buffer_size_]; |
35 |
1/2✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
|
98 | commit_buffer_ = new atomic_int32[buffer_size_]; |
36 |
2/2✓ Branch 0 taken 29358 times.
✓ Branch 1 taken 98 times.
|
29456 | for (int i = 0; i < buffer_size_; i++) |
37 | 29358 | atomic_init32(&commit_buffer_[i]); | |
38 | |||
39 | int retval; | ||
40 | 98 | retval = pthread_cond_init(&sig_continue_trace_, NULL); | |
41 | 98 | retval |= pthread_mutex_init(&sig_continue_trace_mutex_, NULL); | |
42 | 98 | retval |= pthread_cond_init(&sig_flush_, NULL); | |
43 | 98 | retval |= pthread_mutex_init(&sig_flush_mutex_, NULL); | |
44 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
45 | |||
46 | 98 | active_ = true; | |
47 | 98 | } | |
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 | 2357796 | int32_t Tracer::DoTrace(const int event, | |
68 | const PathString &path, | ||
69 | const string &msg) { | ||
70 | 2357796 | const int32_t my_seq_no = atomic_xadd32(&seq_no_, 1); | |
71 | timeval now; | ||
72 | 2495143 | gettimeofday(&now, NULL); | |
73 | 2485329 | const int pos = my_seq_no % buffer_size_; | |
74 | |||
75 |
2/2✓ Branch 1 taken 828128 times.
✓ Branch 2 taken 2508023 times.
|
3353245 | while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) { |
76 | timespec timeout; | ||
77 | int retval; | ||
78 | 828128 | GetTimespecRel(25, &timeout); | |
79 | 809158 | retval = pthread_mutex_lock(&sig_continue_trace_mutex_); | |
80 |
1/2✓ Branch 1 taken 891730 times.
✗ Branch 2 not taken.
|
891730 | retval |= pthread_cond_timedwait(&sig_continue_trace_, |
81 | &sig_continue_trace_mutex_, &timeout); | ||
82 | 891730 | retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_); | |
83 |
2/4✓ Branch 0 taken 868504 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 868504 times.
|
867916 | assert(retval == ETIMEDOUT || retval == 0); |
84 | } | ||
85 | |||
86 | 2508023 | ring_buffer_[pos].time_stamp = now; | |
87 | 2508023 | ring_buffer_[pos].code = event; | |
88 |
1/2✓ Branch 1 taken 2387553 times.
✗ Branch 2 not taken.
|
2508023 | ring_buffer_[pos].path = path; |
89 |
1/2✓ Branch 1 taken 2442580 times.
✗ Branch 2 not taken.
|
2387553 | ring_buffer_[pos].msg = msg; |
90 | 2442580 | atomic_inc32(&commit_buffer_[pos]); | |
91 | |||
92 |
2/2✓ Branch 1 taken 256158 times.
✓ Branch 2 taken 2204377 times.
|
2500568 | if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) { |
93 | 256158 | const MutexLockGuard m(&sig_flush_mutex_); | |
94 | const int err_code | ||
95 | 256158 | __attribute__((unused)) = pthread_cond_signal(&sig_flush_); | |
96 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 256158 times.
|
256158 | assert(err_code == 0 && "Could not signal flush thread"); |
97 | 256158 | } | |
98 | |||
99 | 2459688 | return my_seq_no; | |
100 | } | ||
101 | |||
102 | |||
103 | 10192 | void Tracer::Flush() { | |
104 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 10192 times.
|
10192 | if (!active_) |
105 | ✗ | return; | |
106 | |||
107 |
3/6✓ Branch 2 taken 10248 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 10283 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 10353 times.
✗ Branch 9 not taken.
|
10192 | const int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6), |
108 | "flushed ring buffer"); | ||
109 |
2/2✓ Branch 1 taken 9093 times.
✓ Branch 2 taken 10353 times.
|
19544 | while (atomic_read32(&flushed_) <= save_seq_no) { |
110 | timespec timeout; | ||
111 | int retval; | ||
112 | |||
113 | 9093 | atomic_cas32(&flush_immediately_, 0, 1); | |
114 | { | ||
115 | 9058 | const MutexLockGuard m(&sig_flush_mutex_); | |
116 | 9261 | retval = pthread_cond_signal(&sig_flush_); | |
117 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 9261 times.
|
9261 | assert(retval == 0); |
118 | 9261 | } | |
119 | |||
120 | 9254 | GetTimespecRel(250, &timeout); | |
121 | 9219 | retval = pthread_mutex_lock(&sig_continue_trace_mutex_); | |
122 |
1/2✓ Branch 1 taken 9261 times.
✗ Branch 2 not taken.
|
9261 | retval |= pthread_cond_timedwait(&sig_continue_trace_, |
123 | &sig_continue_trace_mutex_, &timeout); | ||
124 | 9261 | retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_); | |
125 |
3/4✓ Branch 0 taken 8484 times.
✓ Branch 1 taken 714 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 8484 times.
|
9198 | assert(retval == ETIMEDOUT || retval == 0); |
126 | } | ||
127 | } | ||
128 | |||
129 | |||
130 | 1036203 | void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) { | |
131 | timeval now; | ||
132 | 1036203 | gettimeofday(&now, NULL); | |
133 | 1032850 | int64_t nsecs = now.tv_usec * 1000 + (ms % 1000) * 1000 * 1000; | |
134 | 1032850 | int carry = 0; | |
135 |
2/2✓ Branch 0 taken 14392 times.
✓ Branch 1 taken 1018458 times.
|
1032850 | if (nsecs >= 1000 * 1000 * 1000) { |
136 | 14392 | carry = 1; | |
137 | 14392 | nsecs -= 1000 * 1000 * 1000; | |
138 | } | ||
139 | 1032850 | ts->tv_sec = now.tv_sec + ms / 1000 + carry; | |
140 | 1032850 | ts->tv_nsec = nsecs; | |
141 | 1032850 | } | |
142 | |||
143 | |||
144 | 98 | void *Tracer::MainFlush(void *data) { | |
145 | 98 | Tracer *tracer = reinterpret_cast<Tracer *>(data); | |
146 | int retval; | ||
147 | 98 | const MutexLockGuard m(&tracer->sig_flush_mutex_); | |
148 |
1/2✓ Branch 2 taken 98 times.
✗ Branch 3 not taken.
|
98 | FILE *f = fopen(tracer->trace_file_.c_str(), "a"); |
149 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(f != NULL && "Could not open trace file"); |
150 | struct timespec timeout; | ||
151 | |||
152 | do { | ||
153 | 731514 | while ( | |
154 | 947338 | (atomic_read32(&tracer->terminate_flush_thread_) == 0) | |
155 |
2/2✓ Branch 1 taken 943621 times.
✓ Branch 2 taken 3619 times.
|
947240 | && (atomic_read32(&tracer->flush_immediately_) == 0) |
156 |
4/4✓ Branch 0 taken 947240 times.
✓ Branch 1 taken 98 times.
✓ Branch 4 taken 215824 times.
✓ Branch 5 taken 731514 times.
|
2838199 | && (atomic_read32(&tracer->seq_no_) - atomic_read32(&tracer->flushed_) |
157 |
2/2✓ Branch 0 taken 215824 times.
✓ Branch 1 taken 727797 times.
|
943621 | <= tracer->flush_threshold_)) { |
158 | 215824 | tracer->GetTimespecRel(2000, &timeout); | |
159 |
1/2✓ Branch 1 taken 215824 times.
✗ Branch 2 not taken.
|
215824 | retval = pthread_cond_timedwait(&tracer->sig_flush_, |
160 | &tracer->sig_flush_mutex_, &timeout); | ||
161 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 215824 times.
|
215824 | assert(retval != EINVAL); |
162 | } | ||
163 | |||
164 | 731514 | const int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_; | |
165 | 731514 | int pos, i = 0; | |
166 | 731514 | while ((i <= tracer->flush_threshold_) | |
167 |
6/6✓ Branch 0 taken 2954728 times.
✓ Branch 1 taken 385189 times.
✓ Branch 2 taken 2608403 times.
✓ Branch 3 taken 346325 times.
✓ Branch 4 taken 2608403 times.
✓ Branch 5 taken 731514 times.
|
6294645 | && (atomic_read32( |
168 | 2954728 | &tracer->commit_buffer_[pos = ((base + i) | |
169 | 2954728 | % tracer->buffer_size_)]) | |
170 | == 1)) { | ||
171 | 2608403 | string tmp; | |
172 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | tmp = StringifyTimeval(tracer->ring_buffer_[pos].time_stamp); |
173 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval = tracer->WriteCsvFile(f, tmp); |
174 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval |= fputc(',', f) - ','; |
175 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | tmp = StringifyInt(tracer->ring_buffer_[pos].code); |
176 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval = tracer->WriteCsvFile(f, tmp); |
177 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval |= fputc(',', f) - ','; |
178 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval |= tracer->WriteCsvFile(f, |
179 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
5216806 | tracer->ring_buffer_[pos].path.ToString()); |
180 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval |= fputc(',', f) - ','; |
181 |
1/2✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
|
2608403 | retval |= tracer->WriteCsvFile(f, tracer->ring_buffer_[pos].msg); |
182 |
2/4✓ Branch 1 taken 2608403 times.
✗ Branch 2 not taken.
✓ Branch 4 taken 2608403 times.
✗ Branch 5 not taken.
|
2608403 | retval |= (fputc(13, f) - 13) | (fputc(10, f) - 10); |
183 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 2608403 times.
|
2608403 | assert(retval == 0); |
184 | |||
185 | 2608403 | atomic_dec32(&tracer->commit_buffer_[pos]); | |
186 | 2608403 | ++i; | |
187 | 2608403 | } | |
188 |
1/2✓ Branch 1 taken 731514 times.
✗ Branch 2 not taken.
|
731514 | retval = fflush(f); |
189 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 731514 times.
|
731514 | assert(retval == 0); |
190 | 731514 | atomic_xadd32(&tracer->flushed_, i); | |
191 | 731514 | atomic_cas32(&tracer->flush_immediately_, 1, 0); | |
192 | |||
193 | { | ||
194 | 731514 | const MutexLockGuard l(&tracer->sig_continue_trace_mutex_); | |
195 | 731514 | retval = pthread_cond_broadcast(&tracer->sig_continue_trace_); | |
196 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 731514 times.
|
731514 | assert(retval == 0); |
197 | 731514 | } | |
198 | } while ( | ||
199 | 731514 | (atomic_read32(&tracer->terminate_flush_thread_) == 0) | |
200 |
6/6✓ Branch 0 taken 119 times.
✓ Branch 1 taken 731395 times.
✓ Branch 4 taken 21 times.
✓ Branch 5 taken 98 times.
✓ Branch 6 taken 731416 times.
✓ Branch 7 taken 98 times.
|
731514 | || (atomic_read32(&tracer->flushed_) < atomic_read32(&tracer->seq_no_))); |
201 | |||
202 |
1/2✓ Branch 1 taken 98 times.
✗ Branch 2 not taken.
|
98 | retval = fclose(f); |
203 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
204 | 98 | return NULL; | |
205 | 98 | } | |
206 | |||
207 | |||
208 | 105 | void Tracer::Spawn() { | |
209 |
2/2✓ Branch 0 taken 98 times.
✓ Branch 1 taken 7 times.
|
105 | if (active_) { |
210 | 98 | const int retval = pthread_create(&thread_flush_, NULL, MainFlush, this); | |
211 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
212 | |||
213 | 98 | spawned_ = true; | |
214 |
3/6✓ Branch 2 taken 98 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 98 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 98 times.
✗ Branch 9 not taken.
|
98 | DoTrace(kEventStart, PathString("Tracer", 6), "Trace buffer created"); |
215 | } | ||
216 | 105 | } | |
217 | |||
218 | |||
219 | 397 | Tracer::Tracer() | |
220 | 397 | : active_(false) | |
221 | 397 | , spawned_(false) | |
222 | 397 | , buffer_size_(0) | |
223 | 397 | , flush_threshold_(0) | |
224 | 397 | , ring_buffer_(NULL) | |
225 | 397 | , commit_buffer_(NULL) { | |
226 | 397 | memset(&thread_flush_, 0, sizeof(thread_flush_)); | |
227 | 397 | atomic_init32(&seq_no_); | |
228 | 397 | atomic_init32(&flushed_); | |
229 | 397 | atomic_init32(&terminate_flush_thread_); | |
230 | 397 | atomic_init32(&flush_immediately_); | |
231 | 397 | } | |
232 | |||
233 | |||
234 | 495 | Tracer::~Tracer() { | |
235 |
2/2✓ Branch 0 taken 299 times.
✓ Branch 1 taken 98 times.
|
397 | if (!active_) |
236 | 299 | return; | |
237 | int retval; | ||
238 | |||
239 |
1/2✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
|
98 | if (spawned_) { |
240 | 98 | DoTrace(kEventStop, PathString("Tracer", 6), "Destroying trace buffer..."); | |
241 | |||
242 | // Trigger flushing and wait for it | ||
243 | 98 | atomic_inc32(&terminate_flush_thread_); | |
244 | { | ||
245 | 98 | const MutexLockGuard m(&sig_flush_mutex_); | |
246 | 98 | retval = pthread_cond_signal(&sig_flush_); | |
247 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
248 | 98 | } | |
249 | 98 | retval = pthread_join(thread_flush_, NULL); | |
250 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
251 | } | ||
252 | |||
253 | 98 | retval = pthread_cond_destroy(&sig_continue_trace_); | |
254 | 98 | retval |= pthread_mutex_destroy(&sig_continue_trace_mutex_); | |
255 | 98 | retval |= pthread_cond_destroy(&sig_flush_); | |
256 | 98 | retval |= pthread_mutex_destroy(&sig_flush_mutex_); | |
257 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 98 times.
|
98 | assert(retval == 0); |
258 | |||
259 |
3/4✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 29358 times.
✓ Branch 3 taken 98 times.
|
29456 | delete[] ring_buffer_; |
260 |
1/2✓ Branch 0 taken 98 times.
✗ Branch 1 not taken.
|
98 | delete[] commit_buffer_; |
261 |
2/2✓ Branch 1 taken 98 times.
✓ Branch 2 taken 299 times.
|
397 | } |
262 | |||
263 | |||
264 | 10433612 | int Tracer::WriteCsvFile(FILE *fp, const string &field) { | |
265 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 10433612 times.
|
10433612 | if (fp == NULL) |
266 | ✗ | return 0; | |
267 | |||
268 | int retval; | ||
269 | |||
270 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 10433612 times.
|
10433612 | if ((retval = fputc('"', fp)) != '"') |
271 | ✗ | return retval; | |
272 | |||
273 |
2/2✓ Branch 1 taken 150426416 times.
✓ Branch 2 taken 10433612 times.
|
160860028 | for (unsigned i = 0, l = field.length(); i < l; ++i) { |
274 |
2/2✓ Branch 1 taken 1827000 times.
✓ Branch 2 taken 148599416 times.
|
150426416 | if (field[i] == '"') { |
275 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 1827000 times.
|
1827000 | if ((retval = fputc('"', fp)) != '"') |
276 | ✗ | return retval; | |
277 | } | ||
278 |
1/2✗ Branch 3 not taken.
✓ Branch 4 taken 150426416 times.
|
150426416 | if ((retval = fputc(field[i], fp)) != field[i]) |
279 | ✗ | return retval; | |
280 | } | ||
281 | |||
282 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 10433612 times.
|
10433612 | if ((retval = fputc('"', fp)) != '"') |
283 | ✗ | return retval; | |
284 | |||
285 | 10433612 | return 0; | |
286 | } | ||
287 |