daemon: load and cache sysInfo on initialization by thaJeztah · Pull Request #43130 · moby/moby

thaJeztah · 2022-01-07T12:21:40Z

The daemon.RawSysInfo() function can be a heavy operation, as it collects
information about all cgroups on the host, networking, AppArmor, Seccomp, etc.

While looking at our code, I noticed that various parts in the code call this
function, potentially even multiple times per container, for example, it is
called from:

verifyPlatformContainerSettings()
oci.WithCgroups() if the daemon has cpu-rt-period or cpu-rt-runtime configured
in ContainerDecoder.DecodeConfig(), which is called on boith container create and container commit

Given that this information is not expected to change during the daemon's
lifecycle, and various information coming from this (such as seccomp and
apparmor status) was already cached, we may as well load it once, and cache
the results in the daemon instance.

This patch updates daemon.RawSysInfo() to use a sync.Once() so that
it's only executed once for the daemon's lifecycle.

For sake of completenes: I considered updating daemon.RawSysInfo() to use a sync.Once() instead (to make this automatic on first use), but (for now) decided against it, as it could complicate some tests, and for regular use of the daemon, the daemon would be constructed using daemon.NewDaemon().

- Description for the changelog

- A picture of a cute animal (not mandatory but encouraged)

daemon/seccomp_linux.go

thaJeztah · 2022-01-10T16:08:16Z

Seeing a lot of failures like this on Windows now 😞

=== RUN   TestDockerSuite/TestAPIImagesHistory
    docker_api_images_test.go:126: assertion failed: 
        Command:  d:\CI\PR-43130\7\binary\docker.exe build -t test-api-images-history -
        ExitCode: 1
        Error:    exit status 1
        Stdout:   Sending build context to Docker daemon  2.048kB

        Step 1/2 : FROM busybox
         ---> 0b198bce8e39
        Step 2/2 : ENV FOO bar
         ---> Running in d8617b112fd5
        
        Stderr:   rename D:\CI\PR-43130\7\daemon\image\windowsfilter\layerdb\tmp\write-set-3947302945 D:\CI\PR-43130\7\daemon\image\windowsfilter\layerdb\sha256\de62b214663d85a4dc21df186b9b469263701ff02a585cabb1bbf31662af5c75: Access is denied.
        
        
        Failures:
        ExitCode was 1 expected 0
        Expected no error
    --- FAIL: TestDockerSuite/TestAPIImagesHistory (0.80s)

thaJeztah · 2022-01-11T16:28:11Z

win-2022; TestSlowStdinClosing: known flaky test; #43012

=== FAIL: github.com/docker/docker/integration-cli TestDockerSuite/TestSlowStdinClosing (0.97s)
    docker_cli_run_test.go:4177: assertion failed: error is not nil: exit status 127
    --- FAIL: TestDockerSuite/TestSlowStdinClosing (0.97s)

