chore: add log-slow-write-lock crate feature

This feature is nightly only.  To enable:
cargo +nightly build --features log-slow-write-lock

It logs a warning and caller location if the global-state
write-lock is held more than 100 millis.

Useful for finding slow writers that can harm concurrency.

It requires nightly in order to log the caller location for
async methods such as lock_guard_mut().

Cargo.toml

@@ -6,6 +6,12 @@ version = "0.0.5"
 default-run = "neptune-core"
 publish = false
 
+[features]
+
+# logs write-lock acquisitions that take over 100 millis.  requires nightly.
+# to enable: cargo +nightly build --features log-slow-write-lock
+log-slow-write-lock = []
+
 [dependencies]
 aead = { version = "0.5", features = ["std"] }
 aes-gcm = "0.10"

scripts/php/process-log-lock-writes.php

@@ -0,0 +1,32 @@
+#!/usr/bin/env php
+
+<?php
+
+$path = @$argv[1];
+
+if(!$path) die("please specify a neptune log file.");
+
+$lines = file($path);
+
+$found = [];
+
+// sample line:
+// 2024-11-02T20:53:45.472275Z  WARN reorganization_does_not_crash_mempool: neptune_core::locks::tokio::atomic_rw: write-lock held for 4.1489367 seconds. (exceeds max: 100 milli)  location: src/models/state/mod.rs:216:14
+
+foreach($lines as $line) {
+    if(strpos($line, "write-lock held for") === false) {
+        continue;
+    }
+
+    if (preg_match("/for (.*) seconds/i", $line, $matches)) {
+        $secs = $matches[1];
+        $found[$secs] = $line;
+    }
+}
+
+krsort($found);
+
+foreach($found as $line) {
+    echo $line . "\n";
+}
+

src/lib.rs

@@ -1,6 +1,10 @@
 // recursion limit for macros (e.g. triton_asm!)
 #![recursion_limit = "2048"]
 #![deny(clippy::shadow_unrelated)]
+// enables nightly feature async_fn_track_caller for crate feature log-slow-write-lock
+// log-slow-write-lock logs warning when a write-lock is held longer than 100 millis.
+// to enable: cargo +nightly build --features log-slow-write-lock
+#![cfg_attr(feature = "log-slow-write-lock", feature(async_fn_track_caller))]
 
 // danda: making all of these pub for now, so docs are generated.
 // later maybe we ought to split some stuff out into re-usable crate(s)...?

src/locks/tokio/atomic_rw.rs

@@ -1,3 +1,11 @@
+// [track_caller] is used in this module to obtain source location of caller when
+// a write-lock is acquired, and log it upon drop if the lock is held too long.
+//
+// [track_caller] is not (yet?) available for async fn in stable rust.
+// it is available in nightly rust with the async_fn_track_caller
+// feature flag.  To enable the feature in neptune build with
+// cargo +nightly build --features log-slow-write-lock
+
 use std::ops::Deref;
 use std::ops::DerefMut;
 use std::sync::Arc;
@@ -235,6 +243,7 @@ impl<T> AtomicRw<T> {
     /// atomic_car.lock_guard_mut().await.year = 2022;
     /// # })
     /// ```
+    #[cfg_attr(feature = "log-slow-write-lock", track_caller)]
     pub async fn lock_guard_mut(&mut self) -> AtomicRwWriteGuard<T> {
         self.try_acquire_write_cb();
         let guard = self.inner.write().await;
@@ -244,6 +253,7 @@ impl<T> AtomicRw<T> {
     /// Attempt to acquire write lock immediately.
     ///
     /// If the lock cannot be acquired without waiting, an error is returned.
+    #[cfg_attr(feature = "log-slow-write-lock", track_caller)]
     pub fn try_lock_guard_mut(&mut self) -> Result<AtomicRwWriteGuard<T>, TryLockError> {
         self.try_acquire_write_cb();
         let guard = self.inner.try_write()?;
@@ -288,6 +298,7 @@ impl<T> AtomicRw<T> {
     /// let year = atomic_car.lock_mut(|mut c| {c.year = 2023; c.year}).await;
     /// })
     /// ```
+    #[cfg_attr(feature = "log-slow-write-lock", track_caller)]
     pub async fn lock_mut<R, F>(&mut self, f: F) -> R
     where
         F: FnOnce(&mut T) -> R,
@@ -343,6 +354,7 @@ impl<T> AtomicRw<T> {
     /// })
     /// ```
     // design background: https://stackoverflow.com/a/77657788/10087197
+    #[cfg_attr(feature = "log-slow-write-lock", track_caller)]
     pub async fn lock_mut_async<R>(&mut self, f: impl FnOnce(&mut T) -> BoxFuture<'_, R>) -> R {
         self.try_acquire_write_cb();
         let inner_guard = self.inner.write().await;
@@ -423,9 +435,12 @@ impl<T> Deref for AtomicRwReadGuard<'_, T> {
 pub struct AtomicRwWriteGuard<'a, T> {
     guard: RwLockWriteGuard<'a, T>,
     lock_callback_info: &'a LockCallbackInfo,
+    location: &'static core::panic::Location<'static>,
+    timestamp: std::time::Instant,
 }
 
 impl<'a, T> AtomicRwWriteGuard<'a, T> {
+    #[cfg_attr(feature = "log-slow-write-lock", track_caller)]
     fn new(guard: RwLockWriteGuard<'a, T>, lock_callback_info: &'a LockCallbackInfo) -> Self {
         if let Some(cb) = lock_callback_info.lock_callback_fn {
             cb(LockEvent::Acquire {
@@ -436,12 +451,24 @@ impl<'a, T> AtomicRwWriteGuard<'a, T> {
         Self {
             guard,
             lock_callback_info,
+            location: core::panic::Location::caller(),
+            timestamp: std::time::Instant::now(),
         }
     }
 }
 
 impl<T> Drop for AtomicRwWriteGuard<'_, T> {
     fn drop(&mut self) {
+        let duration = self.timestamp.elapsed();
+        let max_duration_milli = 100;
+        if duration.as_millis() > max_duration_milli {
+            tracing::warn!(
+                "write-lock held for {} seconds. (exceeds max: {} milli)  location: {}",
+                duration.as_secs_f32(),
+                max_duration_milli,
+                self.location
+            );
+        }
         let lock_callback_info = self.lock_callback_info;
         if let Some(cb) = lock_callback_info.lock_callback_fn {
             cb(LockEvent::Release {