Question posted in 
Last night we did a vacuum full operation on partitioned tables.
A few hours after the vacuum full, I found cpu rising with an unknown session called “startup” when queried by top command.
We cannot conclude that this is related to vacuum full.
But, I checked that startup was taken after autuvacuum ran in the pg_catalog table. such as pg_class,pg_attribute.
this is not even left in postgresql.log, and I couldn’t get accurate information about this by searching.
We are using the postgresql15.3 version
And This is our top_total log by System activity report
top - 10:35:09 up 33 days, 23:48, 12 users, load average: 240.31, 111.23, 48.79
PID PPID USER VIRT RES SHR %CPU %MEM COMMAND
2979079 2931746 postgres 17.7g 1.1g 1.1g 18.6 3.8 postgres: startup
2977705 2931746 postgres 17.7g 1.1g 1.1g 11.8 3.8 postgres: startup
2978636 2931746 postgres 17.7g 1.1g 1.1g 6.9 3.8 postgres: startup
2979407 2931746 postgres 17.7g 1.1g 1.1g 6.9 3.8 postgres: startup
2984501 2931746 postgres 17.8g 711652 668320 6.9 2.2 postgres: SELECT
74 2 root 0 0 0 5.9 0.0 [kcompactd0]
2584 1 root 170536 35472 2464 5.9 0.1 /usr/local/aegis/aegis_client/aegis_11_83/AliYunDunMonitor
2976958 2931746 postgres 17.6g 1.1g 1.1g 4.9 3.8 postgres: startup
2977028 2931746 postgres 17.6g 1.1g 1.1g 4.9 3.8 postgres: startup
2978115 2931746 postgres 17.7g 1.1g 1.1g 4.9 3.8 postgres: startup
2979350 2931746 postgres 17.7g 1.1g 1.1g 4.9 3.8 postgres: startup
2980154 2931746 postgres 17.7g 1.1g 1.1g 4.9 3.8 postgres: startup
2980160 2931746 postgres 17.7g 1.1g 1.1g 4.9 3.8 postgres: startup
2980192 2931746 postgres 17.7g 1.1g 1.1g 4.9 3.8 postgres: startup
2981112 2931746 postgres 17.7g 662892 659756 4.9 2.1 postgres: startup
2981319 2931746 postgres 17.7g 663528 660392 4.9 2.1 postgres: startup
2984821 2931746 postgres 17.8g 318768 307876 4.9 1.0 postgres: SELECT
2986477 2931746 postgres 17.8g 118200 112736 4.9 0.4 postgres: SELECT
2848228 1 root 32468 15656 6704 3.9 0.0 /usr/bin/python3 /sbin/iotop -botkP -n 3600
2977197 2931746 postgres 17.6g 1.1g 1.1g 3.9 3.8 postgres: startup
2978532 2931746 postgres 17.7g 1.1g 1.1g 3.9 3.8 postgres: startup
2978662 2931746 postgres 17.7g 1.1g 1.1g 3.9 3.8 postgres: startup
2981088 2931746 postgres 17.7g 663464 660328 3.9 2.1 postgres: startup
2982154 2931746 postgres 17.7g 663468 660328 3.9 2.1 postgres: startup
2982402 2931746 postgres 17.7g 662888 659748 3.9 2.1 postgres: startup
2983158 2931746 postgres 17.7g 663468 660328 3.9 2.1 postgres: startup
2983260 2931746 postgres 17.7g 663468 660328 3.9 2.1 postgres: startup
2984317 2931746 postgres 17.8g 447248 415620 3.9 1.4 postgres: SELECT
2984643 2931746 postgres 17.8g 445384 418132 3.9 1.4 postgres: BIND
2986410 2931746 postgres 17.8g 127636 122008 3.9 0.4 postgres: SELECT
2848231 1 root 12540 9264 1800 2.9 0.0 pidstat -u -l 1 3600
2976372 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976379 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976401 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976469 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976881 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976884 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976886 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976894 2931746 postgres 17.6g 1.1g 1.1g 2.9 3.8 postgres: startup
2976896 2931746 postgres 17.8g 1.2g 1.2g 2.9 4.1 postgres: idleWe would like to know what "start up" means and why it happened and how we should act on this situation.
I look forward to your prompt reply.
Thank you.
mean of startup session
how to resolve cpu rising with startup session
relation of startup and vacuum full
relation of startup and autovacuum
++add
I had a vacuum full on the pg_class table last night. Even now, start-up sessions are found intermittently.
We found that it took a long time in "connection authorized" when we re-proceded the vacuum for the table that did the vacuum full.
This is a detailed log
2024-06-24 14:40:30.875 KST [3620][][]DEBUG: forked new backend, pid=243980 socket=9
2024-06-24 14:40:30.876 KST [3620][][]DEBUG: forked new backend, pid=243981 socket=9
2024-06-24 14:40:30.876 KST [243980][[unknown]][mig-pg-arm-241-f.eccenter.com]LOG: connection received: host=mig-pg-arm-241-f.eccenter.com port=16842
2024-06-24 14:40:30.877 KST [243980][][mig-pg-arm-241-f.eccenter.com]DEBUG: InitPostgres
2024-06-24 14:40:30.877 KST [243980][][mig-pg-arm-241-f.eccenter.com]DEBUG: my backend ID is 9
2024-06-24 14:40:30.877 KST [243981][[unknown]][mig-pg-arm-241-f.eccenter.com]LOG: connection received: host=mig-pg-arm-241-f.eccenter.com port=16854
2024-06-24 14:40:30.877 KST [243980][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:30.877 KST [243981][][mig-pg-arm-241-f.eccenter.com]DEBUG: InitPostgres
2024-06-24 14:40:30.877 KST [243981][][mig-pg-arm-241-f.eccenter.com]DEBUG: my backend ID is 10
2024-06-24 14:40:30.877 KST [243980][][mig-pg-arm-241-f.eccenter.com]LOG: connection authorized: user= database=postgres application_name=psql
2024-06-24 14:40:30.877 KST [243981][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:30.878 KST [243981][][mig-pg-arm-241-f.eccenter.com]LOG: connection authorized: user= database=postgres application_name=psql
2024-06-24 14:40:31.016 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.016 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: duration: 172.742 ms
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: statement: VACUUM pg_catalog.pg_class;
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: parse tree:
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]STATEMENT: VACUUM pg_catalog.pg_class;
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: rewritten parse tree:
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]STATEMENT: VACUUM pg_catalog.pg_class;
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.017 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.068 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: launched 0 parallel vacuum workers for index cleanup (planned: 2)
2024-06-24 14:40:31.078 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0 (used)
2024-06-24 14:40:31.078 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.419 KST [237330][][mig-pg-arm-241-f.eccenter.com]STATEMENT: VACUUM pg_catalog.pg_constraint;
2024-06-24 14:40:31.419 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: rewritten parse tree:
2024-06-24 14:40:31.419 KST [237330][][mig-pg-arm-241-f.eccenter.com]STATEMENT: VACUUM pg_catalog.pg_constraint;
2024-06-24 14:40:31.419 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.419 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.425 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: launched 0 parallel vacuum workers for index cleanup (planned: 2)
2024-06-24 14:40:31.426 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.426 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.426 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.426 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.584 KST [237330][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:31.584 KST [237330][][mig-pg-arm-241-f.eccenter.com]LOG: duration: 164.727 ms
2024-06-24 14:40:33.034 KST [243981][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:33.034 KST [243980][][mig-pg-arm-241-f.eccenter.com]DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:33.035 KST [243981][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:33.035 KST [243980][][mig-pg-arm-241-f.eccenter.com]DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-06-24 14:40:33.035 KST [243981][][mig-pg-arm-241-f.eccenter.com]LOG: statement: select count(*) from sync.exp_code where code = 'test0' and table_name = 'SYNC1';
2024-06-24 14:40:33.035 KST [243980][][mig-pg-arm-241-f.eccenter.com]LOG: statement: select count(*) from sync.exp_code where code = 'test2' and table_name = 'SYNC1';
2
Answers
The startup process is the process that performs crash recovery after a crash. So your database must have crashed. Examine the logs for the cause.
Based on your description, the problem may well have been that the database ran out of disk space during
VACUUM (FULL). If PostgreSQL cannot create a new WAL (transaction log) segment, for example because it is out of disk space, it will crash and try to restart.There are two different things using the title ‘startup’. One is the name of the process which handles crash recovery and hot standby. This is what I first assumed you had, as it just like your title "postgres: startup". But there should only be one (at most) of these processes at at time, not dozens.
The other thing is a phase a client backend goes through very briefly after authentication finished but before it is ready to process commands from the client. In my hands this looks more like "postgres: jjanes jjanes [local] startup", where the extra tokens correspond to the username, database, and IP the backend is servicing. Based on the additional information you provided, I think this is the thing you are seeing, although I don’t know why it is using the more concise format for the title string rather than the longer one I see. During this phase it must be consulting the system catalogs, and if doing this is very slow because of extreme bloat or a missing index or something, it could explain many processes piling up at this stage. But I don’t know exactly what all catalogs would be consulted at this point.
Another possibility is that a catalog table is not bloated or slow, but just locked, which will block new connections from starting up at all. For example, if one session has locked the "pg_database" table in access exclusively mode, no other session will be able to startup until the lock is released. Now in my hands the process title looks like "postgres: jjanes jjanes [local] startup waiting" when this is happening, but since your process titles work differently than mine do I guess it shouldn’t be surprising that you see something slightly different.