Single large entry performance issues

[subcon42]

Hi,

I'm seeing a bit of a performance issue with regards to retrieval of individual entries bearing tens of thousands of values for a given attribute type, such as member on an extremely large group entry.

First off, I've ruled out server issues. Although I am testing against a little Raspberry PI running OpenLDAP on my local network, I can retrieve the entry in question from my desktop using the OpenLDAP command-line utility, as well as Apache Directory Studio GUI, within a very reasonable amount of time (ranging from 0.1 -> 0.4 seconds on average).

However, using the go-ldap package (and executing the snippet below), I'm seeing a significant delay in client-side processing time.

Here are the query parameters shared across all tests/tools:

Search base: cn=Extremely_Large_Group_of_Names,ou=Groups,dc=example,dc=com
Search scope: base (in other words, we're calling the above DN directly, and only that DN)
Search filter: (objectClass=*)
Requested attribute(s): member

Note that we're not authenticating, nor are we using transport security of any kind. This is a textbook-simple cleartext/anonymous operation against a very vanilla OpenLDAP DSA (version 2.4.58-1, which is very recent).

Using OpenLDAP CLI (ldapsearch)

$ time ldapsearch -LLLxsbase -b cn=Extremely_Large_Group_of_Names,ou=Groups,dc=example,dc=com member | grep ^member | wc -l

59999                 
real    0m0.111s
user    0m0.031s
sys     0m0.078s

So, 0.1 seconds. This is good, and what I expect.

Using go-ldap

$ time ./perf
2021/06/29 21:15:22 Got *ldap.Entry (len:59999)

real    0m16.412s
user    0m0.469s
sys     0m9.000s

Ouch. 16.4 seconds.

Here is the go code for the perf test executable:

package main

// built using:
// go build -o perf main_perf.go

import (
        "log"

        "github.com/go-ldap/ldap/v3"
)

func main() {

        // Initialize LDAP connection
        dn := `cn=Extremely_Large_Group_of_Names,ou=Groups,dc=example,dc=com`
        dsa := `ldap.example.com`
        l, err := ldap.Dial(`tcp`, dsa+`:389`)
        if err != nil {
                log.Fatal(err)
        }
        defer l.Close()

        // anonymous bind
        err = l.UnauthenticatedBind(``)
        if err != nil {
                log.Fatal(err)
        }

        attrName := `member`
        req := ldap.NewSearchRequest(dn, 0, 0, 0, 0, false, `(objectClass=*)`, []string{attrName}, nil)

        result, err := l.Search(req)
        if err != nil {
                log.Fatal(err)
        }
        ent := result.Entries[0]

        // Report
        log.Printf("Got %T (len:%d)\n", ent, len(ent.GetAttributeValues(attrName)))
}

The test entry looks like the following, though I can reproduce this with any multi-valued attribute on any entry.

dn: cn=Extremely_Large_Group_of_Names,ou=Groups,dc=example,dc=com
objectClass: top
objectClass: groupOfNames
member: uid=account00001,ou=People,dc=example,dc=com
member: uid=account00002,ou=People,dc=example,dc=com
... 59997 other member values omitted for brevity ...

On the server side, I can watch the OpenLDAP daemon logs in real-time, and I definitely see the request finished immediately with a successful result, so I know that (as far as the server is concerned) its job is done and over with. The delay seems to be entirely client-side.

I checked and I have the latest version of go-ldap, having run go get github.com/go-ldap/ldap/v3 before re-testing and filing this issue.

Thanks, please let me know if there are other materials you need, or other tests you wish me to run.

[cpuschma]

I have also encountered this problem. One of the bottlenecks for me was parsing the attributes and the returned values. See #321 ... but none of the maintainers answered or looked into the PR :(

[johnweldon]

I have also encountered this problem. One of the bottlenecks for me was parsing the attributes and the returned values. See #321 ... but none of the maintainers answered or looked into the PR :(

Guilty as charged... merged now. I'll tag a release shortly. Hopefully it'll mitigate the performance issues you're seeing.

[cpuschma]

@johnweldon Thank you for taking care of the library ❤, I don't take that for granted!

I'm currently making a list of things I stumbled upon that could be improved in terms of perfomance. Expect more PRs ^^

[subcon42]

Sadly, I'm still seeing the performance issue. I can't perceive any change in either direction. Using same test app shown in my opening comment.

Time using ldapsearch CLI binary against the same entry: 0.137 seconds.

[cpuschma]

I tried to reproduce your result, but I couldn't. I created an OpenLDAP server (OpenLDAP: slapd 2.4.57+dfsg-1~bpo10+1), 60.000 users and added them to one group

[nevo@mao ~]$ time ldapsearch -D "cn=admin,dc=my-company,dc=com" -b "cn=DE-LEJ-02-All-Users,ou=Groups,ou=LEJ-02,ou=DE,ou=Locations,dc=my-company,dc=com" -w "" "(objectclass=*)" memberUid

real	0m0.132s
user	0m0.037s
sys	0m0.090s

func main() {
	conn, err := ldap.Dial("tcp", "127.0.0.1:389")
	if err != nil {
		fmt.Println(err)
		return
	}

	if err := conn.Bind("cn=admin,dc=my-company,dc=com", ""); err != nil {
		fmt.Println(err)
		return
	}

	start := time.Now()
	result, err := conn.Search(&ldap.SearchRequest{
		BaseDN:       "cn=DE-LEJ-02-All-Users,ou=Groups,ou=LEJ-02,ou=DE,ou=Locations,dc=my-company,dc=com",
		Scope:        0,
		DerefAliases: 0,
		Filter:       "(objectclass=*)",
		Attributes:   []string{"memberUid"},
	})
	if err != nil {
		panic(err)
	}
	_ = result // left during debugging..

	fmt.Printf("%d memberUid entries\n%s\n", len(result.Entries[0].Attributes[0].Values), time.Now().Sub(start).String())
}

Result

60000 memberUid entries
121.874615ms

This result is more than just fine. Would you mind if you share a bit of context of your application or if possible the full source code? I think another factor here is adding alot of delay and not the example you posted.

[subcon42]

Hi sorry for the delay in responding.

Starting from scratch, using a new Go install, I am seeing a considerable improvement performance wise. I think I got poor performance in my previous test due to a bad test build due to issues on my end. I ended up wiping clean and retrying just now -- no issues.

Thank you :)