Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve log delete trace #4906

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
+66 −64
Open

Improve log delete trace #4906

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
129 changes: 65 additions & 64 deletions bdb/file.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3592,7 +3592,7 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
log files greater than that filenum */
lowfilenum = get_lowfilenum_sanclist(bdb_state);
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER, "lowfilenum %d\n", lowfilenum);
logmsg(LOGMSG_USER, "%s: cluster-wide lowfilenum is %d\n", __func__, lowfilenum);

{
struct interned_string *hosts[REPMAX];
Expand All @@ -3617,7 +3617,7 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (sc_logical_lwm < lowfilenum) {
lowfilenum = sc_logical_lwm;
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER, "Setting lowfilenum to %d for schema change logical redo\n", lowfilenum);
logmsg(LOGMSG_USER, "%s: Setting lowfilenum to %d for schema change logical redo\n", __func__, lowfilenum);
}
}
}
Expand All @@ -3642,7 +3642,7 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (gbl_rowlocks) {
rc = bdb_get_file_lwm(bdb_state, NULL, &lwmlsn, &bdberr);
if (rc) {
logmsg(LOGMSG_ERROR, "can't get perm lsn lwm rc %d bdberr %d\n", rc,
logmsg(LOGMSG_ERROR, "%s: can't get perm lsn lwm rc %d bdberr %d\n", __func__, rc,
bdberr);
return;
}
Expand All @@ -3667,17 +3667,17 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (snapylsn.file <= lowfilenum) {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER,
"Setting lowfilenum to %d from %d because snapylsn is "
"%d:%d\n",
"%s: Setting lowfilenum to %d from %d because snapylsn is "
"%d:%d\n", __func__,
snapylsn.file - 1, lowfilenum, snapylsn.file,
snapylsn.offset);
}
lowfilenum = snapylsn.file - 1;
} else {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER,
"Ignoring snapylsn because %d is already <= %d:%d\n",
lowfilenum, snapylsn.file, snapylsn.offset);
"%s: Ignoring snapylsn because %d is already <= %d:%d\n",
__func__, lowfilenum, snapylsn.file, snapylsn.offset);
}
}
}
Expand All @@ -3696,9 +3696,9 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (asoflsn.file <= lowfilenum) {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER,
"Setting lowfilenum to %d from %d because asoflsn is "
"%s: Setting lowfilenum to %d from %d because asoflsn is "
"%d:%d\n",
asoflsn.file - 1, lowfilenum, asoflsn.file,
__func__, asoflsn.file - 1, lowfilenum, asoflsn.file,
asoflsn.offset);
}
lowfilenum = asoflsn.file - 1;
Expand All @@ -3709,16 +3709,16 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (bdb_state->attr->log_delete_low_headroom_breaktime &&
low_headroom_count >
bdb_state->attr->log_delete_low_headroom_breaktime) {
logmsg(LOGMSG_WARN, "low_headroom, but tried %d times and giving up\n",
bdb_state->attr->log_delete_low_headroom_breaktime);
logmsg(LOGMSG_WARN, "%s: low_headroom, but tried %d times and giving up\n",
__func__, bdb_state->attr->log_delete_low_headroom_breaktime);
return;
}

delete_adjacent = 1;
/* ask berk for a list of files that it thinks we can delete */
rc = bdb_state->dbenv->log_archive(bdb_state->dbenv, &list, 0);
if (rc != 0) {
logmsg(LOGMSG_ERROR, "delete_log_files: log_archive failed\n");
logmsg(LOGMSG_ERROR, "%s: log_archive rc(%d)\n", __func__, rc);
return;
}

Expand All @@ -3728,22 +3728,22 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
print(bdb_state, "flushing log file\n");
rc = bdb_state->dbenv->log_flush(bdb_state->dbenv, NULL);
if (rc != 0) {
logmsg(LOGMSG_ERROR, "delete_log_files: log_flush err %d\n", rc);
logmsg(LOGMSG_ERROR, "%s: log_flush rc(%d)\n", __func__, rc);
return;
}

