Out of memory error on automatic vacuum
Hi all, This morning I was checking postgres servers logs, looking for errors (we've recently upgraded them and changed default config) and long running queries when I found one of the servers had really big logs since yesterday. It was giving the error of this mail's subject: out of memory, failed on request of size XXX on automatic vacuum of table YYY. A quick search revealed me some postgresql-lists messages talking about work_mem and shared_buffers configuration options, some kernel config options too. Although all of them were messages from several years ago, I decided to cut my shared_buffers configured value and restart server: now it looks like error is gone. But I'd like to understand what's beyond the logged error (it's really long and refers to things about inner functionalities that I'm missing), how to detect what config options are possibly conflicting and, most important, I want to know if I've solved it right. -- Logged error (one of them) ==> Original log is in spanish and I've translated myself. I've replaced my database objects names TopMemoryContext: 77568 total in 5 blocks; 15612 free (5 chunks); 61956 used TopTransactionContext: 8192 total in 1 blocks; 7604 free (40 chunks); 588 used TOAST to main relid map: 24576 total in 2 blocks; 13608 free (3 chunks); 10968 used AV worker: 8192 total in 1 blocks; 3228 free (6 chunks); 4964 used * Autovacuum Portal: 0 total in 0 blocks; 0 free (0 chunks); 0 used **=> Is this line the one that points to the task that has run of of memory?* Vacuum: 8192 total in 1 blocks; 8132 free (0 chunks); 60 used Operator class cache: 8192 total in 1 blocks; 4420 free (0 chunks); 3772 used smgr relation table: 8192 total in 1 blocks; 316 free (0 chunks); 7876 used TransactionAbortContext: 32768 total in 1 blocks; 32748 free (0 chunks); 20 used Portal hash: 8192 total in 1 blocks; 3460 free (0 chunks); 4732 used PortalMemory: 0 total in 0 blocks; 0 free (0 chunks); 0 used Relcache by OID: 8192 total in 1 blocks; 1884 free (0 chunks); 6308 used CacheMemoryContext: 516096 total in 6 blocks; 234136 free (5 chunks); 281960 used : 1024 total in 1 blocks; 476 free (0 chunks); 548 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used : 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_index_indrelid_index: 1024 total in 1 blocks; 676 free (0 chunks); 348 used pg_attrdef_adrelid_adnum_index: 1024 total in 1 blocks; 604 free (0 chunks); 420 used pg_db_role_setting_databaseid_rol_index: 1024 total in 1 blocks; 644 free (0 chunks); 380 used pg_opclass_am_name_nsp_index: 1024 total in 1 blocks; 476 free (0 chunks); 548 used pg_foreign_data_wrapper_name_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_enum_oid_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_class_relname_nsp_index: 1024 total in 1 blocks; 644 free (0 chunks); 380 used pg_foreign_server_oid_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_statistic_relid_att_inh_index: 1024 total in 1 blocks; 476 free (0 chunks); 548 used pg_cast_source_target_index: 1024 total in 1 blocks; 644 free (0 chunks); 380 used pg_language_name_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_transform_oid_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_collation_oid_index: 1024 total in 1 blocks; 716 free (0 chunks); 308 used pg_amop_fam_strat_index: 1024 total in 1 blocks; 476 free (0 chunk
Re: Out of memory error on automatic vacuum
On Mon, Nov 18, 2019 at 12:41:27PM +0100, Ekaterina Amez wrote: Hi all, This morning I was checking postgres servers logs, looking for errors (we've recently upgraded them and changed default config) and long running queries when I found one of the servers had really big logs since yesterday. It was giving the error of this mail's subject: out of memory, failed on request of size XXX on automatic vacuum of table YYY. A quick search revealed me some postgresql-lists messages talking about work_mem and shared_buffers configuration options, some kernel config options too. Although all of them were messages from several years ago, I decided to cut my shared_buffers configured value and restart server: now it looks like error is gone. But I'd like to understand what's beyond the logged error (it's really long and refers to things about inner functionalities that I'm missing), how to detect what config options are possibly conflicting and, most important, I want to know if I've solved it right. Unfortunately that's hard to say, without further data. The "out of memory" errors simply mean we called malloc() and it returned NULL, because the kernel was unable to provide the memory. There probably were other processes using all the available RAM (the limit depends on various config values, e.g. overcommit). What were these processes doing we don't know :-( For example, there might be multiple complex queries, allocating several work_mem each, using quite a bit of memory. Or there might be a runaway query doing HashAgg allocating much more memory than predicted. Or maybe there was running a completely separate job (say, backup) allocating a lot of memory or dirtying data in page cache. There are countless options what might have happened. The memory context stats are nice, but it's just a snapshot from one particular process, and it does not seem very interesting (the total is just ~1MB, so nothing extreme). We still don't know what else was running. Lowering shared_buffers certainly does reduce the memory pressure in general, i.e. there is 1GB of work for use by processes. It may be sufficient, hard to guess. I don't know if work_mem 64MB is too low, becuase it depends on what queries you're running etc. But you probably don't wat to increase that, as it allows processes to use more memory when executing queries, i.e. it increases memory pressure and makes OOM more likely. So you need to watch system monitoring, see how much memory is being used (excluding page cache) and consider reducing work_mem and/or max_connections if it's too close. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Out of memory error on automatic vacuum
El 18/11/19 a las 13:25, Tomas Vondra escribió: On Mon, Nov 18, 2019 at 12:41:27PM +0100, Ekaterina Amez wrote: Hi all, This morning I was checking postgres servers logs, looking for errors (we've recently upgraded them and changed default config) and long running queries when I found one of the servers had really big logs since yesterday. It was giving the error of this mail's subject: out of memory, failed on request of size XXX on automatic vacuum of table YYY. A quick search revealed me some postgresql-lists messages talking about work_mem and shared_buffers configuration options, some kernel config options too. Although all of them were messages from several years ago, I decided to cut my shared_buffers configured value and restart server: now it looks like error is gone. But I'd like to understand what's beyond the logged error (it's really long and refers to things about inner functionalities that I'm missing), how to detect what config options are possibly conflicting and, most important, I want to know if I've solved it right. Unfortunately that's hard to say, without further data. The "out of memory" errors simply mean we called malloc() and it returned NULL, because the kernel was unable to provide the memory. This (kernel unable to provide memory) was because no more RAM was available to allocate? It was because PG process did not have more memory assigned ready to use? Or is something unknown because it depends on the situations where the error is thrown? There probably were other processes using all the available RAM (the limit depends on various config values, e.g. overcommit). What were these processes doing we don't know :-( For example, there might be multiple complex queries, allocating several work_mem each, using quite a bit of memory. Or there might be a runaway query doing HashAgg allocating much more memory than predicted. Or maybe there was running a completely separate job (say, backup) allocating a lot of memory or dirtying data in page cache. I've looked at cron and I've seen a scheduled process that finished a bit before the error began to log (o couple of minutes or so). Errors began on Sunday morning and this machine doesn't have much workload on work days, and less on weekend. I'll keep an eye on this log and if the problem appears again I'll try to track database activity and machine activity. There are countless options what might have happened. The memory context stats are nice, but it's just a snapshot from one particular process, and it does not seem very interesting (the total is just ~1MB, so nothing extreme). We still don't know what else was running. When you talk about ~1MB are you getting this size from log lines like this? : *1024* total in 1 blocks; 476 free (0 chunks); 548 used Lowering shared_buffers certainly does reduce the memory pressure in general, i.e. there is 1GB of work for use by processes. It may be sufficient, hard to guess. I don't know if work_mem 64MB is too low, becuase it depends on what queries you're running etc. But you probably don't wat to increase that, as it allows processes to use more memory when executing queries, i.e. it increases memory pressure and makes OOM more likely. So you need to watch system monitoring, see how much memory is being used (excluding page cache) and consider reducing work_mem and/or max_connections if it's too close. I'll do, thanks for your suggestions. regards Regards, Ekaterina
Re: Out of memory error on automatic vacuum
On Mon, Nov 18, 2019 at 03:02:16PM +0100, Ekaterina Amez wrote: El 18/11/19 a las 13:25, Tomas Vondra escribió: On Mon, Nov 18, 2019 at 12:41:27PM +0100, Ekaterina Amez wrote: Hi all, This morning I was checking postgres servers logs, looking for errors (we've recently upgraded them and changed default config) and long running queries when I found one of the servers had really big logs since yesterday. It was giving the error of this mail's subject: out of memory, failed on request of size XXX on automatic vacuum of table YYY. A quick search revealed me some postgresql-lists messages talking about work_mem and shared_buffers configuration options, some kernel config options too. Although all of them were messages from several years ago, I decided to cut my shared_buffers configured value and restart server: now it looks like error is gone. But I'd like to understand what's beyond the logged error (it's really long and refers to things about inner functionalities that I'm missing), how to detect what config options are possibly conflicting and, most important, I want to know if I've solved it right. Unfortunately that's hard to say, without further data. The "out of memory" errors simply mean we called malloc() and it returned NULL, because the kernel was unable to provide the memory. This (kernel unable to provide memory) was because no more RAM was available to allocate? It was because PG process did not have more memory assigned ready to use? Or is something unknown because it depends on the situations where the error is thrown? Not sure I understand. Whenever PostgreSQL process needs memory it requests it from the kernel by calling malloc(), and the amount of availabe RAM is limited. So when kernel can't provide more memory, it returns NULL. There probably were other processes using all the available RAM (the limit depends on various config values, e.g. overcommit). What were these processes doing we don't know :-( For example, there might be multiple complex queries, allocating several work_mem each, using quite a bit of memory. Or there might be a runaway query doing HashAgg allocating much more memory than predicted. Or maybe there was running a completely separate job (say, backup) allocating a lot of memory or dirtying data in page cache. I've looked at cron and I've seen a scheduled process that finished a bit before the error began to log (o couple of minutes or so). Errors began on Sunday morning and this machine doesn't have much workload on work days, and less on weekend. I'll keep an eye on this log and if the problem appears again I'll try to track database activity and machine activity. If it finished a couple of minutes before, it's unlikely to be the related. But hard to say, without knowing the details. There are countless options what might have happened. The memory context stats are nice, but it's just a snapshot from one particular process, and it does not seem very interesting (the total is just ~1MB, so nothing extreme). We still don't know what else was running. When you talk about ~1MB are you getting this size from log lines like this? : *1024* total in 1 blocks; 476 free (0 chunks); 548 used No, that's just one of the memory contexts (they form a tree), using only 1kB of memory. What matters is the "grand total" Grand total: 1009356 bytes in 130 blocks; 436888 free (72 chunks); 572468 used which is ~1MB. Lowering shared_buffers certainly does reduce the memory pressure in general, i.e. there is 1GB of work for use by processes. It may be sufficient, hard to guess. I don't know if work_mem 64MB is too low, becuase it depends on what queries you're running etc. But you probably don't wat to increase that, as it allows processes to use more memory when executing queries, i.e. it increases memory pressure and makes OOM more likely. So you need to watch system monitoring, see how much memory is being used (excluding page cache) and consider reducing work_mem and/or max_connections if it's too close. I'll do, thanks for your suggestions. Another thing you might do is adding a swap (if you don't have one already), as a safety. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Out of memory error on automatic vacuum
El 18/11/19 a las 15:16, Tomas Vondra escribió: Not sure I understand. Whenever PostgreSQL process needs memory it requests it from the kernel by calling malloc(), and the amount of availabe RAM is limited. So when kernel can't provide more memory, it returns NULL. Understood. If it finished a couple of minutes before, it's unlikely to be the related. But hard to say, without knowing the details. Yeah, I thought the same but for me is too much coincidence and is suspicious (or at least a thing to have in mind). No, that's just one of the memory contexts (they form a tree), using only 1kB of memory. What matters is the "grand total" Grand total: 1009356 bytes in 130 blocks; 436888 free (72 chunks); 572468 used which is ~1MB. OK, in my lack of knowledge I was understanding "memory context" as the whole message. Another thing you might do is adding a swap (if you don't have one already), as a safety. Excuse my ignorance but... swap? You mean some mechanism that prevents server to be unavailable by having a second instance running but not accesible and changing from one to the other when the main fails? (It's the best way I find to describe it, as I don't usually speak/write english). Thanks for your time.
Re: Out of memory error on automatic vacuum
On Mon, Nov 18, 2019 at 03:46:03PM +0100, Ekaterina Amez wrote: El 18/11/19 a las 15:16, Tomas Vondra escribió: Not sure I understand. Whenever PostgreSQL process needs memory it requests it from the kernel by calling malloc(), and the amount of availabe RAM is limited. So when kernel can't provide more memory, it returns NULL. Understood. If it finished a couple of minutes before, it's unlikely to be the related. But hard to say, without knowing the details. Yeah, I thought the same but for me is too much coincidence and is suspicious (or at least a thing to have in mind). No, that's just one of the memory contexts (they form a tree), using only 1kB of memory. What matters is the "grand total" Grand total: 1009356 bytes in 130 blocks; 436888 free (72 chunks); 572468 used which is ~1MB. OK, in my lack of knowledge I was understanding "memory context" as the whole message. Another thing you might do is adding a swap (if you don't have one already), as a safety. Excuse my ignorance but... swap? You mean some mechanism that prevents server to be unavailable by having a second instance running but not accesible and changing from one to the other when the main fails? (It's the best way I find to describe it, as I don't usually speak/write english). swap = space on disk, so that OS can page out unused data from RAM when there's memory pressure It's a basic sysadmin knowledge, I think. Search for mkswap. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Wrong estimations and NL Anti join poor performance
Hello colleagues - The problem description: We're moving from 9.6 to 11.5. There is a SQL code that never ends in 11.5 but works fine in 9.6. The main cause is the optimizer considers of using NL Anti join instead of Merge in 9.6. And the root cause - wrong estimation while self-joining. System environment: CentOS Linux 3.10.0-1062.4.1.el7.x86_64 x86_64 MemTotal: 16266644 kB Intel(R) Xeon(R) CPU E7-8867 v3 @ 2.50GHz HDD - unknown PostgreSQL: PostgreSQL 11.5 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-36), 64-bit shared_buffers = 1GB huge_pages = on temp_buffers = 1GB max_prepared_transactions = 128 max_connections = 500 work_mem = 256MB maintenance_work_mem = 1024MB autovacuum_work_mem = 512MB max_worker_processes = 100 max_parallel_workers_per_gather = 0 # changing this value to any others takes no effect for issue resolving max_parallel_workers = 8 checkpoint_timeout = 30min max_wal_size = 32GB min_wal_size = 8GB checkpoint_completion_target = 0.9 enable_nestloop = on# off value fixes the issue but this is wrong way random_page_cost = 4.0 effective_cache_size = 4GB default_statistics_target = 2000 Main script: -- preparation -- this table is reverted tree with tree keys position_uuid, parent_position_uuid create temporary table tmp_nsi_klp on commit drop as select k1.gid, k1.smnn_gid, k1.position_uuid, p.parent_position_uuid, k1.order_number, k1.date_start, k1.date_end, k1.is_active, coalesce(p.is_fake_series, false) as is_fake_series from nsi_klp k1 left join (select gid, unnest(parent_position_uuid) as parent_position_uuid, coalesce(array_length(parent_position_uuid, 1),0) > 1 as is_fake_series from nsi_klp where version_esklp = '2.0') p using (gid) where k1.version_esklp = '2.0' ; create unique index tmp_nsi_klp_ui on tmp_nsi_klp(gid, parent_position_uuid); analyze tmp_nsi_klp; -- working set (!!This SQL never ends in 11.5 now) create temporary table tmp_klp_replace on commit drop as select distinct on (klp_gid) * from ( select k2.gid as klp_gid, k2.smnn_gid as klp_smnn_gid, k2.position_uuidas klp_position_uuid, k2.order_number as klp_order_number, k2.is_activeas klp_is_active, k1.gid as klp_child_gid, k1.smnn_gid as klp_child_smnn_gid, k1.position_uuidas klp_child_position_uuid, k1.order_number as klp_child_order_number, k1.is_activeas klp_child_is_active from tmp_nsi_klp k1 join tmp_nsi_klp k2 on (k2.position_uuid = k1.parent_position_uuid) union all select k1.gid as klp_gid, k1.smnn_gid as klp_smnn_gid, k1.position_uuidas klp_position_uuid, k1.order_number as klp_order_number, k1.is_activeas klp_is_active, nullas klp_child_gid, nullas klp_child_smnn_gid, nullas klp_child_position_uuid, nullas klp_child_order_number, nullas klp_child_is_active from tmp_nsi_klp k1 left join tmp_nsi_klp k2 on (k1.position_uuid = k2.parent_position_uuid) left join (select position_uuid from tmp_nsi_klp where not is_fake_series group by position_uuid having count(1) > 1) klp_series on (klp_series.position_uuid = k1.position_uuid) where -- not exists(select 1 from tmp_nsi_klp k2 where k1.position_uuid = k2.parent_position_uuid) k2.gid is null-- none referenced and klp_series.position_uuid is null -- klp series with the same position_uuid ) a order by klp_gid, klp_order_number desc ; Characteristics of source table - tmp_nsi_klp: create table tmp_nsi_klp ( gid uuid NULL, -- not null by the fact smnn_gid uuid NULL, -- not null by the fact position_uuid uuid NULL,-- not null by the fact parent_position_uuid uuid NULL, order_number int8 NULL, date_start timestamp NULL, -- not null by the fact date_end timestamp NULL, is_active bool NULL,-- not null by the fact is_fake_series bool NULL-- not null by the fact ); Rows: 237279 Cols stats: https://docs.google.com/spreadsheets/d/1Ocbult13kZ64vK9nHt-_BV3EENK_ZSHFTAmR ZLISUIE/edit?usp=sharing Execution plans for problematic query - working set "create temporary table tmp_klp_replace on commit drop as": On 11.5 (option nestloop enabled): https://explain.depesz.com/s/pIzd Exec time: never finished On 9.6 (Postgre
