search

testcontainers / testcontainers-dotnet

A library to support tests with throwaway instances of Docker containers for all compatible .NET Standard versions.
https://dotnet.testcontainers.org
MIT License
3.65k stars 250 forks source link

[Bug]: Starting postgres container takes 30 seconds #1191

Closed kanpov closed 4 weeks ago

kanpov commented 4 weeks ago

Testcontainers version

3.8.0

Using the latest Testcontainers version?

Yes

Host OS

Linux

Host arch

x86

.NET version

8.0.6

Docker version

Client:
 Version:           26.1.0-ce
 API version:       1.45
 Go version:        go1.21.9
 Git commit:        c8af8ebe4a89
 Built:             Wed Apr 24 13:43:30 2024
 OS/Arch:           linux/amd64
 Context:           default

Server:
 Engine:
  Version:          26.1.0-ce
  API version:      1.45 (minimum version 1.24)
  Go version:       go1.21.9
  Git commit:       c8af8ebe4a89
  Built:            Wed Apr 24 13:43:30 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.17
  GitCommit:        3a4de459a68952ffb703bbe7f2290861a75b6b67
 runc:
  Version:          1.2.0-rc.1
  GitCommit:        v1.2.0-rc.1-0-g275e6d85f78a
 docker-init:
  Version:          0.2.0_catatonit
  GitCommit:

Docker info

Client:
 Version:    26.1.0-ce
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  0.14.1
    Path:     /usr/lib/docker/cli-plugins/docker-buildx

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 4
 Server Version: 26.1.0-ce
 Storage Driver: overlay2
  Backing Filesystem: btrfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 oci runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 3a4de459a68952ffb703bbe7f2290861a75b6b67
 runc version: v1.2.0-rc.1-0-g275e6d85f78a
 init version: 
 Security Options:
  apparmor
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.9.3-1-default
 Operating System: openSUSE Tumbleweed
 OSType: linux
 Architecture: x86_64
 CPUs: 16
 Total Memory: 31.29GiB
 Name: localhost.localdomain
 ID: f726be14-2349-4586-a8a9-2b6414c30b60
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

What happened?

Creating a postgresql container using Testcontainers.PostgreSql takes about 30 seconds on a fast machine (ryzen 7 2700x, 32gb ram) with native docker (linux, no wsl). The initialization process seems to hang for a while (20-25s) on the syncing data to disk ... ok step.

Relevant log output

In the below log, you can see the change between "10:40:37" and "10:41:07" in time, hence the delay.

