From: Lukáš Ondráček Date: Mon, 28 Apr 2025 10:54:43 +0000 (+0200) Subject: lib/cache: add debug logs where kru will be used X-Git-Tag: v6.0.17~2^2~25 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d2bc0c6fd8dba2270bb7acdbcc398e0b84659570;p=thirdparty%2Fknot-resolver.git lib/cache: add debug logs where kru will be used --- diff --git a/lib/cache/api.c b/lib/cache/api.c index 309a9d6ed..30860ac79 100644 --- a/lib/cache/api.c +++ b/lib/cache/api.c @@ -30,6 +30,7 @@ #include "lib/utils.h" #include "lib/cache/impl.h" +#include "lib/cache/top.h" /* TODO: * - Reconsider when RRSIGs are put in and retrieved from the cache. @@ -624,6 +625,7 @@ static ssize_t stash_rrset(struct kr_cache *cache, const struct kr_query *qry, rdataset_dematerialize(rds_sigs, eh->data + rr_ssize); if (kr_fails_assert(entry_h_consistent_E(val_new_entry, rr->type))) return kr_error(EINVAL); + kr_cache_top_access(cache->top, key.data, key.len, "stash_rrset"); #if 0 /* Occasionally useful when debugging some kinds of changes. */ { @@ -800,6 +802,7 @@ static int stash_nsec_p(const knot_dname_t *dname, const char *nsec_p_v, VERBOSE_MSG(qry, "=> EL write failed (ret: %d)\n", ret); return kr_ok(); } + kr_cache_top_access(cache->top, key.data, key.len, "stash_nsec_p"); if (log_refresh_by) { VERBOSE_MSG(qry, "=> nsec_p stashed for %s (refresh by %d, hash: %x)\n", log_dname, log_refresh_by, log_hash); @@ -877,6 +880,7 @@ static int peek_exact_real(struct kr_cache *cache, const knot_dname_t *name, uin .raw_data = val.data, .raw_bound = knot_db_val_bound(val), }; + kr_cache_top_access(cache->top, key.data, key.len, "peek_exact_real"); // hits only return kr_ok(); } int kr_cache_peek_exact(struct kr_cache *cache, const knot_dname_t *name, uint16_t type, diff --git a/lib/cache/api.h b/lib/cache/api.h index 454f629e8..cefd7a049 100644 --- a/lib/cache/api.h +++ b/lib/cache/api.h @@ -26,6 +26,7 @@ struct kr_cache const struct kr_cdb_api *api; /**< Storage engine */ struct kr_cdb_stats stats; uint32_t ttl_min, ttl_max; /**< TTL limits; enforced primarily in iterator actually. */ + struct kr_cache_top *top; /* A pair of stamps for detection of real-time shifts during runtime. */ struct timeval checkpoint_walltime; /**< Wall time on the last check-point. */ @@ -154,6 +155,7 @@ int kr_cache_remove(struct kr_cache *cache, const knot_dname_t *name, uint16_t t * @return result count or an errcode * @note the cache keys are matched by prefix, i.e. it very much depends * on their structure; CACHE_KEY_DEF. + * @note the only usecase is for subtree removal, KRU is thus not involved here */ KR_EXPORT int kr_cache_match(struct kr_cache *cache, const knot_dname_t *name, diff --git a/lib/cache/cdb_lmdb.c b/lib/cache/cdb_lmdb.c index cb19b9280..f5e56bc64 100644 --- a/lib/cache/cdb_lmdb.c +++ b/lib/cache/cdb_lmdb.c @@ -15,8 +15,11 @@ #include "contrib/ucw/lib.h" #include "lib/cache/cdb_lmdb.h" #include "lib/cache/cdb_api.h" +#include "lib/cache/top.h" #include "lib/utils.h" +#define kr_cache_top_access_cdb(...) { if (env->is_cache) kr_cache_top_access_cdb(__VA_ARGS__); } // TODO remove + /// A hacky way allowing usual usage of kr_log_error(MDB, ...) /// while differentiating between cache and rules in the produced logs. #define LOG_GRP_MDB (env->is_cache ? LOG_GRP_CACHE : LOG_GRP_RULES) @@ -47,6 +50,7 @@ struct lmdb_env } txn; bool is_cache; /**< cache vs. rules; from struct kr_cdb_opts::is_cache */ + struct kr_cache_top *top; // TODO remove /* Cached part of struct stat for data.mdb. */ dev_t st_dev; @@ -654,6 +658,7 @@ static int cdb_readv(kr_cdb_pt db, struct kr_cdb_stats *stats, MDB_val _key = val_knot2mdb(key[i]); MDB_val _val = val_knot2mdb(val[i]); stats->read++; + kr_cache_top_access_cdb(env->top, _key.mv_data, _key.mv_size, "readv"); ret = mdb_get(txn, env->dbi, &_key, &_val); if (ret != MDB_SUCCESS) { if (ret == MDB_NOTFOUND) { @@ -681,6 +686,7 @@ static int cdb_write(struct lmdb_env *env, MDB_txn **txn, const knot_db_val_t *k MDB_val _key = val_knot2mdb(*key); MDB_val _val = val_knot2mdb(*val); stats->write++; + kr_cache_top_access_cdb(env->top, _key.mv_data, _key.mv_size, "write"); /* This is LMDB specific optimisation, * if caller specifies value with NULL data and non-zero length, @@ -773,6 +779,7 @@ static int cdb_match(kr_cdb_pt db, struct kr_cdb_stats *stats, MDB_val cur_key = val_knot2mdb(*key); MDB_val cur_val = { 0, NULL }; stats->match++; + kr_cache_top_access_cdb(env->top, cur_key.mv_data, cur_key.mv_size, "match-prefix"); ret = mdb_cursor_get(cur, &cur_key, &cur_val, MDB_SET_RANGE); if (ret != MDB_SUCCESS) { mdb_cursor_close(cur); @@ -790,6 +797,7 @@ static int cdb_match(kr_cdb_pt db, struct kr_cdb_stats *stats, } /* Add to result set */ if (results < maxcount) { + kr_cache_top_access_cdb(env->top, cur_key.mv_data, cur_key.mv_size, "matched"); keyval[results][0] = val_mdb2knot(cur_key); keyval[results][1] = val_mdb2knot(cur_val); ++results; @@ -824,6 +832,7 @@ static int cdb_read_leq(kr_cdb_pt db, struct kr_cdb_stats *stats, MDB_val key2_m = val_knot2mdb(*key); MDB_val val2_m = { 0, NULL }; stats->read_leq++; + kr_cache_top_access_cdb(env->top, key2_m.mv_data, key2_m.mv_size, "leq-query"); ret = mdb_cursor_get(curs, &key2_m, &val2_m, MDB_SET_RANGE); if (ret) goto failure; /* test for equality //:unlikely */ @@ -841,6 +850,7 @@ static int cdb_read_leq(kr_cdb_pt db, struct kr_cdb_stats *stats, ret = 1; success: /* finalize the output */ + kr_cache_top_access_cdb(env->top, key2_m.mv_data, key2_m.mv_size, "leq"); *key = val_mdb2knot(key2_m); *val = val_mdb2knot(val2_m); return ret; @@ -866,10 +876,12 @@ static int cdb_read_less(kr_cdb_pt db, struct kr_cdb_stats *stats, MDB_val key2_m = val_knot2mdb(*key); MDB_val val2_m = { 0, NULL }; stats->read_less++; + kr_cache_top_access_cdb(env->top, key2_m.mv_data, key2_m.mv_size, "less-query"); // It could keep on the same `key` when MDB_PREV was used. ret = mdb_cursor_get(curs, &key2_m, &val2_m, MDB_PREV_NODUP); if (!ret) { /* finalize the output */ + kr_cache_top_access_cdb(env->top, key2_m.mv_data, key2_m.mv_size, "less"); *key = val_mdb2knot(key2_m); *val = val_mdb2knot(val2_m); return 1; diff --git a/lib/cache/entry_pkt.c b/lib/cache/entry_pkt.c index 9499b69ab..229ec2d96 100644 --- a/lib/cache/entry_pkt.c +++ b/lib/cache/entry_pkt.c @@ -11,6 +11,7 @@ #include "lib/utils.h" #include "lib/layer/iterate.h" /* kr_response_classify */ #include "lib/cache/impl.h" +#include "lib/cache/top.h" /** Compute TTL for a packet. It's minimum TTL or zero. (You can apply limits.) */ @@ -113,6 +114,7 @@ void stash_pkt(const knot_pkt_t *pkt, const struct kr_query *qry, eh->has_optout = qf->DNSSEC_OPTOUT; memcpy(eh->data, &pkt_size, sizeof(pkt_size)); memcpy(eh->data + sizeof(pkt_size), pkt->wire, pkt_size); + kr_cache_top_access(cache->top, key.data, key.len, "stash_pkt"); WITH_VERBOSE(qry) { auto_free char *type_str = kr_rrtype_text(pkt_type), diff --git a/lib/cache/nsec1.c b/lib/cache/nsec1.c index 45543034e..d7d72fe07 100644 --- a/lib/cache/nsec1.c +++ b/lib/cache/nsec1.c @@ -7,6 +7,7 @@ */ #include "lib/cache/impl.h" +#include "lib/cache/top.h" #include "lib/dnssec/nsec.h" #include "lib/layer/iterate.h" @@ -175,7 +176,7 @@ static const char * find_leq_NSEC1(struct kr_cache *cache, const struct kr_query } if (is_exact) { /* Nothing else to do. */ - return NULL; + goto success; } /* The NSEC starts strictly before our target name; * now check that it still belongs into that zone. */ @@ -246,6 +247,10 @@ static const char * find_leq_NSEC1(struct kr_cache *cache, const struct kr_query if (kwz_high) { *kwz_high = kwz_hi; } + +success: + + kr_cache_top_access(cache->top, key_nsec.data, key_nsec.len, "leq_nsec1"); // hits only return NULL; } @@ -404,6 +409,7 @@ int nsec1_src_synth(struct key *k, struct answer *ans, const knot_dname_t *clenc knot_db_val_t val = { NULL, 0 }; knot_db_val_t wild_low_kwz = { NULL, 0 }; uint32_t new_ttl; + kr_cache_top_access(cache->top, key.data, key.len, "nsec1_src_synth"); // TODO remove, probably redundant, hit (exact/cover) or miss const char *err = find_leq_NSEC1(cache, qry, key, k, &val, &exact_match, &wild_low_kwz, NULL, &new_ttl); if (err) { diff --git a/lib/cache/nsec3.c b/lib/cache/nsec3.c index 2716456cc..478c3349e 100644 --- a/lib/cache/nsec3.c +++ b/lib/cache/nsec3.c @@ -7,6 +7,7 @@ */ #include "lib/cache/impl.h" +#include "lib/cache/top.h" #include "contrib/base32hex.h" #include "lib/dnssec/nsec.h" @@ -181,7 +182,7 @@ static const char * find_leq_NSEC3(struct kr_cache *cache, const struct kr_query } if (is_exact) { /* Nothing else to do. */ - return NULL; + goto success; } /* The NSEC3 starts strictly before our target name; * now check that it still belongs into that zone and chain. */ @@ -215,6 +216,10 @@ static const char * find_leq_NSEC3(struct kr_cache *cache, const struct kr_query if (!covers) { return "range search miss (!covers)"; } + +success: + + kr_cache_top_access(cache->top, key_found.data, key_found.len, "leq_nsec3"); // hits only return NULL; } diff --git a/lib/cache/peek.c b/lib/cache/peek.c index 46a4868ce..65a486950 100644 --- a/lib/cache/peek.c +++ b/lib/cache/peek.c @@ -3,6 +3,7 @@ */ #include "lib/cache/impl.h" +#include "lib/cache/top.h" #include "lib/dnssec/ta.h" #include "lib/layer/iterate.h" @@ -126,12 +127,13 @@ int peek_nosync(kr_layer_t *ctx, knot_pkt_t *pkt) /* found an entry: test conditions, materialize into pkt, etc. */ ret = found_exact_hit(qry, pkt, val, lowest_rank); } - } - if (!ret) { - return KR_STATE_DONE; - } else if (kr_fails_assert(ret == kr_error(ENOENT))) { - VERBOSE_MSG(qry, "=> exact hit error: %d %s\n", ret, kr_strerror(ret)); - return ctx->state; + if (!ret) { + kr_cache_top_access(cache->top, key.data, key.len, "peek_nosync:exact"); // hits only + return KR_STATE_DONE; + } else if (kr_fails_assert(ret == kr_error(ENOENT))) { + VERBOSE_MSG(qry, "=> exact hit error: %d %s\n", ret, kr_strerror(ret)); + return ctx->state; + } } /* Avoid aggressive answers in STUB mode. @@ -274,6 +276,7 @@ int peek_nosync(kr_layer_t *ctx, knot_pkt_t *pkt) ret = entry2answer(&ans, AR_SOA, eh, knot_db_val_bound(val), k->zname, KNOT_RRTYPE_SOA, new_ttl); if (ret) return ctx->state; + kr_cache_top_access(cache->top, key.data, key.len, "peek_nosync:SOA"); // hits only } /* Find our target RCODE. */ @@ -592,6 +595,7 @@ static int try_wild(struct key *k, struct answer *ans, const knot_dname_t *clenc ret, (int)new_ttl); if (ret) return kr_error(ret); ans->rcode = PKT_NOERROR; + kr_cache_top_access(cache->top, key.data, key.len, "try_wild"); // hits only return kr_ok(); } @@ -652,10 +656,10 @@ static int closest_NS(struct kr_cache *cache, struct key *k, entry_list_t el, bool exact_match = true; bool need_zero = true; /* Inspect the NS/xNAME entries, shortening by a label on each iteration. */ + knot_db_val_t key, val; do { k->buf[0] = zlf_len; - knot_db_val_t key = key_exact_type(k, KNOT_RRTYPE_NS); - knot_db_val_t val; + key = key_exact_type(k, KNOT_RRTYPE_NS); int ret = cache_op(cache, read, &key, &val, 1); if (ret == kr_error(ENOENT)) goto next_label; if (kr_fails_assert(ret == 0)) { @@ -680,8 +684,7 @@ static int closest_NS(struct kr_cache *cache, struct key *k, entry_list_t el, if (ret < 0) goto next_label; else if (!ret) { /* We found our match. */ - k->zlf_len = zlf_len; - return kr_ok(); + goto success; } } const int el_count = only_NS ? EL_NS + 1 : EL_LENGTH; @@ -692,8 +695,7 @@ static int closest_NS(struct kr_cache *cache, struct key *k, entry_list_t el, if (ret < 0) goto next_label; else if (!ret) { /* We found our match. */ - k->zlf_len = zlf_len; - return kr_ok(); + goto success; } } @@ -721,6 +723,11 @@ static int closest_NS(struct kr_cache *cache, struct key *k, entry_list_t el, return kr_error(ENOENT); } } while (true); + +success: + k->zlf_len = zlf_len; + kr_cache_top_access(cache->top, key.data, key.len, "closest_NS"); // hits only + return kr_ok(); } static int check_NS_entry(struct key *k, const knot_db_val_t entry, const int i, diff --git a/lib/cache/top.c b/lib/cache/top.c new file mode 100644 index 000000000..3cb2b96d0 --- /dev/null +++ b/lib/cache/top.c @@ -0,0 +1,119 @@ +/* Copyright (C) CZ.NIC, z.s.p.o. + * SPDX-License-Identifier: GPL-3.0-or-later + */ + +#include +#include +#include "lib/defines.h" +#include "lib/cache/top.h" + +// #ifdef LOG_GRP_MDB +#define VERBOSE_LOG(...) printf("GC KRU " __VA_ARGS__) + +struct kr_cache_top { + bool using_avx2; // required consistency to use the same hash function + // --- header end --- + size_t capacity; + uint32_t instant_limit; // warn about different settings, but require explicit file removal? + uint32_t rate_limit; + uint32_t time_offset; // to be set on reinit according to last_change timestamp + _Atomic uint32_t last_change; + _Alignas(64) uint8_t kru[]; +}; + +bool kr_cache_top_init(void) { + + return true; +} + +void kr_cache_top_deinit(void) { + +} + +/* text mode: '\0' -> '|' + * hex bytes: + * decimal bytes: <0.1.2.3> + */ +static char *str_key(void *key, size_t len) { + static char str[401]; + if (4 * len + 1 > sizeof(str)) len = (sizeof(str) - 1) / 4; + unsigned char *k = key; + + bool bytes_mode = false; + bool decimal_bytes = false; + int force_bytes = 0; + char *strp = str; + for (size_t i = 0; i < len; i++) { + unsigned char c = k[i]; + if ((force_bytes-- <= 0) && + ((c == 0) || ((c > ' ') && (c <= '~') && (c != '|') && (c != '<') && (c != '>')))) { + //if (c == ' ') c = '_'; + if (c == 0) c = '|'; + if (bytes_mode) { + if (decimal_bytes) strp--; + *strp++ = '>'; + bytes_mode = false; + decimal_bytes = false; + } + *strp++ = c; + if ((i > 0) && (k[i - 1] == '\0') && ((i == 1) || k[i - 2] == '\0')) { + switch (k[i]) { + case 'S': + if (len == 6) decimal_bytes = true; + // pass through + case '3': + force_bytes = INT_MAX; + break; + case 'E': + force_bytes = true; + decimal_bytes = true; + break; + } + } + } else { + if (!bytes_mode) { + *strp++ = '<'; + if (!decimal_bytes) *strp++ = 'x'; + bytes_mode = true; + } + if (decimal_bytes) { + if (c >= 100) *strp++ = '0' + c / 100; + if (c >= 10) *strp++ = '0' + c / 10 % 10; + *strp++ = '0' + c % 10; + *strp++ = '.'; + } else { + *strp++ = "0123456789ABCDEF"[c >> 4]; + *strp++ = "0123456789ABCDEF"[c & 15]; + } + } + } + if (bytes_mode) { + if (decimal_bytes) { + strp--; + } else { + *strp++ = 'x'; + } + *strp++ = '>'; + bytes_mode = false; + } + *strp++ = '\0'; + return str; +} + +void kr_cache_top_access(struct kr_cache_top *top, void *key, size_t len, char *debug_label) { + + VERBOSE_LOG("ACCESS %-19s %s\n", debug_label, str_key(key, len)); +} + +// temporal logging one level under _access +void kr_cache_top_access_cdb(struct kr_cache_top *top, void *key, size_t len, char *debug_label) { + + VERBOSE_LOG("ACCESS %-17s %s\n", debug_label, str_key(key, len)); +} + +uint16_t kr_cache_top_load(void *key, size_t len) { + uint16_t load = 0; + + VERBOSE_LOG("LOAD %s -> %d\n", str_key(key, len), load); + return load; +} diff --git a/lib/cache/top.h b/lib/cache/top.h new file mode 100644 index 000000000..e15c2cc49 --- /dev/null +++ b/lib/cache/top.h @@ -0,0 +1,20 @@ +/* Copyright (C) CZ.NIC, z.s.p.o. + * SPDX-License-Identifier: GPL-3.0-or-later + */ + +struct kr_cache_top; + +KR_EXPORT +bool kr_cache_top_init(void); + +KR_EXPORT +void kr_cache_top_deinit(void); + +KR_EXPORT +void kr_cache_top_access_cdb(struct kr_cache_top *top, void *key, size_t len, char *debug_label); // temporal, TODO remove + +KR_EXPORT +void kr_cache_top_access(struct kr_cache_top *top, void *key, size_t len, char *debug_label); + +KR_EXPORT +uint16_t kr_cache_top_load(void *key, size_t len); diff --git a/lib/meson.build b/lib/meson.build index 94bb80c73..7fe4cec16 100644 --- a/lib/meson.build +++ b/lib/meson.build @@ -7,6 +7,7 @@ libkres_src = files([ 'cache/entry_list.c', 'cache/entry_pkt.c', 'cache/entry_rr.c', + 'cache/top.c', 'cache/knot_pkt.c', 'cache/nsec1.c', 'cache/nsec3.c', @@ -48,6 +49,7 @@ libkres_headers = files([ 'cache/api.h', 'cache/cdb_api.h', 'cache/cdb_lmdb.h', + 'cache/top.h', 'cache/impl.h', 'defines.h', 'dnssec.h', diff --git a/lib/selection.c b/lib/selection.c index ed8ac5a21..4523436ba 100644 --- a/lib/selection.c +++ b/lib/selection.c @@ -9,6 +9,7 @@ #include "lib/selection_iter.h" #include "lib/rplan.h" #include "lib/cache/api.h" +#include "lib/cache/top.h" #include "lib/resolve.h" #include "lib/utils.h" @@ -156,6 +157,7 @@ struct rtt_state get_rtt_state(const uint8_t *ip, size_t len, state = default_rtt_state; } else { // memcpy is safe for unaligned case (on non-x86) memcpy(&state, value.data, sizeof(state)); + kr_cache_top_access(cache->top, key.data, key.len, "get_rtt"); } free(key.data); @@ -174,6 +176,7 @@ int put_rtt_state(const uint8_t *ip, size_t len, struct rtt_state state, int ret = cache->api->write(db, stats, &key, &value, 1); kr_cache_commit(cache); + kr_cache_top_access(cache->top, key.data, key.len, "put_rtt"); free(key.data); return ret; diff --git a/utils/cache_gc/categories.c b/utils/cache_gc/categories.c index aaa1ae538..7b704a7d9 100644 --- a/utils/cache_gc/categories.c +++ b/utils/cache_gc/categories.c @@ -3,6 +3,7 @@ #include #include "lib/utils.h" +#include "lib/cache/top.h" static bool rrtype_is_infrastructure(uint16_t r) { @@ -26,13 +27,15 @@ static unsigned int get_random(int to) } // TODO this is just an example, make this more clever -category_t kr_gc_categorize(gc_record_info_t * info) +category_t kr_gc_categorize(gc_record_info_t * info, void *key, size_t key_len) { category_t res; if (!info->valid) return CATEGORIES - 1; + uint16_t load = kr_cache_top_load(key, key_len); // TODO use it + switch (info->no_labels) { case 0: /* root zone */ res = 5; diff --git a/utils/cache_gc/categories.h b/utils/cache_gc/categories.h index 388fbe782..32d48d66d 100644 --- a/utils/cache_gc/categories.h +++ b/utils/cache_gc/categories.h @@ -7,4 +7,4 @@ typedef uint8_t category_t; #define CATEGORIES 100 // number of categories -category_t kr_gc_categorize(gc_record_info_t * info); +category_t kr_gc_categorize(gc_record_info_t * info, void *key, size_t key_len); diff --git a/utils/cache_gc/kr_cache_gc.c b/utils/cache_gc/kr_cache_gc.c index 4097c8025..0aecb8202 100644 --- a/utils/cache_gc/kr_cache_gc.c +++ b/utils/cache_gc/kr_cache_gc.c @@ -80,8 +80,7 @@ int cb_compute_categories(const knot_db_val_t * key, gc_record_info_t * info, void *vctx) { ctx_compute_categories_t *ctx = vctx; - category_t cat = kr_gc_categorize(info); - (void)key; + category_t cat = kr_gc_categorize(info, key->data, key->len); ctx->categories_sizes[cat] += info->entry_size; ctx->records++; return KNOT_EOK; @@ -99,7 +98,7 @@ int cb_delete_categories(const knot_db_val_t * key, gc_record_info_t * info, void *vctx) { ctx_delete_categories_t *ctx = vctx; - category_t cat = kr_gc_categorize(info); + category_t cat = kr_gc_categorize(info, key->data, key->len); if (cat >= ctx->limit_category) { knot_db_val_t *todelete = dbval_copy(key); size_t used = ctx->used_space + key->len + sizeof(*key);