Postgres Pro
Downloads
Home   >   mailing lists

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

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

From
Thalis Kalfigkopoulos
Date:
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.

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

From
Igor Neyman
Date:

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

 

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

From
Francisco Olarte
Date:
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.​



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

From
"David G. Johnston"
Date:
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.


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.​

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

From
Thalis Kalfigkopoulos
Date:
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 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.


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.​

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

From
"David G. Johnston"
Date:
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.
​