Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Strange behavior while running pgbench: increasing connections and no tps if the run is interrupted and resumed #503

Open
fluca1978 opened this issue Feb 27, 2025 · 0 comments
Open

Strange behavior while running pgbench: increasing connections and no tps if the run is interrupted and resumed #503

fluca1978 opened this issue Feb 27, 2025 · 0 comments
Labels
bug Something isn't working

Comments

@fluca1978
Copy link
Collaborator

This has been observer on head 400e019 while testing #456 .
The operating system is Rocky Linux 9, PostgreSQL 16.6 on localhost. The application has been compiled with clang.

In short: running pgbench several times thru pgagroal works as expected unless it is keyboard interrupted, and from then ongoing the connections keep rising without producing "results".

The pgagroal_databases.conf contains:

% cat /etc/pgagroal/pgagroal_databases.conf
# DATABASE USER MAX INITIAL MIN
 pgbench pgbench 20 5  5

so no more than 20 connections, even if in the end they keep increasing over the limit.

First run (OK)

This completes just as expected:

% psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && time /usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T  60 -h localhost -p 54333 -U pgbench pgbench && psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && pgagroal-cli status details
  pid  | usename  | state  |                                            query                             
               
-------+----------+--------+------------------------------------------------------------------------------
---------------
 24413 | pgbench  | idle   | DISCARD ALL;
 24414 | pgbench  | idle   | DISCARD ALL;
 24415 | pgbench  | idle   | DISCARD ALL;
 24416 | pgbench  | idle   | DISCARD ALL;
 24417 | pgbench  | idle   | DISCARD ALL;
 24419 | postgres | active | select pid, usename, state, query from pg_stat_activity where datname = curre
nt_database();
(6 rows)

pgbench (16.6)
progress: 10.0 s, 1702.3 tps, lat 11.525 ms stddev 6.345, 0 failed
progress: 20.0 s, 1729.5 tps, lat 11.564 ms stddev 2.359, 0 failed
progress: 30.0 s, 1716.5 tps, lat 11.648 ms stddev 2.235, 0 failed
progress: 40.0 s, 1714.1 tps, lat 11.665 ms stddev 2.408, 0 failed
progress: 50.0 s, 1769.7 tps, lat 11.299 ms stddev 2.290, 0 failed
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: simple
number of clients: 20
number of threads: 20
maximum number of tries: 1
duration: 60 s
number of transactions actually processed: 103519
number of failed transactions: 0 (0.000%)
latency average = 11.555 ms
latency stddev = 3.336 ms
initial connection time = 183.264 ms
tps = 1730.345541 (without initial connection time)
/usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T 60 -h localhost -p 54333  2.64s user 3.30s system 9% cpu 1:01.35 total
  pid  | usename  | state  |                                            query                             
               
-------+----------+--------+------------------------------------------------------------------------------
---------------
 24413 | pgbench  | idle   | END;
 24414 | pgbench  | idle   | DISCARD ALL;
 24415 | pgbench  | idle   | DISCARD ALL;
 24416 | pgbench  | idle   | END;
 24417 | pgbench  | idle   | END;
 24466 | pgbench  | idle   | END;
 24469 | pgbench  | idle   | END;
 24470 | pgbench  | idle   | DISCARD ALL;
 24465 | pgbench  | idle   | END;
 24472 | pgbench  | idle   | END;
 24467 | pgbench  | idle   | END;
 24471 | pgbench  | idle   | END;
 24473 | pgbench  | idle   | END;
 24468 | pgbench  | idle   | END;
 24464 | pgbench  | idle   | END;
 24475 | pgbench  | idle   | END;
 24476 | pgbench  | idle   | END;
 24474 | pgbench  | idle   | END;
 24477 | pgbench  | idle   | DISCARD ALL;
 24478 | pgbench  | idle   | DISCARD ALL;
 24485 | postgres | active | select pid, usename, state, query from pg_stat_activity where datname = curre
nt_database();
(21 rows)

Header: 
  ClientVersion: 2.0.0
  Command: status-details
  Compression: none
  Encryption: none
  Output: text
  Timestamp: 20250227113449
Outcome: 
  Status: true
  Time: 00:00:00
Request: {}
Response: 
  ActiveConnections: 0
  Connections: 
    - AppName: ''
      Database: pgbench
      FD: 15
      PID: -1
      StartTime: 1740652420
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 16
      PID: -1
      StartTime: 1740652420
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 17
      PID: -1
      StartTime: 1740652420
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 18
      PID: -1
      StartTime: 1740652420
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 19
      PID: -1
      StartTime: 1740652420
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 33
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 24
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 22
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 32
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 23
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 34
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 31
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 25
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 28
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 20
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 29
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 27
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 21
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 30
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
    - AppName: ''
      Database: pgbench
      FD: 26
      PID: -1
      StartTime: 1740652428
      Timestamp: 1740652488
      Username: pgbench
  Databases: 
    - Database: *
      Enabled: true
  Limits: 
    - ActiveConnections: 0
      Database: pgbench
      InitialConnections: 5
      MaxConnections: 20
      MinConnections: 5
      Username: pgbench
  MaxConnections: 20
  NumberOfServers: 1
  ServerVersion: 2.0.0
  Servers: 
    - Host: 127.0.0.1
      Port: 5432
      Server: rachel
      State: Primary
  Status: Running
  TotalConnections: 20

Second run (manually inrettuped)

This is keyboard interrupted

% psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && time /usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T  60 -h localhost -p 54333 -U pgbench pgbench && psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && pgagroal-cli status details
  pid  | usename  | state  |                                            query                             
               
-------+----------+--------+------------------------------------------------------------------------------
---------------
 24413 | pgbench  | idle   | DISCARD ALL;
 24414 | pgbench  | idle   | DISCARD ALL;
 24415 | pgbench  | idle   | DISCARD ALL;
 24416 | pgbench  | idle   | DISCARD ALL;
 24417 | pgbench  | idle   | DISCARD ALL;
 24466 | pgbench  | idle   | DISCARD ALL;
 24469 | pgbench  | idle   | DISCARD ALL;
 24470 | pgbench  | idle   | DISCARD ALL;
 24465 | pgbench  | idle   | DISCARD ALL;
 24472 | pgbench  | idle   | DISCARD ALL;
 24467 | pgbench  | idle   | DISCARD ALL;
 24471 | pgbench  | idle   | DISCARD ALL;
 24473 | pgbench  | idle   | DISCARD ALL;
 24468 | pgbench  | idle   | DISCARD ALL;
 24464 | pgbench  | idle   | DISCARD ALL;
 24475 | pgbench  | idle   | DISCARD ALL;
 24476 | pgbench  | idle   | DISCARD ALL;
 24474 | pgbench  | idle   | DISCARD ALL;
 24477 | pgbench  | idle   | DISCARD ALL;
 24478 | pgbench  | idle   | DISCARD ALL;
 24491 | postgres | active | select pid, usename, state, query from pg_stat_activity where datname = curre
nt_database();
(21 rows)

pgbench (16.6)
progress: 10.0 s, 1674.0 tps, lat 11.713 ms stddev 3.489, 0 failed
progress: 20.0 s, 1762.2 tps, lat 11.346 ms stddev 2.253, 0 failed
^C
/usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T 60 -h localhost -p 54333  0.96s user 1.09s system 9% cpu 20.793 total

Third run (problematic)

Here the problem is that :tps reported are zero, hence probably pgbench does not honor the -T flag and runs forever, without reporting any particular error. The pgagroal logs do not showing nothing at all during this execution. It seems that the connections are recycled but are in a state "unusable".

% psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && time /usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T  60 -h localhost -p 54333 -U pgbench pgbench && psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && pgagroal-cli status details
  pid  | usename  |        state        |                                                  query          
                                         
-------+----------+---------------------+-----------------------------------------------------------------
-----------------------------------------
 24413 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + 683 WHERE bid 
= 1;
 24414 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1564 WHERE tid
 = 7;
 24415 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -934 WHERE bid
 = 1;
 24416 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -3933 WHERE bi
d = 1;
 24417 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -631 WHERE tid 
= 1;
 24466 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 79637;
 24469 | pgbench  | idle in transaction | UPDATE pgbench_accounts SET abalance = abalance + 3366 WHERE aid
 = 89946;
 24470 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 2003 WHERE tid 
= 9;
 24465 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -1855 WHERE bi
d = 1;
 24472 | pgbench  | idle                | END;
 24467 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -3006 WHERE bi
d = 1;
 24471 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 3337 WHERE tid 
= 3;
 24473 | pgbench  | idle in transaction | INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES
 (3, 1, 71296, 2341, CURRENT_TIMESTAMP);
 24468 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 21339;
 24464 | pgbench  | idle in transaction | UPDATE pgbench_tellers SET tbalance = tbalance + 2803 WHERE tid 
= 4;
 24475 | pgbench  | idle                | END;
 24476 | pgbench  | idle in transaction | UPDATE pgbench_accounts SET abalance = abalance + 3615 WHERE aid
 = 69843;
 24474 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 37254;
 24477 | pgbench  | idle                | END;
 24478 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -1003 WHERE bi
