Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Emitting diagnostic event containing Soroban resource utilization metrics #3847

Merged
merged 3 commits into from
Jul 28, 2023
Merged

Emitting diagnostic event containing Soroban resource utilization metrics #3847

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
888db2b
Add several soroban metrics
jayz22 Jul 20, 2023
856d46f
Emit diagnostic events containing resource utilization metrics
jayz22 Jul 20, 2023
f0f9337
fixup! Emit diagnostic events containing resource utilization metrics
jayz22 Jul 25, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 12 additions & 6 deletions src/rust/src/contract.rs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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};
graydon marked this conversation as resolved.
Show resolved Hide resolved

// 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
Open in desktop
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
Open in desktop
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