Skip to content

General Debugging

Jump to bottom
steviez edited this page Jan 26, 2023 · 33 revisions

Logging

Although it isn't the most advanced procedure, sometimes logging state to the screen is sufficient to figure out a problem. The following outlines how to enable logging for a specific test or binary.

Procedure

  1. Make sure the following line of code is at the top of your test or executable to “route” log statements to terminal: solana_logger::setup()

  2. Add any of the following statements to display whatever information you'd like: error!(), info!(), warn!(), debug!(), trace!()

    • Note that the codebase contains these statements which will also be displayed on screen. As such, if you want to reduce "noise", it may be preferable to choose a higher level (error or info).

  3. Set the RUST_LOG environment variable, making sure to choose a level equal to or lower than the statement in previous step.

    • For example: export RUST_LOG=solana=error
    • The level can also be specified for a single command: `RUST_LOG=solana=warn solana-ledger-tool
    • The level can also be specified on a per-crate basis, such as: RUST_LOG=solana=info,solana_ledger=debug cargo test some_test

For more info, check out the official documentation:

https://docs.rs/log/latest/log/index.html

Debug Builds

Several of the following techniques require the inclusion of debug information in the binary under scrutiny in order for analysis to be useful. The easiest way to configure these options is by passing command line flags to the compiler. The following is a good, general starting point:

RUSTFLAGS='-g -C force-frame-pointers=yes'

So, a complete invocation might look like:

RUSTFLAGS='-g -C force-frame-pointers=yes' cargo build --release --bin solana-validator

Some relevant documentation:

Additionally, profiles in the Cargo.toml file also configuration in a more persistent manner. But, not all of the options that can be passed as flags can be configured in Cargo.toml at the time of writing this. See:

Attach a Debugger

With a debug build (see instructions above), a debugger will allow for very detailed inspection of an executable while it is running. Recall that a binary can be launched with the debugger attached, or the debugger can attach to an already running process. gdb seems to work well, but rust-lldb seems to be another option as well.

Core Dumps

Inspecting core dumps can be useful for examining the state of a program at the time of a crash.

Generating Core Dumps

System configuration may not allow the generation of core dumps by default. Perform the following steps to allow generation of core dumps:

  1. Check that a program is configured to handle core patterns by printing the contents of /proc/sys/kernel/core_pattern. For example,
$ cat /proc/sys/kernel/core_pattern 
|/lib/systemd/systemd-coredump %P %u %g %s %t 9223372036854775808 %h
  1. Confirm that the service in step above is enabled; it might be disabled by default (ie if you're using apport).
systemctl status apport
  1. Confirm that the limit for created core files is large enough.
$ ulimit -c
unlimited

If the above is 0, no core files will be created. Note that you can configure the value with ulmit; however, that value won't extend to other processes or persist. To persistently allow unlimited dumps for all processes, add a line to /etc/security/limits.conf.

Memory Profiling

At the time of writing this, the project is using jemalloc in place of the system allocator. jemalloc has some builtins to allow profiling; the following procedure outlines how to do so. The jemalloc wiki also has some good documentation, specifically in the "Use cases" pages.

Building jeprof

  1. Clone and build the jemalloc repo by following these instructions. Note that it may be preferable to NOT run make install to leave the default binaries alone as we are only building to get the profile analysis tool.
  2. Install ghostscript and graphviz; these will be needed if you wish to create graph outputs.
sudo apt install ghostscript graphviz
  1. Note that there is a jeprof binary in the bin directory.

Collecting Heap Profile Data

The directions listed below will assume that solana-validator is the binary to profile.

  1. Apply the following patch (or similar change should the patch become out of date) to enable debug information in the release binaries, as well as the jemalloc profiling feature itself.
Patch 
diff --git a/Cargo.toml b/Cargo.toml
index 9aad90aeb4..f0492c7fce 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -92,5 +92,14 @@ exclude = [
     "programs/bpf",
 ]
 
+[profile.release]
+debug = true
+
+[profile.release.package."*"]
+debug = true
+
+[profile.release.build-override]
+debug = true
+
 # This prevents a Travis CI error when building for Windows.
 resolver = "2"
diff --git a/ledger-tool/Cargo.toml b/ledger-tool/Cargo.toml
index 7a984bf6ad..28eb7ebf4f 100644
--- a/ledger-tool/Cargo.toml
+++ b/ledger-tool/Cargo.toml
@@ -39,7 +39,7 @@ solana-vote-program = { path = "../programs/vote", version = "=1.14.2" }
 tokio = { version = "1", features = ["full"] }
 
 [target.'cfg(not(target_env = "msvc"))'.dependencies]
-jemallocator = { package = "tikv-jemallocator", version = "0.4.1", features = ["unprefixed_malloc_on_supported_platforms"] }
+jemallocator = { package = "tikv-jemallocator", version = "0.4.1", features = ["profiling", "unprefixed_malloc_on_supported_platforms"] }
 
 [dev-dependencies]
 assert_cmd = "2.0"
diff --git a/validator/Cargo.toml b/validator/Cargo.toml
index 877ffccbc9..8db96cacf2 100644
--- a/validator/Cargo.toml
+++ b/validator/Cargo.toml
@@ -55,7 +55,7 @@ solana-vote-program = { path = "../programs/vote", version = "=1.14.2" }
 symlink = "0.1.0"
 
 [target.'cfg(not(target_env = "msvc"))'.dependencies]
-jemallocator = { package = "tikv-jemallocator", version = "0.4.1", features = ["unprefixed_malloc_on_supported_platforms"] }
+jemallocator = { package = "tikv-jemallocator", version = "0.4.1", features = ["profiling", "unprefixed_malloc_on_supported_platforms"] }
 
 [target."cfg(unix)".dependencies]
 libc = "0.2.126"
  1. With the patch applied, recompile the the desired binary with the following flags. For example, the build command may look like:
RUSTFLAGS='-g -C force-frame-pointers=yes' ./cargo build --release --features jemallocator/profiling
  1. Execute the solana-validator with the following flags; check out the documentation here to see what these flags do and tweak them as necessary to fit your use case.
MALLOC_CONF="prof:true,lg_prof_interval:32,lg_prof_sample:17,prof_prefix:jeprof" solana-validator ...
  1. As your process runs, it should now create files of the format jeprof.<...>.heap.

Analyze Heap Profile Data

  1. Run something similar to the following command to create a PDF output; see the jeprof help for all the options:
jeprof --show_bytes /path/to/binary /path/to/heap/profile/file --pdf > heap.pdf

Note that if your process created multiple files, you can pass multiple files to jeprof. For exampple, if all of your profile files from one run are in the same directory, you could do:

jeprof --show_bytes /path/to/binary /path/to/heap/profile/directory/jeprof.* --pdf > heap.pdf

perf-based profiling

setup: enable frame pointers everywhere

some background for frame pointers to convince you that this is cool: https://fedoraproject.org/wiki/Changes/fno-omit-frame-pointer

use ubuntu 22.04 LTS.

use this ppa:

https://launchpad.net/~ryoqun/+archive/ubuntu/glibc-fp/

RUSTFLAGS

sadly, stable rustc can't be used due to: https://github.com/rust-lang/rust/issues/103711. in short we need to enable -Z build-std.

Run this rustup component add rust-src --toolchain nightly-x86_64-unknown-linux-gnu (requisite of -Z build-std).

then, apply the following patch:

diff -u -r ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_condvar.rs /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_condvar.rs
--- ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_condvar.rs    2022-11-12 23:16:29.000000000 +0000
+++ /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_condvar.rs  2022-11-16 01:41:59.370745687 +0000
@@ -37,7 +37,8 @@
         self.wait_optional_timeout(mutex, Some(timeout))
     }
 
-    unsafe fn wait_optional_timeout(&self, mutex: &Mutex, timeout: Option<Duration>) -> bool {
+    #[inline(never)]
+    pub unsafe fn wait_optional_timeout(&self, mutex: &Mutex, timeout: Option<Duration>) -> bool {
         // Examine the notification counter _before_ we unlock the mutex.
         let futex_value = self.futex.load(Relaxed);
 
diff -u -r ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_mutex.rs /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_mutex.rs
--- ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_mutex.rs      2022-11-12 23:16:29.000000000 +0000
+++ /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_mutex.rs    2022-11-16 01:31:16.190253714 +0000
@@ -30,7 +30,8 @@
     }
 
     #[cold]
-    fn lock_contended(&self) {
+    #[inline(never)]
+    pub fn lock_contended(&self) {
         // Spin first to speed things up if the lock is released quickly.
         let mut state = self.spin();
 
diff -u -r ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_rwlock.rs /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_rwlock.rs
--- ./rust-src-nightly/rust-src/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_rwlock.rs     2022-11-12 23:16:29.000000000 +0000
+++ /home/sol/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/locks/futex_rwlock.rs   2022-11-16 01:43:42.173874145 +0000
@@ -102,7 +102,8 @@
     }
 
     #[cold]
-    fn read_contended(&self) {
+    #[inline(never)]
+    pub fn read_contended(&self) {
         let mut state = self.spin_read();
 
         loop {
@@ -167,7 +168,8 @@
     }
 
     #[cold]
-    fn write_contended(&self) {
+    #[inline(never)]
+    pub fn write_contended(&self) {
         let mut state = self.spin_write();
 
         let mut other_writers_waiting = 0;

RUSTFLAGS="-g -C force-frame-pointers=yes -C target-cpu=native -C opt-level=3 -C lto=no -C symbol-mangling-version=v0" cargo +nightly run -Z build-std --release --target x86_64-unknown-linux-gnu --bin solana-validator

(lto is disabled for now. maybe there's some workaround yet to be found by me...)

off cpu profiling

you need to build patched perf: https://github.com/ryoqun/linux/tree/perf-p-offset-hack, something like this: apt build-dep linux and apt install clang and cd tools/perf and then BUILD_BPF_SKEL=1 make

~/work/linux/tools/perf/perf record --call-graph fp --off-cpu -e dummy --proc-map-timeout 30000 -p $PID_OF_RUNNING_SOLANA_VALIDATOR

sudo ~/work/linux/tools/perf/perf script -F +pid > ./perf-offcpu.perf

use this firefox devtools profiler

https://github.com/firefox-devtools/profiler/pull/4320

Clone this wiki locally