diff --git a/bbinc/thread_stats.h b/bbinc/thread_stats.h index 0f9ed13216..7064186dfd 100644 --- a/bbinc/thread_stats.h +++ b/bbinc/thread_stats.h @@ -53,6 +53,13 @@ struct berkdb_thread_stats { uint64_t rep_collect_time_us; uint64_t rep_exec_time_us; + + uint32_t rep_commit_file; + uint32_t rep_commit_offset; + + uint64_t rep_longest_dispatch_us; + uint32_t rep_longest_dispatch_file; + uint32_t rep_longest_dispatch_offset; }; #endif diff --git a/bdb/bdb.c b/bdb/bdb.c index a155fa7133..eb3b30fab5 100644 --- a/bdb/bdb.c +++ b/bdb/bdb.c @@ -752,6 +752,14 @@ void bdb_print_stats(const struct berkdb_thread_stats *st, const char *prefix, st->rep_log_cnt, st->rep_log_bytes, U2M(st->rep_collect_time_us), U2M(st->rep_exec_time_us)); printfn(s, context); } + + if (st->rep_longest_dispatch_us > 0) { + snprintf(s, sizeof(s), "Longest rep-dispatch time %u ms at [%d:%d], commit-lsn [%u:%u]\n", + U2M(st->rep_longest_dispatch_us), st->rep_longest_dispatch_file, st->rep_longest_dispatch_offset, + st->rep_commit_file, st->rep_commit_offset); + printfn(s, context); + } + if (st->n_lock_waits > 0) { snprintf(s, sizeof(s), "%s%u lock waits took %u ms (%u ms/wait)\n", prefix, st->n_lock_waits, U2M(st->lock_wait_time_us), U2M(st->lock_wait_time_us / st->n_lock_waits)); diff --git a/berkdb/rep/rep_record.c b/berkdb/rep/rep_record.c index 689e29a381..6e21c9b9a8 100644 --- a/berkdb/rep/rep_record.c +++ b/berkdb/rep/rep_record.c @@ -5038,6 +5038,12 @@ __rep_process_txn_int(dbenv, rctl, rec, ltrans, maxlsn, commit_gen, lockid, rp, lock_dbt = &prep_args->locks; } + if (td_stats) { + struct berkdb_thread_stats *t = bb_berkdb_get_thread_stats(); + t->rep_commit_file = maxlsn.file; + t->rep_commit_offset = maxlsn.offset; + } + if (collect_before_locking) { if (lcin) lc = *lcin; @@ -5291,6 +5297,10 @@ __rep_process_txn_int(dbenv, rctl, rec, ltrans, maxlsn, commit_gen, lockid, rp, DB_LSN lsn; lsn = lc.array[i].lsn; lsnp = &lsn; + uint64_t start_dispatch, end_dispatch; + + if (td_stats) + start_dispatch = bb_berkdb_fasttime(); if (!lc.array[i].rec.data) { assert(!lc.filled_from_cache); @@ -5339,6 +5349,14 @@ __rep_process_txn_int(dbenv, rctl, rec, ltrans, maxlsn, commit_gen, lockid, rp, } } else ret = 0; + if (td_stats) { + end_dispatch = bb_berkdb_fasttime(); + if (end_dispatch - start_dispatch > t->rep_longest_dispatch_us) { + t->rep_longest_dispatch_us = end_dispatch - start_dispatch; + t->rep_longest_dispatch_file = lsnp->file; + t->rep_longest_dispatch_offset = lsnp->offset; + } + } } @@ -5700,6 +5718,7 @@ __rep_process_txn_concurrent_int(dbenv, rctl, rec, ltrans, ctrllsn, maxlsn, int get_schema_lk = 0, got_schema_lk = 0; int dontlock = 0; int endianize = 0; + int td_stats = gbl_bb_berkdb_enable_thread_stats; Pthread_mutex_lock(&dbenv->recover_lk); rp = listc_rtl(&dbenv->inactive_transactions); @@ -5989,6 +6008,12 @@ bad_resize: ; } } + if (td_stats) { + struct berkdb_thread_stats *t = bb_berkdb_get_thread_stats(); + t->rep_commit_file = maxlsn.file; + t->rep_commit_offset = maxlsn.offset; + } + if (collect_before_locking) { if ((ret = __rep_collect_txn_txnid(dbenv, &prev_lsn, &rp->lc, &had_serializable_records, rp, txnid)) != 0) { @@ -6024,7 +6049,6 @@ bad_resize: ; got_schema_lk = 1; } - int td_stats = gbl_bb_berkdb_enable_thread_stats; struct berkdb_thread_stats *t, *p; uint64_t x1, x2, d; diff --git a/tests/longreq_stats.test/runit b/tests/longreq_stats.test/runit index a04232f3db..ffde373c50 100755 --- a/tests/longreq_stats.test/runit +++ b/tests/longreq_stats.test/runit @@ -59,6 +59,11 @@ function check_log_node max="$x" echo "$node applied $max log records" done + + # Verify that we are emitting 'Longest rep-apply time' stats + lb=$(egrep "Longest rep-dispatch time" $log) + lines=$(echo "$lb" | wc -l) + [[ "$lines" -eq "0" ]] && failexit "Did not emit longest-rep-apply" } function check_logs