diff --git a/Cargo.lock b/Cargo.lock index 59facab172..9221d50ddd 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2349,7 +2349,6 @@ dependencies = [ "humantime", "hyper", "lazy_static", - "log", "pageserver", "postgres", "postgres-protocol", @@ -2363,6 +2362,7 @@ dependencies = [ "tempfile", "tokio", "tokio-stream", + "tracing", "walkdir", "workspace_hack", "zenith_metrics", diff --git a/walkeeper/Cargo.toml b/walkeeper/Cargo.toml index 69d5f681c5..1b622823aa 100644 --- a/walkeeper/Cargo.toml +++ b/walkeeper/Cargo.toml @@ -16,7 +16,7 @@ routerify = "2" fs2 = "0.4.3" lazy_static = "1.4.0" serde_json = "1" -log = "0.4.14" +tracing = "0.1.27" clap = "2.33.0" daemonize = "0.4.1" rust-s3 = { version = "0.27.0-rc4", features = ["no-verify-ssl"] } diff --git a/walkeeper/src/bin/safekeeper.rs b/walkeeper/src/bin/safekeeper.rs index 0b6b14eb6d..6cc6f7c743 100644 --- a/walkeeper/src/bin/safekeeper.rs +++ b/walkeeper/src/bin/safekeeper.rs @@ -5,9 +5,9 @@ use anyhow::Result; use clap::{App, Arg}; use const_format::formatcp; use daemonize::Daemonize; -use log::*; use std::path::{Path, PathBuf}; use std::thread; +use tracing::*; use walkeeper::defaults::{DEFAULT_HTTP_LISTEN_ADDR, DEFAULT_PG_LISTEN_ADDR}; use walkeeper::http; use walkeeper::s3_offload; diff --git a/walkeeper/src/json_ctrl.rs b/walkeeper/src/json_ctrl.rs index 2279576722..685b4e6335 100644 --- a/walkeeper/src/json_ctrl.rs +++ b/walkeeper/src/json_ctrl.rs @@ -9,8 +9,8 @@ use anyhow::{anyhow, Result}; use bytes::{BufMut, Bytes, BytesMut}; use crc32c::crc32c_append; -use log::*; use serde::{Deserialize, Serialize}; +use tracing::*; use crate::safekeeper::{AcceptorProposerMessage, AppendResponse}; use crate::safekeeper::{ diff --git a/walkeeper/src/receive_wal.rs b/walkeeper/src/receive_wal.rs index a7b9797770..ced057bee2 100644 --- a/walkeeper/src/receive_wal.rs +++ b/walkeeper/src/receive_wal.rs @@ -5,8 +5,8 @@ use anyhow::{bail, Context, Result}; use bytes::Bytes; use bytes::BytesMut; -use log::*; use postgres::{Client, Config, NoTls}; +use tracing::*; use std::net::SocketAddr; use std::thread; @@ -116,6 +116,8 @@ impl<'pg> ReceiveWalConn<'pg> { /// Receive WAL from wal_proposer pub fn run(&mut self, swh: &mut SendWalHandler) -> Result<()> { + let _enter = info_span!("WAL acceptor", timeline = %swh.timelineid.unwrap()).entered(); + // Notify the libpq client that it's allowed to send `CopyData` messages self.pg_backend .write_message(&BeMessage::CopyBothResponse)?; diff --git a/walkeeper/src/replication.rs b/walkeeper/src/replication.rs index f3486e2885..a9ffc2d1ad 100644 --- a/walkeeper/src/replication.rs +++ b/walkeeper/src/replication.rs @@ -5,7 +5,6 @@ use crate::send_wal::SendWalHandler; use crate::timeline::{ReplicaState, Timeline, TimelineTools}; use anyhow::{anyhow, Context, Result}; use bytes::Bytes; -use log::*; use postgres_ffi::xlog_utils::{ get_current_timestamp, TimestampTz, XLogFileName, MAX_SEND_SIZE, PG_TLI, }; @@ -20,6 +19,7 @@ use std::sync::Arc; use std::thread::sleep; use std::time::Duration; use std::{str, thread}; +use tracing::*; use zenith_utils::bin_ser::BeSer; use zenith_utils::lsn::Lsn; use zenith_utils::postgres_backend::PostgresBackend; @@ -177,6 +177,8 @@ impl ReplicationConn { pgb: &mut PostgresBackend, cmd: &Bytes, ) -> Result<()> { + let _enter = info_span!("WAL sender", timeline = %swh.timelineid.unwrap()).entered(); + // spawn the background thread which receives HotStandbyFeedback messages. let bg_timeline = Arc::clone(swh.timeline.get()); let bg_stream_in = self.stream_in.take().unwrap(); diff --git a/walkeeper/src/s3_offload.rs b/walkeeper/src/s3_offload.rs index 841317c848..2b3285e6c6 100644 --- a/walkeeper/src/s3_offload.rs +++ b/walkeeper/src/s3_offload.rs @@ -3,7 +3,6 @@ // use anyhow::Result; -use log::*; use postgres_ffi::xlog_utils::*; use s3::bucket::Bucket; use s3::creds::Credentials; @@ -16,6 +15,7 @@ use std::path::Path; use std::time::SystemTime; use tokio::runtime; use tokio::time::sleep; +use tracing::*; use walkdir::WalkDir; use crate::SafeKeeperConf; diff --git a/walkeeper/src/safekeeper.rs b/walkeeper/src/safekeeper.rs index fdf4520479..77bc74ec16 100644 --- a/walkeeper/src/safekeeper.rs +++ b/walkeeper/src/safekeeper.rs @@ -8,13 +8,13 @@ use bytes::Buf; use bytes::BufMut; use bytes::Bytes; use bytes::BytesMut; -use log::*; use pageserver::waldecoder::WalStreamDecoder; use postgres_ffi::xlog_utils::TimeLineID; use serde::{Deserialize, Serialize}; use std::cmp::min; use std::fmt; use std::io::Read; +use tracing::*; use lazy_static::lazy_static; diff --git a/walkeeper/src/timeline.rs b/walkeeper/src/timeline.rs index a859e4dcb9..3ae9ab3bb3 100644 --- a/walkeeper/src/timeline.rs +++ b/walkeeper/src/timeline.rs @@ -5,7 +5,6 @@ use anyhow::{anyhow, bail, ensure, Context, Result}; use byteorder::{LittleEndian, ReadBytesExt, WriteBytesExt}; use fs2::FileExt; use lazy_static::lazy_static; -use log::*; use postgres_ffi::xlog_utils::{find_end_of_wal, PG_TLI}; use std::cmp::{max, min}; use std::collections::HashMap; @@ -14,6 +13,7 @@ use std::io::{Read, Seek, SeekFrom, Write}; use std::path::PathBuf; use std::sync::{Arc, Condvar, Mutex}; use std::time::Duration; +use tracing::*; use zenith_metrics::{register_histogram_vec, Histogram, HistogramVec, DISK_WRITE_SECONDS_BUCKETS}; use zenith_utils::bin_ser::LeSer; use zenith_utils::lsn::Lsn; diff --git a/walkeeper/src/upgrade.rs b/walkeeper/src/upgrade.rs index 31ede7d4b4..7e52fafeb4 100644 --- a/walkeeper/src/upgrade.rs +++ b/walkeeper/src/upgrade.rs @@ -3,8 +3,8 @@ use crate::safekeeper::{ AcceptorState, PgUuid, SafeKeeperState, ServerInfo, Term, TermHistory, TermSwitchEntry, }; use anyhow::{bail, Result}; -use log::*; use serde::{Deserialize, Serialize}; +use tracing::*; use zenith_utils::{bin_ser::LeSer, lsn::Lsn}; /// Persistent consensus state of the acceptor. diff --git a/walkeeper/src/wal_service.rs b/walkeeper/src/wal_service.rs index fd066680ef..e47bf2eb04 100644 --- a/walkeeper/src/wal_service.rs +++ b/walkeeper/src/wal_service.rs @@ -3,9 +3,10 @@ //! receive WAL from wal_proposer and send it to WAL receivers //! use anyhow::Result; -use log::*; +use regex::Regex; use std::net::{TcpListener, TcpStream}; use std::thread; +use tracing::*; use crate::send_wal::SendWalHandler; use crate::SafeKeeperConf; @@ -33,9 +34,19 @@ pub fn thread_main(conf: SafeKeeperConf, listener: TcpListener) -> Result<()> { } } +// Get unique thread id (Rust internal), with ThreadId removed for shorter printing +fn get_tid() -> u64 { + let tids = format!("{:?}", thread::current().id()); + let r = Regex::new(r"ThreadId\((\d+)\)").unwrap(); + let caps = r.captures(&tids).unwrap(); + caps.get(1).unwrap().as_str().parse().unwrap() +} + /// This is run by `thread_main` above, inside a background thread. /// fn handle_socket(socket: TcpStream, conf: SafeKeeperConf) -> Result<()> { + let _enter = info_span!("", tid = ?get_tid()).entered(); + socket.set_nodelay(true)?; let mut conn_handler = SendWalHandler::new(conf);