if (bdb_state->attr->use_recovery_start_for_log_deletion) {

if ((rc = __db_find_recovery_start_if_enabled(bdb_state->dbenv,
&recovery_lsn)) != 0) {
logmsg(LOGMSG_ERROR, "__db_find_recovery_start ret %d\n", rc);
logmsg(LOGMSG_ERROR, "%s: __db_find_recovery_start rc(%d)\n", __func__, rc);
return;
}

if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER, "recovery lsn %u:%u\n", recovery_lsn.file,
logmsg(LOGMSG_USER, "%s: recovery lsn %u:%u\n", __func__, recovery_lsn.file,
recovery_lsn.offset);
logmsg(LOGMSG_USER, "lowfilenum %d\n", lowfilenum);
logmsg(LOGMSG_USER, "%s: lowfilenum %d\n", __func__, lowfilenum);
}
}

Expand Down Expand Up @@ -3781,25 +3781,26 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
filenum = get_filenum_from_logfile(logname);

if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER, "considering %s filenum %d\n", *file, filenum);
logmsg(LOGMSG_USER, "%s: considering %s filenum %d\n", __func__, *file, filenum);
}

rc = stat(logname, &logfile_stats);
if (rc != 0)
logmsg(LOGMSG_ERROR, "delete_log_files: stat returned %d\n", rc);
logmsg(LOGMSG_ERROR, "%s: delete_log_files: stat returned %d\n", __func__, rc);

time_t log_age = time(NULL) - logfile_stats.st_mtime;

if (log_age < bdb_state->attr->min_keep_logs_age) {
if (delete_hwm_logs == 0) {
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_ERROR,
"Can't delete log, age %ld not older "
"%s: Can't delete %s, age %ld not older "
"than log delete age %d.\n",
log_age, bdb_state->attr->min_keep_logs_age);
__func__, *file, log_age, bdb_state->attr->min_keep_logs_age);
if (ctrace_info)
ctrace("Can't delete log, age %lld not older than log "
ctrace("Can't delete %s, age %lld not older than log "
"delete age %lld.\n",
*file,
(long long int)log_age,
(long long int)bdb_state->attr->min_keep_logs_age);
break;
Expand All @@ -3808,24 +3809,24 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
else {
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER,
"Log age %ld is younger than min_age "
"%s: %s age %ld is younger than min_age "
"but fall-through: numlogs"
" is %d and high water mark is %d\n",
log_age, numlogs,
__func__, *file, log_age, numlogs,
bdb_state->attr->min_keep_logs_age_hwm);
if (ctrace_info)
ctrace("Log age %ld is younger than min_age but "
ctrace("%s: %s age %ld is younger than min_age but "
"fall-through: numlogs"
" is %d and high water mark is %d\n",
log_age, numlogs,
__func__, *file, log_age, numlogs,
bdb_state->attr->min_keep_logs_age_hwm);
delete_hwm_logs--;
}
}

if (!__checkpoint_ok_to_delete_log(bdb_state->dbenv, filenum)) {
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER, "not ok to delete log, newer than checkpoint\n");
logmsg(LOGMSG_USER, "%s: not ok to delete log %s, newer than checkpoint\n", __func__, *file);
if (ctrace_info)
ctrace("not ok to delete log, newer than checkpoint\n");
break;
Expand All @@ -3834,7 +3835,7 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (recovery_lsn.file != 0 && filenum >= recovery_lsn.file) {
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_DEBUG,
"not ok to delete log, newer than recovery point\n");
"%s: not ok to delete log %s, newer than recovery point\n", __func__, *file);
if (ctrace_info)
ctrace("not ok to delete log, newer than recovery point\n");
break;
Expand All @@ -3845,35 +3846,35 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (!gbl_is_physical_replicant && bdb_state->attr->private_blkseq_enabled &&
!bdb_blkseq_can_delete_log(bdb_state, filenum)) {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER, "skipping log %s filenm %d because it has recent blkseqs\n",
*file, filenum);
logmsg(LOGMSG_USER, "%s: skipping log %s because it has recent blkseqs\n",
__func__, *file);
bdb_blkseq_dumplogs(bdb_state);
}
if (ctrace_info)
ctrace("skipping log %s filenm %d because it has recent blkseqs\n",
*file, filenum);
ctrace("skipping log %s because it has recent blkseqs\n",
*file);
break;
}

