diff --git a/bdb/phys_rep_lsn.c b/bdb/phys_rep_lsn.c index 290a5565bf..8b10726501 100644 --- a/bdb/phys_rep_lsn.c +++ b/bdb/phys_rep_lsn.c @@ -18,7 +18,7 @@ logmsg(lvl, "physrep: " __VA_ARGS__); \ } while (0) -int matchable_log_type(int rectype); +int matchable_log_type(DB_ENV *dbenv, int rectype); extern int gbl_physrep_debug; int gbl_physrep_exit_on_invalid_logstream = 0; @@ -126,7 +126,7 @@ int find_log_timestamp(bdb_state_type *bdb_state, time_t time, LOGCOPY_32(&rectype, logrec.data); normalize_rectype(&rectype); - } while (!matchable_log_type(rectype)); + } while (!matchable_log_type(bdb_state->dbenv, rectype)); my_time = get_timestamp_from_matchable_record(logrec.data); if (gbl_physrep_debug) { @@ -194,7 +194,7 @@ static int get_next_matchable(DB_LOGC *logc, LOG_INFO *info, int check_current, LOGCOPY_32(&rectype, logrec->data); normalize_rectype(&rectype); - if (matchable_log_type(rectype) && in_parent_range(&match_lsn, parent_highest, parent_lowest)) { + if (matchable_log_type(logc->dbenv, rectype) && in_parent_range(&match_lsn, parent_highest, parent_lowest)) { if (gbl_physrep_debug) { physrep_logmsg(LOGMSG_USER, "%s: Initial rec {%u:%u} is matchable\n", __func__, info->file, info->offset); @@ -228,7 +228,8 @@ static int get_next_matchable(DB_LOGC *logc, LOG_INFO *info, int check_current, LOGCOPY_32(&rectype, logrec->data); normalize_rectype(&rectype); - matchable = (matchable_log_type(rectype) && in_parent_range(&match_lsn, parent_highest, parent_lowest)); + matchable = + (matchable_log_type(logc->dbenv, rectype) && in_parent_range(&match_lsn, parent_highest, parent_lowest)); } while (!matchable); info->file = match_lsn.file; @@ -565,7 +566,7 @@ int physrep_bdb_wait_for_seqnum(bdb_state_type *bdb_state, DB_LSN *lsn, void *da LOGCOPY_32(&rectype, data); normalize_rectype(&rectype); - if (!matchable_log_type(rectype)) { + if (!matchable_log_type(bdb_state->dbenv, rectype)) { return 0; } diff --git a/berkdb/env/env_recover.c b/berkdb/env/env_recover.c index 88dc233170..ca7a610a12 100644 --- a/berkdb/env/env_recover.c +++ b/berkdb/env/env_recover.c @@ -2507,7 +2507,7 @@ __env_find_verify_recover_start(dbenv, lsnp) do { LOGCOPY_32(&rectype, rec.data); normalize_rectype(&rectype); - } while ((!matchable_log_type(rectype) || log_compare(lsnp, &s_lsn) >= 0) && + } while ((!matchable_log_type(dbenv, rectype) || log_compare(lsnp, &s_lsn) >= 0) && (ret = __log_c_get(logc, lsnp, &rec, DB_PREV)) == 0); if (ret != 0) diff --git a/berkdb/rep/rep_method.c b/berkdb/rep/rep_method.c index 36a797459f..3bb2dad992 100644 --- a/berkdb/rep/rep_method.c +++ b/berkdb/rep/rep_method.c @@ -1197,6 +1197,7 @@ __retrieve_logged_generation_commitlsn(dbenv, lsn, gen) return ret; } +extern int gbl_debug_election; /* * __rep_elect -- * Called after master failure to hold/participate in an election for @@ -1268,7 +1269,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) */ if (in_progress) { *eidp = dbenv->rep_eid; - logmsg(LOGMSG_DEBUG, "%s line %d returning %d master %s egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d returning %d master %s egen is %d\n", __func__, __LINE__, ret, *eidp, *newgen); return (0); } @@ -1276,7 +1278,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) fprintf(stderr, "%s:%d broadcasting REP_MASTER_REQ\n", __FILE__, __LINE__); #endif - logmsg(LOGMSG_DEBUG, "%s start sending master req\n", __func__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s start sending master req\n", __func__); send_master_req(dbenv, __func__, __LINE__); ret = __rep_wait(dbenv, timeout / 4, eidp, newgen, 0, REP_F_EPHASE1); switch (ret) { @@ -1287,7 +1290,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) if (FLD_ISSET(dbenv->verbose, DB_VERB_REPLICATION)) __db_err(dbenv, "Found master %d", *eidp); #endif - logmsg(LOGMSG_DEBUG, "%s line %d returning %d master %s egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d returning %d master %s egen is %d\n", __func__, __LINE__, ret, *eidp, *newgen); return (0); } @@ -1316,7 +1320,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) MUTEX_LOCK(dbenv, db_rep->rep_mutexp); /* WAITSTART pushes us past point of no-return */ - logmsg(LOGMSG_DEBUG, "%s line %d setting PHASE1 clearing TALLY\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting PHASE1 clearing TALLY\n", __func__, __LINE__); F_SET(rep, REP_F_EPHASE1 | REP_F_WAITSTART | REP_F_NOARCHIVE); F_CLR(rep, REP_F_TALLY); @@ -1337,7 +1342,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) /* Tally our own vote */ if (__rep_tally(dbenv, rep, rep->eid, &rep->sites, rep->egen, rep->tally_off, __func__, __LINE__) != 0) { - logmsg(LOGMSG_DEBUG, "%s line %d rep-tally failed, lockdone\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d rep-tally failed, lockdone\n", __func__, __LINE__); goto lockdone; } __rep_cmp_vote(dbenv, rep, &rep->eid, rep->egen, &lsn, priority, @@ -1353,12 +1359,13 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) egen = rep->egen; committed_gen = rep->committed_gen; send_vote2 = (rep->sites >= rep->nsites && rep->w_priority != 0); - logmsg(LOGMSG_DEBUG, "%s line %d send_vote2 is %d, rep->sites is %d, rep->nsites is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d send_vote2 is %d, rep->sites is %d, rep->nsites is %d\n", __func__, __LINE__, send_vote2, rep->sites, rep->nsites); /* If we have all vote1, change to PHASE2 immediately */ if (send_vote2) { - logmsg(LOGMSG_DEBUG, "%s line %d clearing PHASE1 setting PHASE2\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, "%s line %d clearing PHASE1 setting PHASE2\n", __func__, __LINE__); F_SET(rep, REP_F_EPHASE2); F_CLR(rep, REP_F_EPHASE1); if (rep->winner == rep->eid) { @@ -1371,12 +1378,14 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) Pthread_mutex_unlock(&rep_candidate_lock); if (use_committed_gen) { - logmsg(LOGMSG_DEBUG, "%s line %d broadcasting REP_GEN_VOTE1 to all with committed-gen=%d gen=%d egen=%d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d broadcasting REP_GEN_VOTE1 to all with committed-gen=%d gen=%d egen=%d\n", __func__, __LINE__, committed_gen, rep->gen, egen); __rep_send_gen_vote(dbenv, &lsn, nsites, priority, tiebreaker, egen, committed_gen, db_eid_broadcast, REP_GEN_VOTE1); } else { - logmsg(LOGMSG_DEBUG, "%s line %d broadcasting REP_VOTE1 to all (committed-gen=0) gen=%d egen=%d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d broadcasting REP_VOTE1 to all (committed-gen=0) gen=%d egen=%d\n", __func__, __LINE__, rep->gen, egen); __rep_send_vote(dbenv, &lsn, nsites, priority, tiebreaker, egen, db_eid_broadcast, REP_VOTE1); @@ -1395,15 +1404,18 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) #endif /* This increments our election gen */ __rep_elect_done(dbenv, rep, 0, __func__, __LINE__); - logmsg(LOGMSG_DEBUG, "%s line %d returning %d master %s egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d returning %d master %s egen is %d\n", __func__, __LINE__, ret, *eidp, *newgen); return (0); } - logmsg(LOGMSG_DEBUG, "%s line %d going to phase2 because nomaster\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d going to phase2 because nomaster\n", __func__, __LINE__); goto phase2; case DB_ELECTION_GENCHG: case DB_TIMEOUT: - logmsg(LOGMSG_DEBUG, "%s line %d ret is %d break\n", __func__, __LINE__, ret); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d ret is %d break\n", __func__, __LINE__, ret); break; default: goto err; @@ -1428,7 +1440,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) __db_err(dbenv, "Egen changed from %lu to %lu", (u_long)egen, (u_long)rep->egen); #endif - logmsg(LOGMSG_DEBUG, "%s line %d rep egen changed from %d to %d, restarting\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d rep egen changed from %d to %d, restarting\n", __func__, __LINE__, egen, rep->egen); goto restart; } @@ -1438,7 +1451,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) if (rep->sites > rep->nsites / 2) { /* We think we've seen enough to cast a vote. */ - logmsg(LOGMSG_DEBUG, "%s line %d have seen enough votes for vote2\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d have seen enough votes for vote2\n", __func__, __LINE__); send_vote = rep->winner; /* * See if we won. This will make sure we @@ -1454,7 +1468,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) "Counted my vote %d", rep->votes); #endif } - logmsg(LOGMSG_DEBUG, "%s line %d setting PHASE2 clearing PHASE1\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting PHASE2 clearing PHASE1\n", __func__, __LINE__); F_SET(rep, REP_F_EPHASE2); F_CLR(rep, REP_F_EPHASE1); } @@ -1468,7 +1483,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) "Not enough votes to elect: received %d of %d", rep->sites, rep->nsites); #endif - logmsg(LOGMSG_DEBUG, "%s line %d not enough vote1s, failing\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d not enough vote1s, failing\n", __func__, __LINE__); ret = DB_REP_UNAVAIL; goto err; @@ -1477,7 +1493,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) * We have seen enough vote1's. Now we need to wait * for all the vote2's. */ - logmsg(LOGMSG_DEBUG, "%s line %d have seen enough votes to cast vote2!\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d have seen enough votes to cast vote2!\n", __func__, __LINE__); if (send_vote != rep->eid) { #ifdef DIAGNOSTIC if (FLD_ISSET(dbenv->verbose, DB_VERB_REPLICATION) && @@ -1485,13 +1502,15 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) __db_err(dbenv, "Sending vote"); #endif if (use_committed_gen) { - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_GEN_VOTE2 to %s " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_GEN_VOTE2 to %s " "with committed-gen=%d gen=%d egen=%d\n", __func__, __LINE__, send_vote, committed_gen, rep->gen, egen); __rep_send_gen_vote(dbenv, NULL, 0, 0, 0, egen, committed_gen, send_vote, REP_GEN_VOTE2); } else { - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_VOTE2 to %s " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_VOTE2 to %s " "(committed-gen=0) gen=%d egen=%d\n", __func__, __LINE__, send_vote, rep->gen, egen); __rep_send_vote(dbenv, NULL, 0, 0, 0, egen, @@ -1510,7 +1529,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) case 0: /* Increment our election gen */ __rep_elect_done(dbenv, rep, 0, __func__, __LINE__); - logmsg(LOGMSG_DEBUG, "%s line %d returning %d master %s egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d returning %d master %s egen is %d\n", __func__, __LINE__, ret, *eidp, *newgen); return (0); case DB_TIMEOUT: @@ -1530,7 +1550,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) if (send_vote == rep->eid && done) { if (nsites == 1) __rep_elect_master(dbenv, rep, eidp); - logmsg(LOGMSG_DEBUG, "%s line %d elected master %s current-egen " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d elected master %s current-egen " "%d\n", __func__, __LINE__, rep->eid, rep->egen); ret = 0; goto lockdone; @@ -1548,7 +1569,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) * from elect_init where we were unable to grow_sites. In * that case we do not want to discard all known election info. */ - logmsg(LOGMSG_DEBUG, "%s line %d ret is %d\n", __func__, __LINE__, ret); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d ret is %d\n", __func__, __LINE__, ret); assert(ret == 0 || ret == DB_REP_UNAVAIL); if (ret == 0 || ret == DB_REP_UNAVAIL) { __rep_elect_done(dbenv, rep, 0, __func__, __LINE__); @@ -1558,7 +1580,8 @@ __rep_elect(dbenv, nsites, priority, timeout, newgen, already_master, eidp) Pthread_mutex_unlock(&rep_candidate_lock); MUTEX_UNLOCK(dbenv, db_rep->rep_mutexp); - logmsg(LOGMSG_DEBUG, "%s line %d returning %d master %s egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d returning %d master %s egen is %d\n", __func__, __LINE__, ret, *eidp, *newgen); return (ret); } @@ -1590,7 +1613,8 @@ __rep_elect_init(dbenv, lsnp, nsites, priority, beginp, otally) /* If we are already a master; simply broadcast that fact and return. */ if (F_ISSET(rep, REP_F_MASTER)) { - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_NEWMASTER\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_NEWMASTER\n", __func__, __LINE__); (void)__rep_send_message(dbenv, db_eid_broadcast, REP_NEWMASTER, lsnp, NULL, 0, NULL); @@ -1615,7 +1639,8 @@ __rep_elect_init(dbenv, lsnp, nsites, priority, beginp, otally) DB_ENV_TEST_RECOVERY(dbenv, DB_TEST_ELECTINIT, ret, NULL); rep->nsites = nsites; rep->priority = priority; - logmsg(LOGMSG_DEBUG, "%s line %d setting master_id to %s\n", __func__, __LINE__, db_eid_invalid); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting master_id to %s\n", __func__, __LINE__, db_eid_invalid); rep->master_id = db_eid_invalid; } DB_TEST_RECOVERY_LABEL @@ -1636,7 +1661,8 @@ __rep_elect_master(dbenv, rep, eidp) REP *rep; char **eidp; { - logmsg(LOGMSG_DEBUG, "%s line %d setting master_id to %s\n", __func__, __LINE__, rep->eid); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting master_id to %s\n", __func__, __LINE__, rep->eid); rep->master_id = rep->eid; F_SET(rep, REP_F_MASTERELECT); if (eidp != NULL) @@ -1696,7 +1722,8 @@ __rep_wait(dbenv, timeout, eidp, outegen, inegen, flags) Pthread_mutex_lock(&gbl_rep_egen_lk); rc = pthread_cond_timedwait(&gbl_rep_egen_cd, &gbl_rep_egen_lk, &tm); if (rc && rc != ETIMEDOUT) - logmsg(LOGMSG_ERROR, "Err rc=%d from pthread_cond_timedwait\n", rc); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_ERROR, + "Err rc=%d from pthread_cond_timedwait\n", rc); *outegen = rep->egen; Pthread_mutex_unlock(&gbl_rep_egen_lk); @@ -1752,7 +1779,7 @@ __rep_flush(dbenv) /* treat the end of the log as perm */ (void)__rep_send_message(dbenv, - db_eid_broadcast, REP_LOG, &lsn, &rec, DB_LOG_PERM, NULL); + db_eid_broadcast, REP_LOG, &lsn, &rec, DB_LOG_PERM, NULL); err: if ((t_ret = __log_c_close(logc)) != 0 && ret == 0) ret = t_ret; @@ -1830,13 +1857,13 @@ extern pthread_mutex_t gbl_durable_lsn_lk; static int __rep_deadlocks(dbenv, deadlocks) - DB_ENV *dbenv; - u_int64_t *deadlocks; + DB_ENV *dbenv; + u_int64_t *deadlocks; { DB_REP *db_rep = dbenv->rep_handle; REP *rep = db_rep->region; - *deadlocks = ATOMIC_LOAD64(rep->stat.retry); - return 0; + *deadlocks = ATOMIC_LOAD64(rep->stat.retry); + return 0; } /* @@ -1867,7 +1894,7 @@ __rep_stat(dbenv, statp, flags) *statp = NULL; if ((ret = __db_fchk(dbenv, - "DB_ENV->rep_stat", flags, DB_STAT_CLEAR)) != 0) + "DB_ENV->rep_stat", flags, DB_STAT_CLEAR)) != 0) return (ret); /* Allocate a stat struct to return to the user. */ @@ -1925,7 +1952,7 @@ __rep_stat(dbenv, statp, flags) queued = rep->stat.st_log_queued; memset(&rep->stat, 0, sizeof(rep->stat)); rep->stat.st_log_queued = rep->stat.st_log_queued_total = - rep->stat.st_log_queued_max = queued; + rep->stat.st_log_queued_max = queued; } if (dolock) { diff --git a/berkdb/rep/rep_record.c b/berkdb/rep/rep_record.c index 5060d25975..8200bdb8e5 100644 --- a/berkdb/rep/rep_record.c +++ b/berkdb/rep/rep_record.c @@ -94,6 +94,7 @@ int gbl_warn_queue_latency_threshold = 500; int gbl_inmem_repdb_maxlog = 10000; int64_t gbl_inmem_repdb_memory = 0; int64_t gbl_apply_queue_memory = 0; +int gbl_debug_election = 0; /* Finish a fill if we are within 1.5 logfiles */ int gbl_finish_fill_threshold = 60000000; @@ -157,7 +158,7 @@ static inline int wait_for_running_transactions(DB_ENV *dbenv); #define IS_SIMPLE(R) ((R) != DB___txn_regop && (R) != DB___txn_xa_regop && \ (R) != DB___txn_regop_rowlocks && (R) != DB___txn_regop_gen && \ (R) != DB___txn_dist_commit && (R) != DB___txn_ckp && (R) != DB___dbreg_register && \ - (R) != DB___txn_dist_prepare && (R) != DB___txn_dist_abort) + (R) != DB___txn_dist_prepare && (R) != DB___txn_dist_abort) int gbl_rep_process_msg_print_rc; @@ -346,7 +347,8 @@ static inline void send_dupmaster(DB_ENV *dbenv, const char *func, int line) __rep_send_message(dbenv, db_eid_broadcast, REP_DUPMASTER, NULL, NULL, 0, NULL); - logmsg(LOGMSG_DEBUG, "%s line %d sending DUPMASTER\n", func, line); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending DUPMASTER\n", func, line); } void send_master_req(DB_ENV *dbenv, const char *func, int line) @@ -427,24 +429,23 @@ int normalize_rectype(u_int32_t *rectype) { } } -int gbl_match_on_ckp = 1; /* * matchable_log_type -- * - * PUBLIC: int matchable_log_type __P((int)); + * PUBLIC: int matchable_log_type __P((DB_ENV *, int)); */ int -matchable_log_type(int rectype) +matchable_log_type(DB_ENV *dbenv, int rectype) { extern int gbl_only_match_commit_records; int ret; if (gbl_only_match_commit_records) { - ret = (rectype == DB___txn_regop || - rectype == DB___txn_regop_gen || - rectype == DB___txn_dist_commit || - rectype == DB___txn_dist_abort || - rectype == DB___txn_regop_rowlocks || - (gbl_match_on_ckp && rectype == DB___txn_ckp)); + ret = ((!dbenv->attr.elect_highest_committed_gen && rectype == DB___txn_regop) || + rectype == DB___txn_regop_gen || + rectype == DB___txn_dist_commit || + rectype == DB___txn_dist_abort || + rectype == DB___txn_regop_rowlocks || + rectype == DB___txn_ckp); } else { switch (rectype) { case DB___txn_recycle: @@ -549,8 +550,9 @@ int send_rep_all_req(DB_ENV *dbenv, char *master_eid, DB_LSN *lsn, int flags, return send_rep_all_req_dedup(dbenv, master_eid, lsn, flags, func, line); } if (gbl_dedup_rep_all_reqs && rep_qstat_has_allreq()) { - if (gbl_verbose_fills) { - logmsg(LOGMSG_DEBUG, "BLOCKING rep_all_req from %s line %d\n", func, line); + if (gbl_verbose_fills || gbl_debug_election) { + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "BLOCKING rep_all_req from %s line %d\n", func, line); } return 0; } @@ -582,9 +584,9 @@ static void *apply_thread(void *arg) lp = dblp->reginfo.primary; bdb_thread_start_rw(); - thrman_register(THRTYPE_GENERIC); - thread_started("apply thread"); - + thrman_register(THRTYPE_GENERIC); + thread_started("apply thread"); + Pthread_mutex_lock(&rep_queue_lock); while (!db_is_exiting() && gbl_decoupled_logputs) { int pollms = (gbl_apply_thread_pollms > 0) ? @@ -1044,7 +1046,7 @@ __rep_verify_will_recover(dbenv, control, rec) LOGCOPY_32(&rectype, mylog.data); normalize_rectype(&rectype); - if ((will_recover == 1 && !matchable_log_type(rectype)) && + if ((will_recover == 1 && !matchable_log_type(dbenv, rectype)) && ((ret = __log_c_get(logc, &lsn, &mylog, DB_PREV)) == 0)){ will_recover = 0; } @@ -1250,7 +1252,7 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) static u_int32_t lastpr = 0; u_int32_t now; - if (gbl_rep_badgen_trace && ((now = time(NULL)) - lastpr)) { + if ((gbl_debug_election || gbl_rep_badgen_trace) && ((now = time(NULL)) - lastpr)) { logmsg(LOGMSG_USER, "Ignoring rp->gen %u from %s mygen is %u, " "rectype=%u cnt %u\n", rp->gen, *eidp, gen, rp->rectype, rep->stat.st_msgs_badgen); @@ -1268,7 +1270,7 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) */ static u_int32_t lastpr = 0; u_int32_t now; - if (gbl_rep_badgen_trace && ((now = time(NULL)) - lastpr)) { + if ((gbl_rep_badgen_trace || gbl_debug_election) && ((now = time(NULL)) - lastpr)) { logmsg(LOGMSG_USER, "rp->gen %u from %s is larger than " "mygen %u, rectype=%u\n", rp->gen, *eidp, gen, rp->rectype); lastpr = now; @@ -1297,7 +1299,8 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) __db_err(dbenv, "Updating gen from %lu to %lu", (u_long)gen, (u_long)rp->gen); #endif - logmsg(LOGMSG_DEBUG, "%s line %d setting rep->gen to %d for rectype " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting rep->gen to %d for rectype " "%d\n", __func__, __LINE__, rp->gen, rp->rectype); __rep_set_gen(dbenv, __func__, __LINE__, rp->gen); gen = rp->gen; @@ -1672,7 +1675,7 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) logmsg(LOGMSG_USER, "%s line %d continuing REP_ALL_REQ lsn " "%d:%d\n", __func__, __LINE__, lsn.file, lsn.offset); } - fromline = __LINE__; + fromline = __LINE__; } goto errlock; @@ -1781,8 +1784,8 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) "Unable to get prev of [%lu][%lu]", (u_long)lsn.file, (u_long)lsn.offset); - logmsg(LOGMSG_INFO, "%s:%d sending DB_REP_OUTDATED\n", - __func__, __LINE__); + logmsg(LOGMSG_INFO, "%s:%d sending DB_REP_OUTDATED\n", + __func__, __LINE__); ret = DB_REP_OUTDATED; /* Tell the replicant he's outdated. */ if (gbl_verbose_fills) { @@ -1790,9 +1793,9 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) "for LSN %d:%d\n", __func__, __LINE__, lsn.file, lsn.offset); } - logmsg(LOGMSG_INFO, "%s:%d log_c_get failed to find [%d:%d]" - " and [%d:%d]: REP_VERIFY_FAIL\n", __func__, __LINE__, - lsn.file, lsn.offset,endlsn.file, endlsn.offset); + logmsg(LOGMSG_INFO, "%s:%d log_c_get failed to find [%d:%d]" + " and [%d:%d]: REP_VERIFY_FAIL\n", __func__, __LINE__, + lsn.file, lsn.offset,endlsn.file, endlsn.offset); if ((resp_rc = __rep_time_send_message(dbenv, *eidp, REP_VERIFY_FAIL, &lsn, NULL, 0, NULL, &sendtime)) != 0 && gbl_verbose_fills) { @@ -2054,14 +2057,14 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) /* * Skip over any records recovery can write. */ - if ((match == 0 || !matchable_log_type(rectype)) && + if ((match == 0 || !matchable_log_type(dbenv, rectype)) && (ret = __log_c_get(logc, &lsn, &mylog, DB_PREV)) == 0) { match = 0; if (gbl_berkdb_verify_skip_skipables) { LOGCOPY_32(&rectype, mylog.data); normalize_rectype(&rectype); - while (!matchable_log_type(rectype) && (ret = + while (!matchable_log_type(dbenv, rectype) && (ret = __log_c_get(logc, &lsn, &mylog, DB_PREV)) == 0) { LOGCOPY_32(&rectype, mylog.data); @@ -2086,7 +2089,7 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) verify_req_print = now; } - assert(lsn.file > 0); + assert(lsn.file > 0); (void)__rep_send_message(dbenv, *eidp, REP_VERIFY_REQ, &lsn, NULL, 0, NULL); @@ -2122,7 +2125,7 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) verify_req_print = now; } - assert(lsn.file > 0); + assert(lsn.file > 0); (void)__rep_send_message(dbenv, *eidp, REP_VERIFY_REQ, &lsn, NULL, 0, NULL); @@ -2152,8 +2155,8 @@ __rep_process_message(dbenv, control, rec, eidp, ret_lsnp, commit_gen, online) * the same environment and we'll say so. */ ret = DB_REP_OUTDATED; - logmsg(LOGMSG_INFO, "%s:%d returning DB_REP_OUTDATED\n", - __func__, __LINE__); + logmsg(LOGMSG_INFO, "%s:%d returning DB_REP_OUTDATED\n", + __func__, __LINE__); if (rp->lsn.file != 1) __db_err(dbenv, @@ -2183,8 +2186,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && case REP_VERIFY_FAIL: rep->stat.st_outdated++; ret = DB_REP_OUTDATED; - logmsg(LOGMSG_INFO, "%s:%d returning DB_REP_OUTDATED\n", - __func__, __LINE__); + logmsg(LOGMSG_INFO, "%s:%d returning DB_REP_OUTDATED\n", + __func__, __LINE__); fromline = __LINE__; goto errlock; case REP_VERIFY_REQ: @@ -2221,10 +2224,10 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && if (ret == DB_NOTFOUND && __log_is_outdated(dbenv, rp->lsn.file, &old) == 0 && old != 0) { - logmsg(LOGMSG_INFO, "%s rep_verify_req returning REP_VERIFY_FAIL " - "for [%d:%d]\n", __func__, rp->lsn.file, rp->lsn.offset); + logmsg(LOGMSG_INFO, "%s rep_verify_req returning REP_VERIFY_FAIL " + "for [%d:%d]\n", __func__, rp->lsn.file, rp->lsn.offset); type = REP_VERIFY_FAIL; - } + } if (ret != 0) d = NULL; @@ -2253,7 +2256,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && R_LOCK(dbenv, &dblp->reginfo); lsn = lp->lsn; R_UNLOCK(dbenv, &dblp->reginfo); - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_NEWMASTER\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_NEWMASTER\n", __func__, __LINE__); (void)__rep_send_message(dbenv, *eidp, REP_NEWMASTER, &lsn, NULL, 0, NULL); @@ -2270,7 +2274,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && vi_nsites = vi->nsites; vi_priority = vi->priority; vi_tiebreaker = vi->tiebreaker; - logmsg(LOGMSG_DEBUG, "%s line %d processing REP_VOTE1 from %s gen %d egen %d my-egen is %d " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d processing REP_VOTE1 from %s gen %d egen %d my-egen is %d " "(Setting write-gen to 0)\n", __func__, __LINE__, *eidp, rp->gen, vi_egen, rep->egen); } else { @@ -2282,7 +2287,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && vi_nsites = vig->nsites; vi_priority = vig->priority; vi_tiebreaker = vig->tiebreaker; - logmsg(LOGMSG_DEBUG, "%s line %d processed REP_GEN_VOTE1 from %s gen %d egen %d my-egen is %d " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d processed REP_GEN_VOTE1 from %s gen %d egen %d my-egen is %d " "(Setting write-gen to %d)\n", __func__, __LINE__, *eidp, rp->gen, vi_egen, rep->egen, vig->last_write_gen); } @@ -2296,13 +2302,15 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && * start over by tallying it. */ if (vi_egen < rep->egen) { - logmsg(LOGMSG_DEBUG, "%s line %d ignoring %s from %s: it's egen is %d my-egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d ignoring %s from %s: it's egen is %d my-egen is %d\n", __func__, __LINE__, rp->rectype == REP_VOTE1 ? "REP_VOTE1" : "REP_GEN_VOTE1", *eidp, vi_egen, rep->egen); goto errunlock; } if (vi_egen > rep->egen) { - logmsg(LOGMSG_DEBUG, "%s line %d reseting election for %s from %s: it's egen is %d my-egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d reseting election for %s from %s: it's egen is %d my-egen is %d\n", __func__, __LINE__, rp->rectype == REP_VOTE1 ? "REP_VOTE1" : "REP_GEN_VOTE1", *eidp, vi_egen, rep->egen); __rep_elect_done(dbenv, rep, vi_egen, __func__, __LINE__); @@ -2420,7 +2428,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && #endif egen = rep->egen; committed_gen = rep->committed_gen; - logmsg(LOGMSG_DEBUG, "%s line %d Setting PHASE2 clearing PHASE1\n", __func__, __LINE__); + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d Setting PHASE2 clearing PHASE1\n", __func__, __LINE__); F_SET(rep, REP_F_EPHASE2); F_CLR(rep, REP_F_EPHASE1); if (master == rep->eid) { @@ -2433,14 +2442,16 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && /* Vote for someone else. */ if (dbenv->attr.elect_highest_committed_gen) { - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_GEN_VOTE2 to %s " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_GEN_VOTE2 to %s " "with committed-gen=%d gen=%d egen=%d\n", __func__, __LINE__, master, committed_gen, rep->gen, egen); __rep_send_gen_vote(dbenv, NULL, 0, 0, 0, egen, committed_gen, master, REP_GEN_VOTE2); } else { - logmsg(LOGMSG_DEBUG, "%s line %d sending REP_VOTE2 to %s " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d sending REP_VOTE2 to %s " "(committed-gen=0) gen=%d egen=%d\n", __func__, __LINE__, master, rep->gen, egen); __rep_send_vote(dbenv, NULL, 0, 0, 0, egen, @@ -2478,7 +2489,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && vi_nsites = vi->nsites; vi_priority = vi->priority; vi_tiebreaker = vi->tiebreaker; - logmsg(LOGMSG_DEBUG, "%s line %d processing REP_VOTE2 from %s gen %d egen %d my-egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d processing REP_VOTE2 from %s gen %d egen %d my-egen is %d\n", __func__, __LINE__, *eidp, rp->gen, vi_egen, rep->egen); } else { vig = (REP_GEN_VOTE_INFO *) rec->data; @@ -2489,12 +2501,14 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && vi_nsites = vig->nsites; vi_priority = vig->priority; vi_tiebreaker = vig->tiebreaker; - logmsg(LOGMSG_DEBUG, "%s line %d processing REP_GEN_VOTE2 from %s gen %d egen %d my-egen is %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d processing REP_GEN_VOTE2 from %s gen %d egen %d my-egen is %d\n", __func__, __LINE__, *eidp, rp->gen, vi_egen, rep->egen); } if (!IN_ELECTION_TALLY(rep) && vi_egen > rep->egen) { - logmsg(LOGMSG_DEBUG, "%s line %d not in election and vote2-egen %d " + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d not in election and vote2-egen %d " "> rep->egen (%d): returning HOLDELECTION\n", __func__, __LINE__, vi_egen, rep->egen); ret = DB_REP_HOLDELECTION; @@ -2537,7 +2551,8 @@ rep_verify_err:if ((t_ret = __log_c_close(logc)) != 0 && __db_err(dbenv, "Counted vote %d", rep->votes); #endif if (done) { - logmsg(LOGMSG_DEBUG, "%s line %d elected master %s for egen %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d elected master %s for egen %d\n", __func__, __LINE__, rep->eid, vi_egen); __rep_elect_master(dbenv, rep, eidp); ret = (rep->votes > rep->nsites / 2 + 1) ? DB_HAS_MAJORITY : DB_REP_NEWMASTER; @@ -3765,12 +3780,12 @@ gap_check: max_lsn_dbtp = NULL; !(rand() % gbl_slow_rep_process_txn_freq)) { - if (gbl_slow_rep_process_txn_maxms <= gbl_slow_rep_process_txn_minms) { - gbl_slow_rep_process_txn_maxms = gbl_slow_rep_process_txn_minms + 1; - } - int range = gbl_slow_rep_process_txn_maxms - gbl_slow_rep_process_txn_minms; - int polltime = gbl_slow_rep_process_txn_minms + (rand() % range); - logmsg(LOGMSG_DEBUG, "%s polling an additional %d ms\n", __func__, polltime); + if (gbl_slow_rep_process_txn_maxms <= gbl_slow_rep_process_txn_minms) { + gbl_slow_rep_process_txn_maxms = gbl_slow_rep_process_txn_minms + 1; + } + int range = gbl_slow_rep_process_txn_maxms - gbl_slow_rep_process_txn_minms; + int polltime = gbl_slow_rep_process_txn_minms + (rand() % range); + logmsg(LOGMSG_DEBUG, "%s polling an additional %d ms\n", __func__, polltime); poll(0, 0, polltime); } } @@ -3946,10 +3961,10 @@ __rep_apply(dbenv, rp, rec, ret_lsnp, commit_gen, decoupled) int rc, now; bbtime_t start = {0}, end = {0}; - int debug_switch_replicant_latency(void); - if (debug_switch_replicant_latency() && !(time(NULL) % 4)) { - return 0; - } + int debug_switch_replicant_latency(void); + if (debug_switch_replicant_latency() && !(time(NULL) % 4)) { + return 0; + } Pthread_mutex_lock(&apply_lk); getbbtime(&start); @@ -4001,7 +4016,7 @@ int __dbenv_apply_log(DB_ENV* dbenv, unsigned int file, unsigned int offset, /* call with decoupled = 2 to differentiate from true master */ int ret = __rep_apply(dbenv, &rp, &rec, &ret_lsnp, - (gbl_is_physical_replicant) ? &rep->log_gen : &rep->gen, 2); + (gbl_is_physical_replicant) ? &rep->log_gen : &rep->gen, 2); if (ret == 0 || ret == DB_REP_ISPERM) { bdb_set_seqnum(dbenv->app_private); @@ -6871,9 +6886,9 @@ __rep_cmp_vote(dbenv, rep, eidp, egen, lsnp, priority, gen, committed_gen, tiebr * LSN is primary determinant. Then priority if LSNs * are equal, then tiebreaker if both are equal. */ - if (cmp > 0 || - (cmp == 0 && (priority > rep->w_priority || - (priority == rep->w_priority && + if (cmp > 0 || + (cmp == 0 && (priority > rep->w_priority || + (priority == rep->w_priority && (tiebreaker > rep->w_tiebreaker))))) { #ifdef DIAGNOSTIC if (FLD_ISSET(dbenv->verbose, DB_VERB_REPLICATION)) @@ -7206,7 +7221,7 @@ __rep_dorecovery(dbenv, lsnp, trunclsnp, online, undid_schema_change) if (ret) goto err; - } + } if (rectype == DB___txn_regop_gen) { if ((ret = __txn_regop_gen_read(dbenv, mylog.data, @@ -7308,13 +7323,13 @@ __rep_dorecovery(dbenv, lsnp, trunclsnp, online, undid_schema_change) } if (have_recover_lk) { - dbenv->unlock_recovery_lock(dbenv, __func__, __LINE__); + dbenv->unlock_recovery_lock(dbenv, __func__, __LINE__); } - if (logc_dist != NULL) { - __log_c_close(logc_dist); - logc_dist = NULL; - } + if (logc_dist != NULL) { + __log_c_close(logc_dist); + logc_dist = NULL; + } if ((t_ret = __log_c_close(logc)) != 0 && ret == 0) ret = t_ret; @@ -8124,9 +8139,9 @@ __truncate_repdb(dbenv) } if ((!F_ISSET(rep, REP_ISCLIENT) && !gbl_is_physical_replicant) || !db_rep->rep_db) { - logmsg(LOGMSG_FATAL, "%s:%d returning DB_NOTFOUND\n", __func__, __LINE__); + logmsg(LOGMSG_FATAL, "%s:%d returning DB_NOTFOUND\n", __func__, __LINE__); return DB_NOTFOUND; - } + } MUTEX_LOCK(dbenv, db_rep->db_mutexp); diff --git a/berkdb/rep/rep_util.c b/berkdb/rep/rep_util.c index 4189b8a0d5..56763bd253 100644 --- a/berkdb/rep/rep_util.c +++ b/berkdb/rep/rep_util.c @@ -44,6 +44,7 @@ void bdb_set_rep_handle_dead(struct bdb_state_tag *); int bdb_num_connected_nodes(struct bdb_state_tag *); #endif +extern int gbl_debug_election;; int gbl_verbose_master_req = 0; int gbl_trace_repmore_reqs = 0; @@ -385,6 +386,7 @@ __rep_print_logmsg(dbenv, logdbt, lsnp) } #endif + /* * __rep_set_gen -- * Called as a utility function to see places where an instance's @@ -407,7 +409,8 @@ __rep_set_gen(dbenv, func, line, gen) egen = rep->egen; if (rep->egen <= gen) egen = gen + 1; - logmsg(LOGMSG_DEBUG, "%s line %d setting rep->gen from %d to %d, egen from %d to %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, + "%s line %d setting rep->gen from %d to %d, egen from %d to %d\n", func, line, rep->gen, gen, rep->egen, egen); rep->gen = gen; rep->egen = egen; @@ -446,7 +449,7 @@ __rep_set_egen(dbenv, func, line, egen) REP *rep; db_rep = dbenv->rep_handle; rep = db_rep->region; - logmsg(LOGMSG_DEBUG, "%s line %d setting rep->egen from %d to %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, "%s line %d setting rep->egen from %d to %d\n", func, line, rep->egen, egen); rep->egen = egen; } @@ -470,7 +473,7 @@ __rep_set_log_gen(dbenv, func, line, log_gen) REP *rep; db_rep = dbenv->rep_handle; rep = db_rep->region; - logmsg(LOGMSG_DEBUG, "%s line %d setting rep->log_gen from %d to %d\n", + logmsg(gbl_debug_election ? LOGMSG_USER : LOGMSG_DEBUG, "%s line %d setting rep->log_gen from %d to %d\n", func, line, rep->log_gen, log_gen); rep->log_gen = log_gen; } diff --git a/berkdb/txn/txn_rec.c b/berkdb/txn/txn_rec.c index 73146a4a6d..2145d8473a 100644 --- a/berkdb/txn/txn_rec.c +++ b/berkdb/txn/txn_rec.c @@ -57,6 +57,8 @@ static const char revid[] = "$Id: txn_rec.c,v 11.54 2003/10/31 23:26:11 ubell Ex #define IS_XA_TXN(R) (R->xid.size != 0) +extern int gbl_debug_election; + int set_commit_context(unsigned long long context, uint32_t *generation, void *plsn, void *args, unsigned int rectype); @@ -445,6 +447,8 @@ __txn_regop_gen_recover(dbenv, dbtp, lsnp, op, info) if (argp->generation > rep->gen) { __rep_set_gen(dbenv, __func__, __LINE__, argp->generation); __rep_set_log_gen(dbenv, __func__, __LINE__, rep->gen); + } else if (gbl_debug_election) { + logmsg(LOGMSG_USER, "%s line %d: rep->gen is %u, not setting to %u\n", __func__, __LINE__, rep->gen, argp->generation); } MUTEX_UNLOCK(dbenv, db_rep->rep_mutexp); } else if ((dbenv->tx_timestamp != 0 && @@ -748,7 +752,9 @@ __txn_regop_rowlocks_recover(dbenv, dbtp, lsnp, op, info) rep->committed_lsn = *lsnp; if (argp->generation > rep->gen) { __rep_set_gen(dbenv, __func__, __LINE__, argp->generation); - __rep_set_gen(dbenv, __func__, __LINE__, rep->gen); + __rep_set_log_gen(dbenv, __func__, __LINE__, rep->gen); + } else if (gbl_debug_election) { + logmsg(LOGMSG_USER, "%s line %d: rep->gen is %u, not setting to %u\n", __func__, __LINE__, rep->gen, argp->generation); } MUTEX_UNLOCK(dbenv, db_rep->rep_mutexp); } @@ -809,8 +815,8 @@ __txn_regop_rowlocks_recover(dbenv, dbtp, lsnp, op, info) if (NULL == lt) { if((ret = __txn_create_ltrans(dbenv, argp->ltranid, - <, lsnp, &argp->begin_lsn, - &argp->last_commit_lsn)) != 0) + <, lsnp, &argp->begin_lsn, + &argp->last_commit_lsn)) != 0) goto err; } @@ -819,13 +825,13 @@ __txn_regop_rowlocks_recover(dbenv, dbtp, lsnp, op, info) if (argp->lflags & DB_TXN_LOGICAL_BEGIN) { if (NULL == dbenv->txn_logical_commit || - (ret = dbenv->txn_logical_commit(dbenv, dbenv->app_private, - lt->ltranid, lsnp)) != 0) + (ret = dbenv->txn_logical_commit(dbenv, dbenv->app_private, + lt->ltranid, lsnp)) != 0) { logmsg(LOGMSG_ERROR, "%s: txn_logical_commit error, %d\n", __func__, ret); goto err; } - + __txn_deallocate_ltrans(dbenv, lt); } } @@ -1012,10 +1018,17 @@ __txn_ckp_recover(dbenv, dbtp, lsnp, op, info) } if (op == DB_TXN_FORWARD_ROLL) { - /* Record the max generation number that we've seen. */ if (REP_ON(dbenv)) { db_rep = dbenv->rep_handle; rep = db_rep->region; + + if (argp->rep_gen > rep->gen) { + __rep_set_gen(dbenv, __func__, __LINE__, argp->rep_gen); + __rep_set_log_gen(dbenv, __func__, __LINE__, rep->gen); + } else if (gbl_debug_election) { + logmsg(LOGMSG_USER, "%s line %d: rep->gen is %u, not setting to %u\n", __func__, __LINE__, rep->gen, argp->rep_gen); + } + if (argp->rep_gen > rep->recover_gen) rep->recover_gen = argp->rep_gen; } diff --git a/db/db_tunables.c b/db/db_tunables.c index 34f3e491e1..0574e0903f 100644 --- a/db/db_tunables.c +++ b/db/db_tunables.c @@ -253,7 +253,7 @@ extern int gbl_random_sql_work_delayed; extern int gbl_random_sql_work_rejected; extern int gbl_instrument_dblist; extern int gbl_replicated_truncate_timeout; -extern int gbl_match_on_ckp; +extern int gbl_debug_election; extern int gbl_verbose_set_sc_in_progress; extern int gbl_send_failed_dispatch_message; extern int gbl_logdelete_lock_trace; diff --git a/db/db_tunables.h b/db/db_tunables.h index 2d927195e6..846fd1fa97 100644 --- a/db/db_tunables.h +++ b/db/db_tunables.h @@ -1869,9 +1869,8 @@ REGISTER_TUNABLE("instrument_dblist", TUNABLE_BOOLEAN, &gbl_instrument_dblist, READONLY | EXPERIMENTAL | INTERNAL, NULL, NULL, NULL, NULL); -REGISTER_TUNABLE("match_on_ckp", "Allow rep_verify_match on ckp records. (Default: on)", TUNABLE_BOOLEAN, - &gbl_match_on_ckp, EXPERIMENTAL | INTERNAL, NULL, NULL, NULL, NULL); - +REGISTER_TUNABLE("debug_election", "Enable extended election trace. (Default: off)", TUNABLE_BOOLEAN, + &gbl_debug_election, 0, NULL, NULL, NULL, NULL); /* physical replication */ REGISTER_TUNABLE("blocking_physrep", "Physical replicant blocks on select. (Default: off)", TUNABLE_BOOLEAN, &gbl_blocking_physrep, 0, NULL, NULL, NULL, NULL); diff --git a/db/sqlanalyze.c b/db/sqlanalyze.c index fb3fe35164..b35446cd69 100644 --- a/db/sqlanalyze.c +++ b/db/sqlanalyze.c @@ -107,7 +107,6 @@ enum { TABLE_SKIPPED = 5 }; - int analyze_partition(table_descriptor_t *td, struct sqlclntstate *clnt, char *zErrTab, size_t nErrTab); /* loadStat4 (analyze.c) will ignore all stat entries * which have "tbl like 'cdb2.%' */ @@ -348,8 +347,8 @@ static int wait_for_index(index_descriptor_t *ix_des) } /* sample all indicies in this table */ -static int sample_indices(table_descriptor_t *td, struct sqlclntstate *client, - struct dbtable *tbl, int sampling_pct, SBUF2 *sb) +static int sample_indices(table_descriptor_t *td, struct sqlclntstate *client, struct dbtable *tbl, int sampling_pct, + SBUF2 *sb) { int i; int err = 0; @@ -684,47 +683,48 @@ int update_sav(sqlite3 *sqldb, struct sqlclntstate *client, SBUF2 *sb, sqlite3_free(sql); sql = NULL; return 0; } -static int analyze_rename_table_for_backup_stats(char *table, struct sqlclntstate *clnt, - char *zErrTab){ +static int analyze_rename_table_for_backup_stats(char *table, struct sqlclntstate *clnt, char *zErrTab) +{ char *sql = NULL; - sql = sqlite3_mprintf( - "delete from sqlite_stat1 where tbl='cdb2.%q.sav'", table); + sql = sqlite3_mprintf("delete from sqlite_stat1 where tbl='cdb2.%q.sav'", table); assert(sql != NULL); int rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); - sqlite3_free(sql); sql = NULL; + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); + sqlite3_free(sql); + sql = NULL; if (rc) goto error; - sql = sqlite3_mprintf( - "update sqlite_stat1 set tbl='cdb2.%q.sav' where tbl='%q'", - table, table); + sql = sqlite3_mprintf("update sqlite_stat1 set tbl='cdb2.%q.sav' where tbl='%q'", table, table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); - sqlite3_free(sql); sql = NULL; + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); + sqlite3_free(sql); + sql = NULL; if (rc) goto error; if (get_dbtable_by_name("sqlite_stat2")) { - sql = sqlite3_mprintf( - "delete from sqlite_stat2 where tbl='cdb2.%q.sav'", table); + sql = sqlite3_mprintf("delete from sqlite_stat2 where tbl='cdb2.%q.sav'", table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); - sqlite3_free(sql); sql = NULL; + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); + sqlite3_free(sql); + sql = NULL; if (rc) goto error; - sql = sqlite3_mprintf( - "update sqlite_stat2 set tbl='cdb2.%q.sav' where tbl='%q'", - table, table); + sql = sqlite3_mprintf("update sqlite_stat2 set tbl='cdb2.%q.sav' where tbl='%q'", table, table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); sqlite3_free(sql); sql = NULL; if (rc) @@ -732,23 +732,23 @@ static int analyze_rename_table_for_backup_stats(char *table, struct sqlclntstat } if (get_dbtable_by_name("sqlite_stat4")) { - sql = sqlite3_mprintf( - "delete from sqlite_stat4 where tbl='cdb2.%q.sav'", table); + sql = sqlite3_mprintf("delete from sqlite_stat4 where tbl='cdb2.%q.sav'", table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); sqlite3_free(sql); sql = NULL; if (rc) goto error; - sql = sqlite3_mprintf( - "update sqlite_stat4 set tbl='cdb2.%q.sav' where tbl='%q'", - table, table); + sql = sqlite3_mprintf("update sqlite_stat4 set tbl='cdb2.%q.sav' where tbl='%q'", table, table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); - sqlite3_free(sql); sql = NULL; + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); + sqlite3_free(sql); + sql = NULL; if (rc) goto error; @@ -757,13 +757,14 @@ static int analyze_rename_table_for_backup_stats(char *table, struct sqlclntstat return rc; } -int analyze_regular_table(table_descriptor_t *td, struct sqlclntstate *clnt, char *zErrTab, size_t nErrTab) { +int analyze_regular_table(table_descriptor_t *td, struct sqlclntstate *clnt, char *zErrTab, size_t nErrTab) +{ int rc = 0; int sampled_table = 0; struct dbtable *table = get_dbtable_by_name(td->table); rc = analyze_rename_table_for_backup_stats(td->table, clnt, zErrTab); - if (rc) + if (rc) goto err; /* grab the size of the table */ @@ -793,8 +794,10 @@ int analyze_regular_table(table_descriptor_t *td, struct sqlclntstate *clnt, cha char *sql = sqlite3_mprintf("analyzesqlite main.\"%w\"", td->table); assert(sql != NULL); rc = run_internal_sql_clnt(clnt, sql); - if (rc) strncpy(zErrTab, sql, strlen(zErrTab)); - sqlite3_free(sql); sql = NULL; + if (rc) + strncpy(zErrTab, sql, strlen(zErrTab)); + sqlite3_free(sql); + sql = NULL; clnt->is_analyze = 0; if (rc) @@ -809,8 +812,7 @@ int analyze_regular_table(table_descriptor_t *td, struct sqlclntstate *clnt, cha return rc; } -static int analyze_table_int(table_descriptor_t *td, - struct thr_handle *thr_self) +static int analyze_table_int(table_descriptor_t *td, struct thr_handle *thr_self) { char *zErrTab = (char *)malloc(256 * sizeof(char)); size_t nErrTab = 256; @@ -831,8 +833,7 @@ static int analyze_table_int(table_descriptor_t *td, get_saved_scale(td->table, &td->scale); if (td->scale == 0) { - sbuf2printf(td->sb, "?Coverage for table '%s' is 0, skipping analyze\n", - td->table); + sbuf2printf(td->sb, "?Coverage for table '%s' is 0, skipping analyze\n", td->table); logmsg(LOGMSG_INFO, "coverage for table '%s' is 0, skipping analyze\n", td->table); return TABLE_SKIPPED; } @@ -841,7 +842,7 @@ static int analyze_table_int(table_descriptor_t *td, start_internal_sql_clnt(&clnt); clnt.osql_max_trans = 0; // allow large transactions - clnt.current_user = td->current_user; + clnt.current_user = td->current_user; if (td->appdata != NULL) clnt.appdata = td->appdata; if (td->get_authdata != NULL) @@ -884,7 +885,6 @@ static int analyze_table_int(table_descriptor_t *td, logmsg(LOGMSG_INFO, "Analyze completed, table %s\n", td->table); } - end_internal_sql_clnt(&clnt); if (zErrTab) { free(zErrTab); @@ -1204,12 +1204,11 @@ int analyze_database(SBUF2 *sb, int scale, int override_llmeta) strncpy0(td[idx].table, thedb->dbs[i]->sqlaliasname, sizeof(td[idx].table)); else*/ - strncpy0(td[idx].table, thedb->dbs[i]->tablename, - sizeof(td[idx].table)); + strncpy0(td[idx].table, thedb->dbs[i]->tablename, sizeof(td[idx].table)); if (clnt) { td[idx].current_user = clnt->current_user; - td[idx].appdata = clnt->appdata; + td[idx].appdata = clnt->appdata; td[idx].get_authdata = clnt->plugin.get_authdata; } diff --git a/db/sqlinterfaces.c b/db/sqlinterfaces.c index b60ada0403..4b366745bc 100644 --- a/db/sqlinterfaces.c +++ b/db/sqlinterfaces.c @@ -7195,7 +7195,8 @@ void print_idle_clnt(struct sqlclntstate *clnt) struct timeval now, elapsed; gettimeofday(&now, NULL); timersub(&now, &clnt->wait_for_rd_since, &elapsed); - ctrace("fd:%d idle:%ldmins origin:%s [prev=> process:%s pid:%d sql:%s] [process:%s pid:%d sql:%s] opcode:%s local-cache:%c\n", - get_fileno(clnt), elapsed.tv_sec / 60, clnt->origin, clnt->prev_argv0, clnt->prev_pid, clnt->second_last_sql, clnt->argv0, clnt->conninfo.pid, clnt->last_sql, clnt->prev_opcode, - clnt->in_local_cache ? 'Y' : 'N'); + ctrace("fd:%d idle:%ldmins origin:%s [prev=> process:%s pid:%d sql:%s] [process:%s pid:%d sql:%s] opcode:%s " + "local-cache:%c\n", + get_fileno(clnt), elapsed.tv_sec / 60, clnt->origin, clnt->prev_argv0, clnt->prev_pid, clnt->second_last_sql, + clnt->argv0, clnt->conninfo.pid, clnt->last_sql, clnt->prev_opcode, clnt->in_local_cache ? 'Y' : 'N'); } diff --git a/db/truncate_log.c b/db/truncate_log.c index b1e975a99f..b4bab993f6 100644 --- a/db/truncate_log.c +++ b/db/truncate_log.c @@ -8,7 +8,6 @@ extern int gbl_physrep_debug; extern struct dbenv *thedb; -extern int gbl_match_on_ckp; LOG_INFO find_match_lsn(void *bdb_state, cdb2_hndl_tp *repl_db, LOG_INFO start_info); diff --git a/db/views.c b/db/views.c index f24a108e3f..3b4f130aac 100644 --- a/db/views.c +++ b/db/views.c @@ -3472,8 +3472,8 @@ int part_newformat(const char *tptname) return ret; } - -int analyze_partition(table_descriptor_t *td, struct sqlclntstate *clnt, char *zErrTab, size_t nErrTab) { +int analyze_partition(table_descriptor_t *td, struct sqlclntstate *clnt, char *zErrTab, size_t nErrTab) +{ timepart_views_t *views; timepart_view_t *view; int rc = 0; @@ -3493,16 +3493,15 @@ int analyze_partition(table_descriptor_t *td, struct sqlclntstate *clnt, char *z get_saved_scale(td->table, &td->scale); if (td->scale == 0) { - sbuf2printf(td->sb, "?Coverage for table '%s' is 0, skipping analyze\n", - td->table); + sbuf2printf(td->sb, "?Coverage for table '%s' is 0, skipping analyze\n", td->table); logmsg(LOGMSG_INFO, "coverage for table '%s' is 0, skipping analyze\n", td->table); goto done; } else { - /* override llmeta so analyze thread doesn't try to fetch + /* override llmeta so analyze thread doesn't try to fetch * coverage percent for individual shards*/ td->override_llmeta = 1; } - for (i=0; inshards; i++) { + for (i = 0; i < view->nshards; i++) { strncpy0(td->table, view->shards[i].tblname, sizeof(td->table)); rc = analyze_regular_table(td, clnt, zErrTab, nErrTab); if (rc) { @@ -3511,9 +3510,10 @@ int analyze_partition(table_descriptor_t *td, struct sqlclntstate *clnt, char *z } done: Pthread_rwlock_unlock(&views_lk); - strncpy0(td->table,tbl, sizeof(td->table)); - if (rc) - logmsg(LOGMSG_ERROR, "%s:%d analyze failed for shard %s of partition %s. rc : %d\n", __func__, __LINE__, view->shards[i].tblname, tbl, rc); + strncpy0(td->table, tbl, sizeof(td->table)); + if (rc) + logmsg(LOGMSG_ERROR, "%s:%d analyze failed for shard %s of partition %s. rc : %d\n", __func__, __LINE__, + view->shards[i].tblname, tbl, rc); return rc; } diff --git a/tests/tunables.test/t00_all_tunables.expected b/tests/tunables.test/t00_all_tunables.expected index 8f62350198..593f7c4964 100644 --- a/tests/tunables.test/t00_all_tunables.expected +++ b/tests/tunables.test/t00_all_tunables.expected @@ -176,6 +176,7 @@ (name='debug_all_prepare_leak', description='Prepare and leak all transactions. (Default: off)', type='BOOLEAN', value='OFF', read_only='N') (name='debug_bdb_lock_stack', description='', type='BOOLEAN', value='OFF', read_only='N') (name='debug_deadlock_replicant_percent', description='Percent of replicant events getting deadlocks', type='INTEGER', value='0', read_only='N') +(name='debug_election', description='Enable extended election trace. (Default: off)', type='BOOLEAN', value='OFF', read_only='N') (name='debug_enospc_chance', description='DEBUG %% random ENOSPC on writes', type='INTEGER', value='0', read_only='N') (name='debug_log_deletion', description='', type='BOOLEAN', value='OFF', read_only='N') (name='debug_mpalloc_size', description='Alarm on suspicious allocation requests', type='BOOLEAN', value='OFF', read_only='N')