Log agent start / stop timing events (#18632)
* log agent start / stop events * Make it simple * Populate average start/shutdown time in stream path * Get the median and not the average of the values * Change the log
Stelios Fragkakis committed
Oct 1, 2024 at 14:13 UTC
6c6b8e12921be36ff986af9fa794e0b6eae5e21d
5 files changed
+85
-1
src/daemon/main.c
+11
-1
@@ -316,6 +316,7 @@ void web_client_cache_destroy(void);
316
void netdata_cleanup_and_exit(int ret, const char *action, const char *action_result, const char *action_data) {
317
netdata_exit = 1;
318
319
+ usec_t shutdown_start_time = now_monotonic_usec();
320
watcher_shutdown_begin();
321
322
nd_log_limits_unlimited();
@@ -464,6 +465,9 @@ void netdata_cleanup_and_exit(int ret, const char *action, const char *action_re
465
#endif
466
}
467
468
+ // Don't register a shutdown event if we crashed
469
+ if (!ret)
470
+ add_agent_event(EVENT_AGENT_SHUTDOWN_TIME, (int64_t)(now_monotonic_usec() - shutdown_start_time));
471
sqlite_close_databases();
472
watcher_step_complete(WATCHER_STEP_ID_CLOSE_SQL_DATABASES);
473
sqlite_library_shutdown();
@@ -2307,7 +2311,13 @@ int netdata_main(int argc, char **argv) {
2311
delta_startup_time("ready");
2312
2313
usec_t ready_ut = now_monotonic_usec();
2310
- netdata_log_info("NETDATA STARTUP: completed in %llu ms. Enjoy real-time performance monitoring!", (ready_ut - started_ut) / USEC_PER_MS);
2314
+ add_agent_event(EVENT_AGENT_START_TIME, (int64_t ) (ready_ut - started_ut));
2315
+ usec_t median_start_time = get_agent_event_time_median(EVENT_AGENT_START_TIME);
2316
+ netdata_log_info(
2317
+ "NETDATA STARTUP: completed in %llu ms (median start up time is %llu ms). Enjoy real-time performance monitoring!",
2318
+ (ready_ut - started_ut) / USEC_PER_MS, median_start_time / USEC_PER_MS);
2319
+
2320
+ cleanup_agent_event_log();
2321
netdata_ready = true;
2322
2323
analytics_statistic_t start_statistic = { "START", "-", "-" };
src/database/sqlite/sqlite_metadata.c
+59
@@ -78,6 +78,9 @@ const char *database_config[] = {
78
"CREATE INDEX IF NOT EXISTS health_log_d_ind_7 on health_log_detail (alarm_id)",
79
"CREATE INDEX IF NOT EXISTS health_log_d_ind_8 on health_log_detail (new_status, updated_by_id)",
80
81
+ "CREATE TABLE IF NOT EXISTS agent_event_log (id INTEGER PRIMARY KEY, version TEXT, event_type INT, value, date_created INT)",
82
+ "CREATE INDEX IF NOT EXISTS idx_agent_event_log1 on agent_event_log (event_type)",
83
+
84
"CREATE TABLE IF NOT EXISTS alert_queue "
85
" (host_id BLOB, health_log_id INT, unique_id INT, alarm_id INT, status INT, date_scheduled INT, "
86
" UNIQUE(host_id, health_log_id, alarm_id))",
@@ -2337,6 +2340,62 @@ uint64_t sqlite_get_meta_space(void)
2340
return sqlite_get_db_space(db_meta);
2341
}
2342
2343
+#define SQL_ADD_AGENT_EVENT_LOG \
2344
+ "INSERT INTO agent_event_log (event_type, version, value, date_created) VALUES " \
2345
+ " (@event_type, @version, @value, UNIXEPOCH())"
2346
+
2347
+void add_agent_event(event_log_type_t event_id, int64_t value)
2348
+{
2349
+ sqlite3_stmt *res = NULL;
2350
+
2351
+ if (!PREPARE_STATEMENT(db_meta, SQL_ADD_AGENT_EVENT_LOG, &res))
2352
+ return;
2353
+
2354
+ int param = 0;
2355
+ SQLITE_BIND_FAIL(done, sqlite3_bind_int(res, ++param, event_id));
2356
+ SQLITE_BIND_FAIL(done, sqlite3_bind_text(res, ++param, NETDATA_VERSION, -1, SQLITE_STATIC));
2357
+ SQLITE_BIND_FAIL(done, sqlite3_bind_int64(res, ++param, value));
2358
+
2359
+ param = 0;
2360
+ int rc = execute_insert(res);
2361
+ if (rc != SQLITE_DONE)
2362
+ error_report("Failed to store agent event information, rc = %d", rc);
2363
+done:
2364
+ REPORT_BIND_FAIL(res, param);
2365
+ SQLITE_FINALIZE(res);
2366
+}
2367
+
2368
+void cleanup_agent_event_log(void)
2369
+{
2370
+ db_execute(db_meta, "DELETE FROM agent_event_log WHERE date_created < UNIXEPOCH() - 30 * 86400");
2371
+}
2372
+
2373
+#define SQL_GET_AGENT_EVENT_TYPE_MEDIAN \
2374
+ "SELECT AVG(value) AS median FROM " \
2375
+ "(SELECT value FROM agent_event_log WHERE event_type = @event ORDER BY value " \
2376
+ " LIMIT 2 - (SELECT COUNT(*) FROM agent_event_log WHERE event_type = @event) % 2 " \
2377
+ "OFFSET(SELECT(COUNT(*) - 1) / 2 FROM agent_event_log WHERE event_type = @event)) "
2378
+
2379
+usec_t get_agent_event_time_median(event_log_type_t event_id)
2380
+{
2381
+ sqlite3_stmt *res = NULL;
2382
+ if (!PREPARE_STATEMENT(db_meta, SQL_GET_AGENT_EVENT_TYPE_MEDIAN, &res))
2383
+ return 0;
2384
+
2385
+ usec_t avg_time = 0;
2386
+ int param = 0;
2387
+ SQLITE_BIND_FAIL(done, sqlite3_bind_int(res, ++param, event_id));
2388
+
2389
+ param = 0;
2390
+ if (sqlite3_step_monitored(res) == SQLITE_ROW)
2391
+ avg_time = sqlite3_column_int64(res, 0);
2392
+
2393
+done:
2394
+ REPORT_BIND_FAIL(res, param);
2395
+ SQLITE_FINALIZE(res);
2396
+ return avg_time;
2397
+}
2398
+
2399
//
2400
// unitests
2401
//
src/database/sqlite/sqlite_metadata.h
+9
@@ -6,6 +6,11 @@
6
#include "sqlite3.h"
7
#include "sqlite_functions.h"
8
9
+typedef enum event_log_type {
10
+ EVENT_AGENT_START_TIME = 1,
11
+ EVENT_AGENT_SHUTDOWN_TIME,
12
+} event_log_type_t;
13
+
14
// return a node list
15
struct node_instance_list {
16
nd_uuid_t node_id;
@@ -54,6 +59,10 @@ bool sql_set_host_label(nd_uuid_t *host_id, const char *label_key, const char *l
59
uint64_t sqlite_get_meta_space(void);
60
int sql_init_meta_database(db_check_action_type_t rebuild, int memory);
61
62
+void cleanup_agent_event_log(void);
63
+void add_agent_event(event_log_type_t event_id, int64_t value);
64
+usec_t get_agent_event_time_median(event_log_type_t event_id);
65
+
66
// UNIT TEST
67
int metadata_unittest(void);
68
#endif //NETDATA_SQLITE_METADATA_H
src/streaming/stream_path.c
+4
@@ -54,6 +54,8 @@ static void stream_path_to_json_object(BUFFER *wb, STREAM_PATH *p) {
54
buffer_json_member_add_int64(wb, "hops", p->hops);
55
buffer_json_member_add_uint64(wb, "since", p->since);
56
buffer_json_member_add_uint64(wb, "first_time_t", p->first_time_t);
57
+ buffer_json_member_add_uint64(wb, "start_time", p->start_time);
58
+ buffer_json_member_add_uint64(wb, "shutdown_time", p->shutdown_time);
59
stream_capabilities_to_json_array(wb, p->capabilities, "capabilities");
60
STREAM_PATH_FLAGS_2json(wb, "flags", p->flags);
61
buffer_json_object_close(wb);
@@ -68,6 +70,8 @@ static STREAM_PATH rrdhost_stream_path_self(RRDHOST *host) {
70
p.host_id = localhost->host_id;
71
p.node_id = localhost->node_id;
72
p.claim_id = claim_id_get_uuid();
73
+ p.start_time = get_agent_event_time_median(EVENT_AGENT_START_TIME) / USEC_PER_MS;
74
+ p.shutdown_time = get_agent_event_time_median(EVENT_AGENT_SHUTDOWN_TIME) / USEC_PER_MS;
75
76
p.flags = STREAM_PATH_FLAG_NONE;
77
if(!UUIDiszero(p.claim_id))
src/streaming/stream_path.h
+2
@@ -22,6 +22,8 @@ typedef struct stream_path {
22
int16_t hops; // -1 = stale node, 0 = localhost, >0 the hops count
23
STREAM_PATH_FLAGS flags; // ACLK or NONE for the moment
24
STREAM_CAPABILITIES capabilities; // streaming connection capabilities
25
+ uint32_t start_time; // median time in ms the agent needs to start
26
+ uint32_t shutdown_time; // median time in ms the agent needs to shutdown
27
} STREAM_PATH;
28
29
typedef struct rrdhost_stream_path {