Bug 1837982

Summary:	ldif2db can be very slow
Product:	Red Hat Enterprise Linux 9	Reporter:	sgouvern
Component:	389-ds-base	Assignee:	LDAP Maintainers <idm-ds-dev-bugs>
Status:	NEW ---	QA Contact:	LDAP QA Team <idm-ds-qe-bugs>
Severity:	low	Docs Contact:
Priority:	low
Version:	9.3	CC:	idm-ds-dev-bugs, mreynolds, msauton, pasik, progier, spichugi, tbordaz, tmihinto, vashirov
Target Milestone:	rc	Keywords:	Triaged
Target Release:	9.3
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	sync-to-jira
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:		Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description sgouvern 2020-05-20 10:26:44 UTC

Description of problem:

When run from the test framework, ldif2db is very slow (average : 200 entries/sec for an ldif file containing 12000 entries).
Stangely, ldif2db run from the command line with the same ldif file is much faster (more than 2000 entries/sec)

Version-Release number of selected component (if applicable):
389-ds-base-1.4.3.8-2.module+el8.3.0+6591+ebfc9766.x86_64


How reproducible:
always


Steps to Reproduce:
1.Run automated test dirsrvtests/tests/suites/import/regression_test.py::test_large_ldif2db_ancestorid_index_creation, (changing num_users to 10000 to have faster results) with DEBUGGING=True to keep at the end the generated ldif file 

(This test is currently under review as pr/51099)


2.Run ldif2db from the command line, using the ldif file created in the test above :
# ldif2db -n test -i '/var/lib/dirsrv/slapd-standalone1/ldif/large_nested.ldif'


Actual results:
For step 1. (ldif2db started from the test framework) traces in the errors log show a very slow import rate:

[20/May/2020:06:00:25.820924564 -0400] - INFO - bdb_import_main - import test: Import complete.  Processed 12047 entries in 62 seconds. (194.31 entries/sec)


For step 2. (ldif2db started from the cli) traces in the errors log show a much faster import rate for the same ldif file :
[20/May/2020:06:03:04.990715437 -0400] - INFO - bdb_import_main - import test: Import complete.  Processed 12047 entries in 5 seconds. (2409.40 entries/sec)


Expected results:

Same behavior observed for ldif2db launched from the testframework and from the cli.
Performances shown using ldif2db in the test framework improved to get closer to the ones obtained with the cli 


Additional info:
In the 1st case (from test framework), traces in the errors log for the ldif file processing :

[20/May/2020:05:59:24.030003867 -0400] - INFO - import_producer - import test: Processing file "/var/lib/dirsrv/slapd-standalone1/ldif/large_nested.ldif"
[20/May/2020:05:59:44.215667926 -0400] - INFO - import_monitor_threads - import test: Processed 4119 entries -- average rate 196.1/sec, recent rate 196.1/sec, hit ratio 0%
[20/May/2020:06:00:04.687489324 -0400] - INFO - import_monitor_threads - import test: Processed 8118 entries -- average rate 198.0/sec, recent rate 198.0/sec, hit ratio 100%
[20/May/2020:06:00:24.511326169 -0400] - INFO - import_producer - import test: Finished scanning file "/var/lib/dirsrv/slapd-standalone1/ldif/large_nested.ldif" (12047 entries)


Traces in the 2nd case (from cli)
[20/May/2020:06:02:59.413316634 -0400] - INFO - import_producer - import test: Processing file "/var/lib/dirsrv/slapd-standalone1/ldif/large_nested.ldif"
[20/May/2020:06:03:03.122115784 -0400] - INFO - import_producer - import test: Finished scanning file "/var/lib/dirsrv/slapd-standalone1/ldif/large_nested.ldif" (12047 entries)

Comment 3 mreynolds 2020-11-02 22:21:25 UTC

While I still can not figure out why imports are slow in the testing framework, I was able to reproduce very slow imports that appears to be systematic.  Here are the steps:

[1]  Attempt an import with a typo in the LDIF file name so that the import fails:

         # dsconf slapd-localhost backend import userroot 1mil-typo.ldif 

[2] Fix the typo and do the import:

         # dsconf localhost backend import userroot 1mil.ldif 

[02/Nov/2020:16:44:06.244158418 -0500] - INFO - import_monitor_threads - import userroot: Processed 58 entries -- average rate 2.9/sec, recent rate 2.9/sec, hit ratio 0%
[02/Nov/2020:16:44:26.281630749 -0500] - INFO - import_monitor_threads - import userroot: Processed 108 entries -- average rate 2.7/sec, recent rate 2.7/sec, hit ratio 100%
[02/Nov/2020:16:44:46.314696042 -0500] - INFO - import_monitor_threads - import userroot: Processed 158 entries -- average rate 2.6/sec, recent rate 2.5/sec, hit ratio 100%
...

[3]  Restart the server, and try the import again:

[02/Nov/2020:16:51:19.259511417 -0500] - INFO - import_monitor_threads - import userroot: Processed 85095 entries -- average rate 4254.8/sec, recent rate 4254.7/sec, hit ratio 0%
[02/Nov/2020:16:51:39.516911186 -0500] - INFO - import_monitor_threads - import userroot: Processed 153041 entries -- average rate 3825.9/sec, recent rate 3825.9/sec, hit ratio 97%
[02/Nov/2020:16:51:59.708787576 -0500] - INFO - import_monitor_threads - import userroot: Processed 217130 entries -- average rate 3618.8/sec, recent rate 3300.9/sec, hit ratio 96%


I can keep reimporting the same LDIF file over and over and the import is fast, but as soon as an import fails all future attempts are really slow until the server is restarted.

Comment 4 mreynolds 2020-11-12 14:44:29 UTC

https://github.com/389ds/389-ds-base/issues/4432  --> This fixes terrible import performance after a import fails (because the cache size was incorrectly set to zero after the failure), but the issue inside of py.test is still a mystery.