Univention Bugzilla – Bug 49329
UMC slow when a lot of OU exist
Last modified: 2019-05-08 22:26:31 CEST
I created a new VM with UCS, installed UCS@School and created 1000 Schools with: #!/bin/bash for i in {1..1000} do /usr/share/ucs-school-import/scripts/create_ou "schule$i" done This process took as expected a long time but afterwards the UMC loads for a long time when i'm opening the schools module or LDAP-directory. After several minutes i get a error message "internal server error". Doing a LDAP-search or similar thing in the terminal works fine.
It seems that we can slow down UMC significantly just by adding more school OUs. I recreated this with a typical UCS Master on our KVM test environment with 1 CPU and 1 GB RAM and UCS 4.4: root@ucs01:~# univention-app info UCS: 4.4-0 errata59 Installed: samba4=4.10 self-service=4.0 ucsschool=4.4 v2 Upgradable: Opening a user (UDM module) takes the following time: 3 school OUs: not measurable, less than 1 second 200 school OUs: > 5 seconds 250 school OUs: > 7 seconds I will attach the UMC udm logfile with debug/level=4 To me it looks like "Loading choices from ou" takes the most time. FYI: The customer system Lukas mentioned in Comment 1 has 4 CPUs and 16 GB RAM, has around 800 OUs, not the best I/O performance and opening a user takes more than 50 seconds.
Created attachment 9991 [details] Logfile UMC udm
From what I can tell, the query for OUs starts in line 1847 at 23:34:18.847. Extended attribute and UMC layout loading then takes until line 2018 at 23:34:20.722. That's 2 seconds that UDM & UMC require without even starting the LDAP query for OUs. Loading choices for each OU then takes about 25ms to 50ms. For OUs [allo, bello, schule1, ...schule234] from 23:34:20.730 to 23:34:26.852. As a medium that is 236 OUs in 6.122 sec = 38.5 OUs/s or 26ms/OU. The whole procedure is repeated another 5 times in the logfile. The last time it takes a little over 7s. That leads me to believe that it has nothing to do with LDAP (or I/O) performance, but is simply the time it takes to transform a huge LDAP response into UDM objects. The UDM-UMC-module does not seem to take even a ms. Please test this theory by running two tests: # time univention-ldapsearch -LLL objectClass=ucsschoolOrganizationalUnit > /dev/null # time udm containers/ou list > /dev/null
Can you attach a logfile of opening a user? Please also compare to the time it takes to list the one user on the cmdline (udm user/user list --filter uid=...).
Hint: It needs to be # time udm container/ou list > /dev/null without the "s" 1. The customer system (UCS 4.2, 802 OUs, 16 GB RAM, 4 CPUs): root@dczen-01:~# time univention-ldapsearch -LLL objectClass=ucsschoolOrganizationalUnit > /dev/null real 0m1.110s user 0m0.564s sys 0m0.048s root@dczen-01:~# time udm container/ou list > /dev/null real 0m35.414s user 0m0.112s sys 0m0.040s 2. My test system (UCS 4.4, 236 OUs, 1 GB RAM, 1 CPU): root@ucs01:~# time univention-ldapsearch -LLL objectClass=ucsschoolOrganizationalUnit > /dev/null real 0m0,602s user 0m0,344s sys 0m0,020s root@ucs01:~# time udm container/ou list > /dev/null real 0m6,281s user 0m0,056s sys 0m0,012s (sorry for the odd number of OUs, seems like my for-Loop to create the school OUs fell apart somewhere on its way to 250 OUs)
(In reply to Daniel Tröder from comment #5) > Please also compare to the time it takes to list the one user on the cmdline > (udm user/user list --filter uid=...). This doesn't seem to make any difference: root@dczen-01:~# time udm users/user list --filter uid=testmailuser10 > /dev/null real 0m0.187s user 0m0.040s sys 0m0.016s root@ucs01:~# time udm users/user list --filter uid=lt.mue2 > /dev/null real 0m0,141s user 0m0,044s sys 0m0,008s > Can you attach a logfile of opening a user? hang on ...
Created attachment 9992 [details] Logfile UMC module udm - opening a user
(In reply to Michael Grandjean from comment #7) > (In reply to Daniel Tröder from comment #5) > > > Please also compare to the time it takes to list the one user on the cmdline > > (udm user/user list --filter uid=...). > > This doesn't seem to make any difference: OK, so there is no problem with the UDM module, but ofc the UMC spends 6s (or 35s) opening all School objects, to create the drop-down for the Schools a user belongs to. At the customer it took 50s, because it had a bad day. It should take as long as it takes to list the Schools (35s) plus 1-2 sec for the usual.
I see four possible ways to tackle this: * massively speedup UDM in general * use pagination in the UDM-UMC module * create the UDM objects in parallel (use more than 1 core) * don't use UDM for listings in selected, simple UMC modules (like in the Schools module), only use it when opening an object for editing (also: don't use UDM for the Schools-drop-down-widget)
Please test this: diff --git a/management/univention-directory-manager-modules/modules/univention/admin/handlers/container/ou.py b/management/univention-directory-manager-modules/modules/univention/admin/handlers/container/ou.py index bcb850005b..d8ae2f58af 100644 --- a/management/univention-directory-manager-modules/modules/univention/admin/handlers/container/ou.py +++ b/management/univention-directory-manager-modules/modules/univention/admin/handlers/container/ou.py @@ -277,6 +277,7 @@ class object(univention.admin.handlers.simpleLdap): lookup = object.lookup +lookup_filter = object.lookup_filter def identify(dn, attr, canonical=0):
In ucs-school-lib Model.get_all() opens all udm objects but then uses this object in Model.from_udm_obj() where it is opened again. This has been removed in ucs-school-lib 12.1.1-4A~4.4.0.201905021355 Now filling the "School" widget in many UCS@school UMC modules is faster, because get_all() takes less time. (Although more speedup comes from Bug#49408) The syntax ucsschoolSchools was not derived from UDM_Objects, which has a flag use_objects. If set to False, this greatly improves the performance, as no UDM objects are created, but we use plain LDAP for the lookup of syntax/choices. This makes opening a user in such an environment faster: ucs-school-import 17.0.6-6A~4.4.0.201905021351
REOPEN: You are missing that container/ou etc. are not providing a lookup_filter() method! Therefore the new syntax class causes an warning message each time: 02.05.19 14:37:34.462 MODULE ( WARN ) : Syntax ucsschoolSchools wants to get optimizations but may not. This is a Bug! We provide a fallback but the syntax will respond much slower than it could! And even more fatal, and I was wondering why I didn't get the above error message, is that: Your changes are only in /usr/share/ucs-school-import/schema/syntax.ucs-school-import.py but not in /usr/share/pyshared/univention/admin/syntax.d/syntax.ucs-school-import.py. You have to re-execute the joinscript and register the latest file!
(In reply to Florian Best from comment #14) > REOPEN: > > You are missing that container/ou etc. are not providing a lookup_filter() > method! > Therefore the new syntax class causes an warning message each time: > 02.05.19 14:37:34.462 MODULE ( WARN ) : Syntax ucsschoolSchools > wants to get optimizations but may not. This is a Bug! We provide a fallback > but the syntax will respond much slower than it could! > > And even more fatal, and I was wondering why I didn't get the above error > message, is that: > Your changes are only in > /usr/share/ucs-school-import/schema/syntax.ucs-school-import.py but not in > /usr/share/pyshared/univention/admin/syntax.d/syntax.ucs-school-import.py. > You have to re-execute the joinscript and register the latest file! Fixed in ucs-school-import 17.0.6-7A~4.4.0.201905021508 and univention-directory-manager-modules 14.0.12-29A~4.4.0.201905021500
Created attachment 10000 [details] Screenshot FYI: It changes the widget into an MultiObjectSelect.
OK: opening of users, ldap directory tree, schools-module in UMC OK: syntax/choices takes 339ms for ~700 schools OK: udm containers/ou list (takes ~4 seconds for ~700 schools) OK: creating schools via UMC or CLI: takes 15-18 seconds per school OK: YAML
UCS@school 4.4 v2 has been released. https://docs.software-univention.de/changelog-ucsschool-4.4v2-de.html If this error occurs again, please clone this bug.