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.

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

Speculative logging support in Aptos VM #6708

Merged
merged 1 commit into from
Mar 8, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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: 18 additions & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 2 additions & 0 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ members = [
"aptos-move/aptos-transactional-test-harness",
"aptos-move/aptos-validator-interface",
"aptos-move/aptos-vm",
"aptos-move/aptos-vm-logging",
"aptos-move/aptos-vm-profiling",
"aptos-move/block-executor",
"aptos-move/e2e-move-tests",
Expand Down Expand Up @@ -293,6 +294,7 @@ aptos-types = { path = "types" }
aptos-validator-interface = { path = "aptos-move/aptos-validator-interface" }
aptos-vault-client = { path = "secure/storage/vault" }
aptos-vm = { path = "aptos-move/aptos-vm" }
aptos-vm-logging = { path = "aptos-move/aptos-vm-logging" }
aptos-vm-genesis = { path = "aptos-move/vm-genesis" }
aptos-vm-validator = { path = "vm-validator" }
aptos-warp-webserver = { path = "crates/aptos-warp-webserver" }
Expand Down
24 changes: 24 additions & 0 deletions aptos-move/aptos-vm-logging/Cargo.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
[package]
name = "aptos-vm-logging"
description = "Aptos VM speculative logging utility"
version = "0.1.0"

# Workspace inherited keys
authors = { workspace = true }
edition = { workspace = true }
homepage = { workspace = true }
license = { workspace = true }
publish = { workspace = true }
repository = { workspace = true }
rust-version = { workspace = true }

[dependencies]
aptos-crypto = { workspace = true }
aptos-logger = { workspace = true }
aptos-metrics-core = { workspace = true }
aptos-speculative-state-helper = { workspace = true }
aptos-state-view = { workspace = true }
aptos-types = { workspace = true }
arc-swap = { workspace = true }
once_cell = { workspace = true }
serde = { workspace = true }
11 changes: 11 additions & 0 deletions aptos-move/aptos-vm-logging/src/counters.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
// Copyright © Aptos Foundation
// SPDX-License-Identifier: Apache-2.0

use aptos_metrics_core::{register_int_counter, IntCounter};
use once_cell::sync::Lazy;

/// Count the number of errors. This is not intended for display on a dashboard,
/// but rather for triggering alerts.
pub static CRITICAL_ERRORS: Lazy<IntCounter> = Lazy::new(|| {
register_int_counter!("aptos_vm_critical_errors", "Number of critical errors").unwrap()
});
167 changes: 167 additions & 0 deletions aptos-move/aptos-vm-logging/src/lib.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,167 @@
// Copyright © Aptos Foundation
// SPDX-License-Identifier: Apache-2.0

pub mod counters;
pub mod log_schema;

pub mod prelude {
pub use crate::{
alert, counters::CRITICAL_ERRORS, speculative_debug, speculative_error, speculative_info,
speculative_log, speculative_trace, speculative_warn,
};
}

use crate::{counters::CRITICAL_ERRORS, log_schema::AdapterLogSchema};
use aptos_logger::{prelude::*, Level};
use aptos_speculative_state_helper::{SpeculativeEvent, SpeculativeEvents};
use arc_swap::ArcSwapOption;
use once_cell::sync::Lazy;
use std::sync::Arc;

struct VMLogEntry {
level: Level,
context: AdapterLogSchema,
message: String,
}

impl VMLogEntry {
fn new(level: Level, context: AdapterLogSchema, message: String) -> Self {
Self {
level,
context,
message,
}
}
}

// Implement dispatching for a recorded VM log entry to support recording
// as speculative logging event (and eventual dispatching as needed).
impl SpeculativeEvent for VMLogEntry {
fn dispatch(self) {
match self.level {
Level::Error => {
// TODO: Consider using SpeculativeCounter to increase CRITICAL_ERRORS
// on the critical path instead of async dispatching.
alert!(self.context, "{}", self.message);
},
Level::Warn => warn!(self.context, "{}", self.message),
Level::Info => info!(self.context, "{}", self.message),
Level::Debug => debug!(self.context, "{}", self.message),
Level::Trace => trace!(self.context, "{}", self.message),
}
}
}

static BUFFERED_LOG_EVENTS: Lazy<ArcSwapOption<SpeculativeEvents<VMLogEntry>>> =
Lazy::new(|| ArcSwapOption::from(None));

/// Initializes the storage of speculative logs for num_txns many transactions.
pub fn init_speculative_logs(num_txns: usize) {
BUFFERED_LOG_EVENTS.swap(Some(Arc::new(SpeculativeEvents::new(num_txns))));
}

/// Adds a message at a specified logging level and given context (that includes txn index)
/// to speculative buffer. Logs directly and logs a separate (new error) if the speculative
/// events storage is not initialized or appropriately sized.
pub fn speculative_log(level: Level, context: &AdapterLogSchema, message: String) {
let txn_idx = context.get_txn_idx();
match &*BUFFERED_LOG_EVENTS.load() {
Some(log_events) => {
let log_event = VMLogEntry::new(level, context.clone(), message);
if let Err(e) = log_events.record(txn_idx, log_event) {
alert!("{:?}", e);
};
},
None => {
alert!(
"Speculative state not initialized to log message = {}",
message
);
},
};
}

/// Flushes the currently stored logs, and swaps the speculative log / event storage with None.
/// Must be called after block execution is complete (removes the storage from Arc).
pub fn flush_speculative_logs() {
match BUFFERED_LOG_EVENTS.swap(None) {
Some(log_events_ptr) => match Arc::try_unwrap(log_events_ptr) {
Ok(log_events) => log_events.flush(),
Err(_) => {
alert!("Speculative log storage must be uniquely owned to flush");
},
},
None => {
alert!("Flush called on uninitialized speculative log storage");
},
}
}

/// Clear speculative logs recorded for a specific transction, useful when transaction
/// execution fails validation and aborts - setting stage for the re-execution.
pub fn clear_speculative_txn_logs(txn_idx: usize) {
match &*BUFFERED_LOG_EVENTS.load() {
Some(log_events) => {
if let Err(e) = log_events.clear_txn_events(txn_idx) {
alert!("{:?}", e);
};
},
None => {
alert!("Clear all logs called on uninitialized speculative log storage");
},
}
}

/// Combine logging and error and incrementing critical errors counter for alerting.
#[macro_export]
macro_rules! alert {
($($args:tt)+) => {
error!($($args)+);
CRITICAL_ERRORS.inc();
};
}

#[macro_export]
macro_rules! speculative_error {
($($args:tt)+) => {
if enabled!(Level::Error) {
speculative_log(Level::Error, $($args)+);
}
};
}

#[macro_export]
macro_rules! speculative_warn {
($($args:tt)+) => {
if enabled!(Level::Warn) {
speculative_log(Level::Warn, $($args)+);
}
};
}

#[macro_export]
macro_rules! speculative_info {
($($args:tt)+) => {
if enabled!(Level::Info) {
speculative_log(Level::Info, $($args)+);
}
};
}

#[macro_export]
macro_rules! speculative_debug {
($($args:tt)+) => {
if enabled!(Level::Debug) {
speculative_log(Level::Debug, $($args)+);
}
};
}

#[macro_export]
macro_rules! speculative_trace {
($($args:tt)+) => {
if enabled!(Level::Trace) {
speculative_log(Level::Trace, $($args)+);
}
};
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,6 @@
// Parts of the project are originally copyright © Meta Platforms, Inc.
// SPDX-License-Identifier: Apache-2.0

use crate::counters::CRITICAL_ERRORS;
use aptos_crypto::HashValue;
use aptos_logger::Schema;
use aptos_state_view::StateViewId;
Expand All @@ -27,46 +26,45 @@ pub struct AdapterLogSchema {

// transaction position in the list of transactions in the block,
// 0 if the transaction is not part of a block (i.e. validation).
txn_id: usize,
txn_idx: usize,
}

impl AdapterLogSchema {
pub fn new(view_id: StateViewId, txn_id: usize) -> Self {
pub fn new(view_id: StateViewId, txn_idx: usize) -> Self {
match view_id {
StateViewId::BlockExecution { block_id } => Self {
name: LogEntry::Execution,
block_id: Some(block_id),
first_version: None,
base_version: None,
txn_id,
txn_idx,
},
StateViewId::ChunkExecution { first_version } => Self {
name: LogEntry::Execution,
block_id: None,
first_version: Some(first_version),
base_version: None,
txn_id,
txn_idx,
},
StateViewId::TransactionValidation { base_version } => Self {
name: LogEntry::Validation,
block_id: None,
first_version: None,
base_version: Some(base_version),
txn_id,
txn_idx,
},
StateViewId::Miscellaneous => Self {
name: LogEntry::Miscellaneous,
block_id: None,
first_version: None,
base_version: None,
txn_id,
txn_idx,
},
}
}

// Increment the `CRITICAL_ERRORS` monitor event that will fire an alert
pub fn alert(&self) {
CRITICAL_ERRORS.inc();
pub(crate) fn get_txn_idx(&self) -> usize {
self.txn_idx
}
}

Expand Down
1 change: 1 addition & 0 deletions aptos-move/aptos-vm/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ aptos-metrics-core = { workspace = true }
aptos-mvhashmap = { workspace = true }
aptos-state-view = { workspace = true }
aptos-types = { workspace = true }
aptos-vm-logging = { workspace = true }
bcs = { workspace = true }
dashmap = { workspace = true }
fail = { workspace = true }
Expand Down
6 changes: 2 additions & 4 deletions aptos-move/aptos-vm/src/adapter_common.rs
Original file line number Diff line number Diff line change
Expand Up @@ -2,10 +2,7 @@
// Parts of the project are originally copyright © Meta Platforms, Inc.
// SPDX-License-Identifier: Apache-2.0

use crate::{
logging::AdapterLogSchema,
move_vm_ext::{MoveResolverExt, SessionExt, SessionId},
};
use crate::move_vm_ext::{MoveResolverExt, SessionExt, SessionId};
use anyhow::Result;
use aptos_aggregator::transaction::TransactionOutputExt;
use aptos_types::{
Expand All @@ -17,6 +14,7 @@ use aptos_types::{
vm_status::{StatusCode, VMStatus},
write_set::WriteSet,
};
use aptos_vm_logging::log_schema::AdapterLogSchema;

/// This trait describes the VM adapter's interface.
/// TODO: bring more of the execution logic in aptos_vm into this file.
Expand Down
2 changes: 1 addition & 1 deletion aptos-move/aptos-vm/src/aptos_vm.rs
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,6 @@ use crate::{
data_cache::{AsMoveResolver, IntoMoveResolver},
delta_state_view::DeltaStateView,
errors::expect_only_successful_execution,
logging::AdapterLogSchema,
move_vm_ext::{MoveResolverExt, SessionExt, SessionId},
system_module_names::*,
transaction_metadata::TransactionMetadata,
Expand Down Expand Up @@ -42,6 +41,7 @@ use aptos_types::{
vm_status::{AbortLocation, DiscardedVMStatus, StatusCode, VMStatus},
write_set::WriteSet,
};
use aptos_vm_logging::log_schema::AdapterLogSchema;
use fail::fail_point;
use move_binary_format::{
access::ModuleAccess,
Expand Down
Loading