[6.0.5] WINDOWS IIS Shares slow with large or complex LDAP

[ser72]

Steps Load oC6.0.5 on Windows Server Configure Large or complex LDAP Two scenarios were seen 1) Large flat LDAP with 100000 users 2) Smaller LDAP with embedded groups

Create a file Share the file -- in the user dialog box, enter a letter or more -- Notice there is a delay before any users appear

If you select the SHARE AS LINK option before any users come up above, the link never appears. Selecting outside the share dialog and then attempt to share the file again and the share dialog doesn't appear.

Eventually the share dialog appears -- when the LDAP query has completed.

Once LDAP query has completed, all works for a period of the Cache timeout. While all users are cached, there are no issues. After the cache timeout, when oC must query the LDAP again, the latency appears again.

Seems related to slow LDAP queries.

Sample logs and configuration available on S3 under support/github-issues/core/11002

@blizzz

[DeepDiver1975]

The ldap server is windows ad?

Ad has issues wirh big user numbers

@blizzz

[ser72]

Yes AD,

[ser72]

@blizzz Thoughts?

[blizzz]

If you select the SHARE AS LINK option before any users come up above, the link never appears. Selecting outside the share dialog and then attempt to share the file again and the share dialog doesn't appear.

Possible, that it has to do with the sharing autocomplete. I am not convinced it is blocking yet, but I think we should add a delay before starting the search and also cancel pending operations when user decides to type more to make it more responsive.

A quick search did not help me, I would assume that autocomplete() triggers and async operation, but it sounds a bit like it is not?

cc @schiesbn

[ser72]

@blizzz @schiesbn

Any further updates? I am getting asked by the end users.

[blizzz]

autocomplete itself is async, i.e. should not be blocking.

@ser72 does it only happen on Win IIS?

[ser72]

@blizzz good question. My user is on IIS and I tested on IIS. Will test on Linux and report back.

[ser72]

@blizzz Tested on Linux and saw same behavior.

[ser72]

@blizzz

Any updates? My user is getting anxious.

[ser72]

@craigpg @blizzz This is getting HOT!!! Can we get some traction on this one please?

[blizzz]

