Creation of keyless list elements takes a lot of time

[olivier-matz-6wind]

Hello,

This problem was observed in sysrepo, in sr_modinfo_generate_config_change_notif(), where a keyless list is built. When working with large configurations with notification replay enabled, a huge amount of time is spent there.

For reference, this is the output of "perf report":

-   79.40%  netopeer2-serve  libyang.so.2.34.1      [.] lyht_insert_with_resize_cb
   - lyht_insert_with_resize_cb
      - 44.34% lyd_insert_hash_add
	 - 44.33% lyd_insert_node
	    - 44.33% _lyd_new_list
		 lyd_new_list
		 sr_modinfo_generate_config_change_notif
		 sr_changes_notify_store
		 sr_apply_changes
		 np2srv_rpc_editconfig_cb
		 sr_shmsub_rpc_listen_call_callback
		 sr_shmsub_rpc_listen_process_rpc_events
		 sr_subscription_process_events
		 sr_shmsub_listen_thread
		 start_thread
		 __clone3 (inlined)
      - 35.00% lyht_resize
	 - lyht_insert_with_resize_cb
	    - 34.98% lyd_insert_hash_add
	       - lyd_insert_node
		  - 34.98% _lyd_new_list
		       lyd_new_list
		       sr_modinfo_generate_config_change_notif
		       sr_changes_notify_store
		       sr_apply_changes
		       np2srv_rpc_editconfig_cb
		       sr_shmsub_rpc_listen_call_callback
		       sr_shmsub_rpc_listen_process_rpc_events
		       sr_subscription_process_events
		       sr_shmsub_listen_thread
		       start_thread
		       __clone3 (inlined)

I reproduced this behavior with a simple test program:

#include <stddef.h>
#include <stdio.h>
#include <time.h>
#include <stdint.h>
#include <errno.h>

#include <libyang/libyang.h>

const char *keyless_list_yang = "module keyless-list {\n"
				"  yang-version 1.1;\n"
				"  namespace \"http://example.com/keyless-list\";\n"
				"  prefix keyless-list;\n"
				"\n"
				"  container root {\n"
				"    config false;\n"
				"    list list {\n"
				"      leaf value {\n"
				"        type uint32;\n"
				"      }\n"
				"    }\n"
				"  }\n"
				"}\n";

const char *key_list_yang = "module key-list {\n"
			   "  yang-version 1.1;\n"
			   "  namespace \"http://example.com/key-list\";\n"
			   "  prefix key-list;\n"
			   "\n"
			   "  container root {\n"
			   "    config false;\n"
			   "    list list {\n"
			   "      key \"value\";\n"
			   "      leaf value {\n"
			   "        type uint32;\n"
			   "      }\n"
			   "    }\n"
			   "  }\n"
			   "}\n";

int generate_list(struct ly_ctx *ctx, const char *yang, const char *root_path, unsigned int count)
{
	struct lys_module *mod = NULL;
	struct lyd_node *root = NULL;
	struct lyd_node *list = NULL;
	struct timespec ts_start;
	struct timespec ts_end;
	char xpath[32];
	char value[16];
	unsigned int i;
	int64_t ms;
	int ret;

	ret = lys_parse_mem(ctx, yang, LYS_IN_YANG, &mod);
	if (ret != LY_SUCCESS) {
		fprintf(stderr, "lys_parse_mem() failed: %s\n", ly_strerrcode(ret));
		goto fail;
	}

	ret = lyd_new_path(NULL, ctx, root_path, NULL, 0, &root);
	if (ret != LY_SUCCESS) {
		fprintf(stderr, "lys_new_path(root) failed: %s\n", ly_strerrcode(ret));
		goto fail;
	}

	if (clock_gettime(CLOCK_MONOTONIC, &ts_start) == -1) {
		fprintf(stderr, "clock_gettime() failed: %s\n", strerror(errno));
		goto fail;
	}

	for (i = 0; i < count; i++) {
		if (yang == key_list_yang) {
			snprintf(xpath, sizeof(xpath), "list[value='%d']", i);
			ret = lyd_new_path(root, ctx, xpath, NULL, 0, &list);
			if (ret != LY_SUCCESS) {
				fprintf(stderr, "lys_new_path(keyless-list root) failed: %s\n", ly_strerrcode(ret));
				goto fail;
			}
		} else {
			ret = lyd_new_list(root, NULL, "list", 0, &list);
			if (ret != LY_SUCCESS) {
				fprintf(stderr, "lys_new_list() failed: %s\n", ly_strerrcode(ret));
				goto fail;
			}

			snprintf(value, sizeof(value), "%d", i);
			ret = lyd_new_term(list, NULL, "value", value, 0, NULL);
			if (ret != LY_SUCCESS) {
				fprintf(stderr, "lys_new_term() failed: %s\n", ly_strerrcode(ret));
				goto fail;
			}
		}
	}

	if (clock_gettime(CLOCK_MONOTONIC, &ts_end) == -1) {
		fprintf(stderr, "clock_gettime() failed: %s\n", strerror(errno));
		goto fail;
	}

	//lyd_print_file(stdout, root, LYD_JSON, LYD_PRINT_WITHSIBLINGS);
	lyd_free_all(root);

	ms = (ts_end.tv_sec - ts_start.tv_sec) * 1000;
	ms += (ts_end.tv_nsec - ts_start.tv_nsec) / 1000000;

	return ms;

fail:
	lyd_free_all(root);
	return -1;
}

int main(int argc, char **argv)
{
	unsigned int counts[] = { 5000, 10000, 20000, 0 };
	struct ly_ctx *ctx = NULL;
	unsigned int *count;
	int keyless_time;
	int key_time;
	int ret;

	(void)argc;
	(void)argv;

	ret = ly_ctx_new(NULL, 0, &ctx);
	if (ret != LY_SUCCESS) {
		fprintf(stderr, "ly_ctx_new() failed: %s\n", ly_strerrcode(ret));
		return 1;
	}

	for (count = &counts[0]; *count != 0; count++) {
		ret = generate_list(ctx, keyless_list_yang, "/keyless-list:root", *count);
		if (ret < 0)
			return 1;
		keyless_time = ret;
		printf("keyless_time(%u): %d ms\n", *count, keyless_time);

		ret = generate_list(ctx, key_list_yang, "/key-list:root", *count);
		if (ret < 0)
			return 1;
		key_time = ret;
		printf("key_time(%u): %d ms\n", *count, key_time);
	}

	ly_ctx_destroy(ctx);

	return 0;
}

Running this program shows that the time spent to add keyless list elements is quadratic:

keyless_time(5000): 320 ms
key_time(5000): 20 ms
keyless_time(10000): 1201 ms
key_time(10000): 40 ms
keyless_time(20000): 4801 ms
key_time(20000): 81 ms

The problem is that the node we are adding in the the children htable always have the same hash, which results in an insertion in the hash table in O(n).

I have a draft set of patches to solve this issue that I would like to discuss. I'm attaching them as a draft pull request.

[olivier-matz-6wind]

After the pull request is applied, the output of the test program is:

keyless_time(5000): 10 ms
key_time(5000): 30 ms
keyless_time(10000): 11 ms
key_time(10000): 38 ms
keyless_time(20000): 23 ms
key_time(20000): 76 ms

[olivier-matz-6wind]

Fixed in #2107