Add support for client provided transaction identifier to be logged as part of trace logging or transaction profiling.

This commit is contained in:
Balachandar Namasivayam 2019-02-12 13:54:24 -08:00
parent 1b04f9a71a
commit 91d859d791
4 changed files with 66 additions and 23 deletions

View File

@ -115,8 +115,8 @@ public:
// Client status updater
struct ClientStatusUpdater {
std::vector<BinaryWriter> inStatusQ;
std::vector<BinaryWriter> outStatusQ;
std::vector< std::pair<std::string, BinaryWriter> > inStatusQ;
std::vector< std::pair<std::string, BinaryWriter> > outStatusQ;
Future<Void> actor;
};
ClientStatusUpdater clientStatusUpdater;

View File

@ -362,15 +362,17 @@ ACTOR static Future<Void> clientStatusUpdateActor(DatabaseContext *cx) {
cx->clientStatusUpdater.inStatusQ.swap(cx->clientStatusUpdater.outStatusQ);
// Split Transaction Info into chunks
state std::vector<TrInfoChunk> trChunksQ;
for (auto &bw : cx->clientStatusUpdater.outStatusQ) {
for (auto &entry : cx->clientStatusUpdater.outStatusQ) {
auto &bw = entry.second;
int64_t value_size_limit = BUGGIFY ? g_random->randomInt(1e3, CLIENT_KNOBS->VALUE_SIZE_LIMIT) : CLIENT_KNOBS->VALUE_SIZE_LIMIT;
int num_chunks = (bw.getLength() + value_size_limit - 1) / value_size_limit;
std::string random_id = g_random->randomAlphaNumeric(16);
std::string user_provided_id = entry.first.size() ? entry.first + "/" : "";
for (int i = 0; i < num_chunks; i++) {
TrInfoChunk chunk;
BinaryWriter chunkBW(Unversioned());
chunkBW << bigEndian32(i+1) << bigEndian32(num_chunks);
chunk.key = KeyRef(clientLatencyName + std::string(10, '\x00') + "/" + random_id + "/" + chunkBW.toStringRef().toString() + "/" + std::string(4, '\x00'));
chunk.key = KeyRef(clientLatencyName + std::string(10, '\x00') + "/" + random_id + "/" + chunkBW.toStringRef().toString() + "/" + user_provided_id + std::string(4, '\x00'));
int32_t pos = littleEndian32(clientLatencyName.size());
memcpy(mutateString(chunk.key) + chunk.key.size() - sizeof(int32_t), &pos, sizeof(int32_t));
if (i == num_chunks - 1) {
@ -1899,7 +1901,7 @@ void Transaction::operator=(Transaction&& r) noexcept(true) {
void Transaction::flushTrLogsIfEnabled() {
if (trLogInfo && trLogInfo->logsAdded && trLogInfo->trLogWriter.getData()) {
ASSERT(trLogInfo->flushed == false);
cx->clientStatusUpdater.inStatusQ.push_back(std::move(trLogInfo->trLogWriter));
cx->clientStatusUpdater.inStatusQ.push_back({ trLogInfo->identifier, std::move(trLogInfo->trLogWriter) });
trLogInfo->flushed = true;
}
}
@ -2682,16 +2684,50 @@ void Transaction::setOption( FDBTransactionOptions::Option option, Optional<Stri
}
if(trLogInfo) {
if(!trLogInfo->identifier.present()) {
if (trLogInfo->identifier.empty()) {
trLogInfo->identifier = printable(value.get());
}
else if(trLogInfo->identifier.get() != printable(value.get())) {
TraceEvent(SevWarn, "CannotChangeTransactionLoggingIdentifier").detail("PreviousIdentifier", trLogInfo->identifier.get()).detail("NewIdentifier", printable(value.get()));
else if (trLogInfo->identifier != printable(value.get())) {
TraceEvent(SevWarn, "CannotChangeDebugTransactionIdentifier").detail("PreviousIdentifier", trLogInfo->identifier).detail("NewIdentifier", printable(value.get()));
throw client_invalid_operation();
}
trLogInfo->logTo(TransactionLogInfo::TRACE_LOG);
}
else {
trLogInfo = Reference<TransactionLogInfo>(new TransactionLogInfo(printable(value.get()), TransactionLogInfo::TRACE_LOG));
}
break;
case FDBTransactionOptions::DEBUG_TRANSACTION_IDENTIFIER:
validateOptionValue(value, true);
if (value.get().size() > 100) {
throw invalid_option_value();
}
if (trLogInfo) {
if (trLogInfo->identifier.empty()) {
trLogInfo->identifier = printable(value.get());
}
else if (trLogInfo->identifier != printable(value.get())) {
TraceEvent(SevWarn, "CannotChangeDebugTransactionIdentifier").detail("PreviousIdentifier", trLogInfo->identifier).detail("NewIdentifier", printable(value.get()));
throw client_invalid_operation();
}
}
else {
trLogInfo = Reference<TransactionLogInfo>(new TransactionLogInfo(printable(value.get())));
trLogInfo = Reference<TransactionLogInfo>(new TransactionLogInfo(printable(value.get()), TransactionLogInfo::DONT_LOG));
}
break;
case FDBTransactionOptions::LOG_TRANSACTION:
if (trLogInfo) {
trLogInfo->logTo(TransactionLogInfo::TRACE_LOG);
}
else {
TraceEvent(SevWarn, "DebugTransactionIdentifierNotSet").detail("Error", "Debug Transaction Identifier option must be set before logging the transaction");
throw client_invalid_operation();
}
break;
@ -3066,7 +3102,7 @@ Reference<TransactionLogInfo> Transaction::createTrLogInfoProbabilistically(cons
if(!cx->isError()) {
double clientSamplingProbability = std::isinf(cx->clientInfo->get().clientTxnInfoSampleRate) ? CLIENT_KNOBS->CSI_SAMPLING_PROBABILITY : cx->clientInfo->get().clientTxnInfoSampleRate;
if (((networkOptions.logClientInfo.present() && networkOptions.logClientInfo.get()) || BUGGIFY) && g_random->random01() < clientSamplingProbability && (!g_network->isSimulated() || !g_simulator.speedUpSimulation)) {
return Reference<TransactionLogInfo>(new TransactionLogInfo());
return Reference<TransactionLogInfo>(new TransactionLogInfo(TransactionLogInfo::DATABASE));
}
}

View File

@ -166,34 +166,37 @@ struct TransactionInfo {
};
struct TransactionLogInfo : public ReferenceCounted<TransactionLogInfo>, NonCopyable {
TransactionLogInfo() : logToDatabase(true) {}
TransactionLogInfo(std::string identifier) : logToDatabase(false), identifier(identifier) {}
enum LoggingLocation { DONT_LOG=0, TRACE_LOG = 1, DATABASE = 2 };
BinaryWriter trLogWriter{ IncludeVersion() };
bool logsAdded{ false };
bool flushed{ false };
TransactionLogInfo() : logLocation(DONT_LOG) {}
TransactionLogInfo(LoggingLocation location) : logLocation(location) {}
TransactionLogInfo(std::string id, LoggingLocation location) : logLocation(location), identifier(id) {}
void setIdentifier(std::string id) { identifier = id; }
void logTo(LoggingLocation loc) { logLocation = logLocation | loc; }
template <typename T>
void addLog(const T& event) {
ASSERT(logToDatabase || identifier.present());
if(identifier.present()) {
event.logEvent(identifier.get());
if(logLocation & TRACE_LOG) {
ASSERT(!identifier.empty())
event.logEvent(identifier);
}
if (flushed) {
return;
}
if(logToDatabase) {
if(logLocation & DATABASE) {
logsAdded = true;
static_assert(std::is_base_of<FdbClientLogEvents::Event, T>::value, "Event should be derived class of FdbClientLogEvents::Event");
trLogWriter << event;
}
}
bool logToDatabase;
Optional<std::string> identifier;
BinaryWriter trLogWriter{ IncludeVersion() };
bool logsAdded{ false };
bool flushed{ false };
int logLocation;
std::string identifier;
};
struct Watch : public ReferenceCounted<Watch>, NonCopyable {

View File

@ -170,7 +170,11 @@ description is not currently required but encouraged.
hidden="true" />
<Option name="debug_retry_logging" code="401" paramType="String" paramDescription="Optional transaction name" />
<Option name="transaction_logging_enable" code="402" paramType="String" paramDescription="String identifier to be used in the logs when tracing this transaction. The identifier must not exceed 100 characters."
description="Enables tracing for this transaction and logs results to the client trace logs. Client trace logging must be enabled to get log output." />
description="Deprecated." />
<Option name="debug_transaction_identifier" code="403" paramType="String" paramDescription="String identifier to be used in the case if this transaction is to be logged or profiled. The identifier must not exceed 100 characters."
description="Set a client provided identifier for the transaction that will be used in scenarios like tracing or profiling. Client trace logging or transaction profiling must be separately enabled." />
<Option name="log_transaction" code="404" paramType="String"
description="Trace log this transaction. DEBUG_TRANSACTION_IDENTIFIER option must be set before using this option." />
<Option name="timeout" code="500"
paramType="Int" paramDescription="value in milliseconds of timeout"
description="Set a timeout in milliseconds which, when elapsed, will cause the transaction automatically to be cancelled. Valid parameter values are ``[0, INT_MAX]``. If set to 0, will disable all timeouts. All pending and any future uses of the transaction will throw an exception. The transaction can be used again after it is reset. Like all transaction options, a timeout must be reset after a call to onError. This behavior allows the user to make the timeout dynamic." />