2024-06-07T10:40:37.426189094Z The files belonging to this database system will be owned by user "postgres".
2024-06-07T10:40:37.426226284Z This user must also own the server process.
2024-06-07T10:40:37.426241833Z 
2024-06-07T10:40:37.426375196Z The database cluster will be initialized with locale "en_US.utf8".
2024-06-07T10:40:37.426390975Z The default database encoding has accordingly been set to "UTF8".
2024-06-07T10:40:37.426398690Z The default text search configuration will be set to "english".
2024-06-07T10:40:37.426408508Z 
2024-06-07T10:40:37.426415111Z Data page checksums are disabled.
2024-06-07T10:40:37.426421894Z 
2024-06-07T10:40:37.426430540Z fixing permissions on existing directory /var/lib/postgresql/data ... ok
2024-06-07T10:40:37.426921268Z creating subdirectories ... ok
2024-06-07T10:40:37.427045924Z selecting dynamic shared memory implementation ... posix
2024-06-07T10:40:37.444404610Z selecting default max_connections ... 100
2024-06-07T10:40:37.466039281Z selecting default shared_buffers ... 128MB
2024-06-07T10:40:37.498217844Z selecting default time zone ... Etc/UTC
2024-06-07T10:40:37.499122544Z creating configuration files ... ok
2024-06-07T10:40:37.631271392Z running bootstrap script ... ok
2024-06-07T10:40:37.991832582Z performing post-bootstrap initialization ... ok
2024-06-07T10:41:07.843574049Z syncing data to disk ... ok
2024-06-07T10:41:07.843640415Z 
2024-06-07T10:41:07.843657547Z 
2024-06-07T10:41:07.843670271Z Success. You can now start the database server using:
2024-06-07T10:41:07.843699316Z 
2024-06-07T10:41:07.843726898Z     pg_ctl -D /var/lib/postgresql/data -l logfile start
2024-06-07T10:41:07.843744501Z 
2024-06-07T10:41:07.843611620Z initdb: warning: enabling "trust" authentication for local connections
2024-06-07T10:41:07.843760572Z initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
2024-06-07T10:41:07.911191378Z waiting for server to start....2024-06-07 10:41:07.911 UTC [48] LOG:  starting PostgreSQL 16.2 (Debian 16.2-1.pgdg120+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2024-06-07T10:41:07.911323487Z 2024-06-07 10:41:07.911 UTC [48] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-06-07T10:41:07.913580250Z 2024-06-07 10:41:07.913 UTC [51] LOG:  database system was shut down at 2024-06-07 10:40:37 UTC
2024-06-07T10:41:07.918519281Z 2024-06-07 10:41:07.918 UTC [48] LOG:  database system is ready to accept connections
2024-06-07T10:41:07.985181625Z  done
2024-06-07T10:41:07.985219636Z server started
2024-06-07T10:41:08.097760721Z CREATE DATABASE
2024-06-07T10:41:08.098852293Z 
2024-06-07T10:41:08.098938336Z 
2024-06-07T10:41:08.098976448Z /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
2024-06-07T10:41:08.098984633Z 
2024-06-07T10:41:08.099977178Z waiting for server to shut down....2024-06-07 10:41:08.099 UTC [48] LOG:  received fast shutdown request
2024-06-07T10:41:08.100061508Z 2024-06-07 10:41:08.100 UTC [48] LOG:  aborting any active transactions
2024-06-07T10:41:08.103094938Z 2024-06-07 10:41:08.102 UTC [48] LOG:  background worker "logical replication launcher" (PID 54) exited with exit code 1
2024-06-07T10:41:08.103205346Z 2024-06-07 10:41:08.103 UTC [49] LOG:  shutting down
2024-06-07T10:41:08.103242266Z 2024-06-07 10:41:08.103 UTC [49] LOG:  checkpoint starting: shutdown immediate
2024-06-07T10:41:08.113665116Z 2024-06-07 10:41:08.113 UTC [49] LOG:  checkpoint complete: wrote 923 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.010 s, sync=0.001 s, total=0.011 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4256 kB, estimate=4256 kB; lsn=0/1912CF8, redo lsn=0/1912CF8
2024-06-07T10:41:08.127451981Z 2024-06-07 10:41:08.127 UTC [48] LOG:  database system is shut down
2024-06-07T10:41:08.200109010Z  done
2024-06-07T10:41:08.200148034Z server stopped
2024-06-07T10:41:08.201808761Z 
2024-06-07T10:41:08.201824260Z PostgreSQL init process complete; ready for start up.
2024-06-07T10:41:08.201830412Z 
2024-06-07T10:41:08.234110733Z 2024-06-07 10:41:08.234 UTC [1] LOG:  starting PostgreSQL 16.2 (Debian 16.2-1.pgdg120+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2024-06-07T10:41:08.234302966Z 2024-06-07 10:41:08.234 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-06-07T10:41:08.234327452Z 2024-06-07 10:41:08.234 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2024-06-07T10:41:08.234613523Z 2024-06-07 10:41:08.234 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-06-07T10:41:08.238001774Z 2024-06-07 10:41:08.237 UTC [64] LOG:  database system was shut down at 2024-06-07 10:41:08 UTC
2024-06-07T10:41:08.243157353Z 2024-06-07 10:41:08.243 UTC [1] LOG:  database system is ready to accept connections

Additional information

No response

kanpov commented 4 weeks ago

Tried 3.5.0 version of Testcontainers, same issue. This makes testing incredibly unproductive (having to wait 30 secs to even run a test).

kanpov commented 4 weeks ago

image This makes it look much more like a testcontainers bug.

kanpov commented 4 weeks ago

The root of the issue was the fact that the / running btrfs had been tortured to a point where read/write operations slowed down to a grinding halt (I'm using openSUSE where btrfs for everything is default).

For anyone else reading this, please put your /home on xfs and not btrfs.