Re: Problem with ldapsearch and scope one in 1.4.0.20

[Mark Reynolds <mreynolds@xxxxxxxxxx>]

On 1/24/19 10:24 AM, Mihai Carabas wrote:
> Hello Mark,
>
> On Thu, Jan 24, 2019 at 4:35 PM Mark Reynolds <mreynolds@xxxxxxxxxx> wrote:
> > On 1/24/19 8:37 AM, Mihai Carabas wrote:
> > > On Thu, Jan 24, 2019 at 12:52 AM William Brown <wbrown@xxxxxxx> wrote:
> > > > > On 24 Jan 2019, at 00:50, Mihai Carabas <mihai.carabas@xxxxxxxxx> wrote:
> > > > >
> > > > > =profesor
> > > > >          42815 42818 42821 42824 42827 42830 42833 42836 42839 42842
> > > > > 42845 42848 43445 43450 45720 52253
> > > > > =profesori
> > > > >          7 68 3232 3648 5457 6259 6268 6270 6275 6278 6280 6282 6304
> > > > > 6308 6323 7098 21827
> > > > Can you also send me the output of :
> > > >
> > > > ldapsearch -b …. -s sub ‘(ou=Profesori)’ entryid
> > > # extended LDIF
> > > #
> > > # LDAPv3
> > > # base <ou=DPPD,ou=People,dc=curs,dc=pub,dc=ro> with scope subtree
> > > # filter: ou=Profesori
> > > # requesting: entryid
> > > #
> > >
> > > # Profesori, DPPD, People, curs.pub.ro
> > > dn: ou=Profesori,ou=DPPD,ou=People,dc=curs,dc=pub,dc=ro
> > > entryid: 3648
> > >
> > > # search result
> > > search: 2
> > > result: 0 Success
> > >
> > > I issued db2index and I have the following output:
> > > the 50% threshold.
> > > [24/Jan/2019:15:14:31.578343786 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Ending pass number 1 ...
> > > [24/Jan/2019:15:14:31.781708885 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Foreman is done; waiting for workers to finish...
> > > [24/Jan/2019:15:14:32.055444491 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers finished; cleaning up...
> > > [24/Jan/2019:15:14:32.259020991 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers cleaned up.
> > > [24/Jan/2019:15:14:32.262209501 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweeping files for merging
> > > later...
> > > [24/Jan/2019:15:14:33.674826562 +0200] - INFO - dblayer_instance_start
> > > - Import is running with nsslapd-db-private-import-mem on; No other
> > > process is allowed to access the database
> > > [24/Jan/2019:15:14:33.975430948 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweep done.
> > > [24/Jan/2019:15:14:33.982718069 +0200] - INFO - import_main_offline -
> > > reindex cursdb: Beginning pass number 2
> > > [24/Jan/2019:15:14:54.035041942 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 204521866.1/sec, recent rate 0.0/sec, hit ratio 0%
> > >
> > > [24/Jan/2019:15:15:14.086428912 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 104755102.1/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:15:34.138688984 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 70409167.0/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:15:54.189761953 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 53024187.5/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:16:14.239427918 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 42524348.4/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:16:34.483660956 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 35495530.5/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:16:54.533827623 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 30460703.5/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:17:14.586325096 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 26676765.1/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:17:34.636106261 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 23729056.3/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:17:54.686551928 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 21367956.2/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:18:14.812847819 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 19434204.5/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:18:34.883738846 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 17821407.4/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:18:54.938178725 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 16455782.3/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:19:14.995408557 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 15284552.3/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:19:35.047817446 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 2) -- average rate
> > > 14221719.2/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:19:35.051470957 +0200] - INFO - import_throw_in_towel
> > > - reindex cursdb: Decided to end this pass because the progress rate
> > > has dropped below the 50% threshold.
> > > [24/Jan/2019:15:19:35.054926468 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Ending pass number 2 ...
> > > [24/Jan/2019:15:19:35.258101594 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Foreman is done; waiting for workers to finish...
> > > [24/Jan/2019:15:19:35.261243303 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers finished; cleaning up...
> > > [24/Jan/2019:15:19:35.464851131 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers cleaned up.
> > > [24/Jan/2019:15:19:35.467968441 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweeping files for merging
> > > later...
> > > [24/Jan/2019:15:19:35.506390559 +0200] - INFO - dblayer_instance_start
> > > - Import is running with nsslapd-db-private-import-mem on; No other
> > > process is allowed to access the database
> > > [24/Jan/2019:15:19:35.731292752 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweep done.
> > > [24/Jan/2019:15:19:35.734380561 +0200] - INFO - import_main_offline -
> > > reindex cursdb: Beginning pass number 3
> > > [24/Jan/2019:15:19:55.782461337 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 214747959.4/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:20:15.834380724 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 107373979.7/sec, recent rate 0.0/sec, hit ratio 0%
> > >
> > >
> > > [24/Jan/2019:15:20:35.886774313 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 71582653.1/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:20:55.938228899 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 53686989.9/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:21:15.988693682 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 42949591.9/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:21:40.661184607 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 34359673.5/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:22:00.820373724 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 29620408.2/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:22:20.872956514 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 26030055.7/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:22:40.928481812 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 23215995.6/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:23:00.983057008 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 20951020.4/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:23:21.398151214 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 19004244.2/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:23:41.466437252 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 17459183.7/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:24:01.517539137 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 16146463.1/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:24:21.568626321 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 15017339.8/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:24:41.726888036 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 3) -- average rate
> > > 14035814.3/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:24:41.731112549 +0200] - INFO - import_throw_in_towel
> > > - reindex cursdb: Decided to end this pass because the progress rate
> > > has dropped below the 50% threshold.
> > > [24/Jan/2019:15:24:41.734400859 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Ending pass number 3 ...
> > > [24/Jan/2019:15:24:41.837514477 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Foreman is done; waiting for workers to finish...
> > > [24/Jan/2019:15:24:41.841081788 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers finished; cleaning up...
> > > [24/Jan/2019:15:24:41.944805808 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Workers cleaned up.
> > > [24/Jan/2019:15:24:41.948172218 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweeping files for merging
> > > later...
> > > [24/Jan/2019:15:24:41.972718294 +0200] - INFO - dblayer_instance_start
> > > - Import is running with nsslapd-db-private-import-mem on; No other
> > > process is allowed to access the database
> > > [24/Jan/2019:15:24:42.277287032 +0200] - INFO -
> > > import_sweep_after_pass - reindex cursdb: Sweep done.
> > > [24/Jan/2019:15:24:42.524714295 +0200] - INFO - import_main_offline -
> > > reindex cursdb: Beginning pass number 4
> > > [24/Jan/2019:15:25:02.589790122 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 4) -- average rate
> > > 214747959.4/sec, recent rate 0.0/sec, hit ratio 0%
> > > [24/Jan/2019:15:25:22.648607831 +0200] - INFO - import_monitor_threads
> > > - reindex cursdb: Processed 8108 entries (pass 4) -- average rate
> > > 107373979.7/sec, recent rate 0.0/sec, hit ratio 0%
> > >
> > > And it takes a long time. What should I do?
> > This is very odd that the index task is not proceeding.  Are there more
> > than 8108 entries in the database?  Or is that the size of the db in
> > entries?
> I have more de 70000 users. So I do not think that is the size of the db.
Okay, hmm this kind of sounds "like" a known issue that was fixed in 
1.4.0.17, but without more info htere is not much I can do about it 
now.  If it ever happens again check the CPU utilization, and grab as 
few of those stack traces.  Then open a new ticket so we can investigate it.
> > If the task is still running can you grab a stack traces using this process:
> >
> > http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
> >
> > Grab  a few stack traces with that gdb command, and send them to us please.
> Unfortunatelly I've closed the db2index command and I've restored the
> Directory Server from a previous backup. I couldn' afford to wait much
> longer.
Understood
> > Then to fix it I think we need to do an export & import of the
> > database.  That will regenerate everything.  If you are using
> > replication then use the "--replication" option with db2ldif, otherwise
> > do not use that option:
> >
> >       dsctl <INSTANCE> stop    --->  You might have to kill the process
> > if the reindex is hanging :-(
> >
> >       dsctl <INSTANCE> db2ldif userroot <LDIF file name> --replication
> >
> > Then import that LDIF
> >
> >       dsctl <INSTANCE> ldif2db userroot <LDIF file name>
> >
> >       dsctl <INSTANCE> start
> >
> >
> > Then retry your search tests.
> This should be done on my restored running instace?

If the search is still acting up I would do this export/import (with 
--replication option) because the backup/restore is just a snap shot.  
db2ldif/ldif2db regenerates all the indexes, etc.  A 70k entry db should 
only take a few seconds to import (assuming the import does not hang on 
entry 8108).

Mark

> I have a replication with Active Directory. This will be affected?
>
> > Regards,
> >
> > Mark
> >
> >
> > > > This is not contingent on db2index, so you can run the db2index and see if that corrects the issue now (if you have not already).
> > > >
> > > > Thanks
> > > >
> > > > —
> > > > Sincerely,
> > > >
> > > > William Brown
> > > > Software Engineer, 389 Directory Server
> > > > SUSE Labs
> > > > _______________________________________________
> > > > 389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> > > > To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx
> > > > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> > > > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> > > > List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx
> > > _______________________________________________
> > > 389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> > > To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx
> > > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> > > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> > > List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx
> _______________________________________________
> 389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx
> Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx
_______________________________________________
389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx
To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx