#50675 Ticket 50674 - RFE Extend log of operations statistics in access log
Opened 3 months ago by tbordaz. Modified 3 months ago
tbordaz/389-ds-base ticket_50674  into  master

@@ -1030,8 +1030,43 @@ 

      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;

size_t

+ 		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 */

@@ -998,6 +998,7 @@ 

           * changes are replicated as soon as the replication plugin is started.

           */

          pw_exp_init();

+ 		op_stat_init();

tab vs space?

  

          plugin_print_lists();

          plugin_startall(argc, argv, NULL /* specific plugin list */);

@@ -651,3 +651,88 @@ 

  {

      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,

I'm not sure I understand what this object_extension does, how does it work?

+                                         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

@@ -1963,7 +1963,55 @@ 

      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 @@ 

              } 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",

@@ -447,6 +447,26 @@ 

  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

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

Metadata Update from @tbordaz:
- Pull-request tagged with: WIP

3 months ago

I'm not sure I understand what this object_extension does, how does it work?

Yeah, this looks like a really interesting start to how we can profile operations better :)