200 models (no applications) results in a fair bit of CPU/memory overhead

[John A Meinel]

I bootstrapped a 2.5.0 LXD controller, and just did:
 juju controller-config controller-api-port=17071
 juju enable-ha -n3
 for i in `seq -f%03g 0 199`; do juju add-model --no-switch m$i; done

First off, it took a bit longer than I expected to bring up 200 models.

Afterward, lsof | grep 17017 | wc -l reports 419 sockets (probably this is 209 with both source and destination).

top with nothing special going on says:
USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
100000 20 1967592 569424 33368 S 14.2 3.5 63:28.40 /var/lib/juju/tools/machine-1/jujud machine --data-dir /var/lib/juju --machine-id 1 --+
100000 20 2041580 568484 33884 S 36.8 3.5 77:07.14 /var/lib/juju/tools/machine-2/jujud machine --data-dir /var/lib/juju --machine-id 2 --+
100000 20 1921152 463688 50172 S 13.9 2.9 5:50.20 /var/lib/juju/tools/machine-0/jujud machine --data-dir /var/lib/juju --machine-id 0 --+

so across the 3 instances, that is 64% cpu. This is an older machine, so not super fast, but given the only thing running is the model workers (and 5 units of ubuntu), this seems a bit high.

I had run some log sending tests, but AFAICT there isn't any broken routines running.
'juju_cpu_profile 60' reports:
Showing nodes accounting for 3.58s, 53.67% of 6.67s total
Dropped 831 nodes (cum <= 0.03s)
Showing top 10 nodes out of 274
      flat flat% sum% cum cum%
    1950ms 29.24% 29.24% 1950ms 29.24% runtime.futex
     610ms 9.15% 38.38% 610ms 9.15% runtime.usleep
     460ms 6.90% 45.28% 500ms 7.50% syscall.Syscall
     140ms 2.10% 47.38% 140ms 2.10% crypto/sha1.blockAMD64
     100ms 1.50% 48.88% 130ms 1.95% runtime.heapBitsSetType
     100ms 1.50% 50.37% 100ms 1.50% runtime.nextFreeFast
      80ms 1.20% 51.57% 80ms 1.20% runtime.aeshashbody
      80ms 1.20% 52.77% 80ms 1.20% runtime.epollwait
      80ms 1.20% 53.97% 1150ms 17.24% runtime.findrunnable
      80ms 1.20% 55.17% 600ms 9.00% runtime.notetsleep_internal

futex doesn't seem particularly interesting. sha1 seems like something might be going on with that.
If I sort by Cumulative time and do more entries I get:

Showing top 50 nodes out of 274
      flat flat% sum% cum cum%
     1.95s 29.24% 29.24% 1.95s 29.24% runtime.futex
         0 0% 29.24% 1.33s 19.94% runtime.mcall
     0.04s 0.6% 29.84% 1.33s 19.94% runtime.schedule
         0 0% 29.84% 1.25s 18.74% runtime.park_m
     0.02s 0.3% 30.13% 1.24s 18.59% runtime.futexsleep
     0.03s 0.45% 30.58% 1.16s 17.39% runtime.timerproc
     0.08s 1.20% 31.78% 1.15s 17.24% runtime.findrunnable
     0.07s 1.05% 32.83% 1.12s 16.79% runtime.systemstack
         0 0% 32.83% 0.85s 12.74% github.com/juju/juju/vendor/gopkg.in/tomb%2ev2.(*Tomb).run
     0.04s 0.6% 33.43% 0.85s 12.74% runtime.stopm
     0.01s 0.15% 33.58% 0.83s 12.44% runtime.sysmon
         0 0% 33.58% 0.82s 12.29% runtime.mstart
         0 0% 33.58% 0.82s 12.29% runtime.mstart1
     0.02s 0.3% 33.88% 0.77s 11.54% runtime.notesleep
         0 0% 33.88% 0.75s 11.24% runtime.notetsleepg
     0.01s 0.15% 34.03% 0.74s 11.09% runtime.notewakeup
         0 0% 34.03% 0.73s 10.94% runtime.futexwakeup
     0.61s 9.15% 43.18% 0.61s 9.15% runtime.usleep
     0.08s 1.20% 44.38% 0.60s 9.00% runtime.notetsleep_internal
         0 0% 44.38% 0.59s 8.85% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*raftState).goFunc.func1
     0.01s 0.15% 44.53% 0.58s 8.70% runtime.startm
     0.46s 6.90% 51.42% 0.50s 7.50% syscall.Syscall
         0 0% 51.42% 0.48s 7.20% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*Raft).run
         0 0% 51.42% 0.48s 7.20% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*Raft).run-fm
     0.02s 0.3% 51.72% 0.48s 7.20% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*Raft).runFollower
         0 0% 51.72% 0.46s 6.90% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*Raft).processRPC
     0.01s 0.15% 51.87% 0.45s 6.75% github.com/juju/juju/vendor/github.com/hashicorp/raft.(*Raft).appendEntries
     0.05s 0.75% 52.62% 0.45s 6.75% runtime.mallocgc

