Skip to content

Commit

Permalink
Merge pull request #3847 from jayz22/metrics
Browse files Browse the repository at this point in the history 
Emitting diagnostic event containing Soroban resource utilization metrics

Reviewed-by: graydon
  • Loading branch information
@latobarita
latobarita authored Jul 28, 2023
2 parents 9215e8d + f0f9337 commit f054bbd
Show file tree
Hide file tree
Showing 5 changed files with 178 additions and 43 deletions.
18 changes: 12 additions & 6 deletions src/rust/src/contract.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@ use crate::{
},
};
use log::debug;
use std::{fmt::Display, io::Cursor, panic, rc::Rc};
use std::{fmt::Display, io::Cursor, panic, rc::Rc, time::Instant};

// This module (contract) is bound to _two separate locations_ in the module
// tree: crate::lo::contract and crate::hi::contract, each of which has a (lo or
Expand Down Expand Up @@ -466,9 +466,13 @@ fn invoke_host_function_or_maybe_panic(
host.set_diagnostic_level(DiagnosticLevel::Debug)?;
}

let res = {
let (res, time_nsecs) = {
let _span1 = tracy_span!("Host::invoke_function");
host.invoke_function(hf)
let start_time = Instant::now();
let res = host.invoke_function(hf);
let stop_time = Instant::now();
let time_nsecs = stop_time.duration_since(start_time).as_nanos() as u64;
(res, time_nsecs)
};

let (storage, budget, events, bumps) = host
Expand Down Expand Up @@ -498,9 +502,10 @@ fn invoke_host_function_or_maybe_panic(
contract_events: vec![],
diagnostic_events: extract_diagnostic_events(&events)?,
modified_ledger_entries: vec![],
expiration_bumps: vec![],
cpu_insns,
mem_bytes,
expiration_bumps: vec![],
time_nsecs,
});
}
};
Expand All @@ -517,9 +522,10 @@ fn invoke_host_function_or_maybe_panic(
contract_events,
diagnostic_events,
modified_ledger_entries,
cpu_insns: budget.get_cpu_insns_consumed()?,
mem_bytes: budget.get_mem_bytes_consumed()?,
expiration_bumps,
cpu_insns,
mem_bytes,
time_nsecs,
})
}

Expand Down
1 change: 1 addition & 0 deletions src/rust/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,7 @@ mod rust_bridge {
expiration_bumps: Vec<Bump>,
cpu_insns: u64,
mem_bytes: u64,
time_nsecs: u64,
}

// LogLevel declares to cxx.rs a shared type that both Rust and C+++ will
Expand Down
179 changes: 145 additions & 34 deletions src/transactions/InvokeHostFunctionOpFrame.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -112,45 +112,38 @@ validateContractLedgerEntry(LedgerEntry const& le, size_t entrySize,
return true;
}

} // namespace

InvokeHostFunctionOpFrame::InvokeHostFunctionOpFrame(Operation const& op,
OperationResult& res,
TransactionFrame& parentTx)
: OperationFrame(op, res, parentTx)
, mInvokeHostFunction(mOperation.body.invokeHostFunctionOp())
SCVal
makeSymbol(std::string const& str)
{
SCVal val(SCV_SYMBOL);
val.sym().assign(str.begin(), str.end());
return val;
}

bool
InvokeHostFunctionOpFrame::isOpSupported(LedgerHeader const& header) const
SCVal
makeU64(uint64_t u)
{
return header.ledgerVersion >= 20;
SCVal val(SCV_U64);
val.u64() = u;
return val;
}

bool
InvokeHostFunctionOpFrame::doApply(AbstractLedgerTxn& ltx)
DiagnosticEvent
metricsEvent(bool success, std::string const& topic, uint32 value)
{
throw std::runtime_error(
"InvokeHostFunctionOpFrame::doApply needs Config and base PRNG seed");
DiagnosticEvent de;
de.inSuccessfulContractCall = success;
de.event.type = ContractEventType::DIAGNOSTIC;
SCVec topics = {
makeSymbol("core_metrics"),
makeSymbol(topic),
};
de.event.body.v0().topics = topics;
de.event.body.v0().data = makeU64(value);
return de;
}

