This is an automated email from the ASF dual-hosted git repository.
awong pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/kudu.git
The following commit(s) were added to refs/heads/master by this push:
new 777338f KUDU-2762: Improve write transaction tracing
777338f is described below
commit 777338f5650ecfff76faf88050f1d9363138a095
Author: Mitch Barnett <[email protected]>
AuthorDate: Thu Apr 11 17:43:04 2019 -0700
KUDU-2762: Improve write transaction tracing
The trace logging for write transactions had grammatical differences as
well as errors in punctuation. In addition, the `APPLY` phase tracing
was missing an end message while the `REPLICATION` phase tracing was
missing both a start and end message. Finally, trace messaging within
tablet.cc was prepending the `PREPARE` phase to it unnecessarily.
Change-Id: I3e69e45210c1c284d9e43c4e47fe052c41a353d7
Reviewed-on: http://gerrit.cloudera.org:8080/12999
Tested-by: Kudu Jenkins
Reviewed-by: Attila Bukor <[email protected]>
Reviewed-by: Andrew Wong <[email protected]>
---
src/kudu/tablet/tablet.cc | 6 +++---
src/kudu/tablet/transactions/transaction_driver.cc | 2 ++
src/kudu/tablet/transactions/write_transaction.cc | 11 ++++++-----
3 files changed, 11 insertions(+), 8 deletions(-)
diff --git a/src/kudu/tablet/tablet.cc b/src/kudu/tablet/tablet.cc
index 01fb260..b63e5c2 100644
--- a/src/kudu/tablet/tablet.cc
+++ b/src/kudu/tablet/tablet.cc
@@ -436,7 +436,7 @@ Status Tablet::DecodeWriteOperations(const Schema*
client_schema,
// The Schema needs to be held constant while any transactions are between
// PREPARE and APPLY stages
- TRACE("PREPARE: Decoding operations");
+ TRACE("Decoding operations");
vector<DecodedRowOperation> ops;
// Decode the ops
@@ -458,11 +458,11 @@ Status Tablet::DecodeWriteOperations(const Schema*
client_schema,
Status Tablet::AcquireRowLocks(WriteTransactionState* tx_state) {
TRACE_EVENT1("tablet", "Tablet::AcquireRowLocks",
"num_locks", tx_state->row_ops().size());
- TRACE("PREPARE: Acquiring locks for $0 operations",
tx_state->row_ops().size());
+ TRACE("Acquiring locks for $0 operations", tx_state->row_ops().size());
for (RowOp* op : tx_state->row_ops()) {
RETURN_NOT_OK(AcquireLockForOp(tx_state, op));
}
- TRACE("PREPARE: locks acquired");
+ TRACE("Locks acquired");
return Status::OK();
}
diff --git a/src/kudu/tablet/transactions/transaction_driver.cc
b/src/kudu/tablet/transactions/transaction_driver.cc
index beed972..0677cc7 100644
--- a/src/kudu/tablet/transactions/transaction_driver.cc
+++ b/src/kudu/tablet/transactions/transaction_driver.cc
@@ -322,6 +322,7 @@ Status TransactionDriver::Prepare() {
mutable_state()->consensus_round()->replicate_msg()));
RETURN_NOT_OK(transaction_->Start());
VLOG_WITH_PREFIX(4) << "Triggering consensus replication.";
+ TRACE("REPLICATION: Starting.");
// Trigger consensus replication.
{
std::lock_guard<simple_spinlock> lock(lock_);
@@ -434,6 +435,7 @@ void TransactionDriver::ReplicationFinished(const Status&
status) {
}
TRACE_COUNTER_INCREMENT("replication_time_us",
replication_duration.ToMicroseconds());
+ TRACE("REPLICATION: Finished.");
// If we have prepared and replicated, we're ready
// to move ahead and apply this operation.
diff --git a/src/kudu/tablet/transactions/write_transaction.cc
b/src/kudu/tablet/transactions/write_transaction.cc
index 9104754..abd7de0 100644
--- a/src/kudu/tablet/transactions/write_transaction.cc
+++ b/src/kudu/tablet/transactions/write_transaction.cc
@@ -149,7 +149,7 @@ void
WriteTransaction::NewReplicateMsg(gscoped_ptr<ReplicateMsg>* replicate_msg)
Status WriteTransaction::Prepare() {
TRACE_EVENT0("txn", "WriteTransaction::Prepare");
- TRACE("PREPARE: Starting");
+ TRACE("PREPARE: Starting.");
// Decode everything first so that we give up if something major is wrong.
Schema client_schema;
RETURN_NOT_OK_PREPEND(SchemaFromPB(state_->request()->schema(),
&client_schema),
@@ -184,7 +184,7 @@ Status WriteTransaction::Prepare() {
// Now acquire row locks and prepare everything for apply
RETURN_NOT_OK(tablet->AcquireRowLocks(state()));
- TRACE("PREPARE: finished.");
+ TRACE("PREPARE: Finished.");
return Status::OK();
}
@@ -207,7 +207,7 @@ Status WriteTransaction::Start() {
// it seems pointless to return a Status!
Status WriteTransaction::Apply(gscoped_ptr<CommitMsg>* commit_msg) {
TRACE_EVENT0("txn", "WriteTransaction::Apply");
- TRACE("APPLY: Starting");
+ TRACE("APPLY: Starting.");
if (PREDICT_FALSE(
ANNOTATE_UNPROTECTED_READ(FLAGS_tablet_inject_latency_on_apply_write_txn_ms) >
0)) {
@@ -218,6 +218,7 @@ Status WriteTransaction::Apply(gscoped_ptr<CommitMsg>*
commit_msg) {
Tablet* tablet = state()->tablet_replica()->tablet();
RETURN_NOT_OK(tablet->ApplyRowOperations(state()));
+ TRACE("APPLY: Finished.");
// Add per-row errors to the result, update metrics.
int i = 0;
@@ -248,13 +249,13 @@ void WriteTransaction::Finish(TransactionResult result) {
state()->CommitOrAbort(result);
if (PREDICT_FALSE(result == Transaction::ABORTED)) {
- TRACE("FINISH: transaction aborted");
+ TRACE("FINISH: Transaction aborted.");
return;
}
DCHECK_EQ(result, Transaction::COMMITTED);
- TRACE("FINISH: updating metrics");
+ TRACE("FINISH: Updating metrics.");
TabletMetrics* metrics = state_->tablet_replica()->tablet()->metrics();
if (metrics) {
