BTreeFolder2 questions

Hi!

Merry Christmas to all christians, Happy Holidays to the rest of the people who can enjoy them these days and Happy New Year to everyone.

:slight_smile:

I see the index file:
$ ls -l var/filestorage/Data.fs.index
-rw-r--r-- 1 user group 210205001 Dec 10 12:14 var/filestorage/Data.fs.index

I stop and start Plone in the following ways:

1.- Foreground mode (two terminals):

$ bin/zeoserver fg
$ bin/client1 fg

$ Ctrl+C
$ Ctrl+C

2.- Normal mode:

$ bin/plonectl start
$ bin/plonectl stop

Are these OK?

Thanks

MembershipTool.py
delete_localroles=0

bin/plonectl stop
bin/buildout -Nv
bin/plonectl start

The same problem: deleting a user takes 3 minutes (Plone 5.2 with 100,000 users).

The same with:
MembershipTool.py
def deleteMembers(self, member_ids, delete_memberareas=0,
delete_localroles=0, REQUEST=None):
...
# Delete members' local roles.
if delete_localroles:
self.deleteLocalRoles(getUtility(ISiteRoot), member_ids,
reindex=0, recursive=0)

Do I have to disable something else?

Thanks!

Manuel via Plone Community wrote at 2023-2-27 01:59 +0000:

...
Do I have to disable something else?

I suggest you profile the deletion to find out for what the time is used.

There are several tools for profiling. One is dm.zope.profile.

If I have understood correctly, these are the processes that consume the most time (ordered descendingly by time consumed):

     212630522 function calls (210003678 primitive calls) in 217.896 seconds

Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1146149 47.907 0.000 47.907 0.000 {method 'acquire' of 'thread.lock' objects}
33708417 32.141 0.000 32.141 0.000 ro.py:322(_can_choose_base)
11702336 31.867 0.000 33.509 0.000 ro.py:335(_nonempty_bases_ignoring)
100140 7.124 0.000 81.802 0.001 ro.py:416(_merge)
11602197 5.995 0.000 38.136 0.000 ro.py:355(_find_next_C3_base)
6206542/6200089 4.330 0.000 5.679 0.000 {getattr}
53 3.375 0.064 8.915 0.168 ZODBUserManager.py:146(enumerateUsers)
100177 3.136 0.000 89.365 0.001 interface.py:480(changed)
1925573 3.045 0.000 76.121 0.000 {hasattr}
489192 3.001 0.000 15.620 0.000 {built-in method load}
11602197 2.419 0.000 40.555 0.000 ro.py:343(_choose_next_base)
20706227 2.327 0.000 2.327 0.000 {isinstance}
500055/300039 1.935 0.000 99.568 0.000 content.py:128(get)
700048/700042 1.654 0.000 34.931 0.000 content.py:769(getattr)
11702342 1.642 0.000 1.642 0.000 {filter}
221895 1.607 0.000 2.764 0.000 pytz_support.py:251(getitem)
1602070/200202 1.598 0.000 2.224 0.000 adapter.py:969(_lookup)
221899 1.361 0.000 8.887 0.000 DateTime.py:471(_parse_args)
302752/202728 1.356 0.000 103.296 0.001 {method 'adapter_hook' of '_zope_interface_coptimizations.VerifyingBase' objects}
702445 1.327 0.000 32.567 0.000 BTreeFolder2.py:233(getattr)
1550719/1538009 1.124 0.000 3.131 0.000 {method 'get' of 'BTrees.OOBTree.OOBTree' objects}
300579 1.067 0.000 1.067 0.000 ro.py:234(mro)
714595 1.047 0.000 10.057 0.000 threading.py:147(acquire)
11921657 1.040 0.000 1.040 0.000 {method 'get' of 'dict' objects}
1308605 1.038 0.000 1.046 0.000 {method 'providedBy' of '_interface_coptimizations.SpecificationBase' objects}
500085 1.026 0.000 2.932 0.000 schema.py:88(decorator)
221895 1.025 0.000 1.920 0.000 pytz_support.py:219(info)

Should I put the complete list? (there are almost 2400 lines).

Is there a way to improve this?

Thanks!

Note: 100,000 users

The profile output claims to be ordered by "cumulative time", but apparently it is ordered by "tottime".
For the start of the analysis, ordering by "cumulative time" is usually the best approach: it presents the timings mostly in a "caller-callee" order. In the simple case of a function calling other functions not used elsewhere, you will first see the initial function and later on the called functions and can determine how the function costs are distributed (internal time, time for callees). This gets more complex when functions are called from different places, but overall "cumulative time" ordering gives a good overview. In later analysis steps, you can use "caller" or "callee" analysis to get finer information.

