From c7a1377fc69f7ea4534e1974f527b74ab77c75bd Mon Sep 17 00:00:00 2001 From: Thierry Bordaz Date: Oct 25 2019 15:33:38 +0000 Subject: Ticket 50674 - RFE Extend log of operations statistics in access log Bug Description: This ticket is a POC how we can collect and log metrics on operations Fix Description: https://pagure.io/389-ds-base/issue/50674 Reviewed by: ? Platforms tested: F29 Flag Day: no Doc impact: no --- diff --git a/ldap/servers/slapd/back-ldbm/filterindex.c b/ldap/servers/slapd/back-ldbm/filterindex.c index 7e65f73..8ab3ec8 100644 --- a/ldap/servers/slapd/back-ldbm/filterindex.c +++ b/ldap/servers/slapd/back-ldbm/filterindex.c @@ -1030,8 +1030,43 @@ keys2idl( slapi_log_err(SLAPI_LOG_TRACE, "keys2idl", "=> type %s indextype %s\n", type, indextype); for (uint32_t i = 0; ivals[i] != NULL; i++) { IDList *idl2 = NULL; + struct component_keys_lookup *key_stat; + int key_len; + Op_stat *op_stat; idl2 = index_read_ext_allids(pb, be, type, indextype, slapi_value_get_berval(ivals[i]), txn, err, unindexed, allidslimit); + key_stat = (struct component_keys_lookup *) slapi_ch_calloc(1, sizeof(struct component_keys_lookup)); + + /* indextype e.g. "eq" or "sub" (see index.c) */ + if (indextype) { + key_stat->index_type = slapi_ch_strdup(indextype); + } + /* key value e.g. '^st' or 'smith'*/ + key_len = slapi_value_get_length(ivals[i]); + if (key_len) { + key_stat->key = (char *) slapi_ch_calloc(1, key_len + 1); + memcpy(key_stat->key, slapi_value_get_string(ivals[i]), key_len); + } + + /* attribute name e.g. 'uid' */ + if (type) { + key_stat->attribute_type = slapi_ch_strdup(type); + } + + /* Number of lookup IDs with the key */ + key_stat->id_lookup_cnt = idl2 ? idl2->b_nids : 0; + op_stat = op_stat_get_operation_extension(pb); + if (op_stat && op_stat->search_stat) { + if (op_stat->search_stat->keys_lookup) { + /* it already exist key stat. add key_stat at the head */ + key_stat->next = op_stat->search_stat->keys_lookup; + } else { + /* this is the first key stat record */ + key_stat->next = NULL; + } + op_stat->search_stat->keys_lookup = key_stat; + } + #ifdef LDAP_ERROR_LOGGING /* XXX if ( slapd_ldap_debug & LDAP_DEBUG_TRACE ) { XXX */ diff --git a/ldap/servers/slapd/main.c b/ldap/servers/slapd/main.c index b39d95a..28b672b 100644 --- a/ldap/servers/slapd/main.c +++ b/ldap/servers/slapd/main.c @@ -998,6 +998,7 @@ main(int argc, char **argv) * changes are replicated as soon as the replication plugin is started. */ pw_exp_init(); + op_stat_init(); plugin_print_lists(); plugin_startall(argc, argv, NULL /* specific plugin list */); diff --git a/ldap/servers/slapd/operation.c b/ldap/servers/slapd/operation.c index 8590e2d..cfc1112 100644 --- a/ldap/servers/slapd/operation.c +++ b/ldap/servers/slapd/operation.c @@ -651,3 +651,88 @@ slapi_operation_time_expiry(Slapi_Operation *o, time_t timeout, struct timespec { slapi_timespec_expire_rel(timeout, &(o->o_hr_time_rel), expiry); } + +/* + * Operation extension for operation statistics + */ +static int op_stat_objtype = -1; +static int op_stat_handle = -1; + +Op_stat * +op_stat_get_operation_extension(Slapi_PBlock *pb) +{ + Slapi_Operation *op; + + slapi_pblock_get(pb, SLAPI_OPERATION, &op); + return (Op_stat *)slapi_get_object_extension(op_stat_objtype, + op, op_stat_handle); +} + +void +op_stat_set_operation_extension(Slapi_PBlock *pb, Op_stat *op_stat) +{ + Slapi_Operation *op; + + slapi_pblock_get(pb, SLAPI_OPERATION, &op); + slapi_set_object_extension(op_stat_objtype, op, + op_stat_handle, (void *)op_stat); +} + +/* + * constructor for the operation object extension. + */ +static void * +op_stat_constructor(void *object __attribute__((unused)), void *parent __attribute__((unused))) +{ + Op_stat *op_statp = NULL; + op_statp = (Op_stat *)slapi_ch_calloc(1, sizeof(Op_stat)); + op_statp->search_stat = (Op_search_stat *)slapi_ch_calloc(1, sizeof(Op_search_stat)); + + return op_statp; +} +/* + * destructor for the operation object extension. + */ +static void +op_stat_destructor(void *extension, void *object __attribute__((unused)), void *parent __attribute__((unused))) +{ + Op_stat *op_statp = (Op_stat *)extension; + + if (NULL == op_statp) { + return; + } + + if (op_statp->search_stat) { + struct component_keys_lookup *keys, *next; + + /* free all the individual key counter */ + keys = op_statp->search_stat->keys_lookup; + while (keys) { + next = keys->next; + slapi_ch_free((void **) &keys->attribute_type); + slapi_ch_free((void **) &keys->key); + slapi_ch_free((void **) &keys->index_type); + slapi_ch_free((void **) &keys); + keys = next; + } + slapi_ch_free((void **) &op_statp->search_stat); + } + slapi_ch_free((void **) &op_statp); +} + +#define SLAPI_OP_STAT_MODULE "Module to collect operation stat" +/* Called once from main */ +void +op_stat_init(void) +{ + if (slapi_register_object_extension(SLAPI_OP_STAT_MODULE, + SLAPI_EXT_OPERATION, + op_stat_constructor, + op_stat_destructor, + &op_stat_objtype, + &op_stat_handle) != 0) { + slapi_log_err(SLAPI_LOG_ERR, "op_stat_init", + "slapi_register_object_extension failed; " + "operation statistics is not enabled\n"); + } +} \ No newline at end of file diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index 89f7767..536b170 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -1963,7 +1963,55 @@ notes2str(unsigned int notes, char *buf, size_t buflen) return (buf); } +static void +log_op_stat(Slapi_PBlock *pb) +{ + Connection *conn = NULL; + Operation *op = NULL; + Op_stat *op_stat; + + slapi_pblock_get(pb, SLAPI_CONNECTION, &conn); + slapi_pblock_get(pb, SLAPI_OPERATION, &op); + op_stat = op_stat_get_operation_extension(pb); + + if (conn == NULL || op == NULL || op_stat == NULL) { + return; + } + /* process the operation */ + switch (op->o_tag) { + case LDAP_REQ_BIND: + case LDAP_REQ_UNBIND: + case LDAP_REQ_ADD: + case LDAP_REQ_DELETE: + case LDAP_REQ_MODRDN: + case LDAP_REQ_MODIFY: + case LDAP_REQ_COMPARE: + break; + case LDAP_REQ_SEARCH: + if (op_stat->search_stat) { + struct component_keys_lookup *key_info; + for(key_info = op_stat->search_stat->keys_lookup; key_info; key_info = key_info->next) { + slapi_log_access(LDAP_DEBUG_STATS, + "conn=%" PRIu64 " op=%d STAT attribute=%s key(%s)=%s --> count %d\n", + op->o_connid, + op->o_opid, + key_info->attribute_type, key_info->index_type, key_info->key, + key_info->id_lookup_cnt); + } + } + break; + case LDAP_REQ_ABANDON_30: + case LDAP_REQ_ABANDON: + break; + default: + slapi_log_err(SLAPI_LOG_ERR, + "log_op_stat", "Ignoring unknown LDAP request (conn=%" PRIu64 ", tag=0x%lx)\n", + conn->c_connid, op->o_tag); + break; + } + +} static void log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries) { @@ -2110,6 +2158,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries } else { ext_str = ""; } + log_op_stat(pb); slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d RESULT err=%d" " tag=%" BERTAG_T " nentries=%d etime=%s%s%s%s\n", diff --git a/ldap/servers/slapd/slapi-private.h b/ldap/servers/slapd/slapi-private.h index 04c0455..c72eb63 100644 --- a/ldap/servers/slapd/slapi-private.h +++ b/ldap/servers/slapd/slapi-private.h @@ -447,6 +447,26 @@ int operation_is_flag_set(Slapi_Operation *op, int flag); unsigned long operation_get_type(Slapi_Operation *op); LDAPMod **copy_mods(LDAPMod **orig_mods); +struct component_keys_lookup +{ + char *index_type; + char *attribute_type; + char *key; + int id_lookup_cnt; + struct component_keys_lookup *next; +}; +typedef struct op_search_stat +{ + struct component_keys_lookup *keys_lookup; +} Op_search_stat; +typedef struct op_stat +{ + Op_search_stat *search_stat; +} Op_stat; +void op_stat_init(void); +Op_stat *op_stat_get_operation_extension(Slapi_PBlock *pb); +void op_stat_set_operation_extension(Slapi_PBlock *pb, Op_stat *op_stat); + /* * From ldap.h * #define LDAP_MOD_ADD 0x00