long switchover with low CPU requests #2860

ksyblast · 2023-09-25T09:23:56Z

ksyblast
Sep 25, 2023

Hello!

Currently I am choosing a postgresql operator and I am performing some tests.

I have performed some failover tests (draining node with primary pod, deleting primary pod, shutting down the node). During these tests I have noticed that setting low CPU requests value results in quite a long switchover - sometimes it took up to 10 seconds, and once I have even caught a crash (please see attached - promoting-err.txt). By switchover here I mean the delay when the -rw endpoint becomes available after the primary is switched.

Even increasing CPU gives more than one second for the -rw endpoint to become available. I am also making a comparison with zalando operator based on patroni and it switches the master withing 1 second even with low CPU and RAM requests values and using the same nodes.

I haven't made any specific configuration, used the basic examples.

I am wondering if this behavior can be tuned or probably I have missed some configuration options. I would appreciate any feedback.

Version: cloudnative-pg:1.20.2
Cluster config:

kind: Cluster
metadata:
  name: cnpg-cluster-pg13
  namespace: cnpg-cluster
spec:
  imageName: ghcr.io/cloudnative-pg/postgresql:13.6
  instances: 2
  storage:
    storageClass: openebs-lvmpv
    size: 10Gi
  resources:
    limits:
      cpu: 250m
      memory: 6G
    requests:
      cpu: 250m
      memory: 6G
  affinity:
    nodeAffinity:
      requiredDuringSchedulingIgnoredDuringExecution:
        nodeSelectorTerms:
          - matchExpressions:
              - key: kubernetes.io/hostname
                operator: In
                values:
                  - k8s-worker1
                  - k8s-worker2

Here is the replica log being promoted to the master role, in this case -rw endpoint became available in about 3.5s:

{"level":"info","ts":"2023-09-25T08:55:32Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:32.905 UTC","process_id":"77","session_id":"65114ae5.4d","session_line_num":"5","session_start_time":"2023-09-25 08:55:01 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"replication terminated by primary server","detail":"End of WAL reached on timeline 45 at 1/80000A0.","backend_type":"walreceiver"}}
{"level":"info","ts":"2023-09-25T08:55:32Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:32.905 UTC","process_id":"77","session_id":"65114ae5.4d","session_line_num":"6","session_start_time":"2023-09-25 08:55:01 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"XX000","message":"could not send end-of-streaming message to primary: SSL connection has been closed unexpectedly\nno COPY in progress","backend_type":"walreceiver"}}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:33.800 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"7","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"record with incorrect prev-link 0/E6000028 at 1/80000A0","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:33Z","msg":"Setting myself as primary","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"cnpg-cluster-pg13","namespace":"cnpg-cluster"},"namespace":"cnpg-cluster","name":"cnpg-cluster-pg13","reconcileID":"91938709-f8b6-4f36-8b8d-1dd50670aafb","uuid":"495f9f0f-5b81-11ee-956d-de86c5de1360","logging_pod":"cnpg-cluster-pg13-2","phase":"Failing over","currentTimestamp":"2023-09-25T08:55:33.892803Z","targetPrimaryTimestamp":"2023-09-25T08:55:33.314138Z","currentPrimaryTimestamp":"2023-09-25T08:54:55.403982Z","msPassedSinceTargetPrimaryTimestamp":578,"msPassedSinceCurrentPrimaryTimestamp":38488,"msDifferenceBetweenCurrentAndTargetPrimary":-37910}
{"level":"info","ts":"2023-09-25T08:55:33Z","msg":"I'm the target primary, wait for the wal_receiver to be terminated","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"cnpg-cluster-pg13","namespace":"cnpg-cluster"},"namespace":"cnpg-cluster","name":"cnpg-cluster-pg13","reconcileID":"91938709-f8b6-4f36-8b8d-1dd50670aafb","uuid":"495f9f0f-5b81-11ee-956d-de86c5de1360","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:33Z","msg":"I'm the target primary, applying WALs and promoting my instance","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"cnpg-cluster-pg13","namespace":"cnpg-cluster"},"namespace":"cnpg-cluster","name":"cnpg-cluster-pg13","reconcileID":"91938709-f8b6-4f36-8b8d-1dd50670aafb","uuid":"495f9f0f-5b81-11ee-956d-de86c5de1360","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:33Z","msg":"Extracting pg_controldata information","logging_pod":"cnpg-cluster-pg13-2","reason":"promote"}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"pg_controldata","msg":"pg_control version number:            1300\nCatalog version number:               202007201\nDatabase system identifier:           7281241487361605658\nDatabase cluster state:               in archive recovery\npg_control last modified:             Mon 25 Sep 2023 08:55:01 AM UTC\nLatest checkpoint location:           1/7000028\nLatest checkpoint's REDO location:    1/7000028\nLatest checkpoint's REDO WAL file:    0000002C0000000100000007\nLatest checkpoint's TimeLineID:       44\nLatest checkpoint's PrevTimeLineID:   44\nLatest checkpoint's full_page_writes: on\nLatest checkpoint's NextXID:          0:771921\nLatest checkpoint's NextOID:          16579\nLatest checkpoint's NextMultiXactId:  1\nLatest checkpoint's NextMultiOffset:  0\nLatest checkpoint's oldestXID:        478\nLatest checkpoint's oldestXID's DB:   1\nLatest checkpoint's oldestActiveXID:  0\nLatest checkpoint's oldestMultiXid:   1\nLatest checkpoint's oldestMulti's DB: 1\nLatest checkpoint's oldestCommitTsXid:0\nLatest checkpoint's newestCommitTsXid:0\nTime of latest checkpoint:            Mon 25 Sep 2023 08:54:52 AM UTC\nFake LSN counter for unlogged rels:   0/3E8\nMinimum recovery ending location:     1/7000028\nMin recovery ending loc's timeline:   44\nBackup start location:                0/0\nBackup end location:                  0/0\nEnd-of-backup record required:        no\nwal_level setting:                    logical\nwal_log_hints setting:                on\nmax_connections setting:              100\nmax_worker_processes setting:         32\nmax_wal_senders setting:              10\nmax_prepared_xacts setting:           0\nmax_locks_per_xact setting:           64\ntrack_commit_timestamp setting:       off\nMaximum data alignment:               8\nDatabase block size:                  8192\nBlocks per segment of large relation: 131072\nWAL block size:                       8192\nBytes per WAL segment:                16777216\nMaximum length of identifiers:        64\nMaximum columns in an index:          32\nMaximum size of a TOAST chunk:        1996\nSize of a large-object chunk:         2048\nDate/time type storage:               64-bit integers\nFloat8 argument passing:              by value\nData page checksum version:           0\nMock authentication nonce:            fef2d406ddd081afbe15f919dc841a8266f52c69ffd56cb21a46401f0c7de3f8\n","pipe":"stdout","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:33Z","msg":"Promoting instance","logging_pod":"cnpg-cluster-pg13-2","pgctl_options":["-D","/var/lib/postgresql/data/pgdata","-w","promote","-t 40000000"]}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:33.900 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"8","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"received promote request","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:33Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:33.900 UTC","process_id":"202","session_id":"65114b05.ca","session_line_num":"1","session_start_time":"2023-09-25 08:55:33 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P01","message":"terminating walreceiver process due to administrator command","backend_type":"walreceiver"}}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:34.404 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"9","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"redo done at 1/8000028","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:34.404 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"10","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"last completed transaction was at log time 2023-09-25 08:54:55.693858+00","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:34.903 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"11","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"selected new timeline ID: 46","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:34Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:34.955 UTC","process_id":"34","session_id":"65114ae4.22","session_line_num":"12","session_start_time":"2023-09-25 08:55:00 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive recovery complete","backend_type":"startup"}}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"wal-restore","msg":"tried restoring WALs, but no backup was configured","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"pg_ctl","msg":"waiting for server to promote..... done","pipe":"stdout","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"pg_ctl","msg":"server promoted","pipe":"stdout","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:35Z","msg":"Requesting a checkpoint","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:35.207 UTC","process_id":"32","session_id":"65114ae4.20","session_line_num":"7","session_start_time":"2023-09-25 08:55:00 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is ready to accept connections","backend_type":"postmaster"}}
{"level":"info","ts":"2023-09-25T08:55:35Z","msg":"The PostgreSQL instance has been promoted successfully","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"postgres","msg":"record","logging_pod":"cnpg-cluster-pg13-2","record":{"log_time":"2023-09-25 08:55:35.392 UTC","user_name":"postgres","database_name":"postgres","process_id":"284","connection_from":"[local]","session_id":"65114b07.11c","session_line_num":"1","command_tag":"SELECT","session_start_time":"2023-09-25 08:55:35 UTC","virtual_transaction_id":"4/2","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P01","message":"terminating connection due to administrator command","query":"SELECT\n\t\t\t(pg_control_system()).system_identifier,\n\t\t\t-- True if this is a primary instance\n\t\t\tNOT pg_is_in_recovery() as primary,\n\t\t\t-- True if at least one column requires a restart\n\t\t\tEXISTS(SELECT 1 FROM pg_settings WHERE pending_restart),\n\t\t\t-- The size of database in human readable format\n\t\t\t(SELECT pg_size_pretty(SUM(pg_database_size(oid))) FROM pg_database)","application_name":"cnpg-instance-manager","backend_type":"client backend"}}
{"level":"info","ts":"2023-09-25T08:55:35Z","msg":"Instance status probe failing","logging_pod":"cnpg-cluster-pg13-2","err":"FATAL: terminating connection due to administrator command (SQLSTATE 57P01)"}
{"level":"info","ts":"2023-09-25T08:55:35Z","msg":"Finished setting myself as primary","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"cnpg-cluster-pg13","namespace":"cnpg-cluster"},"namespace":"cnpg-cluster","name":"cnpg-cluster-pg13","reconcileID":"91938709-f8b6-4f36-8b8d-1dd50670aafb","uuid":"495f9f0f-5b81-11ee-956d-de86c5de1360","logging_pod":"cnpg-cluster-pg13-2","phase":"Failing over","currentTimestamp":"2023-09-25T08:55:35.392973Z","targetPrimaryTimestamp":"2023-09-25T08:55:33.314138Z","currentPrimaryTimestamp":"2023-09-25T08:55:35.295273Z","msPassedSinceTargetPrimaryTimestamp":2078,"msPassedSinceCurrentPrimaryTimestamp":97,"msDifferenceBetweenCurrentAndTargetPrimary":1981}
{"level":"info","ts":"2023-09-25T08:55:35Z","logger":"wal-archive","msg":"Backup not configured, skip WAL archiving","logging_pod":"cnpg-cluster-pg13-2","walName":"pg_wal/0000002E.history","currentPrimary":"cnpg-cluster-pg13-2","targetPrimary":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-25T08:55:36Z","logger":"wal-archive","msg":"Backup not configured, skip WAL archiving","logging_pod":"cnpg-cluster-pg13-2","walName":"pg_wal/0000002D0000000100000008.partial","currentPrimary":"cnpg-cluster-pg13-2","targetPrimary":"cnpg-cluster-pg13-2"}

gbartolini · 2023-09-26T20:53:26Z

gbartolini
Sep 26, 2023
Maintainer

Thanks @ksyblast for your input. We have actually opened an issue for the problem you experienced (#2863).

We are actually making several changes to the way we control both shutdown and startup of the Postgres cluster. All of them will be in the next 1.21.0 release (and related minor updates), primarily #2848 #2847 and #2846.

Those settings are described in the new "Instance manager" source page.

0 replies

Navigation Menu

Repository navigation

long switchover with low CPU requests #2860

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 1 comment

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Select a reply

Uh oh!

long switchover with low CPU requests #2860

Uh oh!

Uh oh!

ksyblast Sep 25, 2023

Replies: 1 comment

Uh oh!

Uh oh!

gbartolini Sep 26, 2023 Maintainer

ksyblast
Sep 25, 2023

gbartolini
Sep 26, 2023
Maintainer