Actually i am reserved for Gold right now … however i had another look in the log. It seems they are using PHP 5.3, which does not support LDAP Paged Search. Without it, big LDAP installation simply cannot perform reasonably. (Yes, it is not in documentation yet https://github.com/owncloud/documentation/issues/466).

@ser72 Since PHP 5.3 is officially dead anyway, can you make them go to 5.4 or 5.5? This will be better by far.

[ser72]

@blizzz: Tested in lab LINUX with PHP 5.4.33 and performance is no better.

There is still a long delay between when I enter the first letter in the search box to when the drop down with names appears.

[ser72]

@blizzz Understand you are working Golds, but this is a HOT issue for this user. Any chance you can have a deeper look?

[blizzz]

yes, wiil do, I checked back with @craigpg today.

[blizzz]

What are the sharing settings? Especially interesting whether the user is allowed to share with anybody or limited to users in his own groups?

[ser72]

@blizzz

Open sharing. Users can share with anyone or any group.

[blizzz]

So, what i did:

1. Took 6.0.5 (on 5.5, 5.4 should be the same)
2. Configured solely my AD with almost 950k users in few different OUs
3. Logged in as one of them and typed in one letter.
4. Results appear within 0.26 sec

@ser72 Do you have the logs from your attempt with Linux/PHP 5.4?

[blizzz]

When i disable Paged Results in the code to mimic PHP 5.3, it takes about 7s for users to appear. And in that case i can confirm the behaviour with the shared URL not showing until this is done. Interestingly this takes time (also about 7s) even when i do not search for a user. Can you confirm this as well?

[ser72]

@blizzz Here are the logs when I press "a" in the search box with PHP 5.4.33, oC6.0.5 Ubuntu

NOTE: It takes over a minute to get the list of users. In some instances, it doesn't show up so I have to click out of the share dialog then back in and re-enter the letter. Then it shows up.

{"reqId":"542d2ffac6948","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T10:59:06+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d2ffac6948","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T10:59:06+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d2ffac6948","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T10:59:06+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T10:59:09+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T10:59:09+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T10:59:09+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"getUsers: Options: search a limit 15 offset 0 Filter: (&(|(objectclass=inetOrgPerson))(displayname=*a*))","level":0,"time":"2014-10-02T10:59:10+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  Filter(&(|(objectclass=inetOrgPerson))(displayname=*a*)) base Array\n(\n    [0] => o=University of Virginia,c=US\n)\n attr Array\n(\n    [0] => displayname\n    [1] => dn\n)\n limit 15 offset 0","level":1,"time":"2014-10-02T10:59:10+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:10+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"PHP","message":"ldap_control_paged_result_response(): Result is: Size limit exceeded (4) at \/var\/www\/owncloud605\/apps\/user_ldap\/lib\/ldap.php#41","level":3,"time":"2014-10-02T10:59:11+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"LDAP error Size limit exceeded (4) after calling ldap_control_paged_result_response","level":0,"time":"2014-10-02T10:59:12+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"getUsers: 15 Users found","level":0,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aadil abbas \\28aa4zw\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"LDAP error Size limit exceeded (4) after calling ldap_control_paged_result","level":0,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aadil abbas \\28aa4zw\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaditya krishan kaul \\28akk2es\\29,ou=kasg,ou=arts & sciences graduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaditya krishan kaul \\28akk2es\\29,ou=kasg,ou=arts & sciences graduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaditya padmanabhan kaushik \\28apk2uh\\29,ou=kasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaditya padmanabhan kaushik \\28apk2uh\\29,ou=kasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aakansha jain \\28aj9up\\29,ou=jasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:13+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aakansha jain \\28aj9up\\29,ou=jasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aakash tushar bhuta \\28atb2hv\\29,ou=basu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aakash tushar bhuta \\28atb2hv\\29,ou=basu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aamana feroze \\28af5bf\\29,ou=fasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aamana feroze \\28af5bf\\29,ou=fasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aamna khan \\28ak6zu\\29,ou=kasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aamna khan \\28ak6zu\\29,ou=kasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aamna nadia ahmad \\28ana6f\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aamna nadia ahmad \\28ana6f\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaqil inan mohammad \\28aim3pc\\29,ou=masu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaqil inan mohammad \\28aim3pc\\29,ou=masu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaqil muhammad abdullah \\28ama5kk\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaqil muhammad abdullah \\28ama5kk\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron alemseged \\28aa6fe\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaron alemseged \\28aa6fe\\29,ou=aasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron arnold bentley \\28aab9ct\\29,ou=basu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:14+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaron arnold bentley \\28aab9ct\\29,ou=basu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron blane lawson \\28abl3ba\\29,ou=lasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaron blane lawson \\28abl3ba\\29,ou=lasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron daniel stevens \\28ads9zf\\29,ou=sasg,ou=arts & sciences graduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaron daniel stevens \\28ads9zf\\29,ou=sasg,ou=arts & sciences graduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron edward dlugos \\28aed3da\\29,ou=dasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d2ffd81120","app":"user_ldap","message":"readAttribute: cn=aaron edward dlugos \\28aed3da\\29,ou=dasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T10:59:15+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d304a961ec","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T11:00:26+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d304a961ec","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T11:00:26+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d304a961ec","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:00:26+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}

{"reqId":"542d305985f0e","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T11:00:41+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d305985f0e","app":"user_ldap","message":"Base tree for Groups is empty, using Base DN","level":1,"time":"2014-10-02T11:00:41+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}
{"reqId":"542d305985f0e","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:00:41+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=a"}

As a second log example, I now enter 's':

{"reqId":"542d3151ada82","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:04:49+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"getUsers: Options: search s limit 15 offset 0 Filter: (&(|(objectclass=inetOrgPerson))(displayname=*s*))","level":0,"time":"2014-10-02T11:04:59+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  Filter(&(|(objectclass=inetOrgPerson))(displayname=*s*)) base Array\n(\n    [0] => o=University of Virginia,c=US\n)\n attr Array\n(\n    [0] => displayname\n    [1] => dn\n)\n limit 15 offset 0","level":1,"time":"2014-10-02T11:04:59+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:04:59+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"PHP","message":"ldap_control_paged_result_response(): Result is: Size limit exceeded (4) at \/var\/www\/owncloud605\/apps\/user_ldap\/lib\/ldap.php#41","level":3,"time":"2014-10-02T11:05:01+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"LDAP error Size limit exceeded (4) after calling ldap_control_paged_result_response","level":0,"time":"2014-10-02T11:05:01+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us\n)\n attr entryuuid limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"LDAP error Size limit exceeded (4) after calling ldap_control_paged_result","level":0,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Requested attribute entryuuid not found for cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us","level":0,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us\n)\n attr nsuniqueid limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Setting nsuniqueid as ldapUuidUserAttribute","level":0,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us\n)\n attr nsuniqueid limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:05:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"No DN found for 7d50c87f-4a1a11e4-808aa0c7-b026bd07 on ldap.virginia.edu","level":0,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us\n)\n attr nsuniqueid limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"getUsers: 15 Users found","level":0,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aakash hemang shah \\28ahs2hd\\29,ou=sasu,ou=arts & sciences undergraduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"readAttribute: cn=aakash hemang shah \\28ahs2hd\\29,ou=sasu,ou=arts & sciences undergraduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron david heishman \\28adh5jz\\29,ou=hcug,ou=education graduate,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"readAttribute: cn=aaron david heishman \\28adh5jz\\29,ou=hcug,ou=education graduate,o=university of virginia,c=us found","level":0,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"initializing paged search for  FilterobjectClass=* base Array\n(\n    [0] => cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us\n)\n attr  limit 99999 offset 0","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"Ready for a paged search","level":1,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d3151ada82","app":"user_ldap","message":"readAttribute: cn=aaron fernstrom \\28af4ef\\29,ou=fdag,ou=business,o=university of virginia,c=us found","level":0,"time":"2014-10-02T11:05:03+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}
{"reqId":"542d319a5eb8c","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:06:02+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getItem&itemType=file&itemSource=316&checkReshare=true&checkShares=true"}
{"reqId":"542d31a032e1c","app":"user_ldap","message":"No group filter is specified, LDAP group feature will not be used.","level":1,"time":"2014-10-02T11:06:08+00:00","method":"GET","url":"\/owncloud605\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=s"}