void
InvokeHostFunctionOpFrame::maybePopulateDiagnosticEvents(
Config const& cfg, InvokeHostFunctionOutput const& output)
{
if (cfg.ENABLE_SOROBAN_DIAGNOSTIC_EVENTS)
{
xdr::xvector<DiagnosticEvent> diagnosticEvents;
for (auto const& e : output.diagnostic_events)
{
DiagnosticEvent evt;
xdr::xdr_from_opaque(e.data, evt);
diagnosticEvents.emplace_back(evt);
}
mParentTx.pushDiagnosticEvents(std::move(diagnosticEvents));
}
}
} // namespace

struct HostFunctionMetrics
{
Expand All @@ -174,8 +167,16 @@ struct HostFunctionMetrics
uint32 mEmitEvent{0};
uint32 mEmitEventByte{0};

// host runtime metrics
uint32 mCpuInsn{0};
uint32 mMemByte{0};
uint32 mInvokeTimeNsecs{0};

// max single entity size metrics
uint32 mMaxReadWriteKeyByte{0};
uint32 mMaxReadWriteDataByte{0};
uint32 mMaxReadWriteCodeByte{0};
uint32 mMaxEmitEventByte{0};

uint32 mMetadataSizeByte{0};

Expand All @@ -190,14 +191,17 @@ struct HostFunctionMetrics
{
mReadEntry++;
mReadKeyByte += keySize;
mMaxReadWriteKeyByte = std::max(mMaxReadWriteKeyByte, keySize);
mLedgerReadByte += keySize + entrySize;
if (isCodeEntry)
{
mReadCodeByte += keySize + entrySize;
mMaxReadWriteCodeByte = std::max(mMaxReadWriteCodeByte, entrySize);
}
else
{
mReadDataByte += keySize + entrySize;
mMaxReadWriteDataByte = std::max(mMaxReadWriteDataByte, entrySize);
}
}

Expand All @@ -206,14 +210,17 @@ struct HostFunctionMetrics
{
mWriteEntry++;
mWriteKeyByte += keySize;
mMaxReadWriteKeyByte = std::max(mMaxReadWriteKeyByte, keySize);
mLedgerWriteByte += keySize + entrySize;
if (isCodeEntry)
{
mWriteCodeByte += keySize + entrySize;
mMaxReadWriteCodeByte = std::max(mMaxReadWriteCodeByte, entrySize);
}
else
{
mWriteDataByte += keySize + entrySize;
mMaxReadWriteDataByte = std::max(mMaxReadWriteDataByte, entrySize);
}
}

Expand Down Expand Up @@ -257,6 +264,19 @@ struct HostFunctionMetrics
.Mark(mCpuInsn);
mMetrics.NewMeter({"soroban", "host-fn-op", "mem-byte"}, "byte")
.Mark(mMemByte);
mMetrics
.NewMeter({"soroban", "host-fn-op", "invoke-time-nsecs"}, "time")
.Mark(mInvokeTimeNsecs);

mMetrics.NewMeter({"soroban", "host-fn-op", "max-rw-key-byte"}, "byte")
.Mark(mMaxReadWriteKeyByte);
mMetrics.NewMeter({"soroban", "host-fn-op", "max-rw-data-byte"}, "byte")
.Mark(mMaxReadWriteDataByte);
mMetrics.NewMeter({"soroban", "host-fn-op", "max-rw-code-byte"}, "byte")
.Mark(mMaxReadWriteCodeByte);
mMetrics
.NewMeter({"soroban", "host-fn-op", "max-emit-event-byte"}, "byte")
.Mark(mMaxEmitEventByte);

if (mSuccess)
{
Expand All @@ -276,6 +296,92 @@ struct HostFunctionMetrics
}
};

InvokeHostFunctionOpFrame::InvokeHostFunctionOpFrame(Operation const& op,
OperationResult& res,
TransactionFrame& parentTx)
: OperationFrame(op, res, parentTx)
, mInvokeHostFunction(mOperation.body.invokeHostFunctionOp())
{
}