Maybe its just a lot of goroutines hung in sleep?

goroutine profile: total 29150
2170 @ 0x430f2b 0x440fa6 0xa54361 0x45f401
# 0xa54360 github.com/juju/juju/vendor/gopkg.in/juju/worker.v1/catacomb.(*Catacomb).add.func2+0xe0 /workspace/_build/src/github.com/juju/
1972 @ 0x430f2b 0x440fa6 0xa5409b 0x45f401
# 0xa5409a github.com/juju/juju/vendor/gopkg.in/juju/worker.v1/catacomb.Invoke.func2+0x11a /workspace/_build/src/github.com/juju/juju/ven

1811 @ 0x430f2b 0x430fd3 0x40867e 0x40836b 0xa00e89 0xac0d90 0xa5ab5e 0xa5aed4 0x45f401
# 0xa00e88 github.com/juju/juju/rpc.(*Conn).Call+0x118 /workspace/_build/src/github.com/juju/juju/rpc/client.
# 0xac0d8f github.com/juju/juju/api.(*state).APICall+0x1cf /workspace/_build/src/github.com/juju/juju/api/apiclie
# 0xa5ab5d github.com/juju/juju/api/watcher.makeWatcherAPICaller.func1+0x13d /workspace/_build/src/github.com/juju/juju/api/watcher# 0xa5aed3 github.com/juju/juju/api/watcher.(*commonWatcher).commonLoop.func2+0xe3 /workspace/_build/src/github.com/juju/juju/api/watcher

1811 @ 0x430f2b 0x430fd3 0x40867e 0x40836b 0xa5ac22 0x45f401
# 0xa5ac21 github.com/juju/juju/api/watcher.(*commonWatcher).commonLoop.func1+0x71 /workspace/_build/src/github.com/juju/juju/api/watcher
1811 @ 0x430f2b 0x430fd3 0x441b4c 0x441789 0x468f54 0xa57198 0x45f401
# 0x441788 sync.runtime_Semacquire+0x38 /snap/go/3095/src/runtime/sema.go:56
# 0x468f53 sync.(*WaitGroup).Wait+0x63 /snap/go/3095/src/sync/waitgroup.go:130
# 0xa57197 github.com/juju/juju/api/watcher.(*commonWatcher).commonLoop+0xf7 /workspace/_build/src/github.com/juju/juju/api/watcher

1770 @ 0x430f2b 0x430fd3 0x40867e 0x40836b 0xa4b3ea 0xa5724d 0xa54227 0x45f401
# 0xa4b3e9 github.com/juju/juju/vendor/gopkg.in/tomb%2ev2.(*Tomb).Wait+0x49 /workspace/_build/src/github.com/juju/
# 0xa5724c github.com/juju/juju/api/watcher.(*commonWatcher).Wait+0x2c /workspace/_build/src/github.com/juju/
# 0xa54226 github.com/juju/juju/vendor/gopkg.in/juju/worker.v1/catacomb.(*Catacomb).add.func1+0x86 /workspace/_build/src/github.com/juju/

1250 @ 0x430f2b 0x430fd3 0x40867e 0x4083ab 0x1f86f60 0x45d6eb 0x4c4074 0x4c3b04 0x9ff676 0x1f7fd96 0xa034db 0x45f401
# 0x1f86f5f github.com/juju/juju/apiserver.(*srvNotifyWatcher).Next+0x4f /workspace/_build/src/github.com/juju/juju/apiserver/watcher.g
# 0x45d6ea runtime.call32+0x3a /snap/go/3095/src/runtime/asm_amd64.s:522
# 0x4c4073 reflect.Value.call+0x453 /snap/go/3095/src/reflect/value.go:447
# 0x4c3b03 reflect.Value.Call+0xa3 /snap/go/3095/src/reflect/value.go:308
# 0x9ff675 github.com/juju/juju/rpc/rpcreflect.newMethod.func6+0x105 /workspace/_build/src/github.com/juju/juju/rpc/rpcreflect/type
# 0x1f7fd95 github.com/juju/juju/apiserver.(*srvCaller).Call+0xd5 /workspace/_build/src/github.com/juju/juju/apiserver/root.go:1# 0xa034da github.com/juju/juju/rpc.(*Conn).runRequest+0x1aa /workspace/_build/src/github.com/juju/juju/rpc/server.go:560

1250 routines waiting in Next, catacomb.Add() creates 2 goroutines (one synchronizing catacomb shutdown to shut down the worker, and one having the worker stopping shut down the catacomb.) We could pretty easily turn that into a single catacomb shutdown telling all pending workers to stop, and one goroutine watching each worker.

[Tim Penhey (thumper)]

Part of this overhead is that every controller is creating a dependency
engine and all the workers for every model. Now not all those workers
are running, but some, like api-caller are.

The model workers should be reworked so the controller only creates the
nested dependency engine for the models that it currently has leases on.

That would make a significant difference in the idle state at least.