Your profile output is almost unreadable (because it has been reformatted). Please remember to put large literal text (such as output from a program) into its own section starting end ending with a line containing ```.
Fortunately, I have received your message via email where the profile output is much more readable.

Because your profile output is ordered by "tottime", heavily used base functions tend to be at the start, In your case acquire. It is almost impossible to determine from such profile output alone what is responsible for those calls.
I know that ClientStorage is using a lock to wait for results from the ZEO IO thread. Therefore, I assume that you are using ZEO and the acquire time mostly corresponds to waits for ZEO responses. "Cumulative time" ordering would give better information.

First full analysis: https://minombre.es/noplone/dm-zope-profile-1

I'll try the caller or callee thing...

Thanks

If I understood correctly, they are the following:

Hugs

Manuel via Plone Community wrote at 2023-10-13 14:18 +0000:

First full analysis: https://minombre.es/noplone/dm-zope-profile-1

The profile tells you:
Most of the time is spent in deleteLocalRoles.
This is not surprising as it visits all objects in your site
(apparently 100.009 objects).

A custom deleteLocalRoles may save some of this time.

Apparently, a significant part of the time is spent in getOrdering.
deleteLocalRoles does not require ordered content items.
Avoiding the ordering may save time.
Instead of MembershipTool.deleteLocalRoles you could call
your own customDeleteLocalRoles.
This could use a catalog search to list all objects in your site
and then call deleteLocalRoles(...reindex=0, recursive=0) on them.

Should this approach still be too slow, you could
introduce a new local_role index which identifies the objects
a specific member has local roles on.
You could use it to list the objects for which one of the members
you are currently deleting has local roles (instead of all objects).

Your custom deleteLocalRoles likely would also replace
reindexObjectSecurity by local updates of the security related
indexes.

1 Like

Manuel via Plone Community wrote at 2023-10-13 15:27 +0000:

If I understood correctly, they are the following:

In your case, the elementary profile is sufficiently clear
to understand what is responsible for the time.
You do not need the finer analysis above.

I've deleted the eggs directory and rebuilt the buildout to make sure I have all .py back to default.

Then I commented the last 6 lines of Products/CMFPlone/controlpanel/browser/usergroups_usersoverview.py:

     # Delete members' local roles.
     #mtool.deleteLocalRoles(
     # getUtility(ISiteRoot),
     # member_ids,
     # reindex=1,
     # recursive=1
     #)

And I have added the following final lines:

    # We ensure that personal folders are deleted
    for member_id in member_ids:
        mtool.deleteMemberArea(member_id)

I have rebuilt and restarted.

Now, deleting one user on a site with 100,000 users and 100,000 objects takes 5 seconds (before was 230 seconds), deleting two users takes 6 seconds, etc.

Wow !!!

Is this secure? (I don't need sharing neither delete local roles)

Thanks!

Manuel via Plone Community wrote at 2023-11-13 00:51 +0000:

...
Is this secure? (I don't need sharing neither delete local roles)

The main problem: a new user might register (in the future) with the same id
(this is usually the login name) as the deleted one. Without
a complete clean up, this new user may "inherit" permissions (and content)
from the deleted one.

To avoid this, I have recommended in the past not to delete users
but to deactivate them, i.e. prevent them to log in.
This prevents a reuse of their user id.

Privacy considerations may force you to delete most (if not all) data of
deleted users. It might be acceptable to retain the user id
to prevent its reuse.

An alternative could be: split the user deletion into two parts,
a synchronous one and and an asynchronous one.
The synchronous one is executed in the user deletion request
and performs the quick (and most important) steps. It also
registers an asynchronous task to perform the complete cleanup
(the second, asynchronous part).
A periodic process (scheduled when your site is usually idle)
looks for asynchronous tasks and executes them.

This allows you to defer the time comsuming parts of user deletion
(e.g. the complete cleanup) until your site is typically mostly idle
(e.g. the night, the week-end).

You can use a similar approach (split into synchronous/inline
and asynchronous/offline parts) for other cases when a request
requires time consuming secondary operations.
There are several packages, e.g. collective.taskqueue,
five.taskqueue to help in its implementation.

Thanks, Dieter.

I have done the following:

  1. Create the user "test", fill in all the details in the profile and personal folder, and create a page within the personal folder (which is a custom dexterity content type: "person").

2.- Delete the "test" user.

3.- Self-register a new user with the same id ("test").

The new user has only inherited one thing from the previous user: their profile picture: /portal_memberdata/portraits/test

I will try with a new site just installed, to see if this is a consequence of my modification or a Plone error (I understand that the normal thing is that the user's image was deleted when deleting the user).

Same problem on a freshly installed Plone 5.2: the profile image (/portal_memberdata/portraits/userid) is not removed when the user is deleted.

It's not a big problem because I can delete it manually before deleting the user, although I'll investigate if it can be fixed (if I don't find a solution, I'll create another thread).

I'll try this in a test site with a million users and a million objects (custom personal folders -dexterity content type "person"-).