bool
InvokeHostFunctionOpFrame::isOpSupported(LedgerHeader const& header) const
{
return header.ledgerVersion >= 20;
}

bool
InvokeHostFunctionOpFrame::doApply(AbstractLedgerTxn& ltx)
{
throw std::runtime_error(
"InvokeHostFunctionOpFrame::doApply needs Config and base PRNG seed");
}

void
InvokeHostFunctionOpFrame::maybePopulateDiagnosticEvents(
Config const& cfg, InvokeHostFunctionOutput const& output,
HostFunctionMetrics const& metrics)
{
if (cfg.ENABLE_SOROBAN_DIAGNOSTIC_EVENTS)
{
xdr::xvector<DiagnosticEvent> diagnosticEvents;
for (auto const& e : output.diagnostic_events)
{
DiagnosticEvent evt;
xdr::xdr_from_opaque(e.data, evt);
diagnosticEvents.emplace_back(evt);
}

// add additional diagnostic events for metrics
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "read_entry", metrics.mReadEntry));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "write_entry", metrics.mWriteEntry));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "ledger_read_byte", metrics.mLedgerReadByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "ledger_write_byte", metrics.mLedgerWriteByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "read_key_byte", metrics.mReadKeyByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "write_key_byte", metrics.mWriteKeyByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "read_data_byte", metrics.mReadDataByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "write_data_byte", metrics.mWriteDataByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "read_code_byte", metrics.mReadCodeByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "write_code_byte", metrics.mWriteCodeByte));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "emit_event", metrics.mEmitEvent));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "emit_event_byte", metrics.mEmitEventByte));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "cpu_insn", metrics.mCpuInsn));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "mem_byte", metrics.mMemByte));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "invoke_time_nsecs", metrics.mInvokeTimeNsecs));
diagnosticEvents.emplace_back(metricsEvent(
metrics.mSuccess, "max_rw_key_byte", metrics.mMaxReadWriteKeyByte));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "max_rw_data_byte",
metrics.mMaxReadWriteDataByte));
diagnosticEvents.emplace_back(
metricsEvent(metrics.mSuccess, "max_rw_code_byte",
metrics.mMaxReadWriteCodeByte));
diagnosticEvents.emplace_back(metricsEvent(metrics.mSuccess,
"max_emit_event_byte",
metrics.mMaxEmitEventByte));
diagnosticEvents.emplace_back(metricsEvent(metrics.mSuccess,
"max_meta_data_size_byte",
metrics.mMetadataSizeByte));

mParentTx.pushDiagnosticEvents(std::move(diagnosticEvents));
}
}

