Thread: Re: BUG #15641: Autoprewarm worker fails to start on Windows withhuge pages in use Old PostgreSQL community/pgsql-bugs x

On Tue, Feb 19, 2019 at 7:31 AM PG Bug reporting form
<noreply@postgresql.org> wrote:
>
> The following bug has been logged on the website:
>
> Bug reference:      15641
> Logged by:          Hans Buschmann
> Email address:      buschmann@nidsa.net
> PostgreSQL version: 11.2
> Operating system:   Windows Server 2019 Standard
> Description:
>
> I recently moved a production system from PG 10.7 to 11.2 on a different
> Server.
>
> The configuration settings where mostly taken from the old system and
> enhanced by new features of PG 11.
>
> pg_prewarm was used for a long time (with no specific configuration).
>
> Now I have added Huge page support for Windows in the OS and verified it
> with vmmap tool from Sysinternals to be active.
> (the shared buffers are locked in memory: Lock_WS is set).
>
> When pg_prewarm.autoprewarm is set to on (using the default after initial
> database import via pg_restore), the autoprewarm worker process
> terminates immediately and generates a huge number of logfile entries
> like:
>
> CPS PRD 2019-02-17 16:11:53 CET  00000 11:> LOG:  background worker
> "autoprewarm worker" (PID 3996) exited with exit code 1
> CPS PRD 2019-02-17 16:11:53 CET  55000  1:> ERROR:  could not map dynamic
> shared memory segment

Hmm.  It's not clear to me how using large pages for the main
PostgreSQL shared memory region could have any impact on autoprewarm's
entirely separate DSM segment.  I wonder if other DSM use cases are
impacted.  Does parallel query work?  For example, the following
produces a parallel query that uses a few DSM segments:

create table foo as select generate_series(1, 1000000)::int i;
analyze foo;
explain analyze select count(*) from foo f1 join foo f2 using (i);

Looking at the place where that error occurs, it seems like it simply
failed to find the handle, as if it didn't exist at all at the time
dsm_attach() was called.  I'm not entirely sure how that could happen
just because you turned on huge pages.  Is it possible that there is a
race where apw_load_buffers() manages to detach before the worker
attached, and the timing changes?  At a glance, that shouldn't happen
because apw_start_database_worker() waits for the work to exit before
returning.

I think we'll need one of our Windows-enabled hackers to take a look.

PS Sorry for breaking the thread.  I wish our archives app had a
"[re]send me this email" button, for people who subscribed after the
message was sent...

-- 
Thomas Munro
https://enterprisedb.com

Thank you for taking a look.

I encountered this problem after switching the production system and then found it also on the new created replica.

I have no knowledge of the shared memory areas involved.

I did some further investigation and tried to reproduce it on the old System (WS2016, PG 11.2) but there it worked fine (without and with huge pages activated!).

Even on a developer machine under WS2019, PG 11.2 the error did not occur (both cases running on different generation of intel machines, Haswell and Nehalem, under different Hypervisors, WS2012R2 and WS2019).

I am really confused to not being able to reproduce the error outside of production and replica instances...

The error caused a massive flood of the logs (about 800 MB in about 1 day, on SSD)

I'll try to investigate further by configuring a second replica tomorrow, using the configuration of the production system as done per pg_basebackup.

I looked at the non-default configuration settings but could not identify anything special.

Here is a current list of the production System having 4GB of memory allocated to the VM.
(all values with XXX are a little obfuscated).

Here, to avoid the error, pg_prewarm.autoprewarm is off!

             name              |              current_setting               |