unit-tests: TestFollowLogsHandleDecodeErr: known flaky (being worked on in #43105)

=== FAIL: daemon/logger/loggerutils TestFollowLogsHandleDecodeErr (0.02s)
time="2022-01-11T09:24:41Z" level=error msg="Log reader notified that it must re-open log file, some log data may not be streamed to the client." file=/tmp/TestFollowLogsHandleDecodeErr4202986584
    logfile_test.go:317: assertion failed: 5 (int) != 6 (dec.resetCount int)

The `daemon.RawSysInfo()` function can be a heavy operation, as it collects information about all cgroups on the host, networking, AppArmor, Seccomp, etc. While looking at our code, I noticed that various parts in the code call this function, potentially even _multiple times_ per container, for example, it is called from: - `verifyPlatformContainerSettings()` - `oci.WithCgroups()` if the daemon has `cpu-rt-period` or `cpu-rt-runtime` configured - in `ContainerDecoder.DecodeConfig()`, which is called on boith `container create` and `container commit` Given that this information is not expected to change during the daemon's lifecycle, and various information coming from this (such as seccomp and apparmor status) was already cached, we may as well load it once, and cache the results in the daemon instance. This patch updates `daemon.RawSysInfo()` to use a `sync.Once()` so that it's only executed once for the daemon's lifecycle. Signed-off-by: Sebastiaan van Stijn <[email protected]>

thaJeztah · 2022-01-20T08:48:23Z

Flakiness during build; looks like there may be some issues with the SUSE repositories

failed to load cache key:
Get "https://download.opensuse.org/repositories/devel:/tools:/criu/Debian_11/Release.key":
dial tcp 195.135.221.134:443: connect: connection refused
script returned exit code 1

Interesting; somehow a test running where it doesn't support devicemapper? Or just some leftover state from a previous run?

=== RUN   TestDevmapperIncreaseLoopBackSize
time="2022-01-19T20:38:44Z" level=error msg="Udev sync is not supported. This will lead to data loss and unexpected behavior. Install a more recent version of libdevmapper or select a different storage driver. For more information, see https://docs.docker.com/engine/reference/commandline/dockerd/#storage-driver-options" storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=warning msg="Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man dockerd` to refer to dm.thinpooldev section." storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=info msg="Creating filesystem xfs on device docker-0:64-17359-base, mkfs args: [/dev/mapper/docker-0:64-17359-base]" storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=info msg="Successfully created filesystem xfs on device docker-0:64-17359-base" storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=warning msg="unmountAndDeactivate: open /tmp/docker-graphtest-1787891524/devicemapper/mnt: no such file or directory" storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=error msg="Udev sync is not supported. This will lead to data loss and unexpected behavior. Install a more recent version of libdevmapper or select a different storage driver. For more information, see https://docs.docker.com/engine/reference/commandline/dockerd/#storage-driver-options" storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=warning msg="Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man dockerd` to refer to dm.thinpooldev section." storage-driver=devicemapper
time="2022-01-19T20:38:44Z" level=warning msg="Base device already exists and has filesystem xfs on it. User specified filesystem  will be ignored." storage-driver=devicemapper
    devmapper_test.go:124: data or metadata loop back size is incorrect
time="2022-01-19T20:38:44Z" level=warning msg="unmountAndDeactivate: open /tmp/docker-graphtest-1787891524/devicemapper/mnt: no such file or directory" storage-driver=devicemapper
--- FAIL: TestDevmapperIncreaseLoopBackSize (0.19s)

Base device already exists and has filesystem xfs on it.
User specified filesystem  will be ignored."
..
devmapper_test.go:124: data or metadata loop back size is incorrect

thaJeztah · 2022-01-20T12:09:30Z

Windows failure is a known flaky test (we need to look into that one) #43012

=== RUN   TestDockerSuite/TestSlowStdinClosing
    docker_cli_run_test.go:4177: assertion failed: error is not nil: exit status 127
    --- FAIL: TestDockerSuite/TestSlowStdinClosing (4.55s)

thaJeztah · 2022-01-20T12:10:16Z

@AkihiroSuda ptal

thaJeztah · 2022-01-26T15:43:12Z

@AkihiroSuda ptal 🤗

thaJeztah · 2022-02-18T00:51:49Z

@AkihiroSuda PTAL

thaJeztah · 2022-02-18T07:02:26Z

Thanks! (sorry for the repeated ping; had some other changes in this area that may conflict, so wanted to get this one in if possible)

thaJeztah · 2022-06-03T15:05:03Z

This may have caused a regression; first time the daemon is started, docker info now shows the wrong information for networking;

WARNING: IPv4 forwarding is disabled
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled

Checking on the host shows the correct status;

cat /proc/sys/net/ipv4/ip_forward
1
cat /proc/sys/net/bridge/bridge-nf-call-iptables
1
cat /proc/sys/net/bridge/bridge-nf-call-ip6tables
1

After restarting the service (systemctl restart docker.service), values are correct.

I suspect the reason for that is that the SystemInfo is read during daemon startup (and uses a sync.Once()), but the daemon actually modifies those values, and first time the daemon is started, those changes have not yet been set;

For example;

ip forwarding is enabled in libnetwork/drivers/bridge/configureIPForwarding()
called by libnetwork/drivers/bridge/setupIPForwarding()
called by libnetwork/drivers/bridge/driver.configure()
called by libnetwork/drivers/bridge/Init()
called by libnetwork/controller.New()
called by daemon.initNetworkController()
called by daemon.restore()
called by daemon.NewDaemon() (at line 1093)
but we call d.RawSysInfo() in the same function (daemon.NewDaemon()) at line 1008

thaJeztah added status/2-code-review area/daemon Core Engine labels Jan 7, 2022

thaJeztah added this to the 21.xx milestone Jan 7, 2022

thaJeztah mentioned this pull request Jan 7, 2022

daemon: move check for CPU-realtime daemon options #43131

Merged

thaJeztah force-pushed the daemon_cache_sysinfo branch from 92faa25 to d132750 Compare January 7, 2022 12:44

This comment was marked as outdated.

Sign in to view

thaJeztah force-pushed the daemon_cache_sysinfo branch from d132750 to 697bdec Compare January 7, 2022 14:20

thaJeztah commented Jan 7, 2022

View reviewed changes

daemon/seccomp_linux.go Outdated Show resolved Hide resolved

thaJeztah force-pushed the daemon_cache_sysinfo branch from 697bdec to 0607e54 Compare January 7, 2022 23:05

thaJeztah force-pushed the daemon_cache_sysinfo branch from 0607e54 to 483aa62 Compare January 12, 2022 17:28

tianon approved these changes Jan 13, 2022

View reviewed changes

AkihiroSuda approved these changes Feb 18, 2022

View reviewed changes

AkihiroSuda merged commit 54d35c0 into moby:master Feb 18, 2022

thaJeztah deleted the daemon_cache_sysinfo branch February 18, 2022 06:59

thaJeztah mentioned this pull request Jun 3, 2022

daemon.NewDaemon(): fix network feature detection on first start #43689

Merged

crazy-max mentioned this pull request Sep 2, 2022

Dockerfile: pin criu version and build from source #44086

Open

thaJeztah mentioned this pull request Oct 16, 2023

daemon: release sandbox even when NetworkDisabled #46651

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

daemon: load and cache sysInfo on initialization#43130

daemon: load and cache sysInfo on initialization#43130
AkihiroSuda merged 1 commit intomoby:masterfrom
thaJeztah:daemon_cache_sysinfo

thaJeztah commented Jan 7, 2022 •

edited

Loading

Uh oh!

This comment was marked as outdated.

Uh oh!

thaJeztah commented Jan 10, 2022

Uh oh!

thaJeztah commented Jan 11, 2022

Uh oh!

thaJeztah commented Jan 20, 2022 •

edited

Loading

Uh oh!

thaJeztah commented Jan 20, 2022

Uh oh!

thaJeztah commented Jan 20, 2022

Uh oh!

thaJeztah commented Jan 26, 2022

Uh oh!

thaJeztah commented Feb 18, 2022

Uh oh!

thaJeztah commented Feb 18, 2022

Uh oh!

thaJeztah commented Jun 3, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

thaJeztah commented Jan 7, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

This comment was marked as outdated.

Uh oh!

thaJeztah commented Jan 10, 2022

Uh oh!

thaJeztah commented Jan 11, 2022

Uh oh!

thaJeztah commented Jan 20, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jan 20, 2022

Uh oh!

thaJeztah commented Jan 20, 2022

Uh oh!

thaJeztah commented Jan 26, 2022

Uh oh!

thaJeztah commented Feb 18, 2022

Uh oh!

thaJeztah commented Feb 18, 2022

Uh oh!

thaJeztah commented Jun 3, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

thaJeztah commented Jan 7, 2022 •

edited

Loading

thaJeztah commented Jan 20, 2022 •

edited

Loading