chore: add more tracing to vm

crates/core/src/sql/compiler.rs

@@ -14,6 +14,7 @@ use spacetimedb_vm::expr::{ColumnOp, CrudExpr, DbType, Expr, QueryExpr, SourceEx
 use spacetimedb_vm::operator::OpCmp;
 
 /// Compile the `SQL` expression into a `ast`
+#[tracing::instrument(skip(db, tx))]
 pub fn compile_sql(db: &RelationalDB, tx: &MutTxId, sql_text: &str) -> Result<Vec<CrudExpr>, DBError> {
     let ast = compile_to_ast(db, tx, sql_text)?;
 

crates/core/src/sql/execute.rs

@@ -20,6 +20,7 @@ pub struct StmtResult {
 // we always generate a plan, but it may contain errors
 
 /// Run a `SQL` query/statement in the specified `database_instance_id`.
+#[tracing::instrument(skip_all)]
 pub fn execute(
     db_inst_ctx_controller: &DatabaseInstanceContextController,
     database_instance_id: u64,
@@ -51,6 +52,7 @@ fn collect_result(result: &mut Vec<MemTable>, r: CodeResult) -> Result<(), DBErr
     Ok(())
 }
 
+#[tracing::instrument(skip_all)]
 pub fn execute_single_sql(
     db: &RelationalDB,
     tx: &mut MutTxId,
@@ -66,6 +68,7 @@ pub fn execute_single_sql(
 }
 
 /// Run the compiled `SQL` expression inside the `vm` created by [DbProgram]
+#[tracing::instrument(skip_all)]
 pub fn execute_sql(
     db: &RelationalDB,
     tx: &mut MutTxId,
@@ -83,6 +86,7 @@ pub fn execute_sql(
 }
 
 /// Run the `SQL` string using the `auth` credentials
+#[tracing::instrument(skip_all)]
 pub(crate) fn run(
     db: &RelationalDB,
     tx: &mut MutTxId,

crates/core/src/subscription/query.rs

@@ -20,6 +20,7 @@ pub struct Query {
 }
 
 impl Query {
+    #[tracing::instrument(skip(self))]
     pub fn queries_of_table_id<'a>(&'a self, table: &'a DatabaseTableUpdate) -> impl Iterator<Item = QueryExpr> + '_ {
         self.queries.iter().filter_map(move |x| {
             if x.source.get_db_table().map(|x| x.table_id) == Some(table.table_id) {
@@ -35,6 +36,7 @@ impl Query {
 pub const OP_TYPE_FIELD_NAME: &str = "__op_type";
 
 //HACK: To recover the `op_type` of this particular row I add a "hidden" column `OP_TYPE_FIELD_NAME`
+#[tracing::instrument(skip_all)]
 pub fn to_mem_table(of: QueryExpr, data: &DatabaseTableUpdate) -> QueryExpr {
     let mut q = of;
     let table_access = q.source.table_access();
@@ -68,6 +70,7 @@ pub fn to_mem_table(of: QueryExpr, data: &DatabaseTableUpdate) -> QueryExpr {
 }
 
 /// Runs a query that evaluates if the changes made should be reported to the [ModuleSubscriptionManager]
+#[tracing::instrument(skip_all)]
 pub(crate) fn run_query(
     db: &RelationalDB,
     tx: &mut MutTxId,
@@ -77,6 +80,7 @@ pub(crate) fn run_query(
     execute_single_sql(db, tx, CrudExpr::Query(query.clone()), auth)
 }
 
+#[tracing::instrument(skip(relational_db, tx))]
 pub fn compile_query(relational_db: &RelationalDB, tx: &MutTxId, input: &str) -> Result<Query, DBError> {
     let input = input.trim();
     if input.is_empty() {

crates/core/src/vm.rs

@@ -21,6 +21,7 @@ use std::collections::HashMap;
 
 //TODO: This is partially duplicated from the `vm` crate to avoid borrow checker issues
 //and pull all that crate in core. Will be revisited after trait refactor
+#[tracing::instrument(skip_all)]
 pub fn build_query<'a>(
     stdb: &'a RelationalDB,
     tx: &'a mut MutTxId,
@@ -331,6 +332,7 @@ impl RelOps for TableCursor<'_> {
         RowCount::unknown()
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         if let Some(row) = self.iter.next() {
             return Ok(Some(RelValue::new(self.head(), row.view())));
@@ -357,6 +359,7 @@ where
         self.row_count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         if let Some(row) = self.iter.next() {
             return Ok(Some(RelValue::new(self.head(), &row)));

crates/lib/Cargo.toml

@@ -33,6 +33,7 @@ serde = { workspace = true, optional = true }
 serde_with = {workspace = true, optional = true }
 sha3.workspace = true
 thiserror.workspace = true
+tracing.workspace = true
 
 [dev-dependencies]
 rand.workspace = true

crates/lib/src/hash.rs

@@ -46,6 +46,7 @@ impl Hash {
     }
 }
 
+#[tracing::instrument(skip_all)]
 pub fn hash_bytes(bytes: impl AsRef<[u8]>) -> Hash {
     let data: [u8; HASH_SIZE] = Keccak256::digest(bytes).into();
     Hash { data }

crates/sats/Cargo.toml

@@ -20,6 +20,7 @@ hex = { workspace = true, optional = true }
 itertools.workspace = true
 serde = { workspace = true, optional = true }
 thiserror.workspace = true
+tracing.workspace = true
 
 [dev-dependencies]
 bytes.workspace = true

crates/sats/src/bsatn.rs

@@ -12,6 +12,7 @@ pub use ser::Serializer;
 pub use crate::buffer::DecodeError;
 
 /// Serialize `value` into the buffered writer `w` in the BSATN format.
+#[tracing::instrument(skip_all)]
 pub fn to_writer<W: BufWriter, T: Serialize + ?Sized>(w: &mut W, value: &T) -> Result<(), ser::BsatnError> {
     value.serialize(Serializer::new(w))
 }
@@ -24,6 +25,7 @@ pub fn to_vec<T: Serialize + ?Sized>(value: &T) -> Result<Vec<u8>, ser::BsatnErr
 }
 
 /// Deserialize a `T` from the BSATN format in the buffered `reader`.
+#[tracing::instrument(skip_all)]
 pub fn from_reader<'de, T: Deserialize<'de>>(reader: &mut impl BufReader<'de>) -> Result<T, DecodeError> {
     T::deserialize(Deserializer::new(reader))
 }

crates/vm/src/eval.rs

@@ -145,6 +145,7 @@ fn build_typed<P: ProgramVm>(p: &mut P, node: Expr) -> ExprOpt {
 /// Compile the [Expr] into a type-annotated AST [Tree<ExprOpt>].
 ///
 /// Then validate & type-check it.
+#[tracing::instrument(skip_all)]
 pub fn optimize<P: ProgramVm>(p: &mut P, code: Expr) -> Result<ExprOpt, ErrorType> {
     let result = build_typed(p, code);
     check_types(&mut p.env_mut().ty, &result)?;
@@ -196,6 +197,7 @@ fn compile_query(q: QueryExprOpt) -> QueryCode {
 /// Second pass:
 ///
 /// Compiles [Tree<ExprOpt>] into [Code] moving the execution into closures.
+#[tracing::instrument(skip_all)]
 fn compile<P: ProgramVm>(p: &mut P, node: ExprOpt) -> Result<Code, ErrorVm> {
     Ok(match node {
         ExprOpt::Value(x) => Code::Value(x.of),
@@ -400,6 +402,7 @@ pub fn eval<P: ProgramVm>(p: &mut P, code: Code) -> Code {
 
 pub type IterRows<'a> = dyn RelOps + 'a;
 
+#[tracing::instrument(skip_all)]
 pub fn build_query(mut result: Box<IterRows>, query: Vec<Query>) -> Result<Box<IterRows<'_>>, ErrorVm> {
     for q in query {
         result = match q {

crates/vm/src/iterators.rs

@@ -12,6 +12,7 @@ impl RelOps for RelIter<ProductValue> {
         self.row_count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         Ok(if self.pos == 0 {
             self.pos += 1;
@@ -31,6 +32,7 @@ impl RelOps for RelIter<MemTable> {
         self.row_count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         if self.pos < self.of.data.len() {
             let row = &self.of.data[self.pos];

crates/vm/src/program.rs

@@ -167,6 +167,7 @@ impl ProgramVm for Program {
         &self.auth
     }
 
+    #[tracing::instrument(skip_all)]
     fn eval_query(&mut self, query: CrudCode) -> Result<Code, ErrorVm> {
         match query {
             CrudCode::Query(query) => {

crates/vm/src/rel_ops.rs

@@ -162,6 +162,7 @@ where
         self.count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         let filter = &mut self.predicate;
         while let Some(v) = self.iter.next()? {
@@ -205,6 +206,7 @@ where
         self.count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         let extract = &mut self.extractor;
         if let Some(v) = self.iter.next()? {
@@ -262,6 +264,7 @@ where
         self.count
     }
 
+    #[tracing::instrument(skip_all)]
     fn next(&mut self) -> Result<Option<RelValue>, ErrorVm> {
         if !self.filled {
             self.map = HashMap::with_capacity(self.rhs.row_count().min);