1/*
2 * ticker.c
3 *
4 * Copyright (C) 2016-2019 Aerospike, Inc.
5 *
6 * Portions may be licensed to Aerospike, Inc. under one or more contributor
7 * license agreements.
8 *
9 * This program is free software: you can redistribute it and/or modify it under
10 * the terms of the GNU Affero General Public License as published by the Free
11 * Software Foundation, either version 3 of the License, or (at your option) any
12 * later version.
13 *
14 * This program is distributed in the hope that it will be useful, but WITHOUT
15 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
16 * FOR A PARTICULAR PURPOSE. See the GNU Affero General Public License for more
17 * details.
18 *
19 * You should have received a copy of the GNU Affero General Public License
20 * along with this program. If not, see http://www.gnu.org/licenses/
21 */
22
23//==========================================================
24// Includes.
25//
26
27#include "base/ticker.h"
28
29#include <malloc.h>
30#include <mcheck.h>
31#include <stdbool.h>
32#include <stddef.h>
33#include <stdint.h>
34#include <stdio.h>
35#include <sys/param.h>
36#include <unistd.h>
37
38#include "citrusleaf/alloc.h"
39#include "citrusleaf/cf_atomic.h"
40#include "citrusleaf/cf_clock.h"
41
42#include "cf_thread.h"
43#include "dynbuf.h"
44#include "fault.h"
45#include "hist.h"
46#include "hist_track.h"
47
48#include "base/cfg.h"
49#include "base/datamodel.h"
50#include "base/index.h"
51#include "base/secondary_index.h"
52#include "base/stats.h"
53#include "base/thr_info.h"
54#include "base/thr_sindex.h"
55#include "base/thr_tsvc.h"
56#include "fabric/clustering.h"
57#include "fabric/exchange.h"
58#include "fabric/fabric.h"
59#include "fabric/hb.h"
60#include "fabric/partition.h"
61#include "fabric/skew_monitor.h"
62#include "storage/storage.h"
63#include "transaction/proxy.h"
64#include "transaction/rw_request_hash.h"
65
66
67//==========================================================
68// Forward declarations.
69//
70
71extern bool g_shutdown_started;
72
73void* run_ticker(void* arg);
74void log_ticker_frame(uint64_t delta_time);
75
76void log_line_clock();
77void log_line_system();
78void log_line_process();
79void log_line_in_progress();
80void log_line_fds();
81void log_line_heartbeat();
82void log_fabric_rate(uint64_t delta_time);
83void log_line_early_fail();
84void log_line_batch_index();
85
86void log_line_objects(as_namespace* ns, uint64_t n_objects,
87 repl_stats* mp);
88void log_line_tombstones(as_namespace* ns, uint64_t n_tombstones,
89 repl_stats* mp);
90void log_line_appeals(as_namespace* ns);
91void log_line_migrations(as_namespace* ns);
92void log_line_memory_usage(as_namespace* ns, size_t total_mem, size_t index_mem,
93 size_t sindex_mem, size_t data_mem);
94void log_line_persistent_index_usage(as_namespace* ns, size_t used_size);
95void log_line_device_usage(as_namespace* ns);
96
97void log_line_client(as_namespace* ns);
98void log_line_xdr_client(as_namespace* ns);
99void log_line_from_proxy(as_namespace* ns);
100void log_line_xdr_from_proxy(as_namespace* ns);
101void log_line_batch_sub(as_namespace* ns);
102void log_line_from_proxy_batch_sub(as_namespace* ns);
103void log_line_scan(as_namespace* ns);
104void log_line_query(as_namespace* ns);
105void log_line_udf_sub(as_namespace* ns);
106void log_line_ops_sub(as_namespace* ns);
107void log_line_retransmits(as_namespace* ns);
108void log_line_re_repl(as_namespace* ns);
109void log_line_special_errors(as_namespace* ns);
110
111void dump_global_histograms();
112void dump_namespace_histograms(as_namespace* ns);
113
114
115//==========================================================
116// Public API.
117//
118
119void
120as_ticker_start()
121{
122 cf_thread_create_detached(run_ticker, NULL);
123}
124
125
126//==========================================================
127// Local helpers.
128//
129
130void*
131run_ticker(void* arg)
132{
133 // Initialize times used to calculate CPU usage.
134 sys_cpu_info(NULL, NULL);
135 process_cpu();
136
137 uint64_t last_time = cf_getns();
138
139 while (true) {
140 sleep(1); // wake up every second to check
141
142 uint64_t curr_time = cf_getns();
143 uint64_t delta_time = curr_time - last_time;
144
145 if (delta_time < (uint64_t)g_config.ticker_interval * 1000000000) {
146 continue;
147 }
148
149 last_time = curr_time;
150
151 // Reduce likelihood of ticker frames showing after shutdown signal.
152 if (g_shutdown_started) {
153 break;
154 }
155
156 log_ticker_frame(delta_time);
157 }
158
159 return NULL;
160}
161
162void
163log_ticker_frame(uint64_t delta_time)
164{
165 cf_info(AS_INFO, "NODE-ID %lx CLUSTER-SIZE %u",
166 g_config.self_node,
167 as_exchange_cluster_size()
168 );
169
170 log_line_clock();
171 log_line_system();
172 log_line_process();
173 log_line_in_progress();
174 log_line_fds();
175 log_line_heartbeat();
176 log_fabric_rate(delta_time);
177 log_line_early_fail();
178 log_line_batch_index();
179
180 dump_global_histograms();
181
182 size_t total_ns_memory_inuse = 0;
183
184 for (int i = 0; i < g_config.n_namespaces; i++) {
185 as_namespace* ns = g_config.namespaces[i];
186
187 uint64_t n_objects = ns->n_objects;
188 uint64_t n_tombstones = ns->n_tombstones;
189
190 size_t index_used = (n_objects + n_tombstones) * sizeof(as_index);
191
192 size_t index_mem = as_namespace_index_persisted(ns) ? 0 : index_used;
193 size_t sindex_mem = ns->n_bytes_sindex_memory;
194 size_t data_mem = ns->n_bytes_memory;
195 size_t total_mem = index_mem + sindex_mem + data_mem;
196
197 total_ns_memory_inuse += total_mem;
198
199 repl_stats mp;
200 as_partition_get_replica_stats(ns, &mp);
201
202 log_line_objects(ns, n_objects, &mp);
203 log_line_tombstones(ns, n_tombstones, &mp);
204 log_line_appeals(ns);
205 log_line_migrations(ns);
206 log_line_memory_usage(ns, total_mem, index_mem, sindex_mem, data_mem);
207 log_line_persistent_index_usage(ns, index_used);
208 log_line_device_usage(ns);
209
210 log_line_client(ns);
211 log_line_xdr_client(ns);
212 log_line_from_proxy(ns);
213 log_line_xdr_from_proxy(ns);
214 log_line_batch_sub(ns);
215 log_line_from_proxy_batch_sub(ns);
216 log_line_scan(ns);
217 log_line_query(ns);
218 log_line_udf_sub(ns);
219 log_line_ops_sub(ns);
220 log_line_retransmits(ns);
221 log_line_re_repl(ns);
222 log_line_special_errors(ns);
223
224 dump_namespace_histograms(ns);
225 }
226
227 if (g_config.fabric_dump_msgs) {
228 as_fabric_msg_queue_dump();
229 }
230
231 cf_dump_ticker_cache();
232}
233
234void
235log_line_clock()
236{
237 cf_dyn_buf_define_size(outliers_db, 17 * AS_CLUSTER_SZ);
238 uint32_t num_outliers = as_skew_monitor_outliers_append(&outliers_db);
239
240 if (num_outliers != 0) {
241 cf_dyn_buf_append_char(&outliers_db, 0);
242
243 cf_info(AS_INFO, " cluster-clock: skew-ms %lu outliers (%s)",
244 as_skew_monitor_skew(),
245 outliers_db.buf
246 );
247 }
248 else {
249 cf_info(AS_INFO, " cluster-clock: skew-ms %lu",
250 as_skew_monitor_skew()
251 );
252 }
253
254 cf_dyn_buf_free(&outliers_db);
255}
256
257void
258log_line_system()
259{
260 uint32_t user_pct;
261 uint32_t kernel_pct;
262
263 sys_cpu_info(&user_pct, &kernel_pct);
264
265 uint64_t free_mem;
266 uint32_t free_pct;
267
268 sys_mem_info(&free_mem, &free_pct);
269
270 cf_info(AS_INFO, " system: total-cpu-pct %u user-cpu-pct %u kernel-cpu-pct %u free-mem-kbytes %lu free-mem-pct %d",
271 user_pct + kernel_pct, user_pct, kernel_pct,
272 free_mem / 1024,
273 free_pct
274 );
275}
276
277void
278log_line_process()
279{
280 size_t allocated_kbytes;
281 size_t active_kbytes;
282 size_t mapped_kbytes;
283 double efficiency_pct;
284
285 cf_alloc_heap_stats(&allocated_kbytes, &active_kbytes, &mapped_kbytes,
286 &efficiency_pct, NULL);
287
288 cf_info(AS_INFO, " process: cpu-pct %u heap-kbytes (%lu,%lu,%lu) heap-efficiency-pct %.1lf",
289 process_cpu(),
290 allocated_kbytes, active_kbytes, mapped_kbytes,
291 efficiency_pct
292 );
293}
294
295void
296log_line_in_progress()
297{
298 cf_info(AS_INFO, " in-progress: info-q %d rw-hash %u proxy-hash %u tree-gc-q %d",
299 as_info_queue_get_size(),
300 rw_request_hash_count(),
301 as_proxy_hash_count(),
302 as_index_tree_gc_queue_size()
303 );
304}
305
306void
307log_line_fds()
308{
309 uint64_t n_proto_fds_opened = g_stats.proto_connections_opened;
310 uint64_t n_proto_fds_closed = g_stats.proto_connections_closed;
311 uint64_t n_hb_fds_opened = g_stats.heartbeat_connections_opened;
312 uint64_t n_hb_fds_closed = g_stats.heartbeat_connections_closed;
313 uint64_t n_fabric_fds_opened = g_stats.fabric_connections_opened;
314 uint64_t n_fabric_fds_closed = g_stats.fabric_connections_closed;
315
316 uint64_t n_proto_fds_open = n_proto_fds_opened - n_proto_fds_closed;
317 uint64_t n_hb_fds_open = n_hb_fds_opened - n_hb_fds_closed;
318 uint64_t n_fabric_fds_open = n_fabric_fds_opened - n_fabric_fds_closed;
319
320 cf_info(AS_INFO, " fds: proto (%lu,%lu,%lu) heartbeat (%lu,%lu,%lu) fabric (%lu,%lu,%lu)",
321 n_proto_fds_open, n_proto_fds_opened, n_proto_fds_closed,
322 n_hb_fds_open, n_hb_fds_opened, n_hb_fds_closed,
323 n_fabric_fds_open, n_fabric_fds_opened, n_fabric_fds_closed
324 );
325}
326
327void
328log_line_heartbeat()
329{
330 cf_info(AS_INFO, " heartbeat-received: self %lu foreign %lu",
331 g_stats.heartbeat_received_self, g_stats.heartbeat_received_foreign
332 );
333}
334
335void
336log_fabric_rate(uint64_t delta_time)
337{
338 fabric_rate rate = { { 0 } };
339
340 as_fabric_rate_capture(&rate);
341
342 uint64_t dt_sec = delta_time / 1000000000;
343
344 if (dt_sec < 1) {
345 dt_sec = 1;
346 }
347
348 g_stats.fabric_bulk_s_rate = rate.s_bytes[AS_FABRIC_CHANNEL_BULK] / dt_sec;
349 g_stats.fabric_bulk_r_rate = rate.r_bytes[AS_FABRIC_CHANNEL_BULK] / dt_sec;
350 g_stats.fabric_ctrl_s_rate = rate.s_bytes[AS_FABRIC_CHANNEL_CTRL] / dt_sec;
351 g_stats.fabric_ctrl_r_rate = rate.r_bytes[AS_FABRIC_CHANNEL_CTRL] / dt_sec;
352 g_stats.fabric_meta_s_rate = rate.s_bytes[AS_FABRIC_CHANNEL_META] / dt_sec;
353 g_stats.fabric_meta_r_rate = rate.r_bytes[AS_FABRIC_CHANNEL_META] / dt_sec;
354 g_stats.fabric_rw_s_rate = rate.s_bytes[AS_FABRIC_CHANNEL_RW] / dt_sec;
355 g_stats.fabric_rw_r_rate = rate.r_bytes[AS_FABRIC_CHANNEL_RW] / dt_sec;
356
357 cf_info(AS_INFO, " fabric-bytes-per-second: bulk (%lu,%lu) ctrl (%lu,%lu) meta (%lu,%lu) rw (%lu,%lu)",
358 g_stats.fabric_bulk_s_rate, g_stats.fabric_bulk_r_rate,
359 g_stats.fabric_ctrl_s_rate, g_stats.fabric_ctrl_r_rate,
360 g_stats.fabric_meta_s_rate, g_stats.fabric_meta_r_rate,
361 g_stats.fabric_rw_s_rate, g_stats.fabric_rw_r_rate
362 );
363}
364
365void
366log_line_early_fail()
367{
368 uint64_t n_demarshal = g_stats.n_demarshal_error;
369 uint64_t n_tsvc_client = g_stats.n_tsvc_client_error;
370 uint64_t n_tsvc_from_proxy = g_stats.n_tsvc_from_proxy_error;
371 uint64_t n_tsvc_batch_sub = g_stats.n_tsvc_batch_sub_error;
372 uint64_t n_tsvc_from_proxy_batch_sub = g_stats.n_tsvc_from_proxy_batch_sub_error;
373 uint64_t n_tsvc_udf_sub = g_stats.n_tsvc_udf_sub_error;
374 uint64_t n_tsvc_ops_sub = g_stats.n_tsvc_ops_sub_error;
375
376 if ((n_demarshal |
377 n_tsvc_client |
378 n_tsvc_from_proxy |
379 n_tsvc_batch_sub |
380 n_tsvc_from_proxy_batch_sub |
381 n_tsvc_udf_sub |
382 n_tsvc_ops_sub) == 0) {
383 return;
384 }
385
386 cf_info(AS_INFO, " early-fail: demarshal %lu tsvc-client %lu tsvc-from-proxy %lu tsvc-batch-sub %lu tsvc-from-proxy-batch-sub %lu tsvc-udf-sub %lu tsvc-ops-sub %lu",
387 n_demarshal,
388 n_tsvc_client,
389 n_tsvc_from_proxy,
390 n_tsvc_batch_sub,
391 n_tsvc_from_proxy_batch_sub,
392 n_tsvc_udf_sub,
393 n_tsvc_ops_sub
394 );
395}
396
397void
398log_line_batch_index()
399{
400 uint64_t n_complete = g_stats.batch_index_complete;
401 uint64_t n_error = g_stats.batch_index_errors;
402 uint64_t n_timeout = g_stats.batch_index_timeout;
403
404 if ((n_complete | n_error | n_timeout) == 0) {
405 return;
406 }
407
408 cf_info(AS_INFO, " batch-index: batches (%lu,%lu,%lu)",
409 n_complete, n_error, n_timeout
410 );
411}
412
413void
414log_line_objects(as_namespace* ns, uint64_t n_objects, repl_stats* mp)
415{
416 // TODO - show if all 0's ???
417 cf_info(AS_INFO, "{%s} objects: all %lu master %lu prole %lu non-replica %lu",
418 ns->name,
419 n_objects,
420 mp->n_master_objects,
421 mp->n_prole_objects,
422 mp->n_non_replica_objects
423 );
424}
425
426void
427log_line_tombstones(as_namespace* ns, uint64_t n_tombstones, repl_stats* mp)
428{
429 if ((n_tombstones |
430 mp->n_master_tombstones |
431 mp->n_prole_tombstones |
432 mp->n_non_replica_tombstones) == 0) {
433 return;
434 }
435
436 cf_info(AS_INFO, "{%s} tombstones: all %lu master %lu prole %lu non-replica %lu",
437 ns->name,
438 n_tombstones,
439 mp->n_master_tombstones,
440 mp->n_prole_tombstones,
441 mp->n_non_replica_tombstones
442 );
443}
444
445void
446log_line_appeals(as_namespace* ns)
447{
448 int64_t remaining_tx = (int64_t)ns->appeals_tx_remaining;
449 int64_t active_tx = (int64_t)ns->appeals_tx_active;
450 int64_t active_rx = (int64_t)ns->appeals_rx_active;
451
452 if (remaining_tx > 0 || active_tx > 0 || active_rx > 0) {
453 cf_info(AS_INFO, "{%s} appeals: remaining-tx %ld active (%ld,%ld)",
454 ns->name,
455 remaining_tx, active_tx, active_rx
456 );
457 }
458}
459
460void
461log_line_migrations(as_namespace* ns)
462{
463 int64_t initial_tx = (int64_t)ns->migrate_tx_partitions_initial;
464 int64_t initial_rx = (int64_t)ns->migrate_rx_partitions_initial;
465 int64_t remaining_tx = (int64_t)ns->migrate_tx_partitions_remaining;
466 int64_t remaining_rx = (int64_t)ns->migrate_rx_partitions_remaining;
467 int64_t initial = initial_tx + initial_rx;
468 int64_t remaining = remaining_tx + remaining_rx;
469
470 if (initial > 0 && remaining > 0) {
471 float complete_pct = (1 - ((float)remaining / (float)initial)) * 100;
472
473 cf_info(AS_INFO, "{%s} migrations: remaining (%ld,%ld,%ld) active (%ld,%ld,%ld) complete-pct %0.2f",
474 ns->name,
475 remaining_tx, remaining_rx, ns->migrate_signals_remaining,
476 ns->migrate_tx_partitions_active, ns->migrate_rx_partitions_active, ns->migrate_signals_active,
477 complete_pct
478 );
479 }
480 else {
481 cf_info(AS_INFO, "{%s} migrations: complete", ns->name);
482 }
483}
484
485void
486log_line_memory_usage(as_namespace* ns, size_t total_mem, size_t index_mem,
487 size_t sindex_mem, size_t data_mem)
488{
489 double mem_used_pct = (double)(total_mem * 100) / (double)ns->memory_size;
490
491 if (ns->storage_data_in_memory) {
492 cf_info(AS_INFO, "{%s} memory-usage: total-bytes %lu index-bytes %lu sindex-bytes %lu data-bytes %lu used-pct %.2lf",
493 ns->name,
494 total_mem,
495 index_mem,
496 sindex_mem,
497 data_mem,
498 mem_used_pct
499 );
500 }
501 else {
502 cf_info(AS_INFO, "{%s} memory-usage: total-bytes %lu index-bytes %lu sindex-bytes %lu used-pct %.2lf",
503 ns->name,
504 total_mem,
505 index_mem,
506 sindex_mem,
507 mem_used_pct
508 );
509 }
510}
511
512void
513log_line_persistent_index_usage(as_namespace* ns, size_t used_size)
514{
515 if (ns->xmem_type == CF_XMEM_TYPE_PMEM) {
516 uint64_t used_pct = used_size * 100 / ns->mounts_size_limit;
517
518 cf_info(AS_INFO, "{%s} index-pmem-usage: used-bytes %lu used-pct %lu",
519 ns->name,
520 used_size,
521 used_pct
522 );
523 }
524 else if (ns->xmem_type == CF_XMEM_TYPE_FLASH) {
525 uint64_t used_pct = used_size * 100 / ns->mounts_size_limit;
526
527 cf_info(AS_INFO, "{%s} index-flash-usage: used-bytes %lu used-pct %lu",
528 ns->name,
529 used_size,
530 used_pct
531 );
532 }
533}
534
535void
536log_line_device_usage(as_namespace* ns)
537{
538 if (ns->storage_type != AS_STORAGE_ENGINE_SSD) {
539 return;
540 }
541
542 int available_pct;
543 uint64_t inuse_disk_bytes;
544 as_storage_stats(ns, &available_pct, &inuse_disk_bytes);
545
546 if (ns->storage_data_in_memory) {
547 cf_info(AS_INFO, "{%s} device-usage: used-bytes %lu avail-pct %d",
548 ns->name,
549 inuse_disk_bytes,
550 available_pct
551 );
552 }
553 else {
554 uint32_t n_reads_from_cache = ns->n_reads_from_cache;
555 uint32_t n_total_reads = ns->n_reads_from_device + n_reads_from_cache;
556
557 cf_atomic32_set(&ns->n_reads_from_device, 0);
558 cf_atomic32_set(&ns->n_reads_from_cache, 0);
559
560 ns->cache_read_pct =
561 (float)(100 * n_reads_from_cache) /
562 (float)(n_total_reads == 0 ? 1 : n_total_reads);
563
564 cf_info(AS_INFO, "{%s} device-usage: used-bytes %lu avail-pct %d cache-read-pct %.2f",
565 ns->name,
566 inuse_disk_bytes,
567 available_pct,
568 ns->cache_read_pct
569 );
570 }
571}
572
573void
574log_line_client(as_namespace* ns)
575{
576 uint64_t n_tsvc_error = ns->n_client_tsvc_error;
577 uint64_t n_tsvc_timeout = ns->n_client_tsvc_timeout;
578 uint64_t n_proxy_complete = ns->n_client_proxy_complete;
579 uint64_t n_proxy_error = ns->n_client_proxy_error;
580 uint64_t n_proxy_timeout = ns->n_client_proxy_timeout;
581 uint64_t n_read_success = ns->n_client_read_success;
582 uint64_t n_read_error = ns->n_client_read_error;
583 uint64_t n_read_timeout = ns->n_client_read_timeout;
584 uint64_t n_read_not_found = ns->n_client_read_not_found;
585 uint64_t n_read_filtered_out = ns->n_client_read_filtered_out;
586 uint64_t n_write_success = ns->n_client_write_success;
587 uint64_t n_write_error = ns->n_client_write_error;
588 uint64_t n_write_timeout = ns->n_client_write_timeout;
589 uint64_t n_write_filtered_out = ns->n_client_write_filtered_out;
590 uint64_t n_delete_success = ns->n_client_delete_success;
591 uint64_t n_delete_error = ns->n_client_delete_error;
592 uint64_t n_delete_timeout = ns->n_client_delete_timeout;
593 uint64_t n_delete_not_found = ns->n_client_delete_not_found;
594 uint64_t n_delete_filtered_out = ns->n_client_delete_filtered_out;
595 uint64_t n_udf_complete = ns->n_client_udf_complete;
596 uint64_t n_udf_error = ns->n_client_udf_error;
597 uint64_t n_udf_timeout = ns->n_client_udf_timeout;
598 uint64_t n_udf_filtered_out = ns->n_client_udf_filtered_out;
599 uint64_t n_lang_read_success = ns->n_client_lang_read_success;
600 uint64_t n_lang_write_success = ns->n_client_lang_write_success;
601 uint64_t n_lang_delete_success = ns->n_client_lang_delete_success;
602 uint64_t n_lang_error = ns->n_client_lang_error;
603
604 if ((n_tsvc_error | n_tsvc_timeout |
605 n_proxy_complete | n_proxy_error | n_proxy_timeout |
606 n_read_success | n_read_error | n_read_timeout | n_read_not_found | n_read_filtered_out |
607 n_write_success | n_write_error | n_write_timeout | n_write_filtered_out |
608 n_delete_success | n_delete_error | n_delete_timeout | n_delete_not_found | n_delete_filtered_out |
609 n_udf_complete | n_udf_error | n_udf_timeout | n_udf_filtered_out |
610 n_lang_read_success | n_lang_write_success | n_lang_delete_success | n_lang_error) == 0) {
611 return;
612 }
613
614 cf_info(AS_INFO, "{%s} client: tsvc (%lu,%lu) proxy (%lu,%lu,%lu) read (%lu,%lu,%lu,%lu,%lu) write (%lu,%lu,%lu,%lu) delete (%lu,%lu,%lu,%lu,%lu) udf (%lu,%lu,%lu,%lu) lang (%lu,%lu,%lu,%lu)",
615 ns->name,
616 n_tsvc_error, n_tsvc_timeout,
617 n_proxy_complete, n_proxy_error, n_proxy_timeout,
618 n_read_success, n_read_error, n_read_timeout, n_read_not_found, n_read_filtered_out,
619 n_write_success, n_write_error, n_write_timeout, n_write_filtered_out,
620 n_delete_success, n_delete_error, n_delete_timeout, n_delete_not_found, n_delete_filtered_out,
621 n_udf_complete, n_udf_error, n_udf_timeout, n_udf_filtered_out,
622 n_lang_read_success, n_lang_write_success, n_lang_delete_success, n_lang_error
623 );
624}
625
626void
627log_line_xdr_client(as_namespace* ns)
628{
629 uint64_t n_write_success = ns->n_xdr_client_write_success;
630 uint64_t n_write_error = ns->n_xdr_client_write_error;
631 uint64_t n_write_timeout = ns->n_xdr_client_write_timeout;
632 uint64_t n_delete_success = ns->n_xdr_client_delete_success;
633 uint64_t n_delete_error = ns->n_xdr_client_delete_error;
634 uint64_t n_delete_timeout = ns->n_xdr_client_delete_timeout;
635 uint64_t n_delete_not_found = ns->n_xdr_client_delete_not_found;
636
637 if ((n_write_success | n_write_error | n_write_timeout |
638 n_delete_success | n_delete_error | n_delete_timeout | n_delete_not_found) == 0) {
639 return;
640 }
641
642 cf_info(AS_INFO, "{%s} xdr-client: write (%lu,%lu,%lu) delete (%lu,%lu,%lu,%lu)",
643 ns->name,
644 n_write_success, n_write_error, n_write_timeout,
645 n_delete_success, n_delete_error, n_delete_timeout, n_delete_not_found
646 );
647}
648
649void
650log_line_from_proxy(as_namespace* ns)
651{
652 uint64_t n_tsvc_error = ns->n_from_proxy_tsvc_error;
653 uint64_t n_tsvc_timeout = ns->n_from_proxy_tsvc_timeout;
654 uint64_t n_read_success = ns->n_from_proxy_read_success;
655 uint64_t n_read_error = ns->n_from_proxy_read_error;
656 uint64_t n_read_timeout = ns->n_from_proxy_read_timeout;
657 uint64_t n_read_not_found = ns->n_from_proxy_read_not_found;
658 uint64_t n_read_filtered_out = ns->n_from_proxy_read_filtered_out;
659 uint64_t n_write_success = ns->n_from_proxy_write_success;
660 uint64_t n_write_error = ns->n_from_proxy_write_error;
661 uint64_t n_write_timeout = ns->n_from_proxy_write_timeout;
662 uint64_t n_write_filtered_out = ns->n_from_proxy_write_filtered_out;
663 uint64_t n_delete_success = ns->n_from_proxy_delete_success;
664 uint64_t n_delete_error = ns->n_from_proxy_delete_error;
665 uint64_t n_delete_timeout = ns->n_from_proxy_delete_timeout;
666 uint64_t n_delete_not_found = ns->n_from_proxy_delete_not_found;
667 uint64_t n_delete_filtered_out = ns->n_from_proxy_delete_filtered_out;
668 uint64_t n_udf_complete = ns->n_from_proxy_udf_complete;
669 uint64_t n_udf_error = ns->n_from_proxy_udf_error;
670 uint64_t n_udf_timeout = ns->n_from_proxy_udf_timeout;
671 uint64_t n_udf_filtered_out = ns->n_from_proxy_udf_filtered_out;
672 uint64_t n_lang_read_success = ns->n_from_proxy_lang_read_success;
673 uint64_t n_lang_write_success = ns->n_from_proxy_lang_write_success;
674 uint64_t n_lang_delete_success = ns->n_from_proxy_lang_delete_success;
675 uint64_t n_lang_error = ns->n_from_proxy_lang_error;
676
677 if ((n_tsvc_error | n_tsvc_timeout |
678 n_read_success | n_read_error | n_read_timeout | n_read_not_found | n_read_filtered_out |
679 n_write_success | n_write_error | n_write_timeout | n_write_filtered_out |
680 n_delete_success | n_delete_error | n_delete_timeout | n_delete_not_found | n_delete_filtered_out |
681 n_udf_complete | n_udf_error | n_udf_timeout | n_udf_filtered_out |
682 n_lang_read_success | n_lang_write_success | n_lang_delete_success | n_lang_error) == 0) {
683 return;
684 }
685
686 cf_info(AS_INFO, "{%s} from-proxy: tsvc (%lu,%lu) read (%lu,%lu,%lu,%lu,%lu) write (%lu,%lu,%lu,%lu) delete (%lu,%lu,%lu,%lu,%lu) udf (%lu,%lu,%lu,%lu) lang (%lu,%lu,%lu,%lu)",
687 ns->name,
688 n_tsvc_error, n_tsvc_timeout,
689 n_read_success, n_read_error, n_read_timeout, n_read_not_found, n_read_filtered_out,
690 n_write_success, n_write_error, n_write_timeout, n_write_filtered_out,
691 n_delete_success, n_delete_error, n_delete_timeout, n_delete_not_found, n_delete_filtered_out,
692 n_udf_complete, n_udf_error, n_udf_timeout, n_udf_filtered_out,
693 n_lang_read_success, n_lang_write_success, n_lang_delete_success, n_lang_error
694 );
695}
696
697void
698log_line_xdr_from_proxy(as_namespace* ns)
699{
700 uint64_t n_write_success = ns->n_xdr_from_proxy_write_success;
701 uint64_t n_write_error = ns->n_xdr_from_proxy_write_error;
702 uint64_t n_write_timeout = ns->n_xdr_from_proxy_write_timeout;
703 uint64_t n_delete_success = ns->n_xdr_from_proxy_delete_success;
704 uint64_t n_delete_error = ns->n_xdr_from_proxy_delete_error;
705 uint64_t n_delete_timeout = ns->n_xdr_from_proxy_delete_timeout;
706 uint64_t n_delete_not_found = ns->n_xdr_from_proxy_delete_not_found;
707
708 if ((n_write_success | n_write_error | n_write_timeout |
709 n_delete_success | n_delete_error | n_delete_timeout | n_delete_not_found) == 0) {
710 return;
711 }
712
713 cf_info(AS_INFO, "{%s} xdr-from-proxy: write (%lu,%lu,%lu) delete (%lu,%lu,%lu,%lu)",
714 ns->name,
715 n_write_success, n_write_error, n_write_timeout,
716 n_delete_success, n_delete_error, n_delete_timeout, n_delete_not_found
717 );
718}
719
720void
721log_line_batch_sub(as_namespace* ns)
722{
723 uint64_t n_tsvc_error = ns->n_batch_sub_tsvc_error;
724 uint64_t n_tsvc_timeout = ns->n_batch_sub_tsvc_timeout;
725 uint64_t n_proxy_complete = ns->n_batch_sub_proxy_complete;
726 uint64_t n_proxy_error = ns->n_batch_sub_proxy_error;
727 uint64_t n_proxy_timeout = ns->n_batch_sub_proxy_timeout;
728 uint64_t n_read_success = ns->n_batch_sub_read_success;
729 uint64_t n_read_error = ns->n_batch_sub_read_error;
730 uint64_t n_read_timeout = ns->n_batch_sub_read_timeout;
731 uint64_t n_read_not_found = ns->n_batch_sub_read_not_found;
732 uint64_t n_read_filtered_out = ns->n_batch_sub_read_filtered_out;
733
734 if ((n_tsvc_error | n_tsvc_timeout |
735 n_proxy_complete | n_proxy_error | n_proxy_timeout |
736 n_read_success | n_read_error | n_read_timeout | n_read_not_found | n_read_filtered_out) == 0) {
737 return;
738 }
739
740 cf_info(AS_INFO, "{%s} batch-sub: tsvc (%lu,%lu) proxy (%lu,%lu,%lu) read (%lu,%lu,%lu,%lu,%lu)",
741 ns->name,
742 n_tsvc_error, n_tsvc_timeout,
743 n_proxy_complete, n_proxy_error, n_proxy_timeout,
744 n_read_success, n_read_error, n_read_timeout, n_read_not_found, n_read_filtered_out
745 );
746}
747
748void
749log_line_from_proxy_batch_sub(as_namespace* ns)
750{
751 uint64_t n_tsvc_error = ns->n_from_proxy_batch_sub_tsvc_error;
752 uint64_t n_tsvc_timeout = ns->n_from_proxy_batch_sub_tsvc_timeout;
753 uint64_t n_read_success = ns->n_from_proxy_batch_sub_read_success;
754 uint64_t n_read_error = ns->n_from_proxy_batch_sub_read_error;
755 uint64_t n_read_timeout = ns->n_from_proxy_batch_sub_read_timeout;
756 uint64_t n_read_not_found = ns->n_from_proxy_batch_sub_read_not_found;
757 uint64_t n_read_filtered_out = ns->n_from_proxy_batch_sub_read_filtered_out;
758
759 if ((n_tsvc_error | n_tsvc_timeout |
760 n_read_success | n_read_error | n_read_timeout | n_read_not_found | n_read_filtered_out) == 0) {
761 return;
762 }
763
764 cf_info(AS_INFO, "{%s} from-proxy-batch-sub: tsvc (%lu,%lu) read (%lu,%lu,%lu,%lu,%lu)",
765 ns->name,
766 n_tsvc_error, n_tsvc_timeout,
767 n_read_success, n_read_error, n_read_timeout, n_read_not_found, n_read_filtered_out
768 );
769}
770
771void
772log_line_scan(as_namespace* ns)
773{
774 uint64_t n_basic_complete = ns->n_scan_basic_complete;
775 uint64_t n_basic_error = ns->n_scan_basic_error;
776 uint64_t n_basic_abort = ns->n_scan_basic_abort;
777 uint64_t n_aggr_complete = ns->n_scan_aggr_complete;
778 uint64_t n_aggr_error = ns->n_scan_aggr_error;
779 uint64_t n_aggr_abort = ns->n_scan_aggr_abort;
780 uint64_t n_udf_bg_complete = ns->n_scan_udf_bg_complete;
781 uint64_t n_udf_bg_error = ns->n_scan_udf_bg_error;
782 uint64_t n_udf_bg_abort = ns->n_scan_udf_bg_abort;
783 uint64_t n_ops_bg_complete = ns->n_scan_ops_bg_complete;
784 uint64_t n_ops_bg_error = ns->n_scan_ops_bg_error;
785 uint64_t n_ops_bg_abort = ns->n_scan_ops_bg_abort;
786
787 if ((n_basic_complete | n_basic_error | n_basic_abort |
788 n_aggr_complete | n_aggr_error | n_aggr_abort |
789 n_udf_bg_complete | n_udf_bg_error | n_udf_bg_abort |
790 n_ops_bg_complete | n_ops_bg_error | n_ops_bg_abort) == 0) {
791 return;
792 }
793
794 cf_info(AS_INFO, "{%s} scan: basic (%lu,%lu,%lu) aggr (%lu,%lu,%lu) udf-bg (%lu,%lu,%lu) ops-bg (%lu,%lu,%lu)",
795 ns->name,
796 n_basic_complete, n_basic_error, n_basic_abort,
797 n_aggr_complete, n_aggr_error, n_aggr_abort,
798 n_udf_bg_complete, n_udf_bg_error, n_udf_bg_abort,
799 n_ops_bg_complete, n_ops_bg_error, n_ops_bg_abort
800 );
801}
802
803void
804log_line_query(as_namespace* ns)
805{
806 uint64_t n_basic_success = ns->n_lookup_success;
807 uint64_t n_basic_failure = ns->n_lookup_errs + ns->n_lookup_abort;
808 uint64_t n_aggr_success = ns->n_agg_success;
809 uint64_t n_aggr_failure = ns->n_agg_errs + ns->n_agg_abort;
810 uint64_t n_udf_bg_success = ns->n_query_udf_bg_success;
811 uint64_t n_udf_bg_failure = ns->n_query_udf_bg_failure;
812 uint64_t n_ops_bg_success = ns->n_query_ops_bg_success;
813 uint64_t n_ops_bg_failure = ns->n_query_ops_bg_failure;
814
815 if ((n_basic_success | n_basic_failure |
816 n_aggr_success | n_aggr_failure |
817 n_udf_bg_success | n_udf_bg_failure |
818 n_ops_bg_success | n_ops_bg_failure) == 0) {
819 return;
820 }
821
822 cf_info(AS_INFO, "{%s} query: basic (%lu,%lu) aggr (%lu,%lu) udf-bg (%lu,%lu) ops-bg (%lu,%lu)",
823 ns->name,
824 n_basic_success, n_basic_failure,
825 n_aggr_success, n_aggr_failure,
826 n_udf_bg_success, n_udf_bg_failure,
827 n_ops_bg_success, n_ops_bg_failure
828 );
829}
830
831void
832log_line_udf_sub(as_namespace* ns)
833{
834 uint64_t n_tsvc_error = ns->n_udf_sub_tsvc_error;
835 uint64_t n_tsvc_timeout = ns->n_udf_sub_tsvc_timeout;
836 uint64_t n_udf_complete = ns->n_udf_sub_udf_complete;
837 uint64_t n_udf_error = ns->n_udf_sub_udf_error;
838 uint64_t n_udf_timeout = ns->n_udf_sub_udf_timeout;
839 uint64_t n_udf_filtered_out = ns->n_udf_sub_udf_filtered_out;
840 uint64_t n_lang_read_success = ns->n_udf_sub_lang_read_success;
841 uint64_t n_lang_write_success = ns->n_udf_sub_lang_write_success;
842 uint64_t n_lang_delete_success = ns->n_udf_sub_lang_delete_success;
843 uint64_t n_lang_error = ns->n_udf_sub_lang_error;
844
845 if ((n_tsvc_error | n_tsvc_timeout |
846 n_udf_complete | n_udf_error | n_udf_timeout | n_udf_filtered_out |
847 n_lang_read_success | n_lang_write_success | n_lang_delete_success | n_lang_error) == 0) {
848 return;
849 }
850
851 cf_info(AS_INFO, "{%s} udf-sub: tsvc (%lu,%lu) udf (%lu,%lu,%lu,%lu) lang (%lu,%lu,%lu,%lu)",
852 ns->name,
853 n_tsvc_error, n_tsvc_timeout,
854 n_udf_complete, n_udf_error, n_udf_timeout, n_udf_filtered_out,
855 n_lang_read_success, n_lang_write_success, n_lang_delete_success, n_lang_error
856 );
857}
858
859void
860log_line_ops_sub(as_namespace* ns)
861{
862 uint64_t n_tsvc_error = ns->n_ops_sub_tsvc_error;
863 uint64_t n_tsvc_timeout = ns->n_ops_sub_tsvc_timeout;
864 uint64_t n_write_success = ns->n_ops_sub_write_success;
865 uint64_t n_write_error = ns->n_ops_sub_write_error;
866 uint64_t n_write_timeout = ns->n_ops_sub_write_timeout;
867 uint64_t n_write_filtered_out = ns->n_ops_sub_write_filtered_out;
868
869 if ((n_tsvc_error | n_tsvc_timeout |
870 n_write_success | n_write_error | n_write_timeout | n_write_filtered_out) == 0) {
871 return;
872 }
873
874 cf_info(AS_INFO, "{%s} ops-sub: tsvc (%lu,%lu) write (%lu,%lu,%lu,%lu)",
875 ns->name,
876 n_tsvc_error, n_tsvc_timeout,
877 n_write_success, n_write_error, n_write_timeout, n_write_filtered_out
878 );
879}
880
881void
882log_line_retransmits(as_namespace* ns)
883{
884 uint64_t n_migrate_record_retransmits = ns->migrate_record_retransmits;
885 uint64_t n_all_read_dup_res = ns->n_retransmit_all_read_dup_res;
886 uint64_t n_all_write_dup_res = ns->n_retransmit_all_write_dup_res;
887 uint64_t n_all_write_repl_write = ns->n_retransmit_all_write_repl_write;
888 uint64_t n_all_delete_dup_res = ns->n_retransmit_all_delete_dup_res;
889 uint64_t n_all_delete_repl_write = ns->n_retransmit_all_delete_repl_write;
890 uint64_t n_all_udf_dup_res = ns->n_retransmit_all_udf_dup_res;
891 uint64_t n_all_udf_repl_write = ns->n_retransmit_all_udf_repl_write;
892 uint64_t n_all_batch_sub_dup_res = ns->n_retransmit_all_batch_sub_dup_res;
893 uint64_t n_udf_sub_dup_res = ns->n_retransmit_udf_sub_dup_res;
894 uint64_t n_udf_sub_repl_write = ns->n_retransmit_udf_sub_repl_write;
895 uint64_t n_ops_sub_dup_res = ns->n_retransmit_ops_sub_dup_res;
896 uint64_t n_ops_sub_repl_write = ns->n_retransmit_ops_sub_repl_write;
897
898 if ((n_migrate_record_retransmits |
899 n_all_read_dup_res |
900 n_all_write_dup_res | n_all_write_repl_write |
901 n_all_delete_dup_res | n_all_delete_repl_write |
902 n_all_udf_dup_res | n_all_udf_repl_write |
903 n_all_batch_sub_dup_res |
904 n_udf_sub_dup_res | n_udf_sub_repl_write |
905 n_ops_sub_dup_res | n_ops_sub_repl_write) == 0) {
906 return;
907 }
908
909 cf_info(AS_INFO, "{%s} retransmits: migration %lu all-read %lu all-write (%lu,%lu) all-delete (%lu,%lu) all-udf (%lu,%lu) all-batch-sub %lu udf-sub (%lu,%lu) ops-sub (%lu,%lu)",
910 ns->name,
911 n_migrate_record_retransmits,
912 n_all_read_dup_res,
913 n_all_write_dup_res, n_all_write_repl_write,
914 n_all_delete_dup_res, n_all_delete_repl_write,
915 n_all_udf_dup_res, n_all_udf_repl_write,
916 n_all_batch_sub_dup_res,
917 n_udf_sub_dup_res, n_udf_sub_repl_write,
918 n_ops_sub_dup_res, n_ops_sub_repl_write
919 );
920}
921
922void
923log_line_re_repl(as_namespace* ns)
924{
925 uint64_t n_re_repl_success = ns->n_re_repl_success;
926 uint64_t n_re_repl_error = ns->n_re_repl_error;
927 uint64_t n_re_repl_timeout = ns->n_re_repl_timeout;
928
929 if ((n_re_repl_success | n_re_repl_error | n_re_repl_timeout) == 0) {
930 return;
931 }
932
933 cf_info(AS_INFO, "{%s} re-repl: all-triggers (%lu,%lu,%lu)",
934 ns->name,
935 n_re_repl_success, n_re_repl_error, n_re_repl_timeout
936 );
937}
938
939void
940log_line_special_errors(as_namespace* ns)
941{
942 uint64_t n_fail_key_busy = ns->n_fail_key_busy;
943 uint64_t n_fail_record_too_big = ns->n_fail_record_too_big;
944
945 if ((n_fail_key_busy |
946 n_fail_record_too_big) == 0) {
947 return;
948 }
949
950 cf_info(AS_INFO, "{%s} special-errors: key-busy %lu record-too-big %lu",
951 ns->name,
952 n_fail_key_busy,
953 n_fail_record_too_big
954 );
955}
956
957void
958dump_global_histograms()
959{
960 if (g_stats.batch_index_hist_active) {
961 histogram_dump(g_stats.batch_index_hist);
962 }
963
964 if (g_config.info_hist_enabled) {
965 histogram_dump(g_stats.info_hist);
966 }
967
968 if (g_config.svc_benchmarks_enabled) {
969 histogram_dump(g_stats.svc_demarshal_hist);
970 histogram_dump(g_stats.svc_queue_hist);
971 }
972
973 if (g_config.fabric_benchmarks_enabled) {
974 histogram_dump(g_stats.fabric_send_init_hists[AS_FABRIC_CHANNEL_BULK]);
975 histogram_dump(g_stats.fabric_send_fragment_hists[AS_FABRIC_CHANNEL_BULK]);
976 histogram_dump(g_stats.fabric_recv_fragment_hists[AS_FABRIC_CHANNEL_BULK]);
977 histogram_dump(g_stats.fabric_recv_cb_hists[AS_FABRIC_CHANNEL_BULK]);
978 histogram_dump(g_stats.fabric_send_init_hists[AS_FABRIC_CHANNEL_CTRL]);
979 histogram_dump(g_stats.fabric_send_fragment_hists[AS_FABRIC_CHANNEL_CTRL]);
980 histogram_dump(g_stats.fabric_recv_fragment_hists[AS_FABRIC_CHANNEL_CTRL]);
981 histogram_dump(g_stats.fabric_recv_cb_hists[AS_FABRIC_CHANNEL_CTRL]);
982 histogram_dump(g_stats.fabric_send_init_hists[AS_FABRIC_CHANNEL_META]);
983 histogram_dump(g_stats.fabric_send_fragment_hists[AS_FABRIC_CHANNEL_META]);
984 histogram_dump(g_stats.fabric_recv_fragment_hists[AS_FABRIC_CHANNEL_META]);
985 histogram_dump(g_stats.fabric_recv_cb_hists[AS_FABRIC_CHANNEL_META]);
986 histogram_dump(g_stats.fabric_send_init_hists[AS_FABRIC_CHANNEL_RW]);
987 histogram_dump(g_stats.fabric_send_fragment_hists[AS_FABRIC_CHANNEL_RW]);
988 histogram_dump(g_stats.fabric_recv_fragment_hists[AS_FABRIC_CHANNEL_RW]);
989 histogram_dump(g_stats.fabric_recv_cb_hists[AS_FABRIC_CHANNEL_RW]);
990 }
991
992 as_query_histogram_dumpall();
993}
994
995void
996dump_namespace_histograms(as_namespace* ns)
997{
998 if (ns->read_hist_active) {
999 cf_hist_track_dump(ns->read_hist);
1000 }
1001
1002 if (ns->read_benchmarks_enabled) {
1003 histogram_dump(ns->read_start_hist);
1004 histogram_dump(ns->read_restart_hist);
1005 histogram_dump(ns->read_dup_res_hist);
1006 histogram_dump(ns->read_repl_ping_hist);
1007 histogram_dump(ns->read_local_hist);
1008 histogram_dump(ns->read_response_hist);
1009 }
1010
1011 if (ns->write_hist_active) {
1012 cf_hist_track_dump(ns->write_hist);
1013 }
1014
1015 if (ns->write_benchmarks_enabled) {
1016 histogram_dump(ns->write_start_hist);
1017 histogram_dump(ns->write_restart_hist);
1018 histogram_dump(ns->write_dup_res_hist);
1019 histogram_dump(ns->write_master_hist);
1020 histogram_dump(ns->write_repl_write_hist);
1021 histogram_dump(ns->write_response_hist);
1022 }
1023
1024 if (ns->udf_hist_active) {
1025 cf_hist_track_dump(ns->udf_hist);
1026 }
1027
1028 if (ns->udf_benchmarks_enabled) {
1029 histogram_dump(ns->udf_start_hist);
1030 histogram_dump(ns->udf_restart_hist);
1031 histogram_dump(ns->udf_dup_res_hist);
1032 histogram_dump(ns->udf_master_hist);
1033 histogram_dump(ns->udf_repl_write_hist);
1034 histogram_dump(ns->udf_response_hist);
1035 }
1036
1037 if (ns->query_hist_active) {
1038 cf_hist_track_dump(ns->query_hist);
1039 }
1040
1041 if (ns->query_rec_count_hist_active) {
1042 histogram_dump(ns->query_rec_count_hist);
1043 }
1044
1045 if (ns->proxy_hist_enabled) {
1046 histogram_dump(ns->proxy_hist);
1047 }
1048
1049 if (ns->batch_sub_benchmarks_enabled) {
1050 histogram_dump(ns->batch_sub_start_hist);
1051 histogram_dump(ns->batch_sub_restart_hist);
1052 histogram_dump(ns->batch_sub_dup_res_hist);
1053 histogram_dump(ns->batch_sub_repl_ping_hist);
1054 histogram_dump(ns->batch_sub_read_local_hist);
1055 histogram_dump(ns->batch_sub_response_hist);
1056 }
1057
1058 if (ns->udf_sub_benchmarks_enabled) {
1059 histogram_dump(ns->udf_sub_start_hist);
1060 histogram_dump(ns->udf_sub_restart_hist);
1061 histogram_dump(ns->udf_sub_dup_res_hist);
1062 histogram_dump(ns->udf_sub_master_hist);
1063 histogram_dump(ns->udf_sub_repl_write_hist);
1064 histogram_dump(ns->udf_sub_response_hist);
1065 }
1066
1067 if (ns->ops_sub_benchmarks_enabled) {
1068 histogram_dump(ns->ops_sub_start_hist);
1069 histogram_dump(ns->ops_sub_restart_hist);
1070 histogram_dump(ns->ops_sub_dup_res_hist);
1071 histogram_dump(ns->ops_sub_master_hist);
1072 histogram_dump(ns->ops_sub_repl_write_hist);
1073 histogram_dump(ns->ops_sub_response_hist);
1074 }
1075
1076 if (ns->re_repl_hist_active) {
1077 histogram_dump(ns->re_repl_hist);
1078 }
1079
1080 if (ns->storage_benchmarks_enabled) {
1081 as_storage_ticker_stats(ns);
1082 }
1083
1084 as_sindex_histogram_dumpall(ns);
1085}
1086