Directory: | cvmfs/ |
---|---|
File: | cvmfs/tracer.cc |
Date: | 2025-09-28 02:35:26 |
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 | 42 | void Tracer::Activate(const int buffer_size, | |
26 | const int flush_threshold, | ||
27 | const string &trace_file) { | ||
28 | 42 | trace_file_ = trace_file; | |
29 | 42 | buffer_size_ = buffer_size; | |
30 | 42 | flush_threshold_ = flush_threshold; | |
31 |
3/6✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 42 times.
✗ Branch 3 not taken.
✓ Branch 4 taken 42 times.
✗ Branch 5 not taken.
|
42 | assert(buffer_size_ > 1 && flush_threshold_ >= 0 |
32 | && flush_threshold_ < buffer_size_); | ||
33 | |||
34 |
4/8✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
✓ Branch 4 taken 12582 times.
✗ Branch 5 not taken.
✓ Branch 6 taken 12582 times.
✓ Branch 7 taken 42 times.
✗ Branch 9 not taken.
✗ Branch 10 not taken.
|
12624 | ring_buffer_ = new BufferEntry[buffer_size_]; |
35 |
1/2✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
|
42 | commit_buffer_ = new atomic_int32[buffer_size_]; |
36 |
2/2✓ Branch 0 taken 12582 times.
✓ Branch 1 taken 42 times.
|
12624 | for (int i = 0; i < buffer_size_; i++) |
37 | 12582 | atomic_init32(&commit_buffer_[i]); | |
38 | |||
39 | int retval; | ||
40 | 42 | retval = pthread_cond_init(&sig_continue_trace_, NULL); | |
41 | 42 | retval |= pthread_mutex_init(&sig_continue_trace_mutex_, NULL); | |
42 | 42 | retval |= pthread_cond_init(&sig_flush_, NULL); | |
43 | 42 | retval |= pthread_mutex_init(&sig_flush_mutex_, NULL); | |
44 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
45 | |||
46 | 42 | active_ = true; | |
47 | 42 | } | |
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 | 1002639 | int32_t Tracer::DoTrace(const int event, | |
68 | const PathString &path, | ||
69 | const string &msg) { | ||
70 | 1002639 | const int32_t my_seq_no = atomic_xadd32(&seq_no_, 1); | |
71 | timeval now; | ||
72 | 1065639 | gettimeofday(&now, NULL); | |
73 | 1065276 | const int pos = my_seq_no % buffer_size_; | |
74 | |||
75 |
2/2✓ Branch 1 taken 377127 times.
✓ Branch 2 taken 1065234 times.
|
1457100 | while (my_seq_no - atomic_read32(&flushed_) >= buffer_size_) { |
76 | timespec timeout; | ||
77 | int retval; | ||
78 | 377127 | GetTimespecRel(25, &timeout); | |
79 | 370029 | retval = pthread_mutex_lock(&sig_continue_trace_mutex_); | |
80 |
1/2✓ Branch 1 taken 401313 times.
✗ Branch 2 not taken.
|
401313 | retval |= pthread_cond_timedwait(&sig_continue_trace_, |
81 | &sig_continue_trace_mutex_, &timeout); | ||
82 | 401313 | retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_); | |
83 |
2/4✓ Branch 0 taken 392802 times.
✗ Branch 1 not taken.
✗ Branch 2 not taken.
✓ Branch 3 taken 392802 times.
|
391824 | assert(retval == ETIMEDOUT || retval == 0); |
84 | } | ||
85 | |||
86 | 1065234 | ring_buffer_[pos].time_stamp = now; | |
87 | 1065234 | ring_buffer_[pos].code = event; | |
88 |
1/2✓ Branch 1 taken 1024140 times.
✗ Branch 2 not taken.
|
1065234 | ring_buffer_[pos].path = path; |
89 |
1/2✓ Branch 1 taken 1047354 times.
✗ Branch 2 not taken.
|
1024140 | ring_buffer_[pos].msg = msg; |
90 | 1047354 | atomic_inc32(&commit_buffer_[pos]); | |
91 | |||
92 |
2/2✓ Branch 1 taken 109575 times.
✓ Branch 2 taken 942168 times.
|
1068411 | if (my_seq_no - atomic_read32(&flushed_) == flush_threshold_) { |
93 | 109575 | const MutexLockGuard m(&sig_flush_mutex_); | |
94 | const int err_code | ||
95 | 109578 | __attribute__((unused)) = pthread_cond_signal(&sig_flush_); | |
96 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 109578 times.
|
109578 | assert(err_code == 0 && "Could not signal flush thread"); |
97 | 109578 | } | |
98 | |||
99 | 1051461 | return my_seq_no; | |
100 | } | ||
101 | |||
102 | |||
103 | 4251 | void Tracer::Flush() { | |
104 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 4251 times.
|
4251 | if (!active_) |
105 | ✗ | return; | |
106 | |||
107 |
3/6✓ Branch 2 taken 4287 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 4335 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 4383 times.
✗ Branch 9 not taken.
|
4251 | const int32_t save_seq_no = DoTrace(kEventFlush, PathString("Tracer", 6), |
108 | "flushed ring buffer"); | ||
109 |
2/2✓ Branch 1 taken 3882 times.
✓ Branch 2 taken 4401 times.
|
8352 | while (atomic_read32(&flushed_) <= save_seq_no) { |
110 | timespec timeout; | ||
111 | int retval; | ||
112 | |||
113 | 3882 | atomic_cas32(&flush_immediately_, 0, 1); | |
114 | { | ||
115 | 3903 | const MutexLockGuard m(&sig_flush_mutex_); | |
116 | 3975 | retval = pthread_cond_signal(&sig_flush_); | |
117 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 3975 times.
|
3975 | assert(retval == 0); |
118 | 3975 | } | |
119 | |||
120 | 3969 | GetTimespecRel(250, &timeout); | |
121 | 3960 | retval = pthread_mutex_lock(&sig_continue_trace_mutex_); | |
122 |
1/2✓ Branch 1 taken 3975 times.
✗ Branch 2 not taken.
|
3975 | retval |= pthread_cond_timedwait(&sig_continue_trace_, |
123 | &sig_continue_trace_mutex_, &timeout); | ||
124 | 3975 | retval |= pthread_mutex_unlock(&sig_continue_trace_mutex_); | |
125 |
3/4✓ Branch 0 taken 3771 times.
✓ Branch 1 taken 192 times.
✗ Branch 2 not taken.
✓ Branch 3 taken 3771 times.
|
3963 | assert(retval == ETIMEDOUT || retval == 0); |
126 | } | ||
127 | } | ||
128 | |||
129 | |||
130 | 465858 | void Tracer::GetTimespecRel(const int64_t ms, timespec *ts) { | |
131 | timeval now; | ||
132 | 465858 | gettimeofday(&now, NULL); | |
133 | 466521 | int64_t nsecs = now.tv_usec * 1000 + (ms % 1000) * 1000 * 1000; | |
134 | 466521 | int carry = 0; | |
135 |
2/2✓ Branch 0 taken 2943 times.
✓ Branch 1 taken 463578 times.
|
466521 | if (nsecs >= 1000 * 1000 * 1000) { |
136 | 2943 | carry = 1; | |
137 | 2943 | nsecs -= 1000 * 1000 * 1000; | |
138 | } | ||
139 | 466521 | ts->tv_sec = now.tv_sec + ms / 1000 + carry; | |
140 | 466521 | ts->tv_nsec = nsecs; | |
141 | 466521 | } | |
142 | |||
143 | |||
144 | 42 | void *Tracer::MainFlush(void *data) { | |
145 | 42 | Tracer *tracer = reinterpret_cast<Tracer *>(data); | |
146 | int retval; | ||
147 | 42 | const MutexLockGuard m(&tracer->sig_flush_mutex_); | |
148 |
1/2✓ Branch 2 taken 42 times.
✗ Branch 3 not taken.
|
42 | FILE *f = fopen(tracer->trace_file_.c_str(), "a"); |
149 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(f != NULL && "Could not open trace file"); |
150 | struct timespec timeout; | ||
151 | |||
152 | do { | ||
153 | 269556 | while ( | |
154 | 359499 | (atomic_read32(&tracer->terminate_flush_thread_) == 0) | |
155 |
2/2✓ Branch 1 taken 358212 times.
✓ Branch 2 taken 1245 times.
|
359457 | && (atomic_read32(&tracer->flush_immediately_) == 0) |
156 |
4/4✓ Branch 0 taken 359457 times.
✓ Branch 1 taken 42 times.
✓ Branch 4 taken 89943 times.
✓ Branch 5 taken 269556 times.
|
1077168 | && (atomic_read32(&tracer->seq_no_) - atomic_read32(&tracer->flushed_) |
157 |
2/2✓ Branch 0 taken 89943 times.
✓ Branch 1 taken 268269 times.
|
358212 | <= tracer->flush_threshold_)) { |
158 | 89943 | tracer->GetTimespecRel(2000, &timeout); | |
159 |
1/2✓ Branch 1 taken 89943 times.
✗ Branch 2 not taken.
|
89943 | retval = pthread_cond_timedwait(&tracer->sig_flush_, |
160 | &tracer->sig_flush_mutex_, &timeout); | ||
161 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 89943 times.
|
89943 | assert(retval != EINVAL); |
162 | } | ||
163 | |||
164 | 269556 | const int base = atomic_read32(&tracer->flushed_) % tracer->buffer_size_; | |
165 | 269556 | int pos, i = 0; | |
166 | 269556 | while ((i <= tracer->flush_threshold_) | |
167 |
6/6✓ Branch 0 taken 1223145 times.
✓ Branch 1 taken 164298 times.
✓ Branch 2 taken 1117887 times.
✓ Branch 3 taken 105258 times.
✓ Branch 4 taken 1117887 times.
✓ Branch 5 taken 269556 times.
|
2610588 | && (atomic_read32( |
168 | 1223145 | &tracer->commit_buffer_[pos = ((base + i) | |
169 | 1223145 | % tracer->buffer_size_)]) | |
170 | == 1)) { | ||
171 | 1117887 | string tmp; | |
172 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | tmp = StringifyTimeval(tracer->ring_buffer_[pos].time_stamp); |
173 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval = tracer->WriteCsvFile(f, tmp); |
174 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval |= fputc(',', f) - ','; |
175 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | tmp = StringifyInt(tracer->ring_buffer_[pos].code); |
176 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval = tracer->WriteCsvFile(f, tmp); |
177 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval |= fputc(',', f) - ','; |
178 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval |= tracer->WriteCsvFile(f, |
179 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
2235774 | tracer->ring_buffer_[pos].path.ToString()); |
180 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval |= fputc(',', f) - ','; |
181 |
1/2✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
|
1117887 | retval |= tracer->WriteCsvFile(f, tracer->ring_buffer_[pos].msg); |
182 |
2/4✓ Branch 1 taken 1117887 times.
✗ Branch 2 not taken.
✓ Branch 4 taken 1117887 times.
✗ Branch 5 not taken.
|
1117887 | retval |= (fputc(13, f) - 13) | (fputc(10, f) - 10); |
183 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 1117887 times.
|
1117887 | assert(retval == 0); |
184 | |||
185 | 1117887 | atomic_dec32(&tracer->commit_buffer_[pos]); | |
186 | 1117887 | ++i; | |
187 | 1117887 | } | |
188 |
1/2✓ Branch 1 taken 269556 times.
✗ Branch 2 not taken.
|
269556 | retval = fflush(f); |
189 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 269556 times.
|
269556 | assert(retval == 0); |
190 | 269556 | atomic_xadd32(&tracer->flushed_, i); | |
191 | 269556 | atomic_cas32(&tracer->flush_immediately_, 1, 0); | |
192 | |||
193 | { | ||
194 | 269556 | const MutexLockGuard l(&tracer->sig_continue_trace_mutex_); | |
195 | 269556 | retval = pthread_cond_broadcast(&tracer->sig_continue_trace_); | |
196 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 269556 times.
|
269556 | assert(retval == 0); |
197 | 269556 | } | |
198 | } while ( | ||
199 | 269556 | (atomic_read32(&tracer->terminate_flush_thread_) == 0) | |
200 |
6/6✓ Branch 0 taken 51 times.
✓ Branch 1 taken 269505 times.
✓ Branch 4 taken 9 times.
✓ Branch 5 taken 42 times.
✓ Branch 6 taken 269514 times.
✓ Branch 7 taken 42 times.
|
269556 | || (atomic_read32(&tracer->flushed_) < atomic_read32(&tracer->seq_no_))); |
201 | |||
202 |
1/2✓ Branch 1 taken 42 times.
✗ Branch 2 not taken.
|
42 | retval = fclose(f); |
203 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
204 | 42 | return NULL; | |
205 | 42 | } | |
206 | |||
207 | |||
208 | 45 | void Tracer::Spawn() { | |
209 |
2/2✓ Branch 0 taken 42 times.
✓ Branch 1 taken 3 times.
|
45 | if (active_) { |
210 | 42 | const int retval = pthread_create(&thread_flush_, NULL, MainFlush, this); | |
211 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
212 | |||
213 | 42 | spawned_ = true; | |
214 |
3/6✓ Branch 2 taken 42 times.
✗ Branch 3 not taken.
✓ Branch 5 taken 42 times.
✗ Branch 6 not taken.
✓ Branch 8 taken 42 times.
✗ Branch 9 not taken.
|
42 | DoTrace(kEventStart, PathString("Tracer", 6), "Trace buffer created"); |
215 | } | ||
216 | 45 | } | |
217 | |||
218 | |||
219 | 220 | Tracer::Tracer() | |
220 | 220 | : active_(false) | |
221 | 220 | , spawned_(false) | |
222 | 220 | , buffer_size_(0) | |
223 | 220 | , flush_threshold_(0) | |
224 | 220 | , ring_buffer_(NULL) | |
225 | 220 | , commit_buffer_(NULL) { | |
226 | 220 | memset(&thread_flush_, 0, sizeof(thread_flush_)); | |
227 | 220 | atomic_init32(&seq_no_); | |
228 | 220 | atomic_init32(&flushed_); | |
229 | 220 | atomic_init32(&terminate_flush_thread_); | |
230 | 220 | atomic_init32(&flush_immediately_); | |
231 | 220 | } | |
232 | |||
233 | |||
234 | 262 | Tracer::~Tracer() { | |
235 |
2/2✓ Branch 0 taken 178 times.
✓ Branch 1 taken 42 times.
|
220 | if (!active_) |
236 | 178 | return; | |
237 | int retval; | ||
238 | |||
239 |
1/2✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
|
42 | if (spawned_) { |
240 | 42 | DoTrace(kEventStop, PathString("Tracer", 6), "Destroying trace buffer..."); | |
241 | |||
242 | // Trigger flushing and wait for it | ||
243 | 42 | atomic_inc32(&terminate_flush_thread_); | |
244 | { | ||
245 | 42 | const MutexLockGuard m(&sig_flush_mutex_); | |
246 | 42 | retval = pthread_cond_signal(&sig_flush_); | |
247 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
248 | 42 | } | |
249 | 42 | retval = pthread_join(thread_flush_, NULL); | |
250 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
251 | } | ||
252 | |||
253 | 42 | retval = pthread_cond_destroy(&sig_continue_trace_); | |
254 | 42 | retval |= pthread_mutex_destroy(&sig_continue_trace_mutex_); | |
255 | 42 | retval |= pthread_cond_destroy(&sig_flush_); | |
256 | 42 | retval |= pthread_mutex_destroy(&sig_flush_mutex_); | |
257 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 42 times.
|
42 | assert(retval == 0); |
258 | |||
259 |
3/4✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
✓ Branch 2 taken 12582 times.
✓ Branch 3 taken 42 times.
|
12624 | delete[] ring_buffer_; |
260 |
1/2✓ Branch 0 taken 42 times.
✗ Branch 1 not taken.
|
42 | delete[] commit_buffer_; |
261 |
2/2✓ Branch 1 taken 42 times.
✓ Branch 2 taken 178 times.
|
220 | } |
262 | |||
263 | |||
264 | 4471548 | int Tracer::WriteCsvFile(FILE *fp, const string &field) { | |
265 |
1/2✗ Branch 0 not taken.
✓ Branch 1 taken 4471548 times.
|
4471548 | if (fp == NULL) |
266 | ✗ | return 0; | |
267 | |||
268 | int retval; | ||
269 | |||
270 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 4471548 times.
|
4471548 | if ((retval = fputc('"', fp)) != '"') |
271 | ✗ | return retval; | |
272 | |||
273 |
2/2✓ Branch 1 taken 64468464 times.
✓ Branch 2 taken 4471548 times.
|
68940012 | for (unsigned i = 0, l = field.length(); i < l; ++i) { |
274 |
2/2✓ Branch 1 taken 783000 times.
✓ Branch 2 taken 63685464 times.
|
64468464 | if (field[i] == '"') { |
275 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 783000 times.
|
783000 | if ((retval = fputc('"', fp)) != '"') |
276 | ✗ | return retval; | |
277 | } | ||
278 |
1/2✗ Branch 3 not taken.
✓ Branch 4 taken 64468464 times.
|
64468464 | if ((retval = fputc(field[i], fp)) != field[i]) |
279 | ✗ | return retval; | |
280 | } | ||
281 | |||
282 |
1/2✗ Branch 1 not taken.
✓ Branch 2 taken 4471548 times.
|
4471548 | if ((retval = fputc('"', fp)) != '"') |
283 | ✗ | return retval; | |
284 | |||
285 | 4471548 | return 0; | |
286 | } | ||
287 |