Line data Source code
1 : /*
2 : START OF LICENSE STUB
3 : DeDOS: Declarative Dispersion-Oriented Software
4 : Copyright (C) 2017 University of Pennsylvania, Georgetown University
5 :
6 : This program is free software: you can redistribute it and/or modify
7 : it under the terms of the GNU General Public License as published by
8 : the Free Software Foundation, either version 3 of the License, or
9 : (at your option) any later version.
10 :
11 : This program is distributed in the hope that it will be useful,
12 : but WITHOUT ANY WARRANTY; without even the implied warranty of
13 : MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14 : GNU General Public License for more details.
15 :
16 : You should have received a copy of the GNU General Public License
17 : along with this program. If not, see <http://www.gnu.org/licenses/>.
18 : END OF LICENSE STUB
19 : */
20 : /**
21 : * @file rt_stats.c
22 : *
23 : * Collecting statistics within the runtime
24 : */
25 :
26 : #include "rt_stats.h"
27 : #include "stats.h"
28 : #include "logging.h"
29 :
30 : #include <stdio.h>
31 : #include <stdio_ext.h>
32 : #include <stdlib.h>
33 : #include <pthread.h>
34 : #include <stdbool.h>
35 :
36 : /** The clock used to mark the time at which events take place */
37 : #define CLOCK_ID CLOCK_REALTIME_COARSE
38 : #define DURATION_CLOCK_ID CLOCK_MONOTONIC
39 :
40 : /** The time at which the runtime started */
41 : static struct timespec stats_start_time;
42 : /** Whether ::init_statistics has been called */
43 : static bool stats_initialized = false;
44 :
45 :
46 : /**
47 : * The internal statistics structure where stats are aggregated
48 : * One per statistic-item.
49 : */
50 : struct stat_item
51 : {
52 : unsigned int id; /**< A unique identifier for the item being logged */
53 : int write_index; /**< The write index in the circular buffer */
54 : bool rolled_over; /**< Whether the stats structure has rolled over at least once */
55 : struct timed_stat *stats; /**< Timestamp and data for each gathered statistic */
56 : pthread_mutex_t mutex; /**< Lock for changing stat item */
57 : };
58 :
59 : /**
60 : * The structure holding all items of a type of stats
61 : */
62 : struct stat_type {
63 : enum stat_id id; /**< Stat ID as defined in stats.h */
64 : bool enabled; /**< If true, logging for this item is enabled */
65 : int max_stats; /**< Maximum number of statistics that can be held in memory */
66 : char *format; /**< Format for printf */
67 : char *label; /**< Name to output for this statistic */
68 : int id_indices[MAX_STAT_ITEM_ID]; /**< Index at which the IDs are stored */
69 : int num_items; /**< Number of items currently registered for logging */
70 : int max_items; /**< Number of items allocated for logging */
71 : pthread_rwlock_t lock; /**< Lock for adding new stat items */
72 : struct stat_item *items; /**< The items of this type being logged */
73 : };
74 :
75 : #if DUMP_STATS
76 : #define MAX_STATS 262144
77 : #else
78 : /** The maximum number of statistics that can be held in the rrdb */
79 : #define MAX_STATS 8192
80 : #endif
81 :
82 : /** If set to 0, will disable all gathering of statistics */
83 : #define GATHER_STATS 1
84 :
85 : #define GATHER_MSU_STATS 1 & GATHER_STATS
86 : #define GATHER_CUSTOM_STATS 1 & GATHER_STATS
87 : #define GATHER_THREAD_STATS 1 & GATHER_STATS
88 :
89 : #ifdef DEDOS_PROFILER
90 : #define GATHER_PROFILING 1
91 : #else
92 : #define GATHER_PROFILING 0
93 : #endif
94 :
95 : /** The list of all statistics that can be gathered in the system */
96 : struct stat_type stat_types[] = {
97 : {MSU_QUEUE_LEN, GATHER_MSU_STATS, MAX_STATS, "%02.0f", "MSU_Q_LEN"},
98 : {MSU_ITEMS_PROCESSED, GATHER_MSU_STATS, MAX_STATS, "%03.0f", "ITEMS_PROCESSED"},
99 : {MSU_EXEC_TIME, GATHER_MSU_STATS, MAX_STATS, "%0.9f", "MSU_EXEC_TIME"},
100 : {MSU_IDLE_TIME, GATHER_MSU_STATS, MAX_STATS, "%0.9f", "MSU_IDLE_TIME"},
101 : {MSU_MEM_ALLOC, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_MEM_ALLOC"},
102 : {MSU_NUM_STATES, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_NUM_STATES"},
103 : {MSU_ERROR_CNT, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_ERROR_CNT"},
104 : {MSU_UCPUTIME, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_USER_TIME"},
105 : {MSU_SCPUTIME, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_KERNEL_TIME"},
106 : {MSU_MINFLT, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_MINOR_FAULTS"},
107 : {MSU_MAJFLT, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_MAJOR_FAULTS"},
108 : {MSU_VCSW, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_VOL_CTX_SW"},
109 : {MSU_IVCSW, GATHER_MSU_STATS, MAX_STATS, "%09.0f", "MSU_INVOL_CTX_SW"},
110 : {THREAD_UCPUTIME, GATHER_THREAD_STATS, MAX_STATS, "%09.9f", "THREAD_USER_TIME"},
111 : {THREAD_SCPUTIME, GATHER_THREAD_STATS, MAX_STATS, "%09.9f", "THREAD_KERNEL_TIME"},
112 : {THREAD_MAXRSS, GATHER_THREAD_STATS, MAX_STATS, "%09.0f", "THREAD_MAX_RSS"},
113 : {THREAD_MINFLT, GATHER_THREAD_STATS, MAX_STATS, "%09.0f", "THREAD_MINOR_PG_FAULTS"},
114 : {THREAD_MAJFLT, GATHER_THREAD_STATS, MAX_STATS, "%09.0f", "THREAD_MAJOR_PG_FAULTS"},
115 : {THREAD_VCSW, GATHER_THREAD_STATS, MAX_STATS, "%09.0f", "THREAD_VOL_CTX_SW"},
116 : {THREAD_IVCSW, GATHER_THREAD_STATS, MAX_STATS, "%09.0f", "THREAD_INVOL_CTX_SW"},
117 : {MSU_STAT1, GATHER_CUSTOM_STATS, MAX_STATS, "%03.0f", "MSU_STAT1"},
118 : {MSU_STAT2, GATHER_CUSTOM_STATS, MAX_STATS, "%03.0f", "MSU_STAT2"},
119 : {MSU_STAT3, GATHER_CUSTOM_STATS, MAX_STATS, "%03.0f", "MSU_STAT3"},
120 : {PROF_ENQUEUE, GATHER_PROFILING, MAX_STATS, "%0.0f", "ENQUEUE"},
121 : {PROF_DEQUEUE, GATHER_PROFILING, MAX_STATS, "%0.0f", "DEQUEUE"},
122 : {PROF_REMOTE_SEND, GATHER_PROFILING, MAX_STATS, "%0.0f", "SEND"},
123 : {PROF_REMOTE_RECV, GATHER_PROFILING, MAX_STATS, "%0.0f", "RECV"},
124 : {PROF_DEDOS_ENTRY, GATHER_PROFILING, MAX_STATS, "%0.0f", "ENTRY"},
125 : {PROF_DEDOS_EXIT, GATHER_PROFILING, MAX_STATS, "%0.0f", "EXIT"},
126 : };
127 :
128 : /** The number of types of statistics */
129 : #define N_STAT_TYPES (sizeof(stat_types) / sizeof(*stat_types))
130 :
131 : #define CHECK_INITIALIZATION \
132 : if (!stats_initialized) { \
133 : log_error("Statistics not initialized!"); \
134 : return -1; \
135 : }
136 :
137 : /* TODO: Incremental flushes of raw items, followed by eventual conversion
138 : static inline int flush_raw_item_to_log(FILE *file, struct stat_type *type,
139 : int item_idx) {
140 : struct stat_item *item = &type->items[item_idx];
141 : int max_stats = type->max_stats;
142 :
143 : fwrite(&type->id, sizeof(type->id), 1, file);
144 : int label_len = strlen(type->label) + 1;
145 : fwrite(&label_len, sizeof(label_len), 1, file);
146 : fwrite(type->label, sizeof(char), label_len, file);
147 : int fmt_len = strlen(type->format) + 1;
148 : fwrite(&fmt_len, sizeof(fmt_len), 1, file);
149 : fwrite(type->format, sizeof(char), fmt_len, file);
150 :
151 : fwrite(&item->id, sizeof(item->id), 1, file);
152 : fwrite(&item->write_index, sizeof(item->write_index), 1, file);
153 : fwrite(&item->rolled_over, sizeof(item->rolled_over), 1, file);
154 : int n_stats = item->rolled_over ? max_stats : item->write_index;
155 : fwrite(&n_stats, sizeof(n_stats), 1, file);
156 : fwrite(item->stats, sizeof(*item->stats), n_stats, file);
157 :
158 : return 0;
159 : }
160 :
161 : static int convert_raw_item_from_log(FILE *in_file, FILE *out_file) {
162 : struct stat_type type;
163 : struct stat_item item;
164 :
165 : fread(&type.id, sizeof(type.id), 1, in_file);
166 : int label_len;
167 : fread(&label_len, sizeof(label_len), 1, in_file);
168 : fread(type.label, sizeof(char), label_len, in_file);
169 :
170 : int fmt_len;
171 : fread(&fmt_len, sizeof(fmt_len), 1, in_file);
172 : fread(type.format, sizeof(char), fmt_len, in_file);
173 :
174 : fread(&item.id, sizeof(item.id), 1, in_file);
175 : fread(&item.write_index, sizeof(item.write_index), 1, in_file);
176 : fread(&item.rolled_over, sizeof(item.rolled_over), 1, in_file);
177 : int n_stats;
178 : fread(&n_stats, sizeof(n_stats), 1, in_file);
179 : item.stats = malloc(sizeof(*item.stats) * n_stats);
180 : fread(item.stats, sizeof(*item.stats), n_stats, in_file);
181 :
182 : return write_item_to_log(out_file, &type, &item);
183 : }
184 : */
185 :
186 : /** Writes a single stat item to the log file */
187 4 : static int write_item_to_log(FILE *out_file, struct stat_type *type, struct stat_item *item) {
188 :
189 : char label[64];
190 4 : int ln = snprintf(label, 64, "%s:%02d:", type->label, item->id);
191 4 : label[ln] = '\0';
192 : //size_t label_size = strlen(label);
193 :
194 4 : int n_stats = item->rolled_over ? type->max_stats : item->write_index;
195 19116 : for (int i=0; i<n_stats; i++) {
196 : int rtn;
197 19112 : if ((rtn = fprintf(out_file, "%s", label)) > 30 || rtn < 0) {
198 0 : log_warn("printed out %d characters while outputting value %d", rtn, i);
199 : }
200 :
201 : //fwrite(label, 1, label_size, out_file);
202 38224 : if ((rtn = fprintf(out_file, "%010ld.%09ld:",
203 19112 : (long int)item->stats[i].time.tv_sec,
204 38224 : (long int)item->stats[i].time.tv_nsec)) > 30 || rtn < 0) {
205 0 : log_warn("Printed out %d characters outputting value %d",rtn, i);
206 : }
207 19112 : if ((rtn = fprintf(out_file, type->format, item->stats[i].value)) > 30 || rtn < 0) {
208 0 : log_warn("printed out %d characters while outputting value %d", rtn, i);
209 : }
210 19112 : fprintf(out_file, "%s", "\n");
211 : }
212 4 : log(LOG_STATS, "Flushed %d items for type %s (rollover: %d)", n_stats, type->label, item->rolled_over);
213 4 : return 0;
214 : }
215 :
216 :
217 : /**
218 : * Gets the amount of time that has elapsed since logging started.
219 : * @param *t the elapsed time is output into this variable
220 : */
221 15 : static void get_elapsed_time(struct timespec *t) {
222 15 : clock_gettime(CLOCK_ID, t);
223 : //t->tv_sec -= stats_start_time.tv_sec;
224 15 : }
225 :
226 : /** Locks a stat type for writing */
227 13 : static inline int wrlock_type(struct stat_type *type) {
228 13 : if (pthread_rwlock_wrlock(&type->lock) != 0) {
229 0 : log_error("Error locking stat type %s", type->label);
230 0 : return -1;
231 : }
232 13 : return 0;
233 : }
234 :
235 : /** Unlocks a stat type */
236 31 : static inline int unlock_type(struct stat_type *type) {
237 31 : if (pthread_rwlock_unlock(&type->lock) != 0) {
238 0 : log_error("Error unlocking stat type %s", type->label);
239 0 : return -1;
240 : }
241 31 : return 0;
242 : }
243 :
244 : /** Locks a stat type for reading */
245 18 : static inline int rlock_type(struct stat_type *type) {
246 18 : if (pthread_rwlock_rdlock(&type->lock) != 0) {
247 0 : log_error("Error locking stat type %s", type->label);
248 0 : return -1;
249 : }
250 18 : return 0;
251 : }
252 :
253 : /** Locks an item_stats structure, printing an error message on failure
254 : * @param *item the item_stats structure to lock
255 : * @return 0 on success, -1 on error
256 : */
257 22 : static inline int lock_item(struct stat_item *item) {
258 22 : if ( pthread_mutex_lock(&item->mutex) != 0) {
259 0 : log_error("Error locking mutex for an item with ID %u", item->id);
260 0 : return -1;
261 : }
262 22 : return 0;
263 : }
264 :
265 : /** Unlocks an item_stats structure, printing an error message on failure
266 : * @param *item the item_stats structure to unlock
267 : * @return 0 on success, -1 on error
268 : */
269 22 : static inline int unlock_item(struct stat_item *item) {
270 22 : if ( pthread_mutex_unlock(&item->mutex) != 0) {
271 0 : log_error("Error locking mutex for an item with ID %u", item->id);
272 0 : return -1;
273 : }
274 22 : return 0;
275 : }
276 :
277 : /** Writes all statistics to the provided log file */
278 0 : static void UNUSED flush_all_stats_to_log(FILE *file) {
279 0 : for (int i=0; i<N_STAT_TYPES; i++) {
280 0 : if (!stat_types[i].enabled) {
281 0 : continue;
282 : }
283 0 : rlock_type(&stat_types[i]);
284 0 : for (int j=0; j<stat_types[i].num_items; j++) {
285 0 : lock_item(&stat_types[i].items[j]);
286 0 : write_item_to_log(file, &stat_types[i], &stat_types[i].items[j]);
287 0 : unlock_item(&stat_types[i].items[j]);
288 : }
289 0 : unlock_type(&stat_types[i]);
290 : }
291 0 : }
292 :
293 : /** Frees the memory associated with an individual stat item */
294 0 : static void destroy_stat_item(struct stat_item *item) {
295 0 : free(item->stats);
296 0 : pthread_mutex_destroy(&item->mutex);
297 0 : }
298 :
299 : /** Gets the stat item associated with the given item_id in the given type */
300 33 : static struct stat_item *get_item_stat(struct stat_type *type, unsigned int item_id) {
301 33 : if (item_id > MAX_STAT_ITEM_ID) {
302 0 : log_error("Item ID %u too high. Max: %d", item_id, MAX_STAT_ITEM_ID);
303 0 : return NULL;
304 : }
305 33 : int id_index = type->id_indices[item_id];
306 33 : if (id_index == -1) {
307 1 : log_error("Item ID %u not initialized for stat %s",
308 : item_id, type->label);
309 1 : return NULL;
310 : }
311 32 : return &type->items[id_index];
312 : }
313 :
314 3 : static inline long double current_double_time() {
315 : struct timespec t;
316 3 : clock_gettime(DURATION_CLOCK_ID, &t);
317 3 : return (long double)t.tv_sec + (long double)t.tv_nsec / 1e9;
318 : }
319 :
320 3 : int record_start_time(enum stat_id stat_id, unsigned int item_id) {
321 3 : CHECK_INITIALIZATION;
322 :
323 3 : struct stat_type *type = &stat_types[stat_id];
324 3 : if (!type->enabled) {
325 0 : return 0;
326 : }
327 3 : if (rlock_type(type)) {
328 0 : return -1;
329 : }
330 3 : struct stat_item *item = get_item_stat(type, item_id);
331 3 : unlock_type(type);
332 3 : if (item == NULL) {
333 1 : return -1;
334 : }
335 :
336 2 : if (lock_item(item)) {
337 0 : return -1;
338 : }
339 2 : get_elapsed_time(&item->stats[item->write_index].time);
340 2 : item->stats[item->write_index].value = current_double_time();
341 2 : unlock_item(item);
342 :
343 2 : return 0;
344 : }
345 :
346 : #if DUMP_STATS
347 : #define WARN_ROLLOVER(label, item_id) \
348 : log_warn("Stats for type %s.%u rolling over. Log file will be missing data", \
349 : label, item_id);
350 : #else
351 : #define WARN_ROLLOVER(label, item_id)
352 : #endif
353 :
354 :
355 1 : int record_end_time(enum stat_id stat_id, unsigned int item_id) {
356 1 : CHECK_INITIALIZATION;
357 :
358 1 : long double new_time = current_double_time();
359 :
360 1 : struct stat_type *type = &stat_types[stat_id];
361 1 : if (!type->enabled) {
362 0 : return 0;
363 : }
364 1 : if (rlock_type(type)) {
365 0 : return -1;
366 : }
367 1 : struct stat_item *item = get_item_stat(type, item_id);
368 1 : unlock_type(type);
369 1 : if (item == NULL) {
370 0 : return -1;
371 : }
372 :
373 1 : if (lock_item(item)) {
374 0 : return -1;
375 : }
376 :
377 1 : item->stats[item->write_index].value = new_time - item->stats[item->write_index].value;
378 1 : item->write_index++;
379 :
380 1 : if (item->write_index == type->max_stats) {
381 : WARN_ROLLOVER(type->label, item_id);
382 0 : item->write_index = 0;
383 0 : item->rolled_over = true;
384 : }
385 :
386 1 : unlock_item(item);
387 1 : return 0;
388 : }
389 5 : int increment_stat(enum stat_id stat_id, unsigned int item_id, double value) {
390 5 : CHECK_INITIALIZATION;
391 :
392 5 : struct stat_type *type = &stat_types[stat_id];
393 5 : if (!type->enabled) {
394 0 : return 0;
395 : }
396 5 : if (rlock_type(type)) {
397 0 : return -1;
398 : }
399 5 : struct stat_item *item = get_item_stat(type, item_id);
400 5 : unlock_type(type);
401 5 : if (item == NULL) {
402 0 : return -1;
403 : }
404 :
405 5 : if (lock_item(item)) {
406 0 : return -1;
407 : }
408 :
409 5 : get_elapsed_time(&item->stats[item->write_index].time);
410 5 : int last_index = item->write_index - 1;
411 5 : if ( last_index < 0 ) {
412 2 : last_index = type->max_stats - 1;
413 : }
414 5 : item->stats[item->write_index].value = item->stats[last_index].value + value;
415 5 : item->write_index++;
416 5 : if (item->write_index == type->max_stats) {
417 : WARN_ROLLOVER(type->label, item_id);
418 1 : item->write_index = 0;
419 1 : item->rolled_over = true;
420 : }
421 :
422 5 : unlock_item(item);
423 5 : return 0;
424 : }
425 :
426 9 : int record_stat(enum stat_id stat_id, unsigned int item_id, double stat, bool relog) {
427 9 : CHECK_INITIALIZATION;
428 :
429 9 : struct stat_type *type = &stat_types[stat_id];
430 9 : if (!type->enabled) {
431 0 : return 0;
432 : }
433 9 : if (rlock_type(type)) {
434 0 : return -1;
435 : }
436 9 : struct stat_item *item = get_item_stat(type, item_id);
437 9 : unlock_type(type);
438 9 : if (item == NULL) {
439 0 : return -1;
440 : }
441 :
442 9 : if (lock_item(item)) {
443 0 : return -1;
444 : }
445 :
446 9 : int last_index = item->write_index - 1;
447 9 : bool do_log = true;
448 9 : if (last_index >= 0) {
449 6 : do_log = item->stats[last_index].value != stat;
450 : }
451 :
452 9 : if (relog || do_log) {
453 8 : get_elapsed_time(&item->stats[item->write_index].time);
454 8 : item->stats[item->write_index].value = stat;
455 8 : item->write_index++;
456 8 : if (item->write_index == type->max_stats) {
457 : WARN_ROLLOVER(type->label, item_id);
458 1 : item->write_index = 0;
459 1 : item->rolled_over = true;
460 : }
461 : }
462 9 : unlock_item(item);
463 9 : return 0;
464 : }
465 :
466 0 : double get_last_stat(enum stat_id stat_id, unsigned int item_id) {
467 0 : CHECK_INITIALIZATION;
468 :
469 0 : struct stat_type *type = &stat_types[stat_id];
470 0 : if (!type->enabled) {
471 0 : return 0;
472 : }
473 0 : if (rlock_type(type)) {
474 0 : return -1;
475 : }
476 0 : struct stat_item *item = get_item_stat(type, item_id);
477 0 : unlock_type(type);
478 0 : if (item == NULL) {
479 0 : return -1;
480 : }
481 0 : if (lock_item(item)) {
482 0 : return -1;
483 : }
484 :
485 0 : int last_index = item->write_index - 1;
486 0 : double last_stat = 0;
487 0 : if (last_index >= 0) {
488 0 : last_stat = item->stats[last_index].value;
489 : }
490 :
491 0 : unlock_item(item);
492 :
493 0 : return last_stat;
494 : }
495 :
496 : /** Returns 1 if t1 > t2, -1 if t2 > t1, 0 otherwise */
497 294 : static inline int time_cmp(struct timespec *t1, struct timespec *t2) {
498 354 : return t1->tv_sec > t2->tv_sec ? 1 :
499 120 : ( t1->tv_sec < t2->tv_sec ? -1 :
500 120 : ( t1->tv_nsec > t2->tv_nsec ? 1 :
501 60 : ( t1->tv_nsec < t2->tv_nsec ? -1 : 0 ) ) );
502 : }
503 :
504 : /** Finds the index at which the given time occurred in the stats */
505 60 : static int find_time_index(struct timed_stat *stats, struct timespec *time,
506 : int start_index, int stat_size) {
507 60 : if (start_index < 0) {
508 0 : start_index = stat_size - 1;
509 : }
510 60 : if (time_cmp(&stats[start_index].time, time) <= 0) {
511 5 : return start_index;
512 : }
513 55 : int search_index = start_index - 1;
514 : do {
515 234 : if (search_index < 0) {
516 0 : search_index = stat_size - 1;
517 : }
518 234 : if (time_cmp(&stats[search_index].time, time) <= 0) {
519 55 : return search_index;
520 : }
521 179 : search_index--;
522 179 : } while (search_index != start_index - 1);
523 0 : return -1;
524 : }
525 :
526 : /** Takes a sample of the provided stat item and stores it in `sample` */
527 5 : static int sample_stat_item(struct stat_item *item, int stat_size,
528 : struct timespec *sample_end, struct timespec *interval, int sample_size,
529 : struct timed_stat *sample) {
530 5 : struct timespec sample_time = *sample_end;
531 5 : if (lock_item(item)) {
532 0 : return -1;
533 : }
534 5 : int sample_index = item->write_index - 1;
535 5 : if (sample_index < 0) {
536 0 : sample_index = stat_size + sample_index;
537 : }
538 5 : int max_index = item->rolled_over ? stat_size : item->write_index;
539 : int i;
540 65 : for (i=0; i<sample_size; i++) {
541 60 : if (max_index > 1) {
542 60 : sample_index = find_time_index(item->stats, &sample_time, sample_index, max_index);
543 : } else {
544 0 : sample_index = 0;
545 : }
546 60 : if (sample_index < 0) {
547 0 : log(LOG_STATS, "Couldn't find time index for item %d", item->id);
548 0 : unlock_item(item);
549 0 : return i;
550 : }
551 60 : sample[sample_size - i - 1].value = item->stats[sample_index].value;
552 60 : sample[sample_size - i - 1].time = sample_time;
553 60 : sample_time.tv_nsec -= interval->tv_nsec;
554 60 : if (sample_time.tv_nsec < 0) {
555 8 : sample_time.tv_sec -= 1;
556 8 : sample_time.tv_nsec = 1e9 + sample_time.tv_nsec;
557 : }
558 60 : sample_time.tv_sec -= interval->tv_sec;
559 : }
560 5 : unlock_item(item);
561 5 : return i;
562 : }
563 :
564 : /** Takes a sample of the provided stat type (stat_id) and places it in `sample` */
565 1 : static int sample_stat(enum stat_id stat_id, struct timespec *end, struct timespec *interval,
566 : int sample_size, struct stat_sample *sample, int n_samples) {
567 1 : CHECK_INITIALIZATION;
568 :
569 1 : struct stat_type *type = &stat_types[stat_id];
570 1 : if (!type->enabled) {
571 0 : log_error("Attempted to sample disabled statistic %d", stat_id);
572 0 : return -1;
573 : }
574 :
575 :
576 1 : if (n_samples < type->num_items) {
577 0 : log_error("Not enough samples (%d) to fit all stat items (%d)", n_samples, type->num_items);
578 0 : return -1;
579 : }
580 :
581 1 : int item_id = -1;
582 5 : for (int i=0; i<type->num_items; i++) {
583 4 : sample[i].hdr.stat_id = stat_id;
584 : // Find the next item index
585 8 : for (item_id += 1;
586 4 : item_id < MAX_STAT_ITEM_ID && type->id_indices[item_id] == -1;
587 0 : item_id++) {}
588 4 : log(LOG_TEST, "Found :%d", item_id);
589 4 : if (item_id == MAX_STAT_ITEM_ID) {
590 0 : log_error("Cannot find item ID %d", i);
591 0 : return -1;
592 : }
593 4 : int idx = type->id_indices[item_id];
594 4 : sample[i].hdr.item_id = type->items[idx].id;
595 4 : sample[i].hdr.n_stats = sample_size;
596 4 : int rtn = sample_stat_item(&type->items[idx], type->max_stats, end, interval, sample_size,
597 4 : sample[i].stats);
598 :
599 4 : if ( rtn < 0) {
600 0 : log_error("Error sampling item %d (idx %d)", type->items[i].id, i);
601 0 : return -1;
602 : } else {
603 4 : sample[i].hdr.n_stats = rtn;
604 : }
605 : }
606 1 : return type->num_items;
607 : }
608 :
609 : /** Samples `sample_size` most recent stats in `interval` intervals.
610 : * Note: Not used at the moment, deferring to sample_stat instead
611 : * */
612 0 : static int UNUSED sample_recent_stats(enum stat_id stat_id, struct timespec *interval,
613 : int sample_size, struct stat_sample *sample, int n_samples) {
614 0 : CHECK_INITIALIZATION;
615 0 : struct stat_type *type = &stat_types[stat_id];
616 0 : if (!type->enabled) {
617 0 : return 0;
618 : }
619 : struct timespec now;
620 0 : get_elapsed_time(&now);
621 0 : return sample_stat(stat_id, &now, interval, sample_size, sample, n_samples);
622 : }
623 :
624 : /** A statically allocated stat_sample structure which is pre-allocated to store samples
625 : * from each stat type */
626 : static struct stat_sample *stat_samples[N_REPORTED_STAT_TYPES];
627 :
628 : /** The interval at which stats should be sampled */
629 : static struct timespec stat_sample_interval = {
630 : .tv_sec = (STAT_SAMPLE_PERIOD_MS / 1000) / STAT_SAMPLE_SIZE,
631 : .tv_nsec = (int)(STAT_SAMPLE_PERIOD_MS * 1e6 / STAT_SAMPLE_SIZE) % (int)1e9
632 : };
633 :
634 0 : struct stat_sample *get_stat_samples(enum stat_id stat_id, struct timespec *sample_time,
635 : int *n_samples_out) {
636 0 : if (!stats_initialized) {
637 0 : log_error("Stats not initialized");
638 0 : return NULL;
639 : }
640 :
641 0 : *n_samples_out = 0;
642 : int i;
643 0 : for (i=0; i < N_REPORTED_STAT_TYPES; i++) {
644 0 : if (reported_stat_types[i].id == stat_id) {
645 0 : break;
646 : }
647 : }
648 0 : if (i == N_REPORTED_STAT_TYPES) {
649 0 : log_error("%d is not a reported stat type", stat_id);
650 0 : return NULL;
651 : }
652 0 : if (stat_samples[i] == NULL) {
653 : // No stat samples registered!"
654 0 : return NULL;
655 : }
656 0 : struct stat_type *type = &stat_types[stat_id];
657 0 : if (rlock_type(type)) {
658 0 : return NULL;
659 : }
660 0 : int rtn = sample_stat(stat_id, sample_time, &stat_sample_interval, STAT_SAMPLE_SIZE,
661 : stat_samples[i], type->num_items);
662 0 : unlock_type(type);
663 0 : if (rtn < 0) {
664 0 : log_error("Error sampling recent stats");
665 0 : return NULL;
666 : }
667 0 : *n_samples_out = rtn;
668 0 : return stat_samples[i];
669 : }
670 :
671 : /** Reallocates the existing stats structure to store the provided number of samples */
672 13 : static void realloc_stat_samples(enum stat_id stat_id, int n_samples) {
673 13 : for (int i=0; i < N_REPORTED_STAT_TYPES; i++) {
674 13 : if (reported_stat_types[i].id == stat_id) {
675 13 : free_stat_samples(stat_samples[i], n_samples - 1);
676 13 : stat_samples[i] = init_stat_samples(STAT_SAMPLE_SIZE, n_samples);
677 13 : log(LOG_STAT_REALLOC, "Reallocated %d to %d samples", stat_id, n_samples);
678 26 : return;
679 : }
680 : }
681 : }
682 :
683 0 : int remove_stat_item(enum stat_id stat_id, unsigned int item_id) {
684 0 : CHECK_INITIALIZATION;
685 :
686 0 : struct stat_type *type = &stat_types[stat_id];
687 0 : if (!type->enabled) {
688 0 : return 0;
689 : }
690 0 : if (wrlock_type(type) != 0) {
691 0 : return -1;
692 : }
693 0 : if (type->id_indices[item_id] == -1) {
694 0 : log_error("Item ID %u not assigned an index", item_id);
695 0 : return -1;
696 : }
697 :
698 0 : int index = type->id_indices[item_id];
699 0 : struct stat_item *item = &type->items[index];
700 :
701 0 : item->id = -1;
702 0 : item->write_index = 0;
703 0 : item->rolled_over = false;
704 0 : free(item->stats);
705 :
706 0 : type->id_indices[item_id] = -1;
707 0 : type->num_items--;
708 0 : unlock_type(type);
709 0 : return 0;
710 : }
711 :
712 :
713 : /**
714 : * Initializes a stat item so that statistics can be logged to it.
715 : * (e.g. initializing MSU_QUEUE_LEN for item N, corresponding to msu # N)
716 : * @param stat_id ID of the statistic type to be logged
717 : * @param item_id ID of the item to be logged
718 : */
719 13 : int init_stat_item(enum stat_id stat_id, unsigned int item_id) {
720 13 : CHECK_INITIALIZATION;
721 :
722 13 : struct stat_type *type = &stat_types[stat_id];
723 13 : if (!type->enabled) {
724 0 : log(LOG_STATS, "Skipping initialization of type %s item %d",
725 : type->label, item_id);
726 0 : return 0;
727 : }
728 13 : if (wrlock_type(type) != 0) {
729 0 : return -1;
730 : }
731 13 : if (type->id_indices[item_id] != -1) {
732 0 : log_error("Item ID %u already assigned index %d for stat %s",
733 : item_id, type->id_indices[item_id], type->label);
734 0 : return -1;
735 : }
736 : int index;
737 19 : for (index=0; index<type->max_items; index++) {
738 6 : if (type->items[index].id == -1) {
739 0 : break;
740 : }
741 : }
742 13 : if (index == type->max_items) {
743 13 : type->max_items++;
744 13 : type->items = realloc(type->items, sizeof(*type->items) * (type->max_items));
745 13 : realloc_stat_samples(stat_id, type->max_items);
746 :
747 13 : if ( type->items == NULL ) {
748 0 : log_error("Error reallocating stat item");
749 0 : return -1;
750 : }
751 : }
752 13 : log(LOG_STATS, "Item %u has index %d", item_id, index);
753 13 : struct stat_item *item = &type->items[index];
754 :
755 13 : if (pthread_mutex_init(&item->mutex,NULL)) {
756 0 : log_error("Error initializing item %u lock", item_id);
757 0 : return -1;
758 : }
759 :
760 13 : item->id = item_id;
761 13 : item->write_index = 0;
762 13 : item->rolled_over = false;
763 13 : item->stats = calloc(type->max_stats, sizeof(*item->stats));
764 :
765 13 : if (item->stats == NULL) {
766 0 : log_error("Error calloc'ing item statistics");
767 0 : return -1;
768 : }
769 :
770 13 : type->id_indices[item_id] = index;
771 :
772 13 : type->num_items++;
773 :
774 13 : if (unlock_type(type) != 0) {
775 0 : return -1;
776 : }
777 :
778 13 : log(LOG_STAT_INITS, "Initialized stat item %s.%d (idx: %d)",
779 : stat_types[stat_id].label, item_id, index);
780 13 : return 0;
781 : }
782 :
783 11 : int init_statistics() {
784 11 : if ( stats_initialized ) {
785 0 : log_error("Statistics have already been initialized");
786 0 : return -1;
787 : }
788 :
789 11 : clock_gettime(CLOCK_ID, &stats_start_time);
790 :
791 330 : for (int i = 0; i < N_STAT_TYPES; i++) {
792 319 : struct stat_type *type = &stat_types[i];
793 319 : if ( type->id != i ) {
794 0 : log_error("Stat type %s at incorrect index (%d, not %d)! Disabling!!",
795 : type->label, i, type->id);
796 0 : type->enabled = 0;
797 : }
798 :
799 319 : if (type->enabled) {
800 253 : if (pthread_rwlock_init(&type->lock, NULL) != 0) {
801 0 : log_warn("Error initializing lock for stat %s. Disabling!", type->label);
802 0 : type->enabled = 0;
803 : }
804 253 : type->num_items = 0;
805 253 : type->items = NULL;
806 1060829 : for (int j = 0; j < MAX_STAT_ITEM_ID; j++) {
807 1060576 : type->id_indices[j] = -1;
808 : }
809 253 : log(LOG_STATS, "Initialized stat type %s (%d ids)", type->label, MAX_STAT_ITEM_ID);
810 : }
811 : }
812 :
813 : #if DUMP_STATS
814 : log_info("Statistics initialized for eventual dump to log file");
815 : #else
816 11 : log_info("Statistics initialized. Will **NOT** be dumped to log file");
817 : #endif
818 11 : stats_initialized = true;
819 11 : return 0;
820 : }
821 :
822 0 : void finalize_statistics(char *statlog) {
823 0 : if (statlog != NULL) {
824 : #if DUMP_STATS
825 : log_info("Outputting stats to log. Do not quit.");
826 : FILE *file = fopen(statlog, "w");
827 : flush_all_stats_to_log(file);
828 : fclose(file);
829 : log_info("Finished outputting stats to %s", statlog);
830 : #else
831 0 : log_info("Skipping dump to stat log. Set DUMP_STATS=1 to enable");
832 : #endif
833 : }
834 :
835 0 : for (int i = 0; i < N_STAT_TYPES; i++) {
836 0 : struct stat_type *type = &stat_types[i];
837 0 : if (type->enabled) {
838 0 : wrlock_type(type);
839 0 : for (int j = 0; j < type->num_items; j++) {
840 0 : log(LOG_STAT_INITS, "Destroying item %s.idx=%d",
841 : type->label, j);
842 0 : destroy_stat_item(&type->items[j]);
843 : }
844 0 : free(type->items);
845 0 : unlock_type(type);
846 0 : pthread_rwlock_destroy(&type->lock);
847 : }
848 : }
849 0 : }
|