[blizzz]

Cannot reproduce it on 6.0.5 running on Ubuntu 12.04 using PHP 5.3, still fast. I don't really have a clue why it is so slow for you, now.

In the original log there is an error message complaining about a not-found DLL. It does not tell me anything. It may be well enough an configuration issue with the PHP installation about a removed? Sybase module.

{"reqId":"541092b330436","app":"PHP","message":"PHP Startup: Unable to load dynamic library 'C:\\Program Files (x86)\\PHP\\ext\\php_sybase_ct.dll' - The specified module could not be found.\r\n at Unknown#0","level":3,"time":"2014-09-10T18:06:35+00:00","method":"GET","url":"\/owncloud\/index.php\/core\/ajax\/share.php?fetch=getShareWith&search=mark_"}

It is however probably not the cause.

What do you have in common with the original installation that i don't have? any special configuration? apps? network?

[blizzz]

database?

[ser72]

No special configuration or apps. Just out of the box install of oC with LDAP enabled.

I am using Postgresql.

The windows instance is using MYSQL.

[blizzz]

Is there any possibility you could get xdebug running, configure it to profile and provide the result file? See http://www.xdebug.org/docs/profiler (note: it creates file upon every request, please only provide that one from a search action).

[ser72]

@blizzz

I set the following in my php.ini xdebug.profiler_enable = 1 leaving the default folder as /tmp

