Drop/Re-Creating database extremely slow + doesn't lose data

Hi Thalis

On Tue, May 31, 2016 at 3:49 PM, Thalis Kalfigkopoulos <tkalfigo@gmail.com>
wrote:

Intention: to drop a database and recreate it.
Expectation: the newly created db should be empty
What happens: dropping is fast, creation is slow, and when I reconnect,
all the data objects are still there.

Commands (tried both through command line with dropdb/createdb and through
psql)

​Creation is normally slower then dropping. This is normal, as it is a more
involved process, and normally an unusual one, so I suspect it's being
developed ​thinking more on correctness and verifiability than speed.

Onto the other​ problem. I did not see the drop commands in your examples.
And neither did I see how the XXXX/YYYY data got to the first dafodb in the
first place. ​And I saw you connect to template1. ¿ Are you aware databases
in postgres are made by copying a template database ? Maybe you modified
the default template database ( this tends to be template1 ) and this is
the reason they are all equal ( read
https://www.postgresql.org/docs/9.5/static/manage-ag-templatedbs.html
​, and also think newly created postgres database are never empty, they
have the system catalogs inside them ).

Francisco Olarte.​

From: pgsql-general-owner@postgresql.org [mailto:pgsql-general-owner@postgresql.org] On Behalf Of Thalis Kalfigkopoulos
Sent: Tuesday, May 31, 2016 9:49 AM
To: pgsql-general@postgresql.org
Subject: [GENERAL] Drop/Re-Creating database extremely slow + doesn't lose data

Intention: to drop a database and recreate it.
Expectation: the newly created db should be empty
What happens: dropping is fast, creation is slow, and when I reconnect, all the data objects are still there.

Commands (tried both through command line with dropdb/createdb and through psql)

pgdba@template1[[local]:5952] # vacuum full;
VACUUM
Time: 61292.151 ms
pgdba@template1[[local]:5952] # \l
List of databases
Name | Owner | Encoding | Collate | Ctype | Access privileges
-----------+-------+----------+-------------+-------------+-------------------
postgres | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 |
template0 | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 | =c/pgdba +
| | | | | pgdba=CTc/pgdba
template1 | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 | =c/pgdba +
| | | | | pgdba=CTc/pgdba
(3 rows)

pgdba@template1[[local]:5952] # CREATE DATABASE dafodb;
CREATE DATABASE
Time: 35776.047 ms
pgdba@template1[[local]:5952] #

And the corresponding lines from pg_log:

2016-05-31 15:29:46 CEST [4591]: user=pgdba,db=template1,app=psql,client=[local] LOG: statement: CREATE DATABASE dafodb;
2016-05-31 15:29:46 CEST [3470]: user=,db=,app=,client= LOG: checkpoint starting: immediate force wait flush-all
2016-05-31 15:29:46 CEST [3470]: user=,db=,app=,client= LOG: checkpoint complete: wrote 241 buffers (1.5%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.035 s, total=0.045 s; sync files=54, longest=0.003 s, average=0.000 s; distance=67120 kB, estimate=67120 kB
2016-05-31 15:29:52 CEST [4596]: user=,db=,app=,client= LOG: process 4596 still waiting for RowExclusiveLock on object 1 of class 1262 of database 0 after 1000.138 ms
2016-05-31 15:29:52 CEST [4596]: user=,db=,app=,client= DETAIL: Process holding the lock: 4591. Wait queue: 4596.
2016-05-31 15:30:22 CEST [3470]: user=,db=,app=,client= LOG: checkpoint starting: immediate force wait
2016-05-31 15:30:22 CEST [3470]: user=,db=,app=,client= LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 4 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.004 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=60408 kB
2016-05-31 15:30:22 CEST [4591]: user=pgdba,db=template1,app=psql,client=[local] LOG: duration: 35775.909 ms
2016-05-31 15:30:22 CEST [4596]: user=,db=,app=,client= LOG: process 4596 acquired RowExclusiveLock on object 1 of class 1262 of database 0 after 31471.839 ms
2016-05-31 15:30:22 CEST [4596]: user=,db=,app=,client= LOG: automatic vacuum of table "template1.pg_catalog.pg_statistic": index scans: 1
pages: 0 removed, 54 remain, 0 skipped due to pins
tuples: 108 removed, 724 remain, 0 are dead but not yet removable
buffer usage: 106 hits, 39 misses, 62 dirtied
avg read rate: 2.044 MB/s, avg write rate: 3.250 MB/s
system usage: CPU 0.00s/0.00u sec elapsed 0.14 sec
2016-05-31 15:30:51 CEST [4614]: user=,db=,app=,client= LOG: automatic analyze of table "template1.pg_catalog.pg_shdepend" system usage: CPU 0.00s/0.00u sec elapsed 0.02 sec

Then I continue to check the newly created database is there:
pgdba@template1[[local]:5952] # \l
List of databases
Name | Owner | Encoding | Collate | Ctype | Access privileges
-----------+-------+----------+-------------+-------------+-------------------
dafodb | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 |
postgres | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 |
template0 | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 | =c/pgdba +
| | | | | pgdba=CTc/pgdba
template1 | pgdba | UTF8 | en_US.UTF-8 | en_US.UTF-8 | =c/pgdba +
| | | | | pgdba=CTc/pgdba
(4 rows)

pgdba@template1[[local]:5952] # \c dafodb
You are now connected to database "dafodb" as user "pgdba".
pgdba@dafodb[[local]:5952] # \d
List of relations
Schema | Name | Type | Owner
--------+-------------------------------------------------------+----------+-------
public | XXXXXXX | table | pgdba
public | YYYYYYYYYYYYY | sequence | pgdba
....
....
....

So all the data is still there.

Connected processes at the moment:

pgdba@dafodb[[local]:5952] # select * from pg_stat_activity ;
datid | datname | pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | query_start | state_change | waiting | state | backend_xid
--------+---------+------+----------+---------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------+---------+--------+------------
418048 | dafodb | 4622 | 10 | pgdba | psql | (null) | (null) | -1 | 2016-05-31 15:33:16.371456+02 | 2016-05-31 15:34:27.080439+02 | 2016-05-31 15:34:27.080439+02 | 2016-05-31 15:34:27.080442+02 | f | active | (null)

(1 row)

Time: 1.072 ms
pgdba@dafodb[[local]:5952] # select * from pg_locks ;
locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath
------------+----------+----------+--------+--------+------------+---------------+---------+--------+----------+--------------------+------+-----------------+---------+----------
relation | 418048 | 11673 | (null) | (null) | (null) | (null) | (null) | (null) | (null) | 3/165 | 4622 | AccessShareLock | t | t
virtualxid | (null) | (null) | (null) | (null) | 3/165 | (null) | (null) | (null) | (null) | 3/165 | 4622 | ExclusiveLock | t | t
(2 rows)

Even weirder, created a new DB with a completely unrelated name. Again "create database" took long time, but then connected to it and it has all the data from the "dafodb".

Also tried: renaming dafodb to dafodb_OLD and again "create database dafodb". Both contain the same data.

All this on Pg 9.5.2 on 64bit Ubuntu with 3.13.0-74-generic.

Any idea what's going on or how to recover?

BR,
Thalis K.
_______________________________________________________________________________________________________

Check your template db (whichever is used to create new db).
Probably your unexpected table and sequence are coming from there.

Regards,
Igor Neyman

On Tue, May 31, 2016 at 9:49 AM, Thalis Kalfigkopoulos <tkalfigo@gmail.com>
wrote:

Intention: to drop a database and recreate it.
Expectation: the newly created db should be empty
What happens: dropping is fast, creation is slow, and when I reconnect,
all the data objects are still there.

​[...]​

Even weirder, created a new DB with a completely unrelated name. Again

"create database" took long time, but then connected to it and it has all
the data from the "dafodb".

Also tried: renaming dafodb to dafodb_OLD and again "create database
dafodb". Both contain the same data.

All this on Pg 9.5.2 on 64bit Ubuntu with 3.13.0-74-generic.

Any idea what's going on or how to recover?

​Working as designed. Database creation in PostgreSQL operates by copying
a template database and then making minor modifications as specified in the
options to CREATE DATABASE.

https://www.postgresql.org/docs/9.6/static/sql-createdatabase.html

Note that the default template is "template1"

​Typically template0 is basically empty so the behavior you are expecting
to see can be had by explicitly specifying template0 in the command.

Oddly, the notes on the aforementioned page state: "The principal
limitation is that no other sessions can be connected to the template
database while it is being copied." yet in your example you appear to be
connected to template1 when you execute the CREATE DATABASE command...

​David J.​

Hi all.

Ok, Igor nailed it. That was lame on my behalf. I apparently "contaminated"
my template1 db at some point (restored into it instead of into the target
"dafodb"). A simple \d confirmed this immediately.

Apologies for the false alarm.

@DavidJohnston, I don't know why, but yes, I am doing all operations
connected from template1.

BR,
Thalis K.

On Tue, May 31, 2016 at 4:02 PM, David G. Johnston <
david.g.johnston@gmail.com> wrote:

On Tue, May 31, 2016 at 10:06 AM, Thalis Kalfigkopoulos <tkalfigo@gmail.com>
wrote:

@DavidJohnston, I don't know why, but yes, I am doing all operations
connected from template1.

Oddly, the notes on the aforementioned page state: "The principal
limitation is that no other sessions can be connected to the template
database while it is being copied." yet in your example you appear to be
connected to template1 when you execute the CREATE DATABASE command...

​The convention on these lists is to bottom-post (or inline). Top-posting
is greatly disliked as it makes it difficult for observers to follow and
catch-up on an existing thread.

As to my observation - I failed to process the word "other"; the issuing
session can be connected to the template but that is all. This is OK
because the current session would be unable to affect any other changes
while the CREATE DATABASE is in progress.

David J.
​