if (lwm_lowfilenum != -1 && filenum > lwm_lowfilenum) {
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER, "not ok to delete log %d, newer than the "
logmsg(LOGMSG_USER, "%s: not ok to delete log %s, newer than the "
"lwm_lowfilenum %d\n",
filenum, lwm_lowfilenum);
__func__, *file, lwm_lowfilenum);
if (ctrace_info)
ctrace("not ok to delete log %d, newer than the "
ctrace("not ok to delete log %s, newer than the "
"lwm_lowfilenum %d\n",
filenum, lwm_lowfilenum);
*file, lwm_lowfilenum);
break;
}

int lowest_in_use_modsnap_file = bdb_get_lowest_modsnap_file(bdb_state);
if (lowest_in_use_modsnap_file != -1 && filenum >= lowest_in_use_modsnap_file) {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_USER, "not ok to delete log %d, log file "
logmsg(LOGMSG_USER, "%s: not ok to delete log %s, log file "
"needed to maintain current modsnap "
"transactions\n",
filenum);
__func__, *file);
}
break;
}
Expand All @@ -3885,14 +3886,14 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
if (!bdb_osql_trn_asof_ok_to_delete_log(filenum)) {
Pthread_mutex_unlock(&bdb_gbl_recoverable_lsn_mutex);
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER, "not ok to delete log %d, log file "
logmsg(LOGMSG_USER, "%s: not ok to delete log %s, log file "
"needed to maintain begin-as-of "
"transactions\n",
filenum);
__func__, *file);
if (ctrace_info)
ctrace("not ok to delete log %d, log file needed to "
ctrace("not ok to delete log %s, log file needed to "
"maintain begin-as-of transactions\n",
filenum);
*file);
break;
}
}
Expand All @@ -3904,12 +3905,12 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
bdb_state->attr->min_keep_logs_age, filenum)) {
Pthread_mutex_unlock(&bdb_gbl_recoverable_lsn_mutex);
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_USER, "not ok to delete log, log file needed "
logmsg(LOGMSG_USER, "%s: not ok to delete log %s, log file needed "
"to recover to at least %ds ago\n",
bdb_state->attr->min_keep_logs_age);
__func__, *file, bdb_state->attr->min_keep_logs_age);
if (ctrace_info)
ctrace("not ok to delete log, log file needed to "
"recover to at least %ds ago\n",
ctrace("not ok to delete log %s, log file needed to "
"recover to at least %ds ago\n", *file,
bdb_state->attr->min_keep_logs_age);
break;
}
Expand Down Expand Up @@ -3941,15 +3942,15 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
/* delete this file if we got this far AND it's <= the
* replicated low number */
if (is_low_headroom) {
logmsg(LOGMSG_WARN, "LOW HEADROOM : delete_log_files: deleting "
logmsg(LOGMSG_WARN, "%s: LOW HEADROOM : delete_log_files: deleting "
"logfile: %s\n",
logname);
__func__, *file);
}

