Visitar URL original
GracefulStop phases have no bound: a background GC measurement holds it for 17 min; shutdown.gracefulStopTimeout doesn't apply · Issue #15017 · dagger/dagger · GitHub
Skip to content

GracefulStop phases have no bound: a background GC measurement holds it for 17 min; shutdown.gracefulStopTimeout doesn't apply #15017

Open

Description

@yasyf

Engine: built from main at a85c363c (reports v1.0.0-beta.22) plus #14927 and #14953, Linux amd64, m8a.16xlarge. Overlayfs snapshotter on XFS, on a gp3 volume restored from an EBS snapshot that was still hydrating. engine.json sets shutdown.gracefulStopTimeout: 300 and gc maxUsedSpace to 80% of the volume. The engine runs in Docker with --stop-timeout 1800.

What we see:

  1. Repro (test box, goroutine dumps every 30 s during the stop). On a freshly restored engine, a dagger check client ran for 900 s and was killed by its timeout (exit 124). A minute later dagger_connected_clients was 0 and port 1234 had no TCP connections. Then SIGTERM:
    • wait for garbage collection took 17m22s. Every other phase took µs to 30 s. close dagql cache took 5.9 s; close network providers took 29 s.
    • 34 of the 36 dumps show the same two goroutines. GracefulStop waits on a mutex that a timer-started GC holds while it sizes every snapshot:
      GracefulStop server.go:1057 -> GracefulStop.func1 server.go:1020 -> sync.Mutex.Lock
      time.goFunc -> (*Server).gc gc.go:349 -> gcLocked gc.go:388 -> pruneLocalCacheLocked gc.go:437
        -> dagql.(*Cache).Prune cache_prune.go:342 -> measurePruneState cache_prune.go:298
        -> measureAllResultSizes cache.go:5698 -> collectUsageMeasurementInputs cache_usage.go:73
        -> buildCacheUsageMeasurements cache.go:5769 (44,266 results) -> cacheUsageSizeBytesFromSnapshotLink cache.go:7458
        -> snapshotManager.SnapshotSize -> overlay snapshotter.Usage overlay.go:255 -> continuity fs.DiskUsage
        -> filepath.Walk -> os.Lstat
      
    • So a prune sizes every snapshot by walking it with du under the server's GC mutex, and shutdown waits on that mutex with no bound.
  2. Production (no dump; the instance was gone before we took one). A pool engine idle for 60 s (no TCP clients on 1234) got SIGTERM. It logged removing session; stopping client services and flushing session=ZDPE4A7…, then graceful stop phase is slow phase="remove sessions" … no uninterruptible threads, and stayed in that phase for 30 min. Docker SIGKILLed it at --stop-timeout (exit 137).
    • On the next start: dagql persistence store marked unclean; wiping and cold-starting and local cache state invalid; resetting worker and dagql persistence state, so a 600 GB cache went cold.
    • The session had no connected client. It most likely belonged to a client killed at its timeout earlier.
  3. Clean stops on the same engines take 34 s to 9 min. The slow phases are prune local cache (up to 4m18s after heavy builds) and close dagql cache (about 2 min for a 12 GB dagql-cache.db).

Impact: a stop has no upper bound short of the container stop timeout. Hitting that timeout costs the most, because a SIGKILL makes the next start wipe the whole cache. Anything that must stop an engine on a schedule (spot interruption drains with a 2-min notice, rolling restarts, snapshotting a clean cache) can't plan around that.

Asks:

  1. Apply shutdown.gracefulStopTimeout (or a per-phase budget) to every GracefulStop phase. When it expires, skip the remaining optional work (GC wait, prune, session flush) and still run close dagql cache and mark the clean shutdown, so a slow GC or a stuck session never costs the cache.
  2. Make the in-flight GC cancellable by GracefulStop, so wait for garbage collection cancels the prune's context instead of waiting on the mutex.
  3. Don't size snapshots by walking them during prune. Record sizes when snapshots commit, or cache Usage per snapshot. A full du of every snapshot under the GC lock is O(files in the cache) and blocks stop.
  4. Time out or force-remove sessions whose client connections are all gone, both at stop and in the background.

Repro:

  • Restore an engine whose state has tens of thousands of results onto a cold disk.
  • Run a large dagger check against it under timeout 900, and let the timeout fire mid-run.
  • Wait 60 s, then send SIGTERM while the timer-started GC is measuring.
  • Take dumps from --debugaddr with /debug/pprof/goroutine?debug=2 every 30 s.

Activity

  1. yasyf commented on Nov 1, 2026

    @yasyf
    Author

    One more data point. The dagql cache appears to be written only during a graceful stop, so the "close dagql cache" phase grows the longer an engine has been serving. An engine three hours into its life, with about 418k dagql entries, spent over 16 minutes in "close dagql cache" and ran past a 960 s container stop timeout. On the next start it wiped its whole cache.

    Fifth ask: persist dagql state incrementally while the engine runs, or checkpoint it periodically, so a stop only has to flush recent changes and its time doesn't depend on the engine's age.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions