Re: Drop/Re-Creating database extremely slow + doesn't lose data - Mailing list pgsql-general

From Igor Neyman
Subject Re: Drop/Re-Creating database extremely slow + doesn't lose data
Date
Msg-id DM2PR07MB557241ECBD2786BA3F6D2BCDA460@DM2PR07MB557.namprd07.prod.outlook.com
Whole thread Raw
In response to Drop/Re-Creating database extremely slow + doesn't lose data  (Thalis Kalfigkopoulos <tkalfigo@gmail.com>)
List pgsql-general

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

 

pgsql-general by date:

Previous
From: Melvin Davidson
Date:
Subject: Re: Switching roles as an replacement of connection pooling tools
Next
From: Francisco Olarte
Date:
Subject: Re: Drop/Re-Creating database extremely slow + doesn't lose data