Tim

[Joseph Phillips (manadart)]

Same experiment today with 2.9.24 HEAD, with Bionic controllers:

sudo lsof -i 4|grep 17070|wc -l
212

 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4205 root 20 0 1323.7m 594.9m 92.0m S 3.4 0.9 4:00.42 jujud

go tool pprof -text /var/lib/juju/tools/2.9.24.1-ubuntu-amd64/jujud cpu
File: jujud
Type: cpu
Time: Jan 27, 2022 at 11:38am (UTC)
Duration: 1mins, Total samples = 2.04s ( 3.40%)
Showing nodes accounting for 1.58s, 77.45% of 2.04s total
Dropped 225 nodes (cum <= 0.01s)
      flat flat% sum% cum cum%
     0.50s 24.51% 24.51% 0.50s 24.51% syscall.Syscall
     0.29s 14.22% 38.73% 0.29s 14.22% runtime.futex
     0.18s 8.82% 47.55% 0.18s 8.82% runtime.epollwait
     0.05s 2.45% 50.00% 0.21s 10.29% runtime.stealWork
     0.04s 1.96% 51.96% 0.04s 1.96% crypto/sha1.blockAMD64
     0.04s 1.96% 53.92% 0.04s 1.96% runtime.(*randomEnum).next (inline)
     0.04s 1.96% 55.88% 0.05s 2.45% runtime.checkTimers
     0.04s 1.96% 57.84% 0.14s 6.86% runtime.mallocgc
     0.04s 1.96% 59.80% 0.04s 1.96% runtime.pMask.read (inline)
     0.04s 1.96% 61.76% 0.04s 1.96% runtime.write1
     0.03s 1.47% 63.24% 0.03s 1.47% runtime.memmove
     0.02s 0.98% 64.22% 0.02s 0.98% gopkg.in/yaml%2ev2.yaml_emitter_analyze_scalar
     0.02s 0.98% 65.20% 0.02s 0.98% reflect.(*rtype).Kind (inline)
     0.02s 0.98% 66.18% 0.02s 0.98% runtime.(*semaRoot).queue
     0.02s 0.98% 67.16% 0.02s 0.98% runtime.getMCache (inline)
     0.02s 0.98% 68.14% 0.02s 0.98% runtime.mapassign
     0.02s 0.98% 69.12% 0.02s 0.98% runtime.nextFreeFast (inline)
     0.02s 0.98% 70.10% 0.02s 0.98% runtime.runqgrab
     0.01s 0.49% 70.59% 0.02s 0.98% context.(*cancelCtx).cancel
     0.01s 0.49% 71.08% 0.21s 10.29% crypto/tls.(*Conn).write
     0.01s 0.49% 71.57% 0.26s 12.75% crypto/tls.(*atLeastReader).Read
     0.01s 0.49% 72.06% 0.03s 1.47% github.com/hashicorp/go-msgpack/codec.(*Encoder).encode
     0.01s 0.49% 72.55% 0.03s 1.47% github.com/hashicorp/raft-boltdb.(*BoltStore).GetLog
     0.01s 0.49% 73.04% 0.04s 1.96% github.com/hashicorp/raft.(*Raft).setupAppendEntries
     0.01s 0.49% 73.53% 0.03s 1.47% github.com/juju/mgo/v2/bson.(*decoder).readElemTo
     0.01s 0.49% 74.02% 0.02s 0.98% reflect.Value.Field
     0.01s 0.49% 74.51% 0.02s 0.98% regexp.(*Regexp).tryBacktrack
     0.01s 0.49% 75.00% 0.62s 30.39% runtime.findrunnable
     0.01s 0.49% 75.49% 0.20s 9.80% runtime.netpoll
     0.01s 0.49% 75.98% 0.06s 2.94% runtime.newobject (partial-inline)
     0.01s 0.49% 76.47% 0.02s 0.98% runtime.pcvalue
     0.01s 0.49% 76.96% 0.02s 0.98% runtime.runqput
     0.01s 0.49% 77.45% 0.20s 9.80% syscall.write

Many more goroutines.

juju_goroutines
goroutine profile: total 40699
3213 @ 0x438056 0x447df2 0x146fea5 0x468c81
# 0x146fea4 github.com/juju/worker/v3/catacomb.(*Catacomb).add.func2+0xe4 /home/joseph/go/src/github.com/juju/juju/vendor/github.com/juju/worker/v3/catacomb/catacomb.go:182...

[Joseph Phillips (manadart)]

As I read it, we are running model workers without qualification that should depend upon the singlular designation, either by depending on isResponsible, or environTrackerName (which depends on isResponsible).

charmRevisionUpdaterName
stateCleanerName
statusHistoryPrunerName
actionPrunerName

Maybe loggingConfigUpdaterName and validCredentialFlagName too.

[Canonical Juju QA Bot (juju-qa-bot)]

This Medium-priority bug has not been updated in 60 days, so we're marking it Low importance. If you believe this is incorrect, please update the importance.