d = 1;
 24550 | postgres | active              | select pid, usename, state, query from pg_stat_activity where da
tname = current_database();
(21 rows)

pgbench (16.6)
progress: 10.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 20.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 30.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 40.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 50.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 60.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 70.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 80.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 90.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 100.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 110.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 120.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
^C
/usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T 60 -h localhost -p 54333  0.01s user 0.01s system 0% cpu 2:05.89 total

Fourth run (problematic)

Even after a pgagroal-cli flush the situation does not improve, i.e., the tps is still zero. Moreover, the number of connections reported on the PostgreSQL side is increasing over the max_connections configured on the datbaase limit.

~% pgagroal-cli flush
Header: 
  ClientVersion: 2.0.0
  Command: flush
  Compression: none
  Encryption: none
  Output: text
  Timestamp: 20250227114004
Outcome: 
  Status: true
  Time: 00:00:00
Request: 
  Database: *
  Mode: 1





% psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && time /usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T  60 -h localhost -p 54333 -U pgbench pgbench && psql -U postgres -c "select pid, usename, state, query from pg_stat_activity where datname = current_database();" pgbench && pgagroal-cli status details
  pid  | usename  |        state        |                                                  query          
                                         
-------+----------+---------------------+-----------------------------------------------------------------
-----------------------------------------
 24413 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + 683 WHERE bid 
= 1;
 24414 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1564 WHERE tid
 = 7;
 24415 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -934 WHERE bid
 = 1;
 24416 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -3933 WHERE bi
d = 1;
 24417 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -631 WHERE tid 
= 1;
 24466 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 79637;
 24469 | pgbench  | idle in transaction | UPDATE pgbench_accounts SET abalance = abalance + 3366 WHERE aid
 = 89946;
 24470 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 2003 WHERE tid 
= 9;
 24465 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -1855 WHERE bi
d = 1;
 24472 | pgbench  | idle                | END;
 24467 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -3006 WHERE bi
d = 1;
 24471 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 3337 WHERE tid 
= 3;
 24473 | pgbench  | idle in transaction | INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES
 (3, 1, 71296, 2341, CURRENT_TIMESTAMP);
 24468 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 21339;
 24464 | pgbench  | idle in transaction | UPDATE pgbench_tellers SET tbalance = tbalance + 2803 WHERE tid 
= 4;
 24475 | pgbench  | idle                | END;
 24476 | pgbench  | idle in transaction | UPDATE pgbench_accounts SET abalance = abalance + 3615 WHERE aid
 = 69843;
 24474 | pgbench  | idle in transaction | SELECT abalance FROM pgbench_accounts WHERE aid = 37254;
 24477 | pgbench  | idle                | END;
 24478 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -1003 WHERE bi
d = 1;
 24554 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1519 WHERE tid
 = 1;
 24594 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 1387 WHERE tid 
= 8;
 24596 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1972 WHERE tid
 = 1;
 24597 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -2590 WHERE bi
d = 1;
 24598 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 838 WHERE tid =
 6;
 24599 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 1866 WHERE tid 
= 8;
 24595 | pgbench  | active              | UPDATE pgbench_branches SET bbalance = bbalance + -3107 WHERE bi
d = 1;
 24600 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -4513 WHERE tid
 = 8;
 24602 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -96 WHERE tid =
 2;
 24601 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 1911 WHERE tid 
= 3;
 24604 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -3768 WHERE tid
 = 6;
 24603 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 217 WHERE tid =
 1;
 24607 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 506 WHERE tid =
 1;
 24605 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 3905 WHERE tid 
= 4;
 24608 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1868 WHERE tid
 = 9;
 24606 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 4641 WHERE tid 
= 5;
 24609 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 4295 WHERE tid 
= 6;
 24610 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + -1147 WHERE tid
 = 7;
 24611 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 3278 WHERE tid 
= 7;
 24612 | pgbench  | active              | UPDATE pgbench_tellers SET tbalance = tbalance + 2996 WHERE tid 
= 9;
 24632 | postgres | active              | select pid, usename, state, query from pg_stat_activity where da
tname = current_database();
 24628 |          | active              | autovacuum: VACUUM public.pgbench_branches
(42 rows)

pgbench (16.6)
progress: 10.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 20.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 30.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 40.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 50.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 60.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 70.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 80.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 90.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
^C
/usr/pgsql-16/bin/pgbench -j 20 -c 20 -l -n -P 10 -T 60 -h localhost -p 54333  0.01s user 0.01s system 0% cpu 1:33.36 total
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@fluca1978