Re: Postgrsql blocked for more than 120 s

Hi, I have a problem with my slave postgresql instance. During normal operations databaseis locked and in syslog I see stacktrace:

Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.289110] INFO: task postgres:1172 blocked for more than 120 seconds.
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.292137]       Not tainted 5.19.0-1028-aws #29~22.04.1-Ubuntu
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.295239] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299360] task:postgres        state:D stack:    0 pid: 1172 ppid:  1133 flags:0x00000004
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299366] Call Trace:
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299369]  <TASK>
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299373]  __schedule+0x254/0x5a0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299381]  schedule+0x5d/0x100
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299385]  io_schedule+0x46/0x80
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299389]  blk_mq_get_tag+0x117/0x300
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299394]  ? destroy_sched_domains_rcu+0x40/0x40
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299399]  __blk_mq_alloc_requests+0xc4/0x1e0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299404]  blk_mq_get_new_requests+0xcc/0x190
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299408]  blk_mq_submit_bio+0x1eb/0x450
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299411]  __submit_bio+0xf6/0x190
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299414]  ? kmem_cache_alloc+0x1a6/0x2f0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299419]  __submit_bio_noacct+0x81/0x1f0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299422]  submit_bio_noacct_nocheck+0x104/0x1c0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299425]  ? ext4_inode_block_valid+0x1d/0x40
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299430]  submit_bio_noacct+0x1b9/0x600
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299433]  submit_bio+0x40/0xf0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299437]  ext4_mpage_readpages+0x254/0xc20
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299441]  ? xas_load+0x1f/0x100
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299447]  ? __filemap_add_folio+0x1ca/0x540
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299452]  ext4_readahead+0x3f/0x50
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299455]  read_pages+0x7b/0x2e0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299459]  page_cache_ra_unbounded+0x12d/0x180
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299462]  force_page_cache_ra+0xc5/0x100
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299466]  generic_fadvise+0x19d/0x280
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299469]  ksys_fadvise64_64+0x9f/0xb0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299471]  ? syscall_trace_enter.constprop.0+0xb5/0x1a0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299475]  __x64_sys_fadvise64+0x1c/0x30
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299478]  do_syscall_64+0x5c/0x90
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299482]  ? exc_page_fault+0x92/0x190
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299485]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299489] RIP: 0033:0x7f7358c993c2
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299493] RSP: 002b:00007ffd448a8a88 EFLAGS: 00000206 ORIG_RAX: 00000000000000dd
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299498] RAX: ffffffffffffffda RBX: 0000000000000383 RCX: 00007f7358c993c2
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299501] RDX: 0000000000002000 RSI: 00000000099a0000 RDI: 0000000000000389
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299503] RBP: 0000000000002000 R08: 0000000000000002 R09: 0000000000000000

Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299506] R10: 0000000000000003 R11: 0000000000000206 R12: 00000000099a0000
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299508] R13: 000000000a000010 R14: 0000000001504cd0 R15: 00007ffd448a8ad0
Jul 16 22:34:12 ec1-prd-postgresan-2 kernel: [ 1331.299514]  </TASK>
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.119882] INFO: task postgres:1172 blocked for more than 241 seconds.
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.122832]       Not tainted 5.19.0-1028-aws #29~22.04.1-Ubuntu
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.128443] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132098] task:postgres        state:D stack:    0 pid: 1172 ppid:  1133 flags:0x00000004
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132106] Call Trace:
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132109]  <TASK>
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132113]  __schedule+0x254/0x5a0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132121]  schedule+0x5d/0x100
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132125]  io_schedule+0x46/0x80
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132129]  blk_mq_get_tag+0x117/0x300
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132134]  ? destroy_sched_domains_rcu+0x40/0x40
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132143]  __blk_mq_alloc_requests+0xc4/0x1e0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132148]  blk_mq_get_new_requests+0xcc/0x190
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132153]  blk_mq_submit_bio+0x1eb/0x450
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132156]  __submit_bio+0xf6/0x190
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132159]  ? kmem_cache_alloc+0x1a6/0x2f0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132163]  __submit_bio_noacct+0x81/0x1f0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132166]  submit_bio_noacct_nocheck+0x104/0x1c0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132169]  ? ext4_inode_block_valid+0x1d/0x40
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132174]  submit_bio_noacct+0x1b9/0x600
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132176]  submit_bio+0x40/0xf0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132179]  ext4_mpage_readpages+0x254/0xc20
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132183]  ? xas_load+0x1f/0x100
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132188]  ? __filemap_add_folio+0x1ca/0x540
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132193]  ext4_readahead+0x3f/0x50

Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132198]  read_pages+0x7b/0x2e0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132203]  page_cache_ra_unbounded+0x12d/0x180
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132209]  force_page_cache_ra+0xc5/0x100
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132213]  generic_fadvise+0x19d/0x280
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132217]  ksys_fadvise64_64+0x9f/0xb0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132220]  ? syscall_trace_enter.constprop.0+0xb5/0x1a0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132224]  __x64_sys_fadvise64+0x1c/0x30
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132227]  do_syscall_64+0x5c/0x90
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132232]  ? exc_page_fault+0x92/0x190
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132237]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132241] RIP: 0033:0x7f7358c993c2
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132245] RSP: 002b:00007ffd448a8a88 EFLAGS: 00000206 ORIG_RAX: 00000000000000dd
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132251] RAX: ffffffffffffffda RBX: 0000000000000383 RCX: 00007f7358c993c2
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132254] RDX: 0000000000002000 RSI: 00000000099a0000 RDI: 0000000000000389
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132256] RBP: 0000000000002000 R08: 0000000000000002 R09: 0000000000000000
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132258] R10: 0000000000000003 R11: 0000000000000206 R12: 00000000099a0000
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132261] R13: 000000000a000010 R14: 0000000001504cd0 R15: 00007ffd448a8ad0
Jul 16 22:36:13 ec1-prd-postgresan-2 kernel: [ 1452.132267]  </TASK>

My postgres 15.3 is compiled as docker image in alpine 3.17 with flags:

./configure --prefix=${PG_DIR} --exec-prefix=${PG_DIR} --enable-integer-datetimes --enable-thread-safety --disable-rpath --with-uuid=e2fs --with-gnu-ld --with-pgport=5432 --with-system-tzdata=/usr/share/zoneinfo --with-llvm --with-gssapi --with-ldap --with-icu --with-tcl --with-perl --with-python --with-pam --with-openssl --with-libxml --with-libxslt --with-includes=${PG_DIR}/include --with-libs=${PG_DIR}/lib

this is my postgresql.conf:

listen_addresses = '*'
port = 5432
max_connections = 1000
unix_socket_directories = '/opt/pg/data'
superuser_reserved_connections = 3
shared_buffers = 7GB
temp_buffers = 32MB
max_prepared_transactions = 100
work_mem = 1146kB
maintenance_work_mem = 1792MB
max_stack_depth = 4MB
dynamic_shared_memory_type = posix
hot_standby = on
hot_standby_feedback = on
primary_conninfo='host=192.168.1.16 port=5432 user=user'
primary_slot_name='slot1'
promote_trigger_file='/opt/pg/data/MasterNow'
effective_cache_size = 21GB
log_destination = 'stderr'
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql-%a.log'
log_truncate_on_rotation = on
log_rotation_age = 1440
log_rotation_size = 0
log_min_duration_statement = 60000
log_checkpoints = on
log_autovacuum_min_duration = 3000
log_line_prefix = '%m [%p] - [%a - %u - %d] [%h] : %e'
stats_fetch_consistency = 'cache'
datestyle = 'iso, dmy'
default_text_search_config = 'pg_catalog.simple'
jit = on
jit_above_cost = 100000
jit_debugging_support = off
jit_dump_bitcode = off
jit_expressions = on
jit_inline_above_cost = 500000
jit_optimize_above_cost = 500000
jit_profiling_support = off
jit_provider = llvmjit
jit_tuple_deforming = on
max_worker_processes = 8
max_parallel_workers_per_gather = 4
max_parallel_workers = 4
max_parallel_maintenance_workers = 2
default_statistics_target = 100
synchronous_commit = off
random_page_cost = 1.1
effective_io_concurrency = 200
shared_preload_libraries = 'auto_explain,pg_stat_statements'
# Increase the max size of the query strings Postgres records
track_activity_query_size = 10000
# Track statements generated by stored procedures as well
pg_stat_statements.track = all

Pleas give ma a information where is the problem?

Regards

Bogdan