-------------------------------+--------------------------------------------+
 application_name              | psql                                       |
 archive_command               | copy "xxxxxx"                              |
 archive_mode                  | on                                         |
 auto_explain.log_analyze      | off                                        |
 auto_explain.log_min_duration | -1                                         |
 client_encoding               | WIN1252                                    |
 cluster_name                  | XXX_PROD                                   |
 data_checksums                | on                                         |
 DateStyle                     | ISO, DMY                                   |
 default_text_search_config    | pg_catalog.german                          |
 dynamic_shared_memory_type    | windows                                    |
 effective_cache_size          | 8GB                                        |
 lc_collate                    | C                                          |
 lc_ctype                      | German_Germany.1252                        |
 lc_messages                   | C                                          |
 lc_monetary                   | German_Germany.1252                        |
 lc_numeric                    | German_Germany.1252                        |
 lc_time                       | German_Germany.1252                        |
 listen_addresses              | *                                          |
 log_destination               | stderr                                     |
 log_directory                 | <XXX_PATH_TO_LOG)                          |
 log_file_mode                 | 0640                                       |
 log_line_prefix               | XXX PRD %t %i %e %2l:>                     |
 log_statement                 | mod                                        |
 log_temp_files                | 0                                          |
 log_timezone                  | CET                                        |
 logging_collector             | on                                         |
 maintenance_work_mem          | 128MB                                      |
 max_connections               | 200                                        |
 max_stack_depth               | 2MB                                        |
 max_wal_size                  | 1GB                                        |
 min_wal_size                  | 80MB                                       |
 pg_prewarm.autoprewarm        | off                                        |
 pg_stat_statements.max        | 8000                                       |
 pg_stat_statements.track      | all                                        |
 random_page_cost              | 1                                          |
 search_path                   | public, archiv, ablage, admin              |
 server_encoding               | UTF8                                       |
 server_version                | 11.2                                       |
 shared_buffers                | 768MB                                      |
 shared_preload_libraries      | auto_explain,pg_stat_statements,pg_prewarm |
 temp_buffers                  | 32MB                                       |
 TimeZone                      | CET                                        |
 transaction_deferrable        | off                                        |
 transaction_isolation         | read committed                             |
 transaction_read_only         | off                                        |
 update_process_title          | off                                        |
 wal_buffers                   | 16MB                                       |
 wal_compression               | on                                         |
 wal_segment_size              | 16MB                                       |
 work_mem                      | 64MB                                       |
(51 Zeilen)


Thanks

Hans Buschmann

On Thu, Feb 21, 2019 at 4:36 AM Hans Buschmann <buschmann@nidsa.net> wrote:
> I encountered this problem after switching the production system and then found it also on the new created replica.
>
> I have no knowledge of the shared memory areas involved.
>
> I did some further investigation and tried to reproduce it on the old System (WS2016, PG 11.2) but there it worked
fine(without and with huge pages activated!).
 
>
> Even on a developer machine under WS2019, PG 11.2 the error did not occur (both cases running on different generation
ofintel machines, Haswell and Nehalem, under different Hypervisors, WS2012R2 and WS2019).
 
>
> I am really confused to not being able to reproduce the error outside of production and replica instances...
>
> The error caused a massive flood of the logs (about 800 MB in about 1 day, on SSD)
>
> I'll try to investigate further by configuring a second replica tomorrow, using the configuration of the production
systemas done per pg_basebackup.
 

Just to confirm:  on the machines where it happens, does it happen on
every restart, and does it never happen if you set huge_pages = off?

CC'ing the authors of the auto-prewarm feature to see if they have ideas.

There is a known bug (fixed in commit 6c0fb941 for the next release)
that would cause spurious dsm_attach() failure that would look just
this this (dsm_attach() returns NULL), but that should be very rare
and couldn't cause the behaviour described here, because here the
background worker is repeatedly failing to attach in a loop (hence the
800MB of logs).

-- 
Thomas Munro
https://enterprisedb.com

hello

Since these are production systems, I did'nt set huge_pages=off.
(huge pages give performance, autoprewarm is not so necessary)

I think it occured on every start, but the systems were only started 1 to 2 times in this error mode.

In the other cases I tried yesterday the results where very confusing (error not reproducable with or without huge pages).

Hans Buschmann

Hi Thomas, Hans,
On Thu, Feb 21, 2019 at 2:16 PM Hans Buschmann <buschmann@nidsa.net> wrote:
>
> hello
>
> Since these are production systems, I did'nt set huge_pages=off.
> (huge pages give performance, autoprewarm is not so necessary)

I did turn autoprewarm on, windows server 2019 and postgresql 11.2 it
runs fine even with huge_pages=on (Thanks to neha sharma). As Thomas
said error is coming from per database worker and main worker waits
till per data database worker exists so from code review I do see an
issue of having an invalid handle in per database worker. A
reproducible testcase will really help. I shall see to recheck the
code again but I am not much hopeful without a proper testcase.

--
Thanks and Regards
Mithun Chicklore Yogendra
EnterpriseDB: http://www.enterprisedb.com

On Thu, Feb 21, 2019 at 6:23 PM Mithun Cy <mithun.cy@gmail.com> wrote:

