Re: Retro Changelog trimming not working

[Kees Bakker <keesb@xxxxxxx>]

On 13-07-2022 16:31, Thierry Bordaz wrote:

*** EXTERNAL E-MAIL ***

On 7/13/22 3:18 PM, Kees Bakker wrote:

On 13-07-2022 13:39, Kees Bakker wrote:

On 13-07-2022 13:01, Kees Bakker wrote:

Hi,

[...]
In other words, with 1.4.3.28 I don't get to see the message with first_time and cur_time. I'm
quite puzzled how that can happen. The code is like this (stripped a bit):

    if (!ts.ts_s_trimming) {
        int must_trim = 0;
        /* See if we need to trim */
        /* Has enough time elapsed since our last check? */
        if (cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)) {
            /* Is the first entry too old? */
            time_t first_time;
...
            slapi_log_err(SLAPI_LOG_PLUGIN, RETROCL_PLUGIN_NAME,
                          "cltrim: ldrc=%d, first_time=%ld, cur_time=%ld\n",
                          ldrc, first_time, cur_time);
            if (LDAP_SUCCESS == ldrc && first_time > (time_t)0L &&
                first_time + ts.ts_c_max_age < now_maxage)
            {
                must_trim = 1;
            }
        }
        if (must_trim) {
...
        } else {
            slapi_log_err(SLAPI_LOG_PLUGIN, RETROCL_PLUGIN_NAME,
                          "retrocl_housekeeping - changelog does not need to be trimmed\n");
        }
    }

Puzzled, because I don't understand why "cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)"
is FALSE.

Unless, ...
cur_time is the relative time since start of the server (not sure if this is true,
but the code in eq_call_all_rel() seems to suggest it)
ts.ts_s_last_trim is 0 at startup

Shouldn't we compare "first_time" with the current (non-relative) time?

First an answer to Pierre's question
I had nsslapd-changelogmaxage set to 480d. (The reason for that is that I just want to trim
the small subset.)

I changed maxage back to the default 2d. Now I see the this message, quickly after restart.

Jul 13 14:33:13 iparep4.example.com ns-slapd[141407]: [13/Jul/2022:14:33:13.806790126 +0200] - DEBUG - DSRetroclPlugin - cltrim: ldrc=0, first_time=1615990532, cur_time=12006600

I'm now convinced that the logic is (still) flawed. There is still a mix of UTC time and relative time.

        int must_trim = 0;
        /* See if we need to trim */
        /* Has enough time elapsed since our last check? */
        if (cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)) {      <<<< wrong condition
            /* Is the first entry too old? */
            time_t first_time;
            time_t now_maxage = slapi_current_utc_time(); /* real time for trimming candidates */

Hi Kees,

The mix of monotonic/real time was already an issue (https://github.com/389ds/389-ds-base/issues/4869) that was fixed in you version 1.4.3.28-6.

I think 'first_time' is coming from the first registered record in the retroCL.  I wonder if it could be because of an old retroCL DB containing an old value, not matching current monotonic time. Could you dump the first record of the retroCL (dbscan) ?

regards
thierry

    Hi Thierry,
      
      Here is an example of an old changelog entry.
      
      [root@iparep4 ~]# ldapsearch -H ldaps://$HOSTNAME -D "cn=Directory
      Manager" -y p -LLL -o ldif-wrap=no -b
      'changenumber=20000,cn=changelog'
      dn: changenumber=20000,cn=changelog
      objectClass: top
      objectClass: changelogentry
      objectClass: extensibleObject
      targetuniqueid: 23f6980a-87f611eb-872490e8-ab7c8ee8
      changeNumber: 20000
      targetDn:
      idnsName=110,idnsname=30.16.172.in-addr.arpa.,cn=dns,dc=example,dc=com
      changeTime: 20210318152832Z
      changeType: delete
    
    Yes, I know about issue 4869. That's why I am now trying 1.4.3.28
    
    But I want you to take another look at this line
> if (cur_time - ts.ts_s_last_trim
>         >= (ts.ts_c_max_age)) {
>     
    This code has the effect of using "maxage"  to determine when to do
    the trim run!!!.
    This is wrong.
    
    And a few lines further
>             if (LDAP_SUCCESS ==
>         ldrc && first_time > (time_t)0L &&
>                       first_time +
>         ts.ts_c_max_age < now_maxage)
>                   {
>                       must_trim = 1;
>                   }
>     
    Here "maxage" is used the way it should be used, as a maximum age
    for the changelog
    entries. This is good.
    
    If I set maxage to 480 then I have to wait until 480 days after
    restarting the server before it finally
    decides to look at first_time.
    
    Maybe now is also a good time to explain why I set a much higher
    maxage value.
    When trimming finally kicks in (since I now have maxage 2d) then
    entries are being deleted
    at an extreemly slow pace, roughly one per second. But the worse
    part is, the server becomes
    unresponsive after a few minutes. All connected LDAP clients hang,
    without getting a timeout.
    And because plugin debug messages are enabled, I can see that it
    stopped deleting entries.
    -- Kees
  

_______________________________________________
389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx
To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx
Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx
Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure