replication fixes #6 (#14046)
use the faster monotonic clock in workers and replication; avoid unecessary statistics function on every request on replication - gather them all together once every second; check the chart flags on all mirrored hosts, not only the ones that have a sender; cleanup and unify replication logs; added child world time to REND; fix first BEGIN been transmitted when replication starts;
Costa Tsaousis committed
Nov 25, 2022 at 20:37 UTC
2e874e79163771856e4e756b176b729f7d8b0f0f
7 files changed
+401
-260
collectors/plugins.d/pluginsd_parser.c
+75
-52
@@ -151,6 +151,20 @@ PARSER_RC pluginsd_begin(char **words, size_t num_words, void *user)
151
if (microseconds_txt && *microseconds_txt)
152
microseconds = str2ull(microseconds_txt);
153
154
+#ifdef NETDATA_LOG_REPLICATION_REQUESTS
155
+ if(st->replay.log_next_data_collection) {
156
+ st->replay.log_next_data_collection = false;
157
+
158
+ internal_error(true,
159
+ "REPLAY: 'host:%s/chart:%s' first BEGIN after replication, last collected %llu, last updated %llu, microseconds %llu",
160
+ rrdhost_hostname(host), rrdset_id(st),
161
+ st->last_collected_time.tv_sec * USEC_PER_SEC + st->last_collected_time.tv_usec,
162
+ st->last_updated.tv_sec * USEC_PER_SEC + st->last_updated.tv_usec,
163
+ microseconds
164
+ );
165
+ }
166
+#endif
167
+
168
if (likely(st->counter_done)) {
169
if (likely(microseconds)) {
170
if (((PARSER_USER_OBJECT *)user)->trust_durations)
@@ -312,6 +326,7 @@ PARSER_RC pluginsd_chart_definition_end(char **words, size_t num_words, void *us
326
{
327
const char *first_entry_txt = get_word(words, num_words, 1);
328
const char *last_entry_txt = get_word(words, num_words, 2);
329
+ const char *world_time_txt = get_word(words, num_words, 3);
330
331
RRDHOST *host = pluginsd_require_host_from_parent(user, PLUGINSD_KEYWORD_CHART_DEFINITION_END);
332
if(!host) return PLUGINSD_DISABLE_PLUGIN(user);
@@ -319,22 +334,14 @@ PARSER_RC pluginsd_chart_definition_end(char **words, size_t num_words, void *us
334
RRDSET *st = pluginsd_require_chart_from_parent(user, PLUGINSD_KEYWORD_CHART_DEFINITION_END, PLUGINSD_KEYWORD_CHART);
335
if(!st) return PLUGINSD_DISABLE_PLUGIN(user);
336
322
- if(unlikely(!first_entry_txt || !last_entry_txt)) {
323
- error("PLUGINSD: 'host:%s' got a " PLUGINSD_KEYWORD_CHART_DEFINITION_END " without first or last entry. Disabling it.",
324
- rrdhost_hostname(host));
325
- return PLUGINSD_DISABLE_PLUGIN(user);
326
- }
337
+ time_t first_entry_child = (first_entry_txt && *first_entry_txt) ? (time_t)str2ul(first_entry_txt) : 0;
338
+ time_t last_entry_child = (last_entry_txt && *last_entry_txt) ? (time_t)str2ul(last_entry_txt) : 0;
339
+ time_t child_world_time = (world_time_txt && *world_time_txt) ? (time_t)str2ul(world_time_txt) : now_realtime_sec();
340
328
- long first_entry_child = str2l(first_entry_txt);
329
- long last_entry_child = str2l(last_entry_txt);
330
-
331
- internal_error(
332
- (first_entry_child != 0 || last_entry_child != 0)
333
- && (first_entry_child == 0 || last_entry_child == 0),
334
- "PLUGINSD: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_CHART_DEFINITION_END " with malformed timings (first time %llu, last time %llu).",
335
- rrdhost_hostname(host), rrdset_id(st),
336
- (unsigned long long)first_entry_child, (unsigned long long)last_entry_child
337
- );
341
+ if((first_entry_child != 0 || last_entry_child != 0) && (first_entry_child == 0 || last_entry_child == 0))
342
+ error("PLUGINSD REPLAY ERROR: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_CHART_DEFINITION_END " with malformed timings (first time %ld, last time %ld, world time %ld).",
343
+ rrdhost_hostname(host), rrdset_id(st),
344
+ first_entry_child, last_entry_child, child_world_time);
345
346
bool ok = true;
347
if(!rrdset_flag_check(st, RRDSET_FLAG_RECEIVER_REPLICATION_IN_PROGRESS)) {
@@ -350,8 +357,9 @@ PARSER_RC pluginsd_chart_definition_end(char **words, size_t num_words, void *us
357
rrdhost_receiver_replicating_charts_plus_one(st->rrdhost);
358
359
PARSER *parser = ((PARSER_USER_OBJECT *)user)->parser;
353
- ok = replicate_chart_request(send_to_plugin, parser, host, st, first_entry_child,
354
- last_entry_child, 0, 0);
360
+ ok = replicate_chart_request(send_to_plugin, parser, host, st,
361
+ first_entry_child, last_entry_child, child_world_time,
362
+ 0, 0);
363
}
364
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
365
else {
@@ -910,7 +918,7 @@ PARSER_RC pluginsd_clabel_commit(char **words __maybe_unused, size_t num_words _
918
RRDHOST *host = pluginsd_require_host_from_parent(user, PLUGINSD_KEYWORD_CLABEL_COMMIT);
919
if(!host) return PLUGINSD_DISABLE_PLUGIN(user);
920
913
- RRDSET *st = pluginsd_require_chart_from_parent(user, PLUGINSD_KEYWORD_CLABEL_COMMIT, PLUGINSD_KEYWORD_REPLAY_BEGIN);
921
+ RRDSET *st = pluginsd_require_chart_from_parent(user, PLUGINSD_KEYWORD_CLABEL_COMMIT, PLUGINSD_KEYWORD_BEGIN);
922
if(!st) return PLUGINSD_DISABLE_PLUGIN(user);
923
924
debug(D_PLUGINSD, "requested to commit chart labels");
@@ -950,28 +958,35 @@ PARSER_RC pluginsd_replay_rrdset_begin(char **words, size_t num_words, void *use
958
((PARSER_USER_OBJECT *) user)->st = st;
959
960
if(start_time_str && end_time_str) {
953
- time_t start_time = strtol(start_time_str, NULL, 0);
954
- time_t end_time = strtol(end_time_str, NULL, 0);
961
+ time_t start_time = (time_t)str2ul(start_time_str);
962
+ time_t end_time = (time_t)str2ul(end_time_str);
963
964
time_t wall_clock_time = 0, tolerance;
965
bool wall_clock_comes_from_child; (void)wall_clock_comes_from_child;
966
if(child_now_str) {
959
- wall_clock_time = strtol(child_now_str, NULL, 0);
967
+ wall_clock_time = (time_t)str2ul(child_now_str);
968
tolerance = st->update_every + 1;
969
wall_clock_comes_from_child = true;
970
}
971
972
if(wall_clock_time <= 0) {
973
wall_clock_time = now_realtime_sec();
966
- tolerance = st->update_every + 60;
974
+ tolerance = st->update_every + 5;
975
wall_clock_comes_from_child = false;
976
}
977
978
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
979
internal_error(
980
(!st->replay.start_streaming && (end_time < st->replay.after || start_time > st->replay.before)),
973
- "REPLAY: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_BEGIN " from %ld to %ld, which does not match our request (%ld to %ld).",
981
+ "REPLAY ERROR: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_BEGIN " from %ld to %ld, which does not match our request (%ld to %ld).",
982
rrdhost_hostname(st->rrdhost), rrdset_id(st), start_time, end_time, st->replay.after, st->replay.before);
983
+
984
+ internal_error(
985
+ true,
986
+ "REPLAY: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_BEGIN " from %ld to %ld, child wall clock is %ld (%s), had requested %ld to %ld",
987
+ rrdhost_hostname(st->rrdhost), rrdset_id(st),
988
+ start_time, end_time, wall_clock_time, wall_clock_comes_from_child ? "from child" : "parent time",
989
+ st->replay.after, st->replay.before);
990
#endif
991
992
if(start_time && end_time && start_time < wall_clock_time + tolerance && end_time < wall_clock_time + tolerance && start_time < end_time) {
@@ -1002,10 +1017,9 @@ PARSER_RC pluginsd_replay_rrdset_begin(char **words, size_t num_words, void *use
1017
return PARSER_RC_OK;
1018
}
1019
1005
- internal_error(true,
1006
- "PLUGINSD: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_BEGIN " from %ld to %ld, but timestamps are invalid (now is %ld [%s], tolerance %ld).",
1007
- rrdhost_hostname(st->rrdhost), rrdset_id(st), start_time, end_time,
1008
- wall_clock_time, wall_clock_comes_from_child ? "child wall clock" : "parent wall clock", tolerance);
1020
+ error("PLUGINSD REPLAY ERROR: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_BEGIN " from %ld to %ld, but timestamps are invalid (now is %ld [%s], tolerance %ld). Ignoring " PLUGINSD_KEYWORD_REPLAY_SET,
1021
+ rrdhost_hostname(st->rrdhost), rrdset_id(st), start_time, end_time,
1022
+ wall_clock_time, wall_clock_comes_from_child ? "child wall clock" : "parent wall clock", tolerance);
1023
}
1024
1025
// the child sends an RBEGIN without any parameters initially
@@ -1051,7 +1065,7 @@ PARSER_RC pluginsd_replay_set(char **words, size_t num_words, void *user)
1065
dimension,
1066
((PARSER_USER_OBJECT *) user)->replay.start_time,
1067
((PARSER_USER_OBJECT *) user)->replay.end_time);
1054
- return PARSER_RC_ERROR;
1068
+ return PLUGINSD_DISABLE_PLUGIN(user);
1069
}
1070
1071
if (unlikely(!value_str || !*value_str))
@@ -1065,15 +1079,6 @@ PARSER_RC pluginsd_replay_set(char **words, size_t num_words, void *user)
1079
1080
RRDDIM_FLAGS rd_flags = rrddim_flag_check(rd, RRDDIM_FLAG_OBSOLETE | RRDDIM_FLAG_ARCHIVED);
1081
1068
- if(unlikely(rd_flags & RRDDIM_FLAG_OBSOLETE)) {
1069
- error("PLUGINSD: 'host:%s/chart:%s/dim:%s' has the OBSOLETE flag set, but it is collected.",
1070
- rrdhost_hostname(st->rrdhost),
1071
- rrdset_id(st),
1072
- rrddim_id(rd)
1073
- );
1074
- rrddim_isnot_obsolete(st, rd);
1075
- }
1076
-
1082
if(!(rd_flags & RRDDIM_FLAG_ARCHIVED)) {
1083
NETDATA_DOUBLE value = strtondd(value_str, NULL);
1084
SN_FLAGS flags = SN_FLAG_NONE;
@@ -1106,9 +1111,11 @@ PARSER_RC pluginsd_replay_set(char **words, size_t num_words, void *user)
1111
rd->last_collected_time.tv_usec = 0;
1112
rd->collections_counter++;
1113
}
1109
- else
1110
- error("PLUGINSD: 'host:%s/chart:%s/dim:%s' has the ARCHIVED flag set, but it is collected. Ignoring data.",
1111
- rrdhost_hostname(st->rrdhost), rrdset_id(st), rrddim_name(rd));
1114
+ else {
1115
+ error_limit_static_global_var(erl, 1, 0);
1116
+ error_limit(&erl, "PLUGINSD: 'host:%s/chart:%s/dim:%s' has the ARCHIVED flag set, but it is replicated. Ignoring data.",
1117
+ rrdhost_hostname(st->rrdhost), rrdset_id(st), rrddim_name(rd));
1118
+ }
1119
}
1120
1121
rrddim_acquired_release(rda);
@@ -1180,18 +1187,29 @@ PARSER_RC pluginsd_replay_rrdset_collection_state(char **words, size_t num_words
1187
1188
PARSER_RC pluginsd_replay_end(char **words, size_t num_words, void *user)
1189
{
1183
- if (num_words < 7) {
1190
+ if (num_words < 7) { // accepts 7, but the 7th is optional
1191
error("REPLAY: malformed " PLUGINSD_KEYWORD_REPLAY_END " command");
1192
return PARSER_RC_ERROR;
1193
}
1194
1188
- time_t update_every_child = str2l(get_word(words, num_words, 1));
1189
- time_t first_entry_child = (time_t)str2ull(get_word(words, num_words, 2));
1190
- time_t last_entry_child = (time_t)str2ull(get_word(words, num_words, 3));
1195
+ const char *update_every_child_txt = get_word(words, num_words, 1);
1196
+ const char *first_entry_child_txt = get_word(words, num_words, 2);
1197
+ const char *last_entry_child_txt = get_word(words, num_words, 3);
1198
+ const char *start_streaming_txt = get_word(words, num_words, 4);
1199
+ const char *first_entry_requested_txt = get_word(words, num_words, 5);
1200
+ const char *last_entry_requested_txt = get_word(words, num_words, 6);
1201
+ const char *child_world_time_txt = get_word(words, num_words, 7); // optional
1202
+
1203
+ time_t update_every_child = (time_t)str2ul(update_every_child_txt);
1204
+ time_t first_entry_child = (time_t)str2ul(first_entry_child_txt);
1205
+ time_t last_entry_child = (time_t)str2ul(last_entry_child_txt);
1206
1192
- bool start_streaming = (strcmp(get_word(words, num_words, 4), "true") == 0);
1193
- time_t first_entry_requested = (time_t)str2ull(get_word(words, num_words, 5));
1194
- time_t last_entry_requested = (time_t)str2ull(get_word(words, num_words, 6));
1207
+ bool start_streaming = (strcmp(start_streaming_txt, "true") == 0);
1208
+ time_t first_entry_requested = (time_t)str2ul(first_entry_requested_txt);
1209
+ time_t last_entry_requested = (time_t)str2ul(last_entry_requested_txt);
1210
+
1211
+ // the optional child world time
1212
+ time_t child_world_time = (child_world_time_txt && *child_world_time_txt) ? (time_t)str2ul(child_world_time_txt) : now_realtime_sec();
1213
1214
PARSER_USER_OBJECT *user_object = user;
1215
@@ -1201,13 +1219,15 @@ PARSER_RC pluginsd_replay_end(char **words, size_t num_words, void *user)
1219
RRDSET *st = pluginsd_require_chart_from_parent(user, PLUGINSD_KEYWORD_REPLAY_END, PLUGINSD_KEYWORD_REPLAY_BEGIN);
1220
if(!st) return PLUGINSD_DISABLE_PLUGIN(user);
1221
1204
-#ifdef NETDATATA_LOG_REPLICATION_REQUESTS
1222
+#ifdef NETDATA_LOG_REPLICATION_REQUESTS
1223
internal_error(true,
1206
- "PLUGINSD: 'host:%s/chart:%s': received " PLUGINSD_KEYWORD_REPLAY_END " child first_t = %llu, last_t = %llu, start_streaming = %s, requested first_t = %llu, last_t = %llu",
1224
+ "PLUGINSD REPLAY: 'host:%s/chart:%s': got a " PLUGINSD_KEYWORD_REPLAY_END " child db from %llu to %llu, start_streaming %s, had requested from %llu to %llu, wall clock %llu",
1225
rrdhost_hostname(host), rrdset_id(st),
1226
(unsigned long long)first_entry_child, (unsigned long long)last_entry_child,
1227
start_streaming?"true":"false",
1210
- (unsigned long long)first_entry_requested, (unsigned long long)last_entry_requested);
1228
+ (unsigned long long)first_entry_requested, (unsigned long long)last_entry_requested,
1229
+ (unsigned long long)child_world_time
1230
+ );
1231
#endif
1232
1233
((PARSER_USER_OBJECT *) user)->st = NULL;
@@ -1236,6 +1256,8 @@ PARSER_RC pluginsd_replay_end(char **words, size_t num_words, void *user)
1256
st->replay.start_streaming = false;
1257
st->replay.after = 0;
1258
st->replay.before = 0;
1259
+ if(start_streaming)
1260
+ st->replay.log_next_data_collection = true;
1261
#endif
1262
1263
if (start_streaming) {
@@ -1250,7 +1272,7 @@ PARSER_RC pluginsd_replay_end(char **words, size_t num_words, void *user)
1272
}
1273
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
1274
else
1253
- internal_error(true, "REPLAY: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_END " with enable_streaming = true, but there is no replication in progress for this chart.",
1275
+ internal_error(true, "REPLAY ERROR: 'host:%s/chart:%s' got a " PLUGINSD_KEYWORD_REPLAY_END " with enable_streaming = true, but there is no replication in progress for this chart.",
1276
rrdhost_hostname(host), rrdset_id(st));
1277
#endif
1278
worker_set_metric(WORKER_RECEIVER_JOB_REPLICATION_COMPLETION, 100.0);
@@ -1260,7 +1282,8 @@ PARSER_RC pluginsd_replay_end(char **words, size_t num_words, void *user)
1282
1283
rrdcontext_updated_retention_rrdset(st);
1284
1263
- bool ok = replicate_chart_request(send_to_plugin, user_object->parser, host, st, first_entry_child, last_entry_child,
1285
+ bool ok = replicate_chart_request(send_to_plugin, user_object->parser, host, st,
1286
+ first_entry_child, last_entry_child, child_world_time,
1287
first_entry_requested, last_entry_requested);
1288
return ok ? PARSER_RC_OK : PARSER_RC_ERROR;
1289
}
database/rrd.h
+2
@@ -673,6 +673,7 @@ struct rrdset {
673
674
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
675
struct {
676
+ bool log_next_data_collection;
677
bool start_streaming;
678
time_t after;
679
time_t before;
@@ -1078,6 +1079,7 @@ extern RRDHOST *localhost;
1079
#define rrdhost_sender_replicating_charts_minus_one(host) (__atomic_sub_fetch(&((host)->rrdpush_sender_replicating_charts), 1, __ATOMIC_RELAXED))
1080
#define rrdhost_sender_replicating_charts_zero(host) (__atomic_store_n(&((host)->rrdpush_sender_replicating_charts), 0, __ATOMIC_RELAXED))
1081
1082
+extern DICTIONARY *rrdhost_root_index;
1083
long rrdhost_hosts_available(void);
1084
1085
// ----------------------------------------------------------------------------
database/sqlite/sqlite_metadata.c
-2
@@ -2,8 +2,6 @@
2
3
#include "sqlite_metadata.h"
4
5
-extern DICTIONARY *rrdhost_root_index;
6
-
5
// SQL statements
6
7
#define SQL_STORE_CLAIM_ID "insert into node_instance " \
libnetdata/worker_utilization/worker_utilization.c
+4
-4
@@ -56,7 +56,7 @@ void worker_register(const char *workname) {
56
worker->tag = strdupz(netdata_thread_tag());
57
worker->workname = strdupz(workname);
58
59
- usec_t now = now_realtime_usec();
59
+ usec_t now = now_monotonic_usec();
60
worker->statistics_last_checkpoint = now;
61
worker->last_action_timestamp = now;
62
worker->last_action = WORKER_IDLE;
@@ -145,14 +145,14 @@ static inline void worker_is_idle_with_time(usec_t now) {
145
void worker_is_idle(void) {
146
if(unlikely(!worker || worker->last_action != WORKER_BUSY)) return;
147
148
- worker_is_idle_with_time(now_realtime_usec());
148
+ worker_is_idle_with_time(now_monotonic_usec());
149
}
150
151
void worker_is_busy(size_t job_id) {
152
if(unlikely(!worker || job_id >= WORKER_UTILIZATION_MAX_JOB_TYPES))
153
return;
154
155
- usec_t now = now_realtime_usec();
155
+ usec_t now = now_monotonic_usec();
156
157
if(worker->last_action == WORKER_BUSY)
158
worker_is_idle_with_time(now);
@@ -215,7 +215,7 @@ void workers_foreach(const char *workname, void (*callback)(
215
216
struct worker *p;
217
DOUBLE_LINKED_LIST_FOREACH_FORWARD(base, p, prev, next) {
218
- usec_t now = now_realtime_usec();
218
+ usec_t now = now_monotonic_usec();
219
220
// find per job type statistics
221
STRING *per_job_type_name[WORKER_UTILIZATION_MAX_JOB_TYPES];
streaming/replication.c
+279
-181
@@ -6,7 +6,10 @@
6
#define MAX_SENDER_BUFFER_PERCENTAGE_ALLOWED 20
7
#define MIN_SENDER_BUFFER_PERCENTAGE_ALLOWED 10
8
9
-static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, time_t before, bool enable_streaming) {
9
+// ----------------------------------------------------------------------------
10
+// sending replication replies
11
+
12
+static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, time_t before, bool enable_streaming, time_t wall_clock_time) {
13
size_t dimensions = rrdset_number_of_dimensions(st);
14
15
struct storage_engine_query_ops *ops = &st->rrdhost->db[0].eng->api.query_ops;
@@ -23,7 +26,7 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
26
memset(data, 0, sizeof(data));
27
28
if(enable_streaming && st->last_updated.tv_sec > before) {
26
- internal_error(true, "REPLAY: 'host:%s/chart:%s' overwriting replication before from %llu to %llu",
29
+ internal_error(true, "STREAM_SENDER REPLAY: 'host:%s/chart:%s' has start_streaming = true, adjusting replication before timestamp from %llu to %llu",
30
rrdhost_hostname(st->rrdhost), rrdset_id(st),
31
(unsigned long long)before,
32
(unsigned long long)st->last_updated.tv_sec
@@ -35,8 +38,11 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
38
{
39
RRDDIM *rd;
40
rrddim_foreach_read(rd, st) {
38
- if (rd_dfe.counter >= dimensions)
41
+ if (rd_dfe.counter >= dimensions) {
42
+ internal_error(true, "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s' has more dimensions than the replicated ones",
43
+ rrdhost_hostname(st->rrdhost), rrdset_id(st));
44
break;
45
+ }
46
47
if(rd->exposed) {
48
data[rd_dfe.counter].dict = rd_dfe.dict;
@@ -65,7 +71,7 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
71
data[i].sp = ops->next_metric(&data[i].handle);
72
73
internal_error(max_skip <= 0,
68
- "REPLAY: 'host:%s/chart:%s', dimension '%s': db does not advance the query beyond time %llu",
74
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s/dim:%s': db does not advance the query beyond time %llu",
75
rrdhost_hostname(st->rrdhost), rrdset_id(st), rrddim_id(data[i].rd), (unsigned long long) now);
76
77
if(data[i].sp.end_time < now)
@@ -81,10 +87,9 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
87
}
88
}
89
84
- time_t wall_clock_time = now_realtime_sec();
85
- if(min_start_time > wall_clock_time + 1 || min_end_time > wall_clock_time + 1) {
90
+ if(min_start_time > wall_clock_time + 1 || min_end_time > wall_clock_time + st->update_every + 1) {
91
internal_error(true,
87
- "REPLAY: 'host:%s/chart:%s': db provided future start time %llu or end time %llu (now is %llu)",
92
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s': db provided future start time %llu or end time %llu (now is %llu)",
93
rrdhost_hostname(st->rrdhost), rrdset_id(st),
94
(unsigned long long)min_start_time,
95
(unsigned long long)min_end_time,
@@ -95,7 +100,7 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
100
if(min_end_time < now) {
101
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
102
internal_error(true,
98
- "REPLAY: 'host:%s/chart:%s': no data on any dimension beyond time %llu",
103
+ "STREAM_SENDER REPLAY: 'host:%s/chart:%s': no data on any dimension beyond time %llu",
104
rrdhost_hostname(st->rrdhost), rrdset_id(st), (unsigned long long)now);
105
#endif // NETDATA_LOG_REPLICATION_REQUESTS
106
break;
@@ -138,14 +143,14 @@ static time_t replicate_chart_timeframe(BUFFER *wb, RRDSET *st, time_t after, ti
143
log_date(actual_after_buf, LOG_DATE_LENGTH, actual_after);
144
log_date(actual_before_buf, LOG_DATE_LENGTH, actual_before);
145
internal_error(true,
141
- "REPLAY: 'host:%s/chart:%s': sending data %llu [%s] to %llu [%s] (requested %llu [delta %lld] to %llu [delta %lld])",
146
+ "STREAM_SENDER REPLAY: 'host:%s/chart:%s': sending data %llu [%s] to %llu [%s] (requested %llu [delta %lld] to %llu [delta %lld])",
147
rrdhost_hostname(st->rrdhost), rrdset_id(st),
148
(unsigned long long)actual_after, actual_after_buf, (unsigned long long)actual_before, actual_before_buf,
149
(unsigned long long)after, (long long)(actual_after - after), (unsigned long long)before, (long long)(actual_before - before));
150
}
151
else
152
internal_error(true,
148
- "REPLAY: 'host:%s/chart:%s': nothing to send (requested %llu to %llu)",
153
+ "STREAM_SENDER REPLAY: 'host:%s/chart:%s': nothing to send (requested %llu to %llu)",
154
rrdhost_hostname(st->rrdhost), rrdset_id(st),
155
(unsigned long long)after, (unsigned long long)before);
156
#endif // NETDATA_LOG_REPLICATION_REQUESTS
@@ -195,7 +200,7 @@ bool replicate_chart_response(RRDHOST *host, RRDSET *st, bool start_streaming, t
200
time_t first_entry_local = rrdset_first_entry_t(st);
201
if(first_entry_local > now + tolerance) {
202
internal_error(true,
198
- "RRDSET: 'host:%s/chart:%s' first time %llu is in the future (now is %llu)",
203
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s' db first time %llu is in the future (now is %llu)",
204
rrdhost_hostname(st->rrdhost), rrdset_id(st),
205
(unsigned long long)first_entry_local, (unsigned long long)now);
206
first_entry_local = now;
@@ -208,14 +213,20 @@ bool replicate_chart_response(RRDHOST *host, RRDSET *st, bool start_streaming, t
213
time_t last_entry_local = st->last_updated.tv_sec;
214
if(!last_entry_local) {
215
internal_error(true,
211
- "RRDSET: 'host:%s/chart:%s' db reports last updated time zero.",
216
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s' RRDSET reports last updated time zero.",
217
rrdhost_hostname(st->rrdhost), rrdset_id(st));
218
last_entry_local = rrdset_last_entry_t(st);
219
+ if(!last_entry_local) {
220
+ internal_error(true,
221
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s' db reports last time zero.",
222
+ rrdhost_hostname(st->rrdhost), rrdset_id(st));
223
+ last_entry_local = now;
224
+ }
225
}
226
227
if(last_entry_local > now + tolerance) {
228
internal_error(true,
218
- "RRDSET: 'host:%s/chart:%s' last updated time %llu is in the future (now is %llu)",
229
+ "STREAM_SENDER REPLAY ERROR: 'host:%s/chart:%s' last updated time %llu is in the future (now is %llu)",
230
rrdhost_hostname(st->rrdhost), rrdset_id(st),
231
(unsigned long long)last_entry_local, (unsigned long long)now);
232
last_entry_local = now;
@@ -240,28 +251,49 @@ bool replicate_chart_response(RRDHOST *host, RRDSET *st, bool start_streaming, t
251
// and copying the result to the host's buffer in order to avoid
252
// holding the host's buffer lock for too long
253
BUFFER *wb = sender_start(host->sender);
243
- {
244
- // pass the original after/before so that the parent knows about
245
- // which time range we responded
246
- buffer_sprintf(wb, PLUGINSD_KEYWORD_REPLAY_BEGIN " \"%s\"\n", rrdset_id(st));
247
-
248
- if(after != 0 && before != 0)
249
- before = replicate_chart_timeframe(wb, st, query_after, query_before, enable_streaming);
250
- else {
251
- after = 0;
252
- before = 0;
253
- enable_streaming = true;
254
- }
254
256
- if(enable_streaming)
257
- replicate_chart_collection_state(wb, st);
255
+ buffer_sprintf(wb, PLUGINSD_KEYWORD_REPLAY_BEGIN " \"%s\"\n", rrdset_id(st));
256
259
- // end with first/last entries we have, and the first start time and
260
- // last end time of the data we sent
261
- buffer_sprintf(wb, PLUGINSD_KEYWORD_REPLAY_END " %d %llu %llu %s %llu %llu\n",
262
- (int)st->update_every, (unsigned long long)first_entry_local, (unsigned long long)last_entry_local,
263
- enable_streaming ? "true" : "false", (unsigned long long)after, (unsigned long long)before);
257
+ if(after != 0 && before != 0)
258
+ before = replicate_chart_timeframe(wb, st, query_after, query_before, enable_streaming, now);
259
+ else {
260
+ after = 0;
261
+ before = 0;
262
+ enable_streaming = true;
263
}
264
+
265
+ // get again the world clock time
266
+ time_t world_clock_time = now_realtime_sec();
267
+ if(enable_streaming) {
268
+ if(now < world_clock_time) {
269
+ // we needed time to execute this request
270
+ // so, the parent will need to replicate more data
271
+ enable_streaming = false;
272
+ }
273
+ else
274
+ replicate_chart_collection_state(wb, st);
275
+ }
276
+
277
+ // end with first/last entries we have, and the first start time and
278
+ // last end time of the data we sent
279
+ buffer_sprintf(wb, PLUGINSD_KEYWORD_REPLAY_END " %d %llu %llu %s %llu %llu %llu\n",
280
+
281
+ // current chart update every
282
+ (int)st->update_every
283
+
284
+ // child first db time, child end db time
285
+ , (unsigned long long)first_entry_local, (unsigned long long)last_entry_local
286
+
287
+ // start streaming boolean
288
+ , enable_streaming ? "true" : "false"
289
+
290
+ // after requested, before requested ('before' can be altered by the child when the request had enable_streaming true)
291
+ , (unsigned long long)after, (unsigned long long)before
292
+
293
+ // child world clock time
294
+ , (unsigned long long)world_clock_time
295
+ );
296
+
297
sender_commit(host->sender, wb);
298
299
return enable_streaming;
@@ -282,12 +314,14 @@ struct replication_request_details {
314
struct {
315
time_t first_entry_t; // the first entry time the child has
316
time_t last_entry_t; // the last entry time the child has
317
+ time_t world_time_t; // the current time of the child
318
} child_db;
319
320
struct {
321
time_t first_entry_t; // the first entry time we have
322
time_t last_entry_t; // the last entry time we have
323
bool last_entry_t_adjusted_to_now; // true, if the last entry time was in the future and we fixed
324
+ time_t now; // the current local world clock time
325
} local_db;
326
327
struct {
@@ -305,8 +339,6 @@ struct replication_request_details {
339
time_t before; // the end time of this replication request
340
bool start_streaming; // true when we want the child to send anything remaining and start streaming - the child will overwrite 'before'
341
} wanted;
308
-
309
- time_t now; // the current wall clock time
342
};
343
344
static bool send_replay_chart_cmd(struct replication_request_details *r, const char *msg __maybe_unused) {
@@ -316,6 +348,8 @@ static bool send_replay_chart_cmd(struct replication_request_details *r, const c
348
st->rrdhost->receiver->replication_first_time_t = r->wanted.after;
349
350
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
351
+ st->replay.log_next_data_collection = true;
352
+
353
char wanted_after_buf[LOG_DATE_LENGTH + 1] = "", wanted_before_buf[LOG_DATE_LENGTH + 1] = "";
354
355
if(r->wanted.after)
@@ -326,7 +360,7 @@ static bool send_replay_chart_cmd(struct replication_request_details *r, const c
360
361
internal_error(true,
362
"REPLAY: 'host:%s/chart:%s' sending replication request %ld [%s] to %ld [%s], start streaming '%s': %s: "
329
- "last[%ld - %ld] child[%ld - %ld] local[%ld - %ld %s] gap[%ld - %ld %s] %s"
363
+ "last[%ld - %ld] child[%ld - %ld, now %ld %s] local[%ld - %ld %s, now %ld] gap[%ld - %ld %s] %s"
364
, rrdhost_hostname(r->host), rrdset_id(r->st)
365
, r->wanted.after, wanted_after_buf
366
, r->wanted.before, wanted_before_buf
@@ -334,7 +368,9 @@ static bool send_replay_chart_cmd(struct replication_request_details *r, const c
368
, msg
369
, r->last_request.after, r->last_request.before
370
, r->child_db.first_entry_t, r->child_db.last_entry_t
337
- , r->local_db.first_entry_t, r->local_db.last_entry_t, r->local_db.last_entry_t_adjusted_to_now?"FIXED":"RAW"
371
+ , r->child_db.world_time_t, (r->child_db.world_time_t == r->local_db.now) ? "SAME" : (r->child_db.world_time_t < r->local_db.now) ? "BEHIND" : "AHEAD"
372
+ , r->local_db.first_entry_t, r->local_db.last_entry_t
373
+ , r->local_db.last_entry_t_adjusted_to_now?"FIXED":"RAW", r->local_db.now
374
, r->gap.from, r->gap.to
375
, (r->gap.from == r->wanted.after) ? "FULL" : "PARTIAL"
376
, (st->replay.after != 0 || st->replay.before != 0) ? "OVERLAPPING" : ""
@@ -352,7 +388,8 @@ static bool send_replay_chart_cmd(struct replication_request_details *r, const c
388
389
int ret = r->caller.callback(buffer, r->caller.data);
390
if (ret < 0) {
355
- error("REPLICATION: failed to send replication request to child (error %d)", ret);
391
+ error("REPLAY ERROR: 'host:%s/chart:%s' failed to send replication request to child (error %d)",
392
+ rrdhost_hostname(r->host), rrdset_id(r->st), ret);
393
return false;
394
}
395
@@ -360,7 +397,7 @@ static bool send_replay_chart_cmd(struct replication_request_details *r, const c
397
}
398
399
bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST *host, RRDSET *st,
363
- time_t first_entry_child, time_t last_entry_child,
400
+ time_t first_entry_child, time_t last_entry_child, time_t child_world_time,
401
time_t prev_first_entry_wanted, time_t prev_last_entry_wanted)
402
{
403
struct replication_request_details r = {
@@ -375,6 +412,14 @@ bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST
412
.child_db = {
413
.first_entry_t = first_entry_child,
414
.last_entry_t = last_entry_child,
415
+ .world_time_t = child_world_time,
416
+ },
417
+
418
+ .local_db = {
419
+ .first_entry_t = rrdset_first_entry_t(st),
420
+ .last_entry_t = rrdset_last_entry_t(st),
421
+ .last_entry_t_adjusted_to_now = false,
422
+ .now = now_realtime_sec(),
423
},
424
425
.last_request = {
@@ -387,15 +432,11 @@ bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST
432
.before = 0,
433
.start_streaming = true,
434
},
390
-
391
- .now = now_realtime_sec(),
435
};
436
394
- // get our local database retention
395
- r.local_db.first_entry_t = rrdset_first_entry_t(st);
396
- r.local_db.last_entry_t = rrdset_last_entry_t(st);
397
- if(r.local_db.last_entry_t > r.now) {
398
- r.local_db.last_entry_t = r.now;
437
+ // check our local database retention
438
+ if(r.local_db.last_entry_t > r.local_db.now) {
439
+ r.local_db.last_entry_t = r.local_db.now;
440
r.local_db.last_entry_t_adjusted_to_now = true;
441
}
442
@@ -408,7 +449,7 @@ bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST
449
r.gap.from = r.local_db.last_entry_t;
450
else
451
// we don't have any data, the gap is the max timeframe we are allowed to replicate
411
- r.gap.from = r.now - r.host->rrdpush_seconds_to_replicate;
452
+ r.gap.from = r.local_db.now - r.host->rrdpush_seconds_to_replicate;
453
454
}
455
else {
@@ -419,7 +460,7 @@ bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST
460
}
461
462
// we want all the data up to now
422
- r.gap.to = r.now;
463
+ r.gap.to = r.local_db.now;
464
465
// The gap is now r.gap.from -> r.gap.to
466
@@ -461,8 +502,11 @@ bool replicate_chart_request(send_command callback, void *callback_data, RRDHOST
502
if(r.wanted.before > r.child_db.last_entry_t)
503
r.wanted.before = r.child_db.last_entry_t;
504
464
- // the child should start streaming immediately if the wanted duration is small
465
- r.wanted.start_streaming = (r.wanted.before == r.child_db.last_entry_t);
505
+ if(r.wanted.after > r.wanted.before)
506
+ r.wanted.after = r.wanted.before;
507
+
508
+ // the child should start streaming immediately if the wanted duration is small or we reached the last entry of the child
509
+ r.wanted.start_streaming = (r.local_db.now - r.wanted.after <= host->rrdpush_replication_step || r.wanted.before == r.child_db.last_entry_t);
510
511
// the wanted timeframe is now r.wanted.after -> r.wanted.before
512
// send it
@@ -499,11 +543,12 @@ struct replication_sort_entry {
543
static struct replication_thread {
544
netdata_mutex_t mutex;
545
546
+ size_t pending;
547
size_t added;
548
size_t executed;
549
size_t removed;
550
+ size_t last_executed;
551
time_t first_time_t;
506
- size_t requests_count;
552
Word_t next_unique_id;
553
struct replication_request *requests;
554
@@ -516,12 +561,13 @@ static struct replication_thread {
561
size_t waits;
562
563
Pvoid_t JudyL_array;
519
-} rep = {
564
+} replication_globals = {
565
.mutex = NETDATA_MUTEX_INITIALIZER,
566
+ .pending = 0,
567
.added = 0,
568
.executed = 0,
569
+ .last_executed = 0,
570
.first_time_t = 0,
524
- .requests_count = 0,
571
.next_unique_id = 1,
572
.skipped_no_room = 0,
573
.skipped_not_connected = 0,
@@ -535,7 +581,7 @@ static __thread int replication_recursive_mutex_recursions = 0;
581
582
static void replication_recursive_lock() {
583
if(++replication_recursive_mutex_recursions == 1)
538
- netdata_mutex_lock(&rep.mutex);
584
+ netdata_mutex_lock(&replication_globals.mutex);
585
586
#ifdef NETDATA_INTERNAL_CHECKS
587
if(replication_recursive_mutex_recursions < 0 || replication_recursive_mutex_recursions > 2)
@@ -545,7 +591,7 @@ static void replication_recursive_lock() {
591
592
static void replication_recursive_unlock() {
593
if(--replication_recursive_mutex_recursions == 0)
548
- netdata_mutex_unlock(&rep.mutex);
594
+ netdata_mutex_unlock(&replication_globals.mutex);
595
596
#ifdef NETDATA_INTERNAL_CHECKS
597
if(replication_recursive_mutex_recursions < 0 || replication_recursive_mutex_recursions > 2)
@@ -563,7 +609,7 @@ static struct replication_sort_entry *replication_sort_entry_create(struct repli
609
610
// copy the request
611
rse->rq = rq;
566
- rse->unique_id = rep.next_unique_id++;
612
+ rse->unique_id = replication_globals.next_unique_id++;
613
614
// save the unique id into the request, to be able to delete it later
615
rq->unique_id = rse->unique_id;
@@ -580,29 +626,29 @@ static struct replication_sort_entry *replication_sort_entry_add(struct replicat
626
627
struct replication_sort_entry *rse = replication_sort_entry_create(rq);
628
583
- if(rq->after < (time_t)rep.last_after) {
629
+ if(rq->after < (time_t)replication_globals.last_after) {
630
// make it find this request first
585
- rep.last_after = rq->after;
586
- rep.last_unique_id = rq->unique_id;
631
+ replication_globals.last_after = rq->after;
632
+ replication_globals.last_unique_id = rq->unique_id;
633
}
634
589
- rep.added++;
590
- rep.requests_count++;
635
+ replication_globals.added++;
636
+ replication_globals.pending++;
637
638
Pvoid_t *inner_judy_ptr;
639
640
// find the outer judy entry, using after as key
595
- inner_judy_ptr = JudyLGet(rep.JudyL_array, (Word_t) rq->after, PJE0);
641
+ inner_judy_ptr = JudyLGet(replication_globals.JudyL_array, (Word_t) rq->after, PJE0);
642
if(!inner_judy_ptr)
597
- inner_judy_ptr = JudyLIns(&rep.JudyL_array, (Word_t) rq->after, PJE0);
643
+ inner_judy_ptr = JudyLIns(&replication_globals.JudyL_array, (Word_t) rq->after, PJE0);
644
645
// add it to the inner judy, using unique_id as key
646
Pvoid_t *item = JudyLIns(inner_judy_ptr, rq->unique_id, PJE0);
647
*item = rse;
648
rq->indexed_in_judy = true;
649
604
- if(!rep.first_time_t || rq->after < rep.first_time_t)
605
- rep.first_time_t = rq->after;
650
+ if(!replication_globals.first_time_t || rq->after < replication_globals.first_time_t)
651
+ replication_globals.first_time_t = rq->after;
652
653
replication_recursive_unlock();
654
@@ -612,8 +658,8 @@ static struct replication_sort_entry *replication_sort_entry_add(struct replicat
658
static bool replication_sort_entry_unlink_and_free_unsafe(struct replication_sort_entry *rse, Pvoid_t **inner_judy_ppptr) {
659
bool inner_judy_deleted = false;
660
615
- rep.removed++;
616
- rep.requests_count--;
661
+ replication_globals.removed++;
662
+ replication_globals.pending--;
663
664
rrdpush_sender_pending_replication_requests_minus_one(rse->rq->sender);
665
@@ -624,7 +670,7 @@ static bool replication_sort_entry_unlink_and_free_unsafe(struct replication_sor
670
671
// if no items left, delete it from the outer judy
672
if(**inner_judy_ppptr == NULL) {
627
- JudyLDel(&rep.JudyL_array, rse->rq->after, PJE0);
673
+ JudyLDel(&replication_globals.JudyL_array, rse->rq->after, PJE0);
674
inner_judy_deleted = true;
675
}
676
@@ -641,7 +687,7 @@ static void replication_sort_entry_del(struct replication_request *rq) {
687
replication_recursive_lock();
688
if(rq->indexed_in_judy) {
689
644
- inner_judy_pptr = JudyLGet(rep.JudyL_array, rq->after, PJE0);
690
+ inner_judy_pptr = JudyLGet(replication_globals.JudyL_array, rq->after, PJE0);
691
if (inner_judy_pptr) {
692
Pvoid_t *our_item_pptr = JudyLGet(*inner_judy_pptr, rq->unique_id, PJE0);
693
if (our_item_pptr) {
@@ -651,7 +697,7 @@ static void replication_sort_entry_del(struct replication_request *rq) {
697
}
698
699
if (!rse_to_delete)
654
- fatal("Cannot find sort entry to delete for host '%s', chart '%s', time %ld.",
700
+ fatal("REPLAY: 'host:%s/chart:%s' Cannot find sort entry to delete for time %ld.",
701
rrdhost_hostname(rq->sender->host), string2str(rq->chart_id), rq->after);
702
703
}
@@ -674,16 +720,16 @@ static struct replication_request replication_request_get_first_available() {
720
struct replication_request rq = (struct replication_request){ .found = false };
721
722
677
- if(unlikely(!rep.last_after || !rep.last_unique_id)) {
678
- rep.last_after = 0;
679
- rep.last_unique_id = 0;
723
+ if(unlikely(!replication_globals.last_after || !replication_globals.last_unique_id)) {
724
+ replication_globals.last_after = 0;
725
+ replication_globals.last_unique_id = 0;
726
}
727
728
bool find_same_after = true;
683
- while(!rq.found && (inner_judy_pptr = JudyLFirstOrNext(rep.JudyL_array, &rep.last_after, find_same_after))) {
729
+ while(!rq.found && (inner_judy_pptr = JudyLFirstOrNext(replication_globals.JudyL_array, &replication_globals.last_after, find_same_after))) {
730
Pvoid_t *our_item_pptr;
731
686
- while(!rq.found && (our_item_pptr = JudyLNext(*inner_judy_pptr, &rep.last_unique_id, PJE0))) {
732
+ while(!rq.found && (our_item_pptr = JudyLNext(*inner_judy_pptr, &replication_globals.last_unique_id, PJE0))) {
733
struct replication_sort_entry *rse = *our_item_pptr;
734
struct sender_state *s = rse->rq->sender;
735
@@ -697,7 +743,7 @@ static struct replication_request replication_request_get_first_available() {
743
s->buffer_used_percentage <= MAX_SENDER_BUFFER_PERCENTAGE_ALLOWED;
744
745
if(unlikely(!sender_is_connected || sender_has_been_flushed_since_this_request)) {
700
- rep.skipped_not_connected++;
746
+ replication_globals.skipped_not_connected++;
747
if(replication_sort_entry_unlink_and_free_unsafe(rse, &inner_judy_pptr))
748
break;
749
}
@@ -714,14 +760,14 @@ static struct replication_request replication_request_get_first_available() {
760
break;
761
}
762
else
717
- rep.skipped_no_room++;
763
+ replication_globals.skipped_no_room++;
764
}
765
766
// call JudyLNext from now on
767
find_same_after = false;
768
769
// prepare for the next iteration on the outer loop
724
- rep.last_unique_id = 0;
770
+ replication_globals.last_unique_id = 0;
771
}
772
773
replication_recursive_unlock();
@@ -756,64 +802,28 @@ static bool replication_request_conflict_callback(const DICTIONARY_ITEM *item __
802
struct replication_request *rq = old_value; (void)rq;
803
struct replication_request *rq_new = new_value;
804
759
- replication_recursive_lock();
760
-
761
- if(!rq->indexed_in_judy) {
762
- replication_sort_entry_add(rq);
763
- internal_error(
764
- true,
765
- "STREAM %s [send to %s]: REPLAY: 'host:%s/chart:%s' adding duplicate replication command received (existing from %llu to %llu [%s], new from %llu to %llu [%s])",
766
- rrdhost_hostname(s->host), s->connected_to, rrdhost_hostname(s->host), dictionary_acquired_item_name(item),
767
- (unsigned long long)rq->after, (unsigned long long)rq->before, rq->start_streaming ? "true" : "false",
768
- (unsigned long long)rq_new->after, (unsigned long long)rq_new->before, rq_new->start_streaming ? "true" : "false");
769
- }
770
- else
771
- internal_error(
772
- true,
773
- "STREAM %s [send to %s]: REPLAY: 'host:%s/chart:%s' ignoring duplicate replication command received (existing from %llu to %llu [%s], new from %llu to %llu [%s])",
774
- rrdhost_hostname(s->host), s->connected_to, rrdhost_hostname(s->host), dictionary_acquired_item_name(item),
775
- (unsigned long long)rq->after, (unsigned long long)rq->before, rq->start_streaming ? "true" : "false",
776
- (unsigned long long)rq_new->after, (unsigned long long)rq_new->before, rq_new->start_streaming ? "true" : "false");
805
+ replication_recursive_lock();
806
778
- replication_recursive_unlock();
807
+ if(!rq->indexed_in_judy) {
808
+ replication_sort_entry_add(rq);
809
+ internal_error(
810
+ true,
811
+ "STREAM %s [send to %s]: REPLAY: 'host:%s/chart:%s' adding duplicate replication command received (existing from %llu to %llu [%s], new from %llu to %llu [%s])",
812
+ rrdhost_hostname(s->host), s->connected_to, rrdhost_hostname(s->host), dictionary_acquired_item_name(item),
813
+ (unsigned long long)rq->after, (unsigned long long)rq->before, rq->start_streaming ? "true" : "false",
814
+ (unsigned long long)rq_new->after, (unsigned long long)rq_new->before, rq_new->start_streaming ? "true" : "false");
815
+ }
816
+ else {
817
+ internal_error(
818
+ true,
819
+ "STREAM %s [send to %s]: REPLAY: 'host:%s/chart:%s' ignoring duplicate replication command received (existing from %llu to %llu [%s], new from %llu to %llu [%s])",
820
+ rrdhost_hostname(s->host), s->connected_to, rrdhost_hostname(s->host),
821
+ dictionary_acquired_item_name(item),
822
+ (unsigned long long) rq->after, (unsigned long long) rq->before, rq->start_streaming ? "true" : "false",
823
+ (unsigned long long) rq_new->after, (unsigned long long) rq_new->before, rq_new->start_streaming ? "true" : "false");
824
+ }
825
780
-// bool updated_after = false, updated_before = false, updated_start_streaming = false, updated = false;
781
-//
782
-// if(rq_new->after < rq->after && rq_new->after != 0)
783
-// updated_after = true;
784
-//
785
-// if(rq_new->before > rq->before)
786
-// updated_before = true;
787
-//
788
-// if(rq_new->start_streaming != rq->start_streaming)
789
-// updated_start_streaming = true;
790
-//
791
-// if(updated_after || updated_before || updated_start_streaming) {
792
-// replication_recursive_lock();
793
-//
794
-// if(rq->indexed_in_judy)
795
-// replication_sort_entry_del(rq);
796
-//
797
-// if(rq_new->after < rq->after && rq_new->after != 0)
798
-// rq->after = rq_new->after;
799
-//
800
-// if(rq->after == 0)
801
-// rq->before = 0;
802
-// else if(rq_new->before > rq->before)
803
-// rq->before = rq_new->before;
804
-//
805
-// rq->start_streaming = rq->start_streaming;
806
-// replication_sort_entry_add(rq);
807
-//
808
-// replication_recursive_unlock();
809
-// updated = true;
810
-//
811
-// internal_error(
812
-// true,
813
-// "STREAM %s [send to %s]: REPLAY ERROR: updated duplicate replication command for chart '%s' (from %llu to %llu [%s])",
814
-// rrdhost_hostname(s->host), s->connected_to, dictionary_acquired_item_name(item),
815
-// (unsigned long long)rq->after, (unsigned long long)rq->before, rq->start_streaming ? "true" : "false");
816
-// }
826
+ replication_recursive_unlock();
827
828
string_freez(rq_new->chart_id);
829
return false;
@@ -880,9 +890,9 @@ void replication_recalculate_buffer_used_ratio_unsafe(struct sender_state *s) {
890
percentage <= MIN_SENDER_BUFFER_PERCENTAGE_ALLOWED) {
891
s->replication_reached_max = false;
892
replication_recursive_lock();
883
- rep.last_after = 0;
884
- rep.last_unique_id = 0;
885
- rep.sender_resets++;
893
+ replication_globals.last_after = 0;
894
+ replication_globals.last_unique_id = 0;
895
+ replication_globals.sender_resets++;
896
replication_recursive_unlock();
897
}
898
@@ -916,6 +926,79 @@ static void replication_main_cleanup(void *ptr) {
926
#define WORKER_JOB_CUSTOM_METRIC_SKIPPED_NO_ROOM 12
927
#define WORKER_JOB_CUSTOM_METRIC_SENDER_RESETS 13
928
#define WORKER_JOB_CUSTOM_METRIC_WAITS 14
929
+#define WORKER_JOB_CHECK_CONSISTENCY 15
930
+
931
+#define ITERATIONS_IDLE_WITHOUT_PENDING_TO_RUN_SENDER_VERIFICATION 10
932
+
933
+static size_t verify_host_charts_are_streaming_now(RRDHOST *host) {
934
+ if(host->sender) {
935
+ size_t pending_requests = host->sender->replication_pending_requests;
936
+ size_t dict_entries = dictionary_entries(host->sender->replication_requests);
937
+
938
+ internal_error(
939
+ !pending_requests && dict_entries,
940
+ "REPLICATION SUMMARY: 'host:%s' reports %zu pending replication requests, but its chart replication index says there are %zu charts pending replication",
941
+ rrdhost_hostname(host), pending_requests, dict_entries);
942
+ }
943
+
944
+ size_t ok = 0;
945
+ size_t errors = 0;
946
+
947
+ RRDSET *st;
948
+ rrdset_foreach_read(st, host) {
949
+ RRDSET_FLAGS flags = rrdset_flag_check(st, RRDSET_FLAG_SENDER_REPLICATION_IN_PROGRESS | RRDSET_FLAG_SENDER_REPLICATION_FINISHED);
950
+
951
+ bool is_error = false;
952
+
953
+ if(!flags) {
954
+ internal_error(
955
+ true,
956
+ "REPLICATION SUMMARY: 'host:%s/chart:%s' is neither IN PROGRESS nor FINISHED",
957
+ rrdhost_hostname(host), rrdset_id(st)
958
+ );
959
+ is_error = true;
960
+ }
961
+
962
+ if(!(flags & RRDSET_FLAG_SENDER_REPLICATION_FINISHED) || (flags & RRDSET_FLAG_SENDER_REPLICATION_IN_PROGRESS)) {
963
+ internal_error(
964
+ true,
965
+ "REPLICATION SUMMARY: 'host:%s/chart:%s' is IN PROGRESS although replication is finished",
966
+ rrdhost_hostname(host), rrdset_id(st)
967
+ );
968
+ is_error = true;
969
+ }
970
+
971
+ if(is_error)
972
+ errors++;
973
+ else
974
+ ok++;
975
+ }
976
+ rrdset_foreach_done(st);
977
+
978
+ internal_error(errors,
979
+ "REPLICATION SUMMARY: 'host:%s' finished replicating %zu charts, but %zu charts are still in progress although replication finished",
980
+ rrdhost_hostname(host), ok, errors);
981
+
982
+ return errors;
983
+}
984
+
985
+static void verify_all_hosts_charts_are_streaming_now(void) {
986
+#ifdef NETDATA_INTERNAL_CHECKS
987
+ worker_is_busy(WORKER_JOB_CHECK_CONSISTENCY);
988
+
989
+ size_t errors = 0;
990
+ RRDHOST *host;
991
+ dfe_start_reentrant(rrdhost_root_index, host)
992
+ errors += verify_host_charts_are_streaming_now(host);
993
+ dfe_done(host);
994
+
995
+ size_t executed = replication_globals.executed;
996
+ internal_error(true, "REPLICATION SUMMARY: finished, executed %zu replication requests, %zu charts pending replication", executed - replication_globals.last_executed, errors);
997
+ replication_globals.last_executed = executed;
998
+#else
999
+ ;
1000
+#endif
1001
+}
1002
1003
void *replication_thread_main(void *ptr __maybe_unused) {
1004
netdata_thread_cleanup_push(replication_main_cleanup, ptr);
@@ -927,6 +1010,8 @@ void *replication_thread_main(void *ptr __maybe_unused) {
1010
worker_register_job_name(WORKER_JOB_DELETE_ENTRY, "dict delete");
1011
worker_register_job_name(WORKER_JOB_FIND_CHART, "find chart");
1012
worker_register_job_name(WORKER_JOB_ACTIVATE_ENABLE_STREAMING, "enable streaming");
1013
+ worker_register_job_name(WORKER_JOB_CHECK_CONSISTENCY, "check consistency");
1014
+ worker_register_job_name(WORKER_JOB_STATISTICS, "statistics");
1015
1016
worker_register_job_custom_metric(WORKER_JOB_CUSTOM_METRIC_PENDING_REQUESTS, "pending requests", "requests", WORKER_METRIC_ABSOLUTE);
1017
worker_register_job_custom_metric(WORKER_JOB_CUSTOM_METRIC_COMPLETION, "completion", "%", WORKER_METRIC_ABSOLUTE);
@@ -937,62 +1022,75 @@ void *replication_thread_main(void *ptr __maybe_unused) {
1022
worker_register_job_custom_metric(WORKER_JOB_CUSTOM_METRIC_SENDER_RESETS, "sender resets", "resets/s", WORKER_METRIC_INCREMENTAL_TOTAL);
1023
worker_register_job_custom_metric(WORKER_JOB_CUSTOM_METRIC_WAITS, "waits", "waits/s", WORKER_METRIC_INCREMENTAL_TOTAL);
1024
1025
+ // start from 100% completed
1026
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_COMPLETION, 100.0);
1027
+
1028
time_t latest_first_time_t = 0;
1029
+ long run_verification_countdown = LONG_MAX; // LONG_MAX to prevent an initial verification when no replication ever took place
1030
+ usec_t last_now_mono_ut = now_monotonic_usec();
1031
1032
while(!netdata_exit) {
943
- worker_is_busy(WORKER_JOB_FIND_NEXT);
944
- struct replication_request rq = replication_request_get_first_available();
1033
946
- worker_is_busy(WORKER_JOB_STATISTICS);
947
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_PENDING_REQUESTS, (NETDATA_DOUBLE)rep.requests_count);
948
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_ADDED, (NETDATA_DOUBLE)rep.added);
949
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_DONE, (NETDATA_DOUBLE)rep.executed);
950
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SKIPPED_NOT_CONNECTED, (NETDATA_DOUBLE)rep.skipped_not_connected);
951
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SKIPPED_NO_ROOM, (NETDATA_DOUBLE)rep.skipped_no_room);
952
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SENDER_RESETS, (NETDATA_DOUBLE)rep.sender_resets);
953
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_WAITS, (NETDATA_DOUBLE)rep.waits);
954
-
955
- if(latest_first_time_t) {
956
- time_t now = now_realtime_sec();
957
- time_t total = now - rep.first_time_t;
958
- time_t done = latest_first_time_t - rep.first_time_t;
959
- worker_set_metric(WORKER_JOB_CUSTOM_METRIC_COMPLETION, (NETDATA_DOUBLE)done * 100.0 / (NETDATA_DOUBLE)total);
960
- }
1034
+ // statistics
1035
+ usec_t now_mono_ut = now_monotonic_usec();
1036
+ if(unlikely(now_mono_ut - last_now_mono_ut > default_rrd_update_every * USEC_PER_SEC)) {
1037
+ last_now_mono_ut = now_mono_ut;
1038
962
- if(unlikely(!rq.found)) {
963
- worker_is_idle();
1039
+ if(!replication_globals.pending && run_verification_countdown-- == 0) {
1040
+ replication_globals.first_time_t = 0; // reset the statistics about completion percentage
1041
+ verify_all_hosts_charts_are_streaming_now();
1042
+ }
1043
965
- if(!rep.requests_count)
1044
+ worker_is_busy(WORKER_JOB_STATISTICS);
1045
+
1046
+ if(latest_first_time_t && replication_globals.pending) {
1047
+ // completion percentage statistics
1048
+ time_t now = now_realtime_sec();
1049
+ time_t total = now - replication_globals.first_time_t;
1050
+ time_t done = latest_first_time_t - replication_globals.first_time_t;
1051
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_COMPLETION,
1052
+ (NETDATA_DOUBLE) done * 100.0 / (NETDATA_DOUBLE) total);
1053
+ }
1054
+ else
1055
worker_set_metric(WORKER_JOB_CUSTOM_METRIC_COMPLETION, 100.0);
1056
968
- // make it start from the beginning
969
- rep.last_after = 0;
970
- rep.last_unique_id = 0;
1057
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_PENDING_REQUESTS, (NETDATA_DOUBLE)replication_globals.pending);
1058
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_ADDED, (NETDATA_DOUBLE)replication_globals.added);
1059
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_DONE, (NETDATA_DOUBLE)replication_globals.executed);
1060
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SKIPPED_NOT_CONNECTED, (NETDATA_DOUBLE)replication_globals.skipped_not_connected);
1061
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SKIPPED_NO_ROOM, (NETDATA_DOUBLE)replication_globals.skipped_no_room);
1062
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_SENDER_RESETS, (NETDATA_DOUBLE)replication_globals.sender_resets);
1063
+ worker_set_metric(WORKER_JOB_CUSTOM_METRIC_WAITS, (NETDATA_DOUBLE)replication_globals.waits);
1064
+ }
1065
+
1066
+ worker_is_busy(WORKER_JOB_FIND_NEXT);
1067
+ struct replication_request rq = replication_request_get_first_available();
1068
972
- rep.waits++;
1069
+ if(unlikely(!rq.found)) {
1070
+ // make it scan all the pending requests next time
1071
+ replication_globals.last_after = 0;
1072
+ replication_globals.last_unique_id = 0;
1073
974
- sleep_usec(1000 * USEC_PER_MS);
1074
+ replication_globals.waits++;
1075
+
1076
+ worker_is_idle();
1077
+ sleep_usec(((replication_globals.pending) ? 10 : 1000) * USEC_PER_MS);
1078
continue;
1079
}
977
- else {
978
- // delete the request from the dictionary
979
- worker_is_busy(WORKER_JOB_DELETE_ENTRY);
980
- if(!dictionary_del(rq.sender->replication_requests, string2str(rq.chart_id)))
981
- error("REPLAY: 'host:%s/chart:%s' failed to be deleted from sender dictionary",
982
- rrdhost_hostname(rq.sender->host), string2str(rq.chart_id));
983
-
984
- if(rq.sender->replication_pending_requests == 0 && dictionary_entries(rq.sender->replication_requests) != 0)
985
- error("REPLAY: 'host:%s/chart:%s' sender dictionary has %zu entries, but sender pending requests are %zu",
986
- rrdhost_hostname(rq.sender->host), string2str(rq.chart_id),
987
- dictionary_entries(rq.sender->replication_requests),
988
- rq.sender->replication_pending_requests);
989
- }
1080
+
1081
+ run_verification_countdown = ITERATIONS_IDLE_WITHOUT_PENDING_TO_RUN_SENDER_VERIFICATION;
1082
+
1083
+ // delete the request from the dictionary
1084
+ worker_is_busy(WORKER_JOB_DELETE_ENTRY);
1085
+ if(!dictionary_del(rq.sender->replication_requests, string2str(rq.chart_id)))
1086
+ error("REPLAY ERROR: 'host:%s/chart:%s' failed to be deleted from sender pending charts index",
1087
+ rrdhost_hostname(rq.sender->host), string2str(rq.chart_id));
1088
1089
worker_is_busy(WORKER_JOB_FIND_CHART);
1090
RRDSET *st = rrdset_find(rq.sender->host, string2str(rq.chart_id));
1091
if(!st) {
994
- internal_error(true, "REPLAY ERROR: chart '%s' not found on host '%s'",
995
- string2str(rq.chart_id), rrdhost_hostname(rq.sender->host));
1092
+ internal_error(true, "REPLAY ERROR: 'host:%s/chart:%s' not found",
1093
+ rrdhost_hostname(rq.sender->host), string2str(rq.chart_id));
1094
1095
continue;
1096
}
@@ -1010,12 +1108,12 @@ void *replication_thread_main(void *ptr __maybe_unused) {
1108
netdata_thread_disable_cancelability();
1109
1110
// send the replication data
1013
- bool start_streaming = replicate_chart_response(st->rrdhost, st,
1014
- rq.start_streaming, rq.after, rq.before);
1111
+ bool start_streaming = replicate_chart_response(
1112
+ st->rrdhost, st, rq.start_streaming, rq.after, rq.before);
1113
1114
netdata_thread_enable_cancelability();
1115
1018
- rep.executed++;
1116
+ replication_globals.executed++;
1117
1118
if(start_streaming && rq.sender_last_flush_ut == rrdpush_sender_get_flush_time(rq.sender)) {
1119
worker_is_busy(WORKER_JOB_ACTIVATE_ENABLE_STREAMING);
@@ -1034,8 +1132,8 @@ void *replication_thread_main(void *ptr __maybe_unused) {
1132
#endif
1133
}
1134
else
1037
- internal_error(true, "REPLAY ERROR: received start streaming command for chart '%s' or host '%s', but the chart is not in progress replicating",
1038
- string2str(rq.chart_id), rrdhost_hostname(st->rrdhost));
1135
+ internal_error(true, "REPLAY ERROR: 'host:%s/chart:%s' received start streaming command, but the chart is not in progress replicating",
1136
+ rrdhost_hostname(st->rrdhost), string2str(rq.chart_id));
1137
}
1138
1139
string_freez(rq.chart_id);
streaming/replication.h
+1
-1
@@ -11,7 +11,7 @@ typedef int (*send_command)(const char *txt, void *data);
11
12
bool replicate_chart_request(send_command callback, void *callback_data,
13
RRDHOST *rh, RRDSET *rs,
14
- time_t first_entry_child, time_t last_entry_child,
14
+ time_t first_entry_child, time_t last_entry_child, time_t child_world_time,
15
time_t response_first_start_time, time_t response_last_end_time);
16
17
void replication_init_sender(struct sender_state *sender);
streaming/rrdpush.c
+40
-20
@@ -223,7 +223,9 @@ static void rrdpush_send_clabels(BUFFER *wb, RRDSET *st) {
223
224
// Send the current chart definition.
225
// Assumes that collector thread has already called sender_start for mutex / buffer state.
226
-static inline void rrdpush_send_chart_definition(BUFFER *wb, RRDSET *st) {
226
+static inline bool rrdpush_send_chart_definition(BUFFER *wb, RRDSET *st) {
227
+ bool replication_progress = false;
228
+
229
RRDHOST *host = st->rrdhost;
230
231
rrdset_flag_set(st, RRDSET_FLAG_UPSTREAM_EXPOSED);
@@ -296,29 +298,43 @@ static inline void rrdpush_send_chart_definition(BUFFER *wb, RRDSET *st) {
298
time_t first_entry_local = rrdset_first_entry_t_of_tier(st, 0);
299
time_t last_entry_local = st->last_updated.tv_sec;
300
299
- if(!last_entry_local) {
301
+ if(unlikely(!last_entry_local))
302
+ last_entry_local = rrdset_last_entry_t(st);
303
+
304
+ time_t now = now_realtime_sec();
305
+ if(unlikely(last_entry_local > now)) {
306
internal_error(true,
301
- "RRDSET: 'host:%s/chart:%s' db reports last updated time zero.",
302
- rrdhost_hostname(st->rrdhost), rrdset_id(st));
307
+ "RRDSET REPLAY ERROR: 'host:%s/chart:%s' last updated time %ld is in the future, adjusting it to now %ld",
308
+ rrdhost_hostname(st->rrdhost), rrdset_id(st),
309
+ last_entry_local, now);
310
+ last_entry_local = now;
311
+ }
312
304
- last_entry_local = rrdset_last_entry_t(st);
305
- time_t now = now_realtime_sec();
306
-
307
- if(last_entry_local > now) {
308
- internal_error(true,
309
- "RRDSET: 'host:%s/chart:%s' last updated time %llu is in the future (now is %llu)",
310
- rrdhost_hostname(st->rrdhost), rrdset_id(st),
311
- (unsigned long long)last_entry_local, (unsigned long long)now);
312
- last_entry_local = now;
313
- }
313
+ if(unlikely(first_entry_local && last_entry_local && first_entry_local >= last_entry_local)) {
314
+ internal_error(true,
315
+ "RRDSET REPLAY ERROR: 'host:%s/chart:%s' first updated time %ld is equal or bigger than last updated time %ld, adjusting it last updated time - update every",
316
+ rrdhost_hostname(st->rrdhost), rrdset_id(st),
317
+ first_entry_local, last_entry_local);
318
+ first_entry_local = last_entry_local - st->update_every;
319
+ }
320
+
321
+ if(unlikely(!first_entry_local && last_entry_local)) {
322
+ internal_error(true,
323
+ "RRDSET REPLAY ERROR: 'host:%s/chart:%s' first time %ld, last time %ld, setting both to last time",
324
+ rrdhost_hostname(st->rrdhost), rrdset_id(st),
325
+ first_entry_local, last_entry_local);
326
+ first_entry_local = last_entry_local;
327
}
328
316
- buffer_sprintf(wb, PLUGINSD_KEYWORD_CHART_DEFINITION_END " %llu %llu\n",
317
- (unsigned long long)first_entry_local, (unsigned long long)last_entry_local);
329
+ buffer_sprintf(wb, PLUGINSD_KEYWORD_CHART_DEFINITION_END " %llu %llu %llu\n",
330
+ (unsigned long long)first_entry_local,
331
+ (unsigned long long)last_entry_local,
332
+ (unsigned long long)now);
333
334
rrdset_flag_set(st, RRDSET_FLAG_SENDER_REPLICATION_IN_PROGRESS);
335
rrdset_flag_clear(st, RRDSET_FLAG_SENDER_REPLICATION_FINISHED);
336
rrdhost_sender_replicating_charts_plus_one(st->rrdhost);
337
+ replication_progress = true;
338
339
#ifdef NETDATA_LOG_REPLICATION_REQUESTS
340
internal_error(true, "REPLAY: 'host:%s/chart:%s' replication starts",
@@ -327,6 +343,7 @@ static inline void rrdpush_send_chart_definition(BUFFER *wb, RRDSET *st) {
343
}
344
345
st->upstream_resync_time = st->last_collected_time.tv_sec + (remote_clock_resync_iterations * st->update_every);
346
+ return replication_progress;
347
}
348
349
// sends the current chart dimensions
@@ -411,16 +428,19 @@ void rrdset_done_push(RRDSET *st) {
428
}
429
430
RRDSET_FLAGS rrdset_flags = __atomic_load_n(&st->flags, __ATOMIC_SEQ_CST);
431
+ bool exposed_upstream = (rrdset_flags & RRDSET_FLAG_UPSTREAM_EXPOSED);
432
+ bool replication_in_progress = !(rrdset_flags & RRDSET_FLAG_SENDER_REPLICATION_FINISHED);
433
415
- if(unlikely(!should_send_chart_matching(st, rrdset_flags)))
434
+ if(unlikely((exposed_upstream && replication_in_progress) ||
435
+ !should_send_chart_matching(st, rrdset_flags)))
436
return;
437
438
BUFFER *wb = sender_start(host->sender);
439
420
- if(unlikely(!(rrdset_flags & RRDSET_FLAG_UPSTREAM_EXPOSED)))
421
- rrdpush_send_chart_definition(wb, st);
440
+ if(unlikely(!exposed_upstream))
441
+ replication_in_progress = rrdpush_send_chart_definition(wb, st);
442
423
- if (likely(rrdset_flags & RRDSET_FLAG_SENDER_REPLICATION_FINISHED))
443
+ if (likely(!replication_in_progress))
444
rrdpush_send_chart_metrics(wb, st, host->sender, rrdset_flags);
445
446
sender_commit(host->sender, wb);