> said error is coming from per database worker and main worker waits
> till per data database worker exists so from code review I do see an
> issue of having an invalid handle in per database worker.

Sorry a typo error, I meant I do not see an issue from the code.

On the weekend, I did some more investigations:

It seems that Huge pages are NOT the cause of this problem.

The problem is only reproducable ONCE, after a database restart it disappears.

By reinstalling the original pg_pasebackup on another test VM the problem reappeared once.

Here is the start of  the error log:

CPS PRD 2019-02-24 12:11:57 CET  00000  1:> LOG:  database system was interrupted; last known up at 2019-02-17 16:14:05 CET
CPS PRD 2019-02-24 12:12:16 CET  00000  2:> LOG:  entering standby mode
CPS PRD 2019-02-24 12:12:16 CET  00000  3:> LOG:  redo starts at 0/23000028
CPS PRD 2019-02-24 12:12:16 CET  00000  4:> LOG:  consistent recovery state reached at 0/23000168
CPS PRD 2019-02-24 12:12:16 CET  00000  5:> LOG:  invalid record length at 0/24000060: wanted 24, got 0
CPS PRD 2019-02-24 12:12:16 CET  00000  9:> LOG:  database system is ready to accept read only connections
CPS PRD 2019-02-24 12:12:16 CET  3D000  1:> FATAL:  database 16384 does not exist
CPS PRD 2019-02-24 12:12:16 CET  00000 10:> LOG:  background worker "autoprewarm worker" (PID 3968) exited with exit code 1
CPS PRD 2019-02-24 12:12:16 CET  00000  1:> LOG:  autoprewarm successfully prewarmed 0 of 12402 previously-loaded blocks
CPS PRD 2019-02-24 12:12:17 CET  XX000  1:> FATAL:  could not connect to the primary server: FATAL:  no pg_hba.conf entry for replication connection from host "192.168.27.155", user "replicator", SSL off
CPS PRD 2019-02-24 12:12:17 CET  55000  1:> ERROR:  could not map dynamic shared memory segment
CPS PRD 2019-02-24 12:12:17 CET  00000 11:> LOG:  background worker "autoprewarm worker" (PID 3296) exited with exit code 1
CPS PRD 2019-02-24 12:12:17 CET  XX000  1:> FATAL:  could not connect to the primary server: FATAL:  no pg_hba.conf entry for replication connection from host "192.168.27.155", user "replicator", SSL off
CPS PRD 2019-02-24 12:12:17 CET  55000  1:> ERROR:  could not map dynamic shared memory segment
CPS PRD 2019-02-24 12:12:17 CET  00000 12:> LOG:  background worker "autoprewarm worker" (PID 2756) exited with exit code 1
CPS PRD 2019-02-24 12:12:17 CET  55000  1:> ERROR:  could not map dynamic shared memory segment
...
(PS: the correct replication function was not set, so causing the errors concerning replication)

It seems that an outdated autoprewarm.blocks causes the problem.

After a restart the autoprewarm.blocks file seems to be rewritten, so that the next start gives no error.

For a test, I copied the erroneus autoprewarm.blocks files over to the data section and the problem reappeared.


The autoprewarm.blocks file is not corrupted or moved around manually but rather a leftover from the preceding test installation.

On this instance I had installed a copy of the production database under 11.2.
By doing the production switch, I dropped the test database and pg_restored the current one.

This left the previous autoprewarm.blocks file in the data directory.

On the first start the autoprewarm files does not match the newly restored database (perhpas the cause of the fatal error: database 16384 does not exist)

So the problem lies in the initial detection of the autoprewarm.blocks file.

This seems easy to reproduce:

- Install/create a database with autoprewarm on and pg_prewarm loaded.
- Fill the autoprewarm cache with some data
- pg_dump the database
- drop the database
- create the database and pg_restore it from the dump
- start the instance and logs are flooded

I have taken no further investigation in the sourcecode due to limited skills so far...


Thanks

Hans Buschmann

Glad to hear you could reproduce the case easily.

I wanted to add that the problem as it seems now should'nt be restricted to Windows only.

Another thing is the semantic scope of pg_prewarm:

Prewarming affects the whole cluster, so at instance start we can meet some active and/or some dropped databases.

To not affect the other databases the prewarming should occur on all non dropped databases and omit only the dropped ones.

Hope your thinking gives a good patch... ;)

Hans Buschmann