upstream/openldap
1
0
Fork 0
mirror of https://git.openldap.org/openldap/openldap.git synced 2026-02-03 20:40:05 -05:00
Code Issues Projects Releases Packages Wiki Activity Actions

ITS#10293 Report syncrepl workload outline in STATS

Browse source
This commit is contained in:
Ondřej Kuzník 2025-12-17 09:57:19 +00:00 committed by Quanah Gibson-Mount
parent 80a75662ae
commit 74d0c6d992
1 changed files with 142 additions and 21 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

163
servers/slapd/syncrepl.c
View file

@ -1372,7 +1372,7 @@ do_syncrep2(
BerVarray syncUUIDs; BerVarray syncUUIDs;
ber_len_t len; ber_len_t len;
ber_tag_t si_tag; ber_tag_t si_tag;
Entry *entry; Entry *entry = NULL;
struct berval bdn; struct berval bdn;
if ( slapd_shutdown ) { if ( slapd_shutdown ) {
@ -1391,6 +1391,22 @@ do_syncrep2(
op->o_tmpfree( syncUUID[0].bv_val, op->o_tmpmemctx ); op->o_tmpfree( syncUUID[0].bv_val, op->o_tmpmemctx );
if ( modlist ) if ( modlist )
slap_mods_free( modlist, 1); slap_mods_free( modlist, 1);
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
now.tv_usec -= si->si_lastcontact.tv_usec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
Debug( LDAP_DEBUG_STATS, "%s DIRSYNC ENTRY "
"dn=\"%s\" state=%d etime=%d.%06d result=%s\n",
si->si_ridtxt, entry ? entry->e_name.bv_val : "NULL",
syncstate, (int)now.tv_sec, (int)now.tv_usec,
rc ? "failed" : "processed" );
}
if ( rc ) if ( rc )
goto done; goto done;
break; break;
@ -1429,7 +1445,7 @@ do_syncrep2(
slap_mods_free( modlist, 1); slap_mods_free( modlist, 1);
} }
if ( rc ) if ( rc )
goto done; goto entry_done;
break; break;
} }
/* we can't work without the control */ /* we can't work without the control */
@ -1451,7 +1467,7 @@ do_syncrep2(
"Sync State control (%s)\n", si->si_ridtxt, bdn.bv_val ); "Sync State control (%s)\n", si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = -1; rc = -1;
goto done; goto entry_done;
} }
} }
if ( rctrlp == NULL ) { if ( rctrlp == NULL ) {
@ -1462,7 +1478,7 @@ do_syncrep2(
rc = -1; rc = -1;
if ( rctrls ) if ( rctrls )
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
goto done; goto entry_done;
} }
ber_init2( ber, &rctrlp->ldctl_value, LBER_USE_DER ); ber_init2( ber, &rctrlp->ldctl_value, LBER_USE_DER );
if ( ber_scanf( ber, "{em" /*"}"*/, &syncstate, &syncUUID[0] ) if ( ber_scanf( ber, "{em" /*"}"*/, &syncstate, &syncUUID[0] )
@ -1472,7 +1488,7 @@ do_syncrep2(
si->si_ridtxt, bdn.bv_val ); si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = -1; rc = -1;
goto done; goto entry_done;
} }
/* FIXME: what if syncUUID is NULL or empty? /* FIXME: what if syncUUID is NULL or empty?
* (happens with back-sql...) */ * (happens with back-sql...) */
@ -1484,7 +1500,7 @@ do_syncrep2(
syncrepl_state2str( syncstate ), bdn.bv_val ); syncrepl_state2str( syncstate ), bdn.bv_val );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = -1; rc = -1;
goto done; goto entry_done;
} }
if ( ber_peek_tag( ber, &len ) == LDAP_TAG_SYNC_COOKIE ) { if ( ber_peek_tag( ber, &len ) == LDAP_TAG_SYNC_COOKIE ) {
if ( ber_scanf( ber, /*"{"*/ "m}", &cookie ) != LBER_ERROR ) { if ( ber_scanf( ber, /*"{"*/ "m}", &cookie ) != LBER_ERROR ) {
@ -1514,14 +1530,15 @@ do_syncrep2(
si->si_too_old = 1; si->si_too_old = 1;
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = 0; rc = 0;
goto done; /* Should we loop instead? */
goto entry_done;
} }
si->si_too_old = 0; si->si_too_old = 0;
/* check pending CSNs too */ /* check pending CSNs too */
if (( rc = get_pmutex( si ))) { if (( rc = get_pmutex( si ))) {
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
goto done; goto entry_done;
} }
i = check_csn_age( si, &bdn, syncCookie.ctxcsn, sid, (cookie_vals *)&si->si_cookieState->cs_pvals, &slot ); i = check_csn_age( si, &bdn, syncCookie.ctxcsn, sid, (cookie_vals *)&si->si_cookieState->cs_pvals, &slot );
@ -1532,7 +1549,8 @@ do_syncrep2(
ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_pmutex ); ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_pmutex );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = 0; rc = 0;
goto done; /* Should we loop instead? */
goto entry_done;
} else { } else {
/* new SID, add it */ /* new SID, add it */
slap_insert_csn_sids( slap_insert_csn_sids(
@ -1547,7 +1565,8 @@ do_syncrep2(
si->si_ridtxt, bdn.bv_val ); si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = 0; rc = 0;
goto done; /* Should we loop instead? */
goto entry_done;
} }
op->o_controls[slap_cids.sc_LDAPsync] = &syncCookie; op->o_controls[slap_cids.sc_LDAPsync] = &syncCookie;
} }
@ -1590,7 +1609,7 @@ logerr:
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
slap_mods_free( modlist, 1 ); slap_mods_free( modlist, 1 );
entry_free( entry ); entry_free( entry );
goto done; goto entry_done;
} }
} }
if ( ( rc = syncrepl_entry( si, op, entry, &modlist, if ( ( rc = syncrepl_entry( si, op, entry, &modlist,
@ -1624,7 +1643,8 @@ logerr:
if ( modlist ) { if ( modlist ) {
slap_mods_free( modlist, 1 ); slap_mods_free( modlist, 1 );
} }
if ( LogTest( LDAP_DEBUG_SYNC ) ) { entry_done:
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now; struct timeval now;
gettimeofday( &now, NULL ); gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec; now.tv_sec -= si->si_lastcontact.tv_sec;
@ -1632,8 +1652,13 @@ logerr:
if ( now.tv_usec < 0 ) { if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000; --now.tv_sec; now.tv_usec += 1000000;
} }
Debug( LDAP_DEBUG_SYNC, "do_syncrep2: %s etime=%d.%06d\n",
si->si_ridtxt, (int)now.tv_sec, (int)now.tv_usec ); Debug( LDAP_DEBUG_STATS, "%s SYNC ENTRY "
"dn=\"%s\" state=%d cookie=%s etime=%d.%06d result=%s\n",
si->si_ridtxt, bdn.bv_val, syncstate,
BER_BVISNULL( &cookie ) ? "" : cookie.bv_val,
(int)now.tv_sec, (int)now.tv_usec,
rc ? "failed" : "processed" );
} }
if ( rc ) if ( rc )
goto done; goto done;
@ -1643,6 +1668,19 @@ logerr:
Debug( LDAP_DEBUG_ANY, Debug( LDAP_DEBUG_ANY,
"do_syncrep2: %s reference received error\n", "do_syncrep2: %s reference received error\n",
si->si_ridtxt ); si->si_ridtxt );
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
now.tv_usec -= si->si_lastcontact.tv_usec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
Debug( LDAP_DEBUG_STATS, "%s SYNC REFERENCE "
"etime=%d.%06d result=failed\n",
si->si_ridtxt, (int)now.tv_sec, (int)now.tv_usec );
}
break; break;
case LDAP_RES_SEARCH_RESULT: case LDAP_RES_SEARCH_RESULT:
@ -1669,7 +1707,7 @@ logerr:
} }
} }
rc = err; rc = err;
goto done; goto result_done;
} }
if ( err ) { if ( err ) {
Debug( LDAP_DEBUG_ANY, Debug( LDAP_DEBUG_ANY,
@ -1687,7 +1725,7 @@ logerr:
rc = SYNC_REPOLL; rc = SYNC_REPOLL;
} }
} }
goto done; goto result_done;
} }
if ( rctrls ) { if ( rctrls ) {
LDAPControl **next = NULL; LDAPControl **next = NULL;
@ -1696,7 +1734,7 @@ logerr:
rc = syncrepl_dirsync_cookie( si, op, rctrls ); rc = syncrepl_dirsync_cookie( si, op, rctrls );
if ( rc == LDAP_SUCCESS ) if ( rc == LDAP_SUCCESS )
rc = SYNC_REPOLL; /* schedule a re-poll */ rc = SYNC_REPOLL; /* schedule a re-poll */
goto done; goto result_done;
} }
#endif #endif
/* NOTE: make sure we use the right one; /* NOTE: make sure we use the right one;
@ -1714,7 +1752,7 @@ logerr:
"Sync State control\n", si->si_ridtxt ); "Sync State control\n", si->si_ridtxt );
ldap_controls_free( rctrls ); ldap_controls_free( rctrls );
rc = SYNC_ERROR; rc = SYNC_ERROR;
goto done; goto result_done;
} }
} }
if ( rctrlp ) { if ( rctrlp ) {
@ -1794,6 +1832,25 @@ logerr:
else else
rc = SYNC_REPOLL; rc = SYNC_REPOLL;
} }
result_done:
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
now.tv_usec -= si->si_lastcontact.tv_usec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
/* Space pointed to by cookie.bv_val is freed but the pointer
* can still work as a discriminator */
Debug( LDAP_DEBUG_STATS, "%s SYNC RESULT "
"err=%d delete=%d cookie=%s etime=%d.%06d result=%s\n",
si->si_ridtxt, err, refreshDeletes != 0,
BER_BVISNULL(&cookie) ? "" : syncCookie.octet_str.bv_val,
(int)now.tv_sec, (int)now.tv_usec,
( si->si_refreshDone || rc == SYNC_REPOLL ) ?
"processed" : "failed" );
}
goto done; goto done;
case LDAP_RES_INTERMEDIATE: case LDAP_RES_INTERMEDIATE:
@ -1802,11 +1859,13 @@ logerr:
rc = ldap_parse_intermediate( si->si_ld, msg, rc = ldap_parse_intermediate( si->si_ld, msg,
&retoid, &retdata, NULL, 0 ); &retoid, &retdata, NULL, 0 );
if ( !rc && !strcmp( retoid, LDAP_SYNC_INFO ) ) { if ( !rc && !strcmp( retoid, LDAP_SYNC_INFO ) ) {
const char *name;
ber_init2( ber, retdata, LBER_USE_DER ); ber_init2( ber, retdata, LBER_USE_DER );
switch ( si_tag = ber_peek_tag( ber, &len ) ) { switch ( si_tag = ber_peek_tag( ber, &len ) ) {
ber_tag_t tag; ber_tag_t tag;
case LDAP_TAG_SYNC_NEW_COOKIE: case LDAP_TAG_SYNC_NEW_COOKIE:
name = "NEW_COOKIE";
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n", "do_syncrep2: %s %s - %s\n",
si->si_ridtxt, si->si_ridtxt,
@ -1832,18 +1891,34 @@ logerr:
break; break;
case LDAP_TAG_SYNC_REFRESH_DELETE: case LDAP_TAG_SYNC_REFRESH_DELETE:
case LDAP_TAG_SYNC_REFRESH_PRESENT: case LDAP_TAG_SYNC_REFRESH_PRESENT:
name = (si_tag == LDAP_TAG_SYNC_REFRESH_PRESENT) ?
"REFRESH_PRESENT" : "REFRESH_DELETE";
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n", "do_syncrep2: %s %s - %s\n",
si->si_ridtxt, si->si_ridtxt,
"LDAP_RES_INTERMEDIATE", "LDAP_RES_INTERMEDIATE", name );
si_tag == LDAP_TAG_SYNC_REFRESH_PRESENT ?
"REFRESH_PRESENT" : "REFRESH_DELETE" );
if ( si->si_refreshDone ) { if ( si->si_refreshDone ) {
Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s " Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s "
"server sent multiple refreshDone " "server sent multiple refreshDone "
"messages? Ending session\n", "messages? Ending session\n",
si->si_ridtxt ); si->si_ridtxt );
rc = LDAP_PROTOCOL_ERROR; rc = LDAP_PROTOCOL_ERROR;
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
now.tv_usec -= si->si_lastcontact.tv_usec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
Debug( LDAP_DEBUG_STATS, "%s SYNC %s "
"refreshDone=%d cookie=%s etime=%d.%06d result=failed\n",
si->si_ridtxt, name, si->si_refreshDone != 0,
BER_BVISNULL(&cookie) ? "" : cookie.bv_val,
(int)now.tv_sec, (int)now.tv_usec );
}
goto done; goto done;
} }
if ( si_tag == LDAP_TAG_SYNC_REFRESH_DELETE ) { if ( si_tag == LDAP_TAG_SYNC_REFRESH_DELETE ) {
@ -1890,6 +1965,7 @@ logerr:
} }
break; break;
case LDAP_TAG_SYNC_ID_SET: case LDAP_TAG_SYNC_ID_SET:
name = "ID_SET";
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n", "do_syncrep2: %s %s - %s\n",
si->si_ridtxt, si->si_ridtxt,
@ -1951,6 +2027,8 @@ logerr:
si->si_ridtxt, (long) si_tag ); si->si_ridtxt, (long) si_tag );
ldap_memfree( retoid ); ldap_memfree( retoid );
ber_bvfree( retdata ); ber_bvfree( retdata );
ldap_msgfree( msg );
msg = NULL;
continue; continue;
} }
@ -1987,6 +2065,49 @@ logerr:
ldap_memfree( retoid ); ldap_memfree( retoid );
ber_bvfree( retdata ); ber_bvfree( retdata );
if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
const char *cookiestr = "";
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
now.tv_usec -= si->si_lastcontact.tv_usec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
if ( !BER_BVISNULL( &cookie ) ) {
cookiestr = syncCookie.octet_str.bv_val;
}
switch ( si_tag ) {
case LDAP_TAG_SYNC_NEW_COOKIE:
Debug( LDAP_DEBUG_STATS, "%s SYNC %s "
"cookie=%s etime=%d.%06d result=%s\n",
si->si_ridtxt, name, cookiestr,
(int)now.tv_sec, (int)now.tv_usec,
rc ? "failed" : "processed" );
break;
case LDAP_TAG_SYNC_REFRESH_DELETE:
case LDAP_TAG_SYNC_REFRESH_PRESENT:
Debug( LDAP_DEBUG_STATS, "%s SYNC %s refreshDone=%d "
"cookie=%s etime=%d.%06d result=%s\n",
si->si_ridtxt, name, si->si_refreshDone != 0,
cookiestr, (int)now.tv_sec, (int)now.tv_usec,
rc ? "failed" : "processed" );
break;
case LDAP_TAG_SYNC_ID_SET:
Debug( LDAP_DEBUG_STATS, "%s SYNC %s refreshDeletes=%d "
"cookie=%s etime=%d.%06d result=%s\n",
si->si_ridtxt, name, refreshDeletes != 0,
cookiestr, (int)now.tv_sec, (int)now.tv_usec,
rc ? "failed" : "processed" );
break;
default:
break;
}
}
if ( rc ) if ( rc )
goto done; goto done;