Then I restarted apache

Doesn't seem to be doing anything. I get no cachegrind.out files at all

[ser72]

@blizzz

Figured it out -- had to install php5-xdebug

Files are here:

support/github-issues/core/11002

[ser72]

Sorry -- I too am using Mysql -- Was thining of the wrong instance when I wrote before.

[blizzz]

@ser72 thank you for the profiling data!

First, none of them indicates a run time of over one minute. The longest one (cachegrind.out.26889) took over 100 seconds, but does not seem to be related to LDAP.

cachegrind.out.26890 indicated that the process run for over 9 seconds. It looks like this one was triggered by the sharing dialog. About 40% of the time is spent by an PHP-internal function which is used to fire up and deal with the LDAP queries. And indeed the source is to look for the users. However, the measured time is only about executing the PHP-internal method (i.e. no LDAP interaction) and this is super-slow here! call_user_func_array is know to be slower than direct calls of the method, however it is called 59 times only (and of those 42 times caused by the LDAP backend).

I could write a different routing to invoke those methods, but before i like to sort out one other aspect (read on).

Then we have 1.3 secs for the actual search in LDAP and 0.7 for sanitizing (of 10k results). These parts should be faster with PHP >= 5.4 (using Paged Seach).

In cachegrind.out.26889 i see that almost all of the time is used by file read operations (3/4 of time) and file write operations (1/4). This seems like one or more file operations and thus unrelated.

Q: What is the setting of the cron job? Is it set to Ajax? If so, could you change it to cron (admin settings) and try again?

The other requests were not related to LDAP and did not take overly long either.

[ser72]

@blizzz

Changed cron to cron. Still took sometime for the names to appear. Perhaps a little quicker, but still a noticeable delay.

See support/github-issues/core/11002/cachegrind

If you want to see this on my server we can do a screen share and I can show you the delay.

[blizzz]

@ser72 again i see the usage of file operations, resulting in > 210 seconds, but there is no LDAP access. The request dealing with the search takes 10.5s this time.

The 210s taking process may just be opening the files interface, possibly? But then it is unwritten how the reported delay can happen. Yes, screen share makes sense.

[blizzz]

Recap of screen share:

• it is the ~10s running process
• i prepare a patch to work around call_user_func_array. Not sure why it performs so badly there there, hopefully we come around this.
• the 10k results should not have happend, since having paged results and a limit. I investigate what is going on here, too.

[blizzz]

@ser72 could you please apply following patch, try again and provide the profiling data?

diff --git a/apps/user_ldap/lib/ldap.php b/apps/user_ldap/lib/ldap.php
index a99c648..9085966 100644
--- a/apps/user_ldap/lib/ldap.php
+++ b/apps/user_ldap/lib/ldap.php
@@ -138,7 +138,20 @@ class LDAP implements ILDAPWrapper {
                $func = 'ldap_' . array_shift($arguments);
                if(function_exists($func)) {
                        $this->preFunctionCall($func, $arguments);
-                       $result = call_user_func_array($func, $arguments);
+
+                       switch (count($arguments)) {
+                               case 0: $result = $func(); break;
+                               case 1: $result = $func($arguments[0]); break;
+                               case 2: $result = $func($arguments[0], $arguments[1]); break;
+                               case 3: $result = $func($arguments[0], $arguments[1], $arguments[2]); break;
+                               case 4: $result = $func($arguments[0], $arguments[1], $arguments[2], $arguments[3]); break;
+                               case 5: $result = $func($arguments[0], $arguments[1], $arguments[2], $arguments[3], $arguments[4]); break;
+                               //actually, because of switch overhead anything more than with 5 arguments will be outperformed by call_user_func_array.
+                               // 6 is added for testing reasons.
+                               case 6: $result = $func($arguments[0], $arguments[1], $arguments[2], $arguments[3], $arguments[4], $arguments[5]); break;
+                               default: $result = call_user_func_array($func, $arguments); break;
+                       }
+
                        $this->postFunctionCall();
                        return $result;
                }
@@ -176,4 +189,4 @@ class LDAP implements ILDAPWrapper {
                $this->curFunc = '';
                $this->curArgs = array();
        }
-}
\ No newline at end of file
+}

[ser72]

Error

(Stripping trailing CRs from patch.) patching file apps/user_ldap/lib/ldap.php Hunk #1 FAILED at 138. Hunk #2 FAILED at 176. 2 out of 2 hunks FAILED -- saving rejects to file apps/user_ldap/lib/ldap.php.rej

[blizzz]

It is 6.0.5, isn't it?

$ patch -p1 < ldap-invoke.patch 
patching file apps/user_ldap/lib/ldap.php

(i saved it as ldap-invole.patch)

[blizzz]

just in case, i left a copy of my patched file in s3, "patched" folder in this issue's folder.

[ser72]

@blizzz

Took the file from the patched folder above and results are still slow. No apparent change

[blizzz]

Do you have a cachegrind file for me?

[ser72]

See support/github-issues/core/11002/cachegrind2

[blizzz]

Ok, we wen't down from ~10.5s to ~7.5s by getting rid of call_user_func_array().

Now, >1/3 of time is spend for 30 ldap_read – let's see whether we can reduce it. And find out why we have 10k answers and reduce it as well.

[blizzz]

I still fail to reproduce the retrievement of 10k results, also using one of the lab's LDAP server.

[ser72]

Interesting -- as you saw on the screen share -- I can reproduce it at will. I also saw this in a lab setup by @jnfrmarks .

@gig13

[blizzz]

Indeed, and i don't doubt it, especially since it has been proven by the profiling info. I will try with PHP 5.4, maybe there is a difference compared to 5.5 (i am not aware of one though).

[blizzz]

Now I run it on a Debian Wheezy with PHP 5.4.4 and LDAP from the lab (that one with 1m users) and what can i say. Works like a charm.

What else is different?

[ser72]

Try this LDAP which is open on the internet for testing purposes:

ldap://ldap.virginia.edu anonymous o=University of Virginia,c=US

[blizzz]

@ser72 the University's LDAP Server does not support Paged Results. It is not in the clients (i.e. ownCloud) power. Since the server does not offer Paged Results we can either get all results (to a server-defined limit, 10k here) or none.

[blizzz]

@ser72 to verify this with the original problem owner, can she run this script https://gist.github.com/blizzz/0b57f85c122dedf34da8 by

php -f serverSupportsPagedResults.php HOST PORT BASE [DN] [PWD]

Examples with output:
$ php -f serverSupportsPagedResults.php ldap://ldap.virginia.edu 389 "o=University of Virginia,c=US"
LDAP Server does not support Paged Results!!
$ php -f serverSupportsPagedResults.php ldap.owncloud.bzoc 7770 "dc=owncloud,dc=bzoc" "uid=owncloudagent,ou=Users,dc=owncloud,dc=bzoc" password
LDAP Server supports Paged Results

to verify this?

All we can do is try to optimize this a little bit, like not using call_user_func_array (patch earlier here) and to reduce some other operations, but we will not become significantly faster. A big directory must support paged results, otherwise it cannot work properly in a web environment.

[ser72]

@blizzz Just so you know -- the LDAP I provided was MY testing LDAP. It is NOT the LDAP used by this end user. They have their own LDAP which exhibits the issue -- even worse than what I was able to show you using this LDAP.

[blizzz]

@ser72 yes, that's why i would like to confirm or refute whether the root of the evil is the same for the end user.

[ser72]

@blizzz Got it. Sorry -- I misread and thought you wanted her to run it against that same LDAP server. Understand now.

Request sent to my user

@gig13 Will follow up with her once I am gone.

[blizzz]

no prob – thx for forwarding.

[gig13]

@blizzz There is an error in the code, "Call to undefined functin ldap_control_paged_result() in serverSupportPagedResults.php on line 22"