bool
InvokeHostFunctionOpFrame::doApply(Application& app, AbstractLedgerTxn& ltx,
Hash const& sorobanBasePrngSeed)
Expand Down Expand Up @@ -409,7 +515,7 @@ InvokeHostFunctionOpFrame::doApply(Application& app, AbstractLedgerTxn& ltx,
}
else
{
maybePopulateDiagnosticEvents(cfg, out);
maybePopulateDiagnosticEvents(cfg, out, metrics);
}
}
catch (std::exception& e)
Expand All @@ -419,6 +525,8 @@ InvokeHostFunctionOpFrame::doApply(Application& app, AbstractLedgerTxn& ltx,

metrics.mCpuInsn = static_cast<uint32>(out.cpu_insns);
metrics.mMemByte = static_cast<uint32>(out.mem_bytes);
metrics.mInvokeTimeNsecs = static_cast<uint32>(out.time_nsecs);

if (!metrics.mSuccess)
{
if (resources.instructions < out.cpu_insns ||
Expand Down Expand Up @@ -602,8 +710,11 @@ InvokeHostFunctionOpFrame::doApply(Application& app, AbstractLedgerTxn& ltx,
for (auto const& buf : out.contract_events)
{
metrics.mEmitEvent++;
metrics.mEmitEventByte += static_cast<uint32>(buf.data.size());
metrics.mMetadataSizeByte += static_cast<uint32>(buf.data.size());
uint32 eventSize = static_cast<uint32>(buf.data.size());
metrics.mEmitEventByte += eventSize;
metrics.mMaxEmitEventByte =
std::max(metrics.mMaxEmitEventByte, eventSize);
metrics.mMetadataSizeByte += eventSize;
if (resources.extendedMetaDataSizeBytes < metrics.mMetadataSizeByte)
{
innerResult().code(INVOKE_HOST_FUNCTION_RESOURCE_LIMIT_EXCEEDED);
Expand All @@ -614,7 +725,7 @@ InvokeHostFunctionOpFrame::doApply(Application& app, AbstractLedgerTxn& ltx,
success.events.emplace_back(evt);
}

maybePopulateDiagnosticEvents(cfg, out);
maybePopulateDiagnosticEvents(cfg, out, metrics);
// This may throw, but only in case of the Core version misconfiguration.
int64_t rentFee = rust_bridge::compute_rent_fee(
cfg.CURRENT_LEDGER_PROTOCOL_VERSION,
Expand Down
3 changes: 2 additions & 1 deletion src/transactions/InvokeHostFunctionOpFrame.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,8 @@ class InvokeHostFunctionOpFrame : public OperationFrame
}

void maybePopulateDiagnosticEvents(Config const& cfg,
InvokeHostFunctionOutput const& output);
InvokeHostFunctionOutput const& output,
HostFunctionMetrics const& metrics);

InvokeHostFunctionOp const& mInvokeHostFunction;

Expand Down
20 changes: 18 additions & 2 deletions src/transactions/test/InvokeHostFunctionTests.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1151,7 +1151,7 @@ TEST_CASE("failed invocation with diagnostics", "[tx][soroban]")
ltx.commit();

auto const& opEvents = txm.getXDR().v3().sorobanMeta->diagnosticEvents;
REQUIRE(opEvents.size() == 2);
REQUIRE(opEvents.size() == 22);

auto const& call_ev = opEvents.at(0);
REQUIRE(!call_ev.inSuccessfulContractCall);
Expand All @@ -1162,6 +1162,14 @@ TEST_CASE("failed invocation with diagnostics", "[tx][soroban]")
REQUIRE(!contract_ev.inSuccessfulContractCall);
REQUIRE(contract_ev.event.type == ContractEventType::CONTRACT);
REQUIRE(contract_ev.event.body.v0().data.type() == SCV_VEC);

auto const& read_entry_ev = opEvents.at(2);
REQUIRE(!read_entry_ev.inSuccessfulContractCall);
REQUIRE(read_entry_ev.event.type == ContractEventType::DIAGNOSTIC);
auto const& v0 = read_entry_ev.event.body.v0();
REQUIRE((v0.topics.size() == 2 && v0.topics.at(0).sym() == "core_metrics" &&
v0.topics.at(1).sym() == "read_entry"));
REQUIRE(v0.data.type() == SCV_U64);
}

TEST_CASE("complex contract", "[tx][soroban]")
Expand Down Expand Up @@ -1200,7 +1208,7 @@ TEST_CASE("complex contract", "[tx][soroban]")

auto verifyDiagnosticEvents =
[&](xdr::xvector<DiagnosticEvent> events) {
REQUIRE(events.size() == 3);
REQUIRE(events.size() == 23);

auto call_ev = events.at(0);
REQUIRE(call_ev.event.type == ContractEventType::DIAGNOSTIC);
Expand All @@ -1213,6 +1221,14 @@ TEST_CASE("complex contract", "[tx][soroban]")
auto return_ev = events.at(2);
REQUIRE(return_ev.event.type == ContractEventType::DIAGNOSTIC);
REQUIRE(return_ev.event.body.v0().data.type() == SCV_VOID);

auto const& metrics_ev = events.back();
REQUIRE(metrics_ev.event.type == ContractEventType::DIAGNOSTIC);
auto const& v0 = metrics_ev.event.body.v0();
REQUIRE((v0.topics.size() == 2 &&
v0.topics.at(0).sym() == "core_metrics" &&
v0.topics.at(1).sym() == "max_meta_data_size_byte"));
REQUIRE(v0.data.type() == SCV_U64);
};

SECTION("single op")
Expand Down

0 comments on commit f054bbd

Please sign in to comment.