The branch, master has been updated via f7f65ceb46d s4:dsdb/descriptor: skip duplicates in descriptor_sd_propagation_object() via bd1e667a62d s4:dsdb/descriptor: sort descriptor_changes tree based via ce38b30cdcf s4:dsdb/descriptor: pass parent guid to dsdb_module_schedule_sd_propagation() via b812ade416f s4:dsdb/descriptor: skip duplicates in descriptor_extended_sec_desc_propagation() via 4c32f46a868 s4:dsdb/descriptor: add statistics for security descriptor propagation via 8597cc9d6c8 s4:dsdb/descriptor: split out struct descriptor_transaction via 36ccb98aba8 python/join: improve logging of join_replicate() from 420bbb1d92f wafsamba: require PYTHONHASHSEED=1 to be exported
https://git.samba.org/?p=samba.git;a=shortlog;h=master - Log ----------------------------------------------------------------- commit f7f65ceb46d04e48667e6cba8f3e9b9fd0cd290e Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 12:46:10 2022 +0100 s4:dsdb/descriptor: skip duplicates in descriptor_sd_propagation_object() We're now sure that the security descriptor propagation happened first for parent objects. It means we can safely skip processing the same object twice in descriptor_sd_propagation_object(). For the database with ~ 22000 objects it reduced the commit time from 2m 50s down to 2m 24s. The statistics are changed from: descriptor_prepare_commit: changes: num_registrations=50000 descriptor_prepare_commit: changes: num_registered=22000 descriptor_prepare_commit: changes: num_toplevel=5 descriptor_prepare_commit: changes: num_processed=5200 descriptor_prepare_commit: objects: num_processed=68800 to: descriptor_prepare_commit: changes: num_registrations=50000 descriptor_prepare_commit: changes: num_registered=22000 descriptor_prepare_commit: changes: num_toplevel=5 descriptor_prepare_commit: changes: num_processed=5200 descriptor_prepare_commit: objects: num_processed=22000 descriptor_prepare_commit: objects: num_skipped=41600 It means that we have "changes: num_registered" and "objects: num_processed" exactly match the number of replicated objects. Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> Autobuild-User(master): Stefan Metzmacher <me...@samba.org> Autobuild-Date(master): Wed Mar 30 12:06:21 UTC 2022 on sn-devel-184 commit bd1e667a62d63c51a3b5e43660c7c23dd855785a Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 17:19:31 2022 +0100 s4:dsdb/descriptor: sort descriptor_changes tree based For the hot code path, e.g. the commit after the initial replication, we typically have one descriptor_changes for each object in the database. It means that we most likely have 5 naming contexts/partitions. Except of their head/root object have a valid parent_guid, so can move all of them into the tree structure. Now we start the processing at the partition root objects, which means that we also process all child objects in the same run. While processing these objects we are most likely able to mark their related descriptor_changes structure as done removing it from the hierarchy. With the 22000 object domain it reduces the time spend in the commit stage from 3m 20s down to 2m 50s. The statistics are changed from: descriptor_prepare_commit: changes: num_registrations=50000 descriptor_prepare_commit: changes: num_registered=22000 descriptor_prepare_commit: changes: num_processed=22000 descriptor_prepare_commit: objects: num_processed=80800 to: descriptor_prepare_commit: changes: num_registrations=50000 descriptor_prepare_commit: changes: num_registered=22000 descriptor_prepare_commit: changes: num_toplevel=5 descriptor_prepare_commit: changes: num_processed=5200 descriptor_prepare_commit: objects: num_processed=68800 Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> commit ce38b30cdcf4a8d7225f830b8054c1df1d748da0 Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 15:08:47 2022 +0100 s4:dsdb/descriptor: pass parent guid to dsdb_module_schedule_sd_propagation() This is preparation to optimize the security descriptor propagation in the following commits. Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> commit b812ade416faf6e41e9def5689f9b2e21d7f718f Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 14:36:28 2022 +0100 s4:dsdb/descriptor: skip duplicates in descriptor_extended_sec_desc_propagation() During replication we may need to fallback to using DRS_GET_TGT, which means that we'll get a lot of objects more than once, the most important one it the partition root object. It means we'll also do the security descriptor propagation more than once for these objects, which is extrememly costly for the partition root objects and other objects near the root. I analyzed a domain where we collected ~ 50000 descriptor_changes registrations for the initial replication of ~ 22000 objects in the database. For that domain we spend ~ 4 hours for the security descriptor propagation in descriptor_prepare_commit(), while the replication itself was finished in less than 2 minutes. With this change we reduce the number of registered/processed descriptor_changes down to ~ 22000, while is reduces the time from ~ 4 hours to just ~ 3 minutes 20 seconds! The statitics changed from: descriptor_prepare_commit: changes: num_registered=50000 descriptor_prepare_commit: changes: num_processed=50000 descriptor_prepare_commit: objects: num_processed=12000000 to: descriptor_prepare_commit: changes: num_registrations=50000 descriptor_prepare_commit: changes: num_registered=22000 descriptor_prepare_commit: changes: num_processed=22000 descriptor_prepare_commit: objects: num_processed=80800 Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> commit 4c32f46a8687e96436abd83fd212468709fadb64 Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 16:20:51 2022 +0100 s4:dsdb/descriptor: add statistics for security descriptor propagation In order to analyze the security descriptor propagation we remember how much work we registered/processed. Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> commit 8597cc9d6c85dff8941333a9de4750c714c05cdb Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 14:33:15 2022 +0100 s4:dsdb/descriptor: split out struct descriptor_transaction This will make it easier to add more details to the per transaction state. Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> commit 36ccb98aba815dc96263e2e419f8411e938e08d3 Author: Stefan Metzmacher <me...@samba.org> Date: Thu Feb 10 16:57:01 2022 +0100 python/join: improve logging of join_replicate() It's useful to have timestamps to see the time used for replication and committing. We also warn the user that the committing stage may take some time. Signed-off-by: Stefan Metzmacher <me...@samba.org> Reviewed-by: Andrew Bartlett <abart...@samba.org> ----------------------------------------------------------------------- Summary of changes: python/samba/join.py | 5 +- source4/dsdb/samdb/ldb_modules/acl_util.c | 2 + source4/dsdb/samdb/ldb_modules/descriptor.c | 469 ++++++++++++++++++++++-- source4/dsdb/samdb/ldb_modules/repl_meta_data.c | 9 + source4/dsdb/samdb/samdb.h | 1 + 5 files changed, 456 insertions(+), 30 deletions(-) Changeset truncated at 500 lines: diff --git a/python/samba/join.py b/python/samba/join.py index 4399367c817..91ed6da1147 100644 --- a/python/samba/join.py +++ b/python/samba/join.py @@ -936,7 +936,7 @@ class DCJoinContext(object): def join_replicate(ctx): """Replicate the SAM.""" - print("Starting replication") + ctx.logger.info("Starting replication") ctx.local_samdb.transaction_start() try: source_dsa_invocation_id = misc.GUID(ctx.samdb.get_invocation_id()) @@ -1016,12 +1016,13 @@ class DCJoinContext(object): ctx.source_dsa_invocation_id = source_dsa_invocation_id ctx.destination_dsa_guid = destination_dsa_guid - print("Committing SAM database") + ctx.logger.info("Committing SAM database - this may take some time") except: ctx.local_samdb.transaction_cancel() raise else: ctx.local_samdb.transaction_commit() + ctx.logger.info("Committed SAM database") # A large replication may have caused our LDB connection to the # remote DC to timeout, so check the connection is still alive diff --git a/source4/dsdb/samdb/ldb_modules/acl_util.c b/source4/dsdb/samdb/ldb_modules/acl_util.c index 08a95c1c310..12f00fbff16 100644 --- a/source4/dsdb/samdb/ldb_modules/acl_util.c +++ b/source4/dsdb/samdb/ldb_modules/acl_util.c @@ -327,6 +327,7 @@ uint32_t dsdb_request_sd_flags(struct ldb_request *req, bool *explicit) int dsdb_module_schedule_sd_propagation(struct ldb_module *module, struct ldb_dn *nc_root, struct GUID guid, + struct GUID parent_guid, bool include_self) { struct ldb_context *ldb = ldb_module_get_ctx(module); @@ -341,6 +342,7 @@ int dsdb_module_schedule_sd_propagation(struct ldb_module *module, op->nc_root = nc_root; op->guid = guid; op->include_self = include_self; + op->parent_guid = parent_guid; ret = dsdb_module_extended(module, op, NULL, DSDB_EXTENDED_SEC_DESC_PROPAGATION_OID, diff --git a/source4/dsdb/samdb/ldb_modules/descriptor.c b/source4/dsdb/samdb/ldb_modules/descriptor.c index 8a4c2c3591f..0f221b794d4 100644 --- a/source4/dsdb/samdb/ldb_modules/descriptor.c +++ b/source4/dsdb/samdb/ldb_modules/descriptor.c @@ -42,20 +42,62 @@ #include "auth/auth.h" #include "param/param.h" #include "dsdb/samdb/ldb_modules/util.h" -#include "lib/util/binsearch.h" +#include "lib/util/util_tdb.h" +#include "lib/dbwrap/dbwrap.h" +#include "lib/dbwrap/dbwrap_rbt.h" struct descriptor_changes { struct descriptor_changes *prev, *next; struct ldb_dn *nc_root; struct GUID guid; + struct GUID parent_guid; bool force_self; bool force_children; struct ldb_dn *stopped_dn; + size_t ref_count; + size_t sort_count; +}; + +struct descriptor_transaction { + TALLOC_CTX *mem; + struct { + /* + * We used to have a list of changes, appended with each + * DSDB_EXTENDED_SEC_DESC_PROPAGATION_OID operation. + * + * But the main problem was that a replication + * cycle (mainly the initial replication) calls + * DSDB_EXTENDED_SEC_DESC_PROPAGATION_OID for the + * same object[GUID] more than once. With + * DRSUAPI_DRS_GET_TGT we'll get the naming + * context head object and other top level + * containers, every often. + * + * It means we'll process objects more + * than once and waste a lot of time + * doing the same work again and again. + * + * We use an objectGUID based map in order to + * avoid registering objects more than once. + * In an domain with 22000 object it can + * reduce the work from 4 hours down to ~ 3.5 minutes. + */ + struct descriptor_changes *list; + struct db_context *map; + size_t num_registrations; + size_t num_registered; + size_t num_toplevel; + size_t num_processed; + } changes; + struct { + struct db_context *map; + size_t num_processed; + size_t num_skipped; + } objects; }; struct descriptor_data { - TALLOC_CTX *trans_mem; - struct descriptor_changes *changes; + struct descriptor_transaction transaction; }; struct descriptor_context { @@ -714,6 +756,7 @@ static int descriptor_modify(struct ldb_module *module, struct ldb_request *req) static const char * const current_attrs[] = { "nTSecurityDescriptor", "instanceType", "objectClass", NULL }; + struct GUID parent_guid = { .time_low = 0 }; struct ldb_control *sd_propagation_control; int cmp_ret = -1; @@ -789,6 +832,8 @@ static int descriptor_modify(struct ldb_module *module, struct ldb_request *req) * use for calculation */ if (!ldb_dn_is_null(current_res->msgs[0]->dn) && !(instanceType & INSTANCE_TYPE_IS_NC_HEAD)) { + NTSTATUS status; + parent_dn = ldb_dn_get_parent(req, dn); if (parent_dn == NULL) { return ldb_oom(ldb); @@ -797,7 +842,8 @@ static int descriptor_modify(struct ldb_module *module, struct ldb_request *req) parent_attrs, DSDB_FLAG_NEXT_MODULE | DSDB_FLAG_AS_SYSTEM | - DSDB_SEARCH_SHOW_RECYCLED, + DSDB_SEARCH_SHOW_RECYCLED | + DSDB_SEARCH_SHOW_EXTENDED_DN, req); if (ret != LDB_SUCCESS) { ldb_debug(ldb, LDB_DEBUG_ERROR, "descriptor_modify: Could not find SD for %s\n", @@ -808,6 +854,13 @@ static int descriptor_modify(struct ldb_module *module, struct ldb_request *req) return ldb_operr(ldb); } parent_sd = ldb_msg_find_ldb_val(parent_res->msgs[0], "nTSecurityDescriptor"); + + status = dsdb_get_extended_dn_guid(parent_res->msgs[0]->dn, + &parent_guid, + "GUID"); + if (!NT_STATUS_IS_OK(status)) { + return ldb_operr(ldb); + } } schema = dsdb_get_schema(ldb, req); @@ -898,6 +951,7 @@ static int descriptor_modify(struct ldb_module *module, struct ldb_request *req) ret = dsdb_module_schedule_sd_propagation(module, nc_root, guid, + parent_guid, false); if (ret != LDB_SUCCESS) { return ldb_operr(ldb); @@ -998,10 +1052,22 @@ static int descriptor_rename(struct ldb_module *module, struct ldb_request *req) * does not exit, force SD propagation on * this record (get a new inherited SD from * the potentially new parent + * + * We don't now the parent guid here, + * but we're not in a hot code path here, + * as the "descriptor" module is located + * above the "repl_meta_data", only + * originating changes are handled here. + * + * If it turns out to be a problem we may + * search for the new parent guid. */ + struct GUID parent_guid = { .time_low = 0 }; + ret = dsdb_module_schedule_sd_propagation(module, nc_root, guid, + parent_guid, true); if (ret != LDB_SUCCESS) { return ldb_operr(ldb); @@ -1012,16 +1078,35 @@ static int descriptor_rename(struct ldb_module *module, struct ldb_request *req) return ldb_next_request(module, req); } +static void descriptor_changes_parser(TDB_DATA key, TDB_DATA data, void *private_data) +{ + struct descriptor_changes **c_ptr = (struct descriptor_changes **)private_data; + uintptr_t ptr = 0; + + SMB_ASSERT(data.dsize == sizeof(ptr)); + + memcpy(&ptr, data.dptr, data.dsize); + + *c_ptr = talloc_get_type_abort((void *)ptr, struct descriptor_changes); +} + +static void descriptor_object_parser(TDB_DATA key, TDB_DATA data, void *private_data) +{ + SMB_ASSERT(data.dsize == 0); +} + static int descriptor_extended_sec_desc_propagation(struct ldb_module *module, struct ldb_request *req) { struct descriptor_data *descriptor_private = talloc_get_type_abort(ldb_module_get_private(module), struct descriptor_data); + struct descriptor_transaction *t = &descriptor_private->transaction; struct ldb_context *ldb = ldb_module_get_ctx(module); struct dsdb_extended_sec_desc_propagation_op *op; - TALLOC_CTX *parent_mem = NULL; - struct descriptor_changes *c; + struct descriptor_changes *c = NULL; + TDB_DATA key; + NTSTATUS status; op = talloc_get_type(req->op.extended.data, struct dsdb_extended_sec_desc_propagation_op); @@ -1032,28 +1117,108 @@ static int descriptor_extended_sec_desc_propagation(struct ldb_module *module, return LDB_ERR_PROTOCOL_ERROR; } - if (descriptor_private->trans_mem == NULL) { + if (t->mem == NULL) { return ldb_module_operr(module); } - parent_mem = descriptor_private->trans_mem; + if (GUID_equal(&op->parent_guid, &op->guid)) { + /* + * This is an unexpected situation, + * it should never happen! + */ + DBG_ERR("ERROR: Object %s is its own parent (nc_root=%s)\n", + GUID_string(t->mem, &op->guid), + ldb_dn_get_extended_linearized(t->mem, op->nc_root, 1)); + return ldb_module_operr(module); + } + + /* + * First we check if we already have an registration + * for the given object. + */ + + key = make_tdb_data((const void*)&op->guid, sizeof(op->guid)); + status = dbwrap_parse_record(t->changes.map, key, + descriptor_changes_parser, &c); + if (NT_STATUS_EQUAL(status, NT_STATUS_NOT_FOUND)) { + c = NULL; + status = NT_STATUS_OK; + } + if (!NT_STATUS_IS_OK(status)) { + ldb_debug(ldb, LDB_DEBUG_FATAL, + "dbwrap_parse_record() - %s\n", + nt_errstr(status)); + return ldb_module_operr(module); + } - c = talloc_zero(parent_mem, struct descriptor_changes); if (c == NULL) { - return ldb_module_oom(module); + /* + * Create a new structure if we + * don't know about the object yet. + */ + + c = talloc_zero(t->mem, struct descriptor_changes); + if (c == NULL) { + return ldb_module_oom(module); + } + c->nc_root = ldb_dn_copy(c, op->nc_root); + if (c->nc_root == NULL) { + return ldb_module_oom(module); + } + c->guid = op->guid; } - c->nc_root = ldb_dn_copy(c, op->nc_root); - if (c->nc_root == NULL) { - return ldb_module_oom(module); + + if (ldb_dn_compare(c->nc_root, op->nc_root) != 0) { + /* + * This is an unexpected situation, + * we don't expect the nc root to change + * during a replication cycle. + */ + DBG_ERR("ERROR: Object %s nc_root changed %s => %s\n", + GUID_string(c, &c->guid), + ldb_dn_get_extended_linearized(c, c->nc_root, 1), + ldb_dn_get_extended_linearized(c, op->nc_root, 1)); + return ldb_module_operr(module); } - c->guid = op->guid; + + c->ref_count += 1; + + /* + * always use the last known parent_guid. + */ + c->parent_guid = op->parent_guid; + + /* + * Note that we only set, but don't clear values here, + * it means c->force_self and c->force_children can + * both be true in the end. + */ if (op->include_self) { c->force_self = true; } else { c->force_children = true; } - DLIST_ADD_END(descriptor_private->changes, c); + if (c->ref_count == 1) { + struct TDB_DATA val = make_tdb_data((const void*)&c, sizeof(c)); + + /* + * Remember the change by objectGUID in order + * to avoid processing it more than once. + */ + + status = dbwrap_store(t->changes.map, key, val, TDB_INSERT); + if (!NT_STATUS_IS_OK(status)) { + ldb_debug(ldb, LDB_DEBUG_FATAL, + "dbwrap_parse_record() - %s\n", + nt_errstr(status)); + return ldb_module_operr(module); + } + + DLIST_ADD_END(t->changes.list, c); + t->changes.num_registered += 1; + } + t->changes.num_registrations += 1; return ldb_module_done(req, NULL, NULL, LDB_SUCCESS); } @@ -1094,14 +1259,86 @@ static int descriptor_sd_propagation_object(struct ldb_module *module, struct ldb_message *msg, bool *stop) { + struct descriptor_data *descriptor_private = + talloc_get_type_abort(ldb_module_get_private(module), + struct descriptor_data); + struct descriptor_transaction *t = &descriptor_private->transaction; struct ldb_context *ldb = ldb_module_get_ctx(module); struct ldb_request *sub_req; struct ldb_result *mod_res; struct ldb_control *sd_propagation_control; + struct GUID guid; int ret; + TDB_DATA key; + TDB_DATA empty_val = { .dsize = 0, }; + NTSTATUS status; + struct descriptor_changes *c = NULL; *stop = false; + /* + * We get the GUID of the object + * in order to have the cache key + * for the object. + */ + + status = dsdb_get_extended_dn_guid(msg->dn, &guid, "GUID"); + if (!NT_STATUS_IS_OK(status)) { + return ldb_operr(ldb); + } + key = make_tdb_data((const void*)&guid, sizeof(guid)); + + /* + * Check if we already processed this object. + */ + status = dbwrap_parse_record(t->objects.map, key, + descriptor_object_parser, NULL); + if (NT_STATUS_IS_OK(status)) { + /* + * All work is already one + */ + t->objects.num_skipped += 1; + *stop = true; + return LDB_SUCCESS; + } + if (!NT_STATUS_EQUAL(status, NT_STATUS_NOT_FOUND)) { + ldb_debug(ldb, LDB_DEBUG_FATAL, + "dbwrap_parse_record() - %s\n", + nt_errstr(status)); + return ldb_module_operr(module); + } + + t->objects.num_processed += 1; + + /* + * Remember that we're processing this object. + */ + status = dbwrap_store(t->objects.map, key, empty_val, TDB_INSERT); + if (!NT_STATUS_IS_OK(status)) { + ldb_debug(ldb, LDB_DEBUG_FATAL, + "dbwrap_parse_record() - %s\n", + nt_errstr(status)); + return ldb_module_operr(module); + } + + /* + * Check that if there's a descriptor_change in our list, + * which we may be able to remove from the pending list + * when we processed the object. + */ + + status = dbwrap_parse_record(t->changes.map, key, descriptor_changes_parser, &c); + if (NT_STATUS_EQUAL(status, NT_STATUS_NOT_FOUND)) { + c = NULL; + status = NT_STATUS_OK; + } + if (!NT_STATUS_IS_OK(status)) { + ldb_debug(ldb, LDB_DEBUG_FATAL, + "dbwrap_parse_record() - %s\n", + nt_errstr(status)); + return ldb_module_operr(module); + } + mod_res = talloc_zero(msg, struct ldb_result); if (mod_res == NULL) { return ldb_module_oom(module); @@ -1153,7 +1390,34 @@ static int descriptor_sd_propagation_object(struct ldb_module *module, } if (sd_propagation_control->critical != 0) { - *stop = true; + if (c == NULL) { + /* + * If we don't have a + * descriptor_changes structure + * we're done. + */ + *stop = true; + } else if (!c->force_children) { + /* + * If we don't need to + * propagate to children, + * we're done. + */ + *stop = true; + } + } + + if (c != NULL && !c->force_children) { + /* + * Remove the pending change, + * we already done all required work, + * there's no need to do it again. + * + * Note DLIST_REMOVE() is a noop + * if the element is not part of + * the list. + */ + DLIST_REMOVE(t->changes.list, c); } talloc_free(mod_res); @@ -1176,6 +1440,10 @@ static int descriptor_sd_propagation_msg_sort(struct ldb_message **m1, static int descriptor_sd_propagation_recursive(struct ldb_module *module, struct descriptor_changes *change) { + struct descriptor_data *descriptor_private = + talloc_get_type_abort(ldb_module_get_private(module), + struct descriptor_data); + struct descriptor_transaction *t = &descriptor_private->transaction; struct ldb_result *guid_res = NULL; struct ldb_result *res = NULL; unsigned int i; @@ -1185,6 +1453,8 @@ static int descriptor_sd_propagation_recursive(struct ldb_module *module, int ret; bool stop = false; + t->changes.num_processed += 1; + /* * First confirm this object has children, or exists * (depending on change->force_self) @@ -1205,7 +1475,8 @@ static int descriptor_sd_propagation_recursive(struct ldb_module *module, DSDB_FLAG_NEXT_MODULE | DSDB_FLAG_AS_SYSTEM | DSDB_SEARCH_SHOW_DELETED | - DSDB_SEARCH_SHOW_RECYCLED, + DSDB_SEARCH_SHOW_RECYCLED | + DSDB_SEARCH_SHOW_EXTENDED_DN, NULL, /* parent_req */ "(objectGUID=%s)", GUID_buf_string(&change->guid, @@ -1300,7 +1571,8 @@ static int descriptor_sd_propagation_recursive(struct ldb_module *module, -- Samba Shared Repository