print(bdb_state, "%sdelete_log_files: deleting logfile: %s "
"filenum %d lowfilenum was %d\n",
(is_low_headroom) ? "LOW HEADROOM : " : "", logname,
filenum, lowfilenum);
print(bdb_state, "%s: %sdelete_log_files: deleting logfile: %s "
"lowfilenum was %d\n",
__func__, (is_low_headroom) ? "LOW HEADROOM : " : "", *file,
lowfilenum);
print(bdb_state, "filenums: %s\n", filenums_str);
if (gbl_rowlocks)
print(bdb_state, "lwm at log delete time: %u:%u\n",
Expand All @@ -3963,11 +3964,11 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
char *newname = comdb2_location("backup_logfiles_dir", "%s", base);

if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_DEBUG, "backingup log %s to %s\n", logname, newname);
logmsg(LOGMSG_DEBUG, "%s: backing up log %s to %s\n", __func__, logname, newname);
}

if (ctrace_info) {
ctrace("backingup log %s to %s\n", logname, newname);
ctrace("backing up log %s to %s\n", logname, newname);
}

char cmd[4048];
Expand All @@ -3983,19 +3984,19 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
}
if (!deleted) {
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_DEBUG, "deleting log %s %d\n", logname, filenum);
logmsg(LOGMSG_DEBUG, "%s: deleting log %s\n", __func__, logname);
}

if (ctrace_info) {
ctrace("deleting log %s %d\n", logname, filenum);
ctrace("deleting log %s\n", logname);
}

__log_invalidate(filenum);
rc = unlink(logname);
if (rc) {
logmsg(LOGMSG_ERROR,
"delete_log_files: unlink for <%s> returned %d %d\n",
logname, rc, errno);
"%s: unlink for <%s> returned %d %d\n",
__func__, logname, rc, errno);
}
}
} else {
Expand All @@ -4006,13 +4007,13 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
* loop, so don't actually delete so we don't create log holes.
*/
if (bdb_state->attr->debug_log_deletion) {
logmsg(LOGMSG_DEBUG, "not deleting %d, lowfilenum %d adj %d low %d\n",
filenum, lowfilenum, delete_adjacent,
logmsg(LOGMSG_DEBUG, "%s: Not deleting %s, lowfilenum %d adj %d low %d\n",
__func__, *file, lowfilenum, delete_adjacent,
is_low_headroom);
}
if (ctrace_info)
ctrace("not deleting %d, lowfilenum %d adj %d low %d\n",
filenum, lowfilenum, delete_adjacent,
ctrace("not deleting %s, lowfilenum %d adj %d low %d\n",
*file, lowfilenum, delete_adjacent,
is_low_headroom);
delete_adjacent = 0;
}
Expand Down Expand Up @@ -4070,7 +4071,7 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
send_filenum = filenum;

if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_DEBUG, "nothing to delete, at file %d\n", first_log_lsn.file);
logmsg(LOGMSG_DEBUG, "%s: nothing to delete, at file %d\n", __func__, first_log_lsn.file);

if (ctrace_info)
ctrace("nothing to delete, at file %d\n", first_log_lsn.file);
Expand All @@ -4081,9 +4082,9 @@ static void delete_log_files_int(bdb_state_type *bdb_state)
struct hostinfo *h = retrieve_hostinfo(bdb_state->repinfo->myhost_interned);
h->filenum = send_filenum;
if (bdb_state->attr->debug_log_deletion)
logmsg(LOGMSG_WARN, "sending filenum %d\n", send_filenum);
logmsg(LOGMSG_WARN, "%s: sending local lowfilenum (%d) to cluster\n", __func__, send_filenum);
if (ctrace_info)
ctrace("sending filenum %d\n", send_filenum);
ctrace("%s: sending local lowfilenum (%d) to cluster\n", __func__, send_filenum);
}

int bdb_get_low_headroom_count(bdb_state_type *bdb_state)
Expand Down
1 change: 1 addition & 0 deletions tests/logdelete.test/lrl.options
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
setattr LOGFILESIZE 10000000
LOGMEMSIZE 1048576
setattr DEBUG_LOG_DELETION 1
setattr LOGDELETELOWFILENUM -1
setattr MIN_KEEP_LOGS_AGE 60
setattr PRIVATE_BLKSEQ_MAXAGE 60
Expand Down