diff --git a/CHANGELOG.md b/CHANGELOG.md --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,25 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/) and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html) +## [1.15.1] - 2026-11-14 + +### Added +- **Metrics of the garbage collector.** With `--statsd`, the store sends + GHC's statistics under `rts.*` once a second: collections, the time that + every thread was stopped for them, the CPU that they used, the work of + the non-moving collector, allocation, and the size of the live data and + of the heap. Every collection stops every thread, so they say how much + of a slow answer is the collector's. The executable now runs with + `+RTS -T`, which GHC needs to keep them. + +### Changed +- **The old generation is collected while the store runs.** The executable + uses GHC's non-moving collector (`--nonmoving-gc`). The copying collector + stopped every thread while it copied all live data, gigabytes for a store + of mainnet, and under load every request waited for it, `/health` + included. The heap can be larger, as old objects are not moved together. + `GHCRTS=--copying-gc` goes back to the copying collector. + ## [1.15.0] - 2026-11-14 Answers decode less of what they read, and write hex faster. diff --git a/README.md b/README.md --- a/README.md +++ b/README.md @@ -739,6 +739,7 @@ | `Haskoin.Store.Fleet.Member`, `Haskoin.Store.Fleet.XPub` | A fleet, and its cache | | `Haskoin.Store.Web`, `Haskoin.Store.Web.Events` | The web server, and `/events` | | `Haskoin.Store.Web.Pieces` | Answers that are sent while they are read | +| `Haskoin.Store.Runtime` | GHC's garbage collector, as StatsD metrics | | `Haskoin.Store.Web.Publish` | Checking a transaction and handing it to the peers, or to a full node over RPC | The rules and queries of version 20 (`Haskoin.Store.Logic`, @@ -793,6 +794,7 @@ | `cache.*` | Cache hits, misses, reloads and full reloads | | `store.*` | Block and header heights, mempool size and other gauges | | `fleet.cache.*` | What a server of a fleet does with the fleet's cache of xpubs | +| `rts.*` | GHC's garbage collector | The metrics of the fleet's cache: @@ -816,6 +818,33 @@ - With `--debug` the log also has a line for each entry built and each block that the cache was brought to. +The metrics of the garbage collector, sent once a second: + +| Metric | Kind | Meaning | +| --- | --- | --- | +| `rts.gcs` | counter | Collections | +| `rts.major_gcs` | counter | Collections of the whole heap | +| `rts.gc_pause_us` | counter | Microseconds that every thread was stopped for the collector | +| `rts.gc_pause_mean_us` | gauge | Mean pause of a collection in the last second | +| `rts.gc_pause_percent` | gauge | Share of the last second that every thread was stopped | +| `rts.gc_cpu_us` | counter | Microseconds of CPU that the collector used, on all cores | +| `rts.nonmoving_sync_us` | counter | Microseconds stopped to end a mark of the non-moving collector | +| `rts.nonmoving_mark_us` | counter | Microseconds that the non-moving collector marked, while the store ran | +| `rts.allocated_bytes` | counter | Bytes allocated | +| `rts.live_bytes` | gauge | Bytes live after the last collection | +| `rts.heap_bytes` | gauge | Bytes that the heap holds from the system | + +- **Every collection stops every thread**, the small ones too. While it is + stopped the store answers nothing, not even `/health`, so a high + `rts.gc_pause_percent` shows up as slow answers everywhere. +- **The executable runs with `+RTS -T`**, which GHC needs to keep these + statistics. Without it, as in a program that uses the library, the log + says so and there are no `rts.*` metrics. +- **The `rts.nonmoving_*` metrics** are the work of the non-moving + collector, which the executable uses for the old generation (see + [Memory](#memory)). They stay at zero if the store runs with the copying + collector instead. + ### Database statistics `/dbstats` returns the memory that RocksDB uses for each column family, and @@ -832,8 +861,18 @@ `--disable-delayed-os-memory-return` for that. Without the flag, Linux keeps counting returned memory as resident until it needs it, and the heap looks as if it never shrinks after a peak. +- **The old generation is collected while the store runs**, with GHC's + non-moving collector (`--nonmoving-gc`). The default copying collector + stops every thread while it copies all live data, which takes longer as + the heap grows. A store of mainnet holds gigabytes, and under load every + request waited for it, `/health` included. Small collections of new + objects still stop every thread, but they are short. +- **The price is memory.** Old objects are not moved together, so the heap + can hold more than the copying collector would for the same live data. + To go back to the copying collector, run the store with + `GHCRTS=--copying-gc` in its environment, or `+RTS --copying-gc -RTS`. - If you build the store some other way, pass - `+RTS --disable-delayed-os-memory-return -RTS` yourself. + `+RTS --nonmoving-gc --disable-delayed-os-memory-return -RTS` yourself. - **To tell such memory from a leak**, see `stress/results/2026-11-09-memory/README.md`: how to read `smaps`, and a heap profile of a busy store, with live data flat at about 10 MiB. diff --git a/app/Main.hs b/app/Main.hs --- a/app/Main.hs +++ b/app/Main.hs @@ -33,6 +33,7 @@ withStore, ) import Haskoin.Store.Common (loopForever) +import Haskoin.Store.Runtime (runtimeMetrics) import NQE (receive, withSubscription) import Options.Applicative ( Mod, @@ -75,6 +76,7 @@ ( createDirectoryIfMissing, getAppUserDataDirectory, ) +import UnliftIO.Async (withAsync) import UnliftIO.Environment (lookupEnv) -- | Version of the package, set at build time. @@ -802,7 +804,8 @@ reportSamples = not cfg.statsdNoEvents, reportStats = cfg.statsdAggregates } - (go . Just) + -- the metrics of the garbage collector, beside those of the store + (\stats -> withAsync (runtimeMetrics (withSource "Runtime" logger) stats) (\_ -> go (Just stats))) | otherwise = go Nothing level | cfg.debug = LevelDebug diff --git a/haskoin-store.cabal b/haskoin-store.cabal --- a/haskoin-store.cabal +++ b/haskoin-store.cabal @@ -5,7 +5,7 @@ -- see: https://github.com/sol/hpack name: haskoin-store -version: 1.15.0 +version: 1.15.1 synopsis: Storage and index for Bitcoin and Bitcoin Cash description: An indexer for Bitcoin and Bitcoin Cash. It downloads blocks and mempool transactions from the peer-to-peer network, indexes them in RocksDB, and @@ -76,6 +76,7 @@ Haskoin.Store.Logic.Layered Haskoin.Store.Manager Haskoin.Store.Outage + Haskoin.Store.Runtime Haskoin.Store.Web Haskoin.Store.Web.Docs Haskoin.Store.Web.Events @@ -218,7 +219,7 @@ NoFieldSelectors OverloadedRecordDot OverloadedStrings - ghc-options: -Wall -Wcompat -Widentities -Wincomplete-record-updates -Wincomplete-uni-patterns -Wmissing-export-lists -Wmissing-home-modules -Wpartial-fields -Wredundant-constraints -threaded -rtsopts "-with-rtsopts=-N --disable-delayed-os-memory-return" + ghc-options: -Wall -Wcompat -Widentities -Wincomplete-record-updates -Wincomplete-uni-patterns -Wmissing-export-lists -Wmissing-home-modules -Wpartial-fields -Wredundant-constraints -threaded -rtsopts "-with-rtsopts=-N -T --nonmoving-gc --disable-delayed-os-memory-return" build-depends: aeson >=2.2.5.1 && <2.3 , base >=4.21.2.0 && <4.22 diff --git a/src/Haskoin/Store/Runtime.hs b/src/Haskoin/Store/Runtime.hs new file mode 100644 --- /dev/null +++ b/src/Haskoin/Store/Runtime.hs @@ -0,0 +1,123 @@ +{-# LANGUAGE OverloadedRecordDot #-} +{-# LANGUAGE OverloadedStrings #-} + +-- | +-- Module : Haskoin.Store.Runtime +-- Copyright : (c) Haskoin Developers +-- License : MIT +-- Maintainer : jprupp@protonmail.ch +-- Stability : experimental +-- Portability : POSIX +-- +-- The garbage collector of GHC, as StatsD metrics. +-- +-- Every collection of GHC stops every core, the small ones included, and a +-- busy store collects hundreds of times a second. While it is stopped, no +-- request moves: not even @\/health@, which only reads memory. So how long +-- the store spends stopped, and how the heap grows, say as much about how +-- it answers as the timings of its requests do. The statistics that GHC +-- keeps are read once a second and sent as metrics, under @rts.*@. +-- +-- GHC keeps them only when the program runs with @+RTS -T@, which the +-- executable of the store turns on by default: it costs a few counters at +-- each collection. A program that uses the library without it gets a line +-- in the log that says so, and no metrics. +-- +-- The statistics come as totals since the start, and are sent as what +-- changed in the second: counters, which StatsD sums and turns into rates. +-- The last collection's details would have given a pause time for each +-- collection; read once a second, they would have shown one collection in +-- hundreds, and not the longest. The mean pause of the second is sent +-- instead. +module Haskoin.Store.Runtime + ( runtimeMetrics, + ) +where + +import Control.Monad (forever, unless) +import GHC.Stats (GCDetails (..), RTSStats (..), getRTSStats, getRTSStatsEnabled) +import Haskoin.Node (Logger, logInfo) +import System.Metrics.StatsD + ( Stats, + StatCounter, + StatGauge, + incrementCounter, + newStatCounter, + newStatGauge, + setGauge, + ) +import UnliftIO.Concurrent (threadDelay) + +-- | The metrics of the collector. +data Metrics = Metrics + { gcs :: !StatCounter, + majorGcs :: !StatCounter, + paused :: !StatCounter, + pauseMean :: !StatGauge, + pausePercent :: !StatGauge, + gcCpu :: !StatCounter, + syncs :: !StatCounter, + marking :: !StatCounter, + allocated :: !StatCounter, + live :: !StatGauge, + heap :: !StatGauge + } + +-- | Send the statistics of the collector to StatsD once a second, forever: +-- run it in a thread of its own. If the program does not keep them, it +-- says so in the log and returns. +runtimeMetrics :: Logger -> Stats -> IO () +runtimeMetrics logger stats = do + enabled <- getRTSStatsEnabled + if not enabled + then logInfo logger "No garbage collector metrics: run with +RTS -T for them" + else do + m <- metrics + start <- getRTSStats + let loop before = do + threadDelay 1000000 + now <- getRTSStats + report m before now + loop now + forever (loop start) + where + -- one sample a second each: sent whole, unless only aggregates are wanted + counter k = newStatCounter stats ("rts." <> k) 1 + gauge k = newStatGauge stats ("rts." <> k) 0 + metrics = + Metrics + <$> counter "gcs" + <*> counter "major_gcs" + <*> counter "gc_pause_us" + <*> gauge "gc_pause_mean_us" + <*> gauge "gc_pause_percent" + <*> counter "gc_cpu_us" + <*> counter "nonmoving_sync_us" + <*> counter "nonmoving_mark_us" + <*> counter "allocated_bytes" + <*> gauge "live_bytes" + <*> gauge "heap_bytes" + +-- | Send what changed between two readings of the statistics. +report :: Metrics -> RTSStats -> RTSStats -> IO () +report m before now = do + add m.gcs collections + add m.majorGcs (delta (.major_gcs)) + add m.paused (micros (.gc_elapsed_ns)) + setGauge m.pauseMean (if collections > 0 then micros (.gc_elapsed_ns) `div` collections else 0) + setGauge m.pausePercent (if wall > 0 then 100 * delta (.gc_elapsed_ns) `div` wall else 0) + add m.gcCpu (micros (.gc_cpu_ns)) + add m.syncs (micros (.nonmoving_gc_sync_elapsed_ns)) + add m.marking (micros (.nonmoving_gc_elapsed_ns)) + add m.allocated (delta (.allocated_bytes)) + setGauge m.live (fromIntegral now.gc.gcdetails_live_bytes) + setGauge m.heap (fromIntegral now.gc.gcdetails_mem_in_use_bytes) + where + delta :: (Integral a) => (RTSStats -> a) -> Int + delta f = fromIntegral (f now) - fromIntegral (f before) + micros :: (Integral a) => (RTSStats -> a) -> Int + micros f = delta f `div` 1000 + collections = delta (.gcs) + wall = delta (.elapsed_ns) + -- a counter that did not move is not sent + add c n = unless (n <= 0) (incrementCounter c n) diff --git a/swagger.yaml b/swagger.yaml --- a/swagger.yaml +++ b/swagger.yaml @@ -11,7 +11,7 @@ - url: './' info: - version: &version 1.15.0 + version: &version 1.15.1 title: Haskoin contact: name: JP Rupp