Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WDtVS-0006IR-Uq for pgsql-performance@arkaria.postgresql.org; Thu, 13 Feb 2014 10:27:00 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1WDtVS-0006HR-AW for pgsql-performance@arkaria.postgresql.org; Thu, 13 Feb 2014 10:26:58 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WDtVR-0006HK-0n for pgsql-performance@postgresql.org; Thu, 13 Feb 2014 10:26:57 +0000 Received: from forward1l.mail.yandex.net ([2a02:6b8:0:1819::1]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WDtVM-0006Dq-UC for pgsql-performance@postgresql.org; Thu, 13 Feb 2014 10:26:56 +0000 Received: from smtp6.mail.yandex.net (smtp6.mail.yandex.net [77.88.61.56]) by forward1l.mail.yandex.net (Yandex) with ESMTP id 605621520CB9; Thu, 13 Feb 2014 14:26:50 +0400 (MSK) Received: from smtp6.mail.yandex.net (localhost [127.0.0.1]) by smtp6.mail.yandex.net (Yandex) with ESMTP id 0CD2F16400BD; Thu, 13 Feb 2014 14:26:49 +0400 (MSK) Received: from 5.45.212.104-red3.dhcp.yndx.net (5.45.212.104-red3.dhcp.yndx.net [5.45.212.104]) by smtp6.mail.yandex.net (nwsmtp/Yandex) with ESMTPSA id ceKaSimv2m-QnLaSUcW; Thu, 13 Feb 2014 14:26:49 +0400 (using TLSv1 with cipher AES128-SHA (128/128 bits)) (Client certificate not present) X-Yandex-Uniq: d39047f4-13fc-4345-86ac-4267b11d9d0c DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=simply.name; s=mail; t=1392287209; bh=gI9TWgV8fwmnV8RJuz0osoWHH/9HmhZt1c9YAmcDzLM=; h=Content-Type:Mime-Version:Subject:From:In-Reply-To:Date:Cc: Message-Id:References:To:X-Mailer; b=ePuyUM+efYHAJsAVHB9Gl6tBbptjh+H0JFDWyr+Q1hRHqSU+VWyjYATtJiairqKnF pCGiqOKNYYsBMofuFw6OhyEkObqJ0c3heJH+u5PKsDViR8LlYbcpOTc167T6F0dDAW SsTQ3mGera/IELeSRe9UpTEIQRyxA/JAQbVeIQ2E= Authentication-Results: smtp6.mail.yandex.net; dkim=pass header.i=@simply.name Content-Type: multipart/alternative; boundary="Apple-Mail=_6E197BF0-4FC2-403B-85E2-601620910D20" Mime-Version: 1.0 (Mac OS X Mail 6.6 \(1510\)) Subject: Re: Problem with ExclusiveLock on inserts From: =?koi8-r?B?4s/Sz8TJziD3zMHEyc3J0g==?= In-Reply-To: Date: Thu, 13 Feb 2014 14:26:49 +0400 Cc: "pgsql-performance@postgresql.org" Message-Id: <78DFED11-B94D-43D5-BEDF-B5AB5D78B2EC@simply.name> References: <466D72D2-68EC-4FF4-93B8-43B687E7B705@simply.name> <15987F63-82EB-453A-958E-96839CB036ED@simply.name> To: Ilya Kosmodemiansky X-Mailer: Apple Mail (2.1510) X-Pg-Spam-Score: -2.0 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --Apple-Mail=_6E197BF0-4FC2-403B-85E2-601620910D20 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=koi8-r 13.02.2014, =D7 13:29, Ilya Kosmodemiansky = =CE=C1=D0=C9=D3=C1=CC(=C1): > Vladimir, >=20 > And, any effect on your problem? It worked without problems longer than previous configuration but = repeated again several minutes ago :( >=20 > On Thu, Feb 13, 2014 at 9:35 AM, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD= =C9=D2 wrote: >> I have limited max connections to 1000, reduced shared buffers to 8G = and restarted postgres. >=20 > 1000 is still to much in most cases. With pgbouncer in transaction > pooling mode normaly pool size 8-32, max_connections =3D 100 (default > value) and client_connections 500-1500 looks more reasonable. Clients for this db are plproxy hosts. As far as I know plproxy can work = only with statement pooling. >=20 >=20 >> I have also noticed that this big tables stopped vacuuming = automatically a couple of weeks ago. It could be the reason of the = problem, I will now try to tune autovacuum parameters to turn it back. = But yesterday I ran "vacuum analyze" for all relations manually but that = did not help. >=20 > How do your autovacuum parameters look like now? They were all default except for vacuum_defer_cleanup_age =3D 100000. I = have increased autovacuum_max_workers =3D 20 because I have 10 databases = with about 10 tables each. That did not make better (I haven't seen more = than two auto vacuum workers simultaneously). Then I have tried to set = vacuum_cost_limit =3D 1000. Still not vacuuming big tables. Right now = the parameters look like this: root@rpopdb01e ~ # fgrep vacuum = /var/lib/pgsql/9.3/data/conf.d/postgresql.conf=20 #vacuum_cost_delay =3D 0 # 0-100 milliseconds #vacuum_cost_page_hit =3D 1 # 0-10000 credits #vacuum_cost_page_miss =3D 10 # 0-10000 credits #vacuum_cost_page_dirty =3D 20 # 0-10000 credits vacuum_cost_limit =3D 1000 # 1-10000 credits vacuum_defer_cleanup_age =3D 100000 # number of xacts by which = cleanup is delayed autovacuum =3D on # Enable autovacuum = subprocess? 'on' log_autovacuum_min_duration =3D 0 # -1 disables, 0 logs all = actions and autovacuum_max_workers =3D 20 # max number of autovacuum = subprocesses #autovacuum_naptime =3D 1min # time between autovacuum runs #autovacuum_vacuum_threshold =3D 50 # min number of row updates = before # vacuum #autovacuum_analyze_threshold =3D 50 # min number of row updates = before #autovacuum_vacuum_scale_factor =3D 0.2 # fraction of table size = before vacuum #autovacuum_analyze_scale_factor =3D 0.1 # fraction of table size = before analyze #autovacuum_freeze_max_age =3D 200000000 # maximum XID age before = forced vacuum #autovacuum_vacuum_cost_delay =3D 20ms # default vacuum cost delay = for # autovacuum, in milliseconds; # -1 means use vacuum_cost_delay #autovacuum_vacuum_cost_limit =3D -1 # default vacuum cost limit = for # autovacuum, -1 means use # vacuum_cost_limit #vacuum_freeze_min_age =3D 50000000 #vacuum_freeze_table_age =3D 150000000 root@rpopdb01e ~ # >=20 >> 13.02.2014, =D7 0:14, Ilya Kosmodemiansky = =CE=C1=D0=C9=D3=C1=CC(=C1): >>=20 >> On Wed, Feb 12, 2014 at 8:57 PM, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD= =C9=D2 wrote: >>=20 >>=20 >> Yes, this is legacy, I will fix it. We had lots of inactive = connections but right now we use pgbouncer for this. When the workload = is normal we have some kind of 80-120 backends. Less than 10 of them are = in active state. Having problem with locks we get lots of sessions = (sometimes more than 1000 of them are in active state). According to = vmstat the number of context switches is not so big (less than 20k), so = I don't think it is the main reason. Yes, it can aggravate the problem, = but imho not create it. >>=20 >>=20 >>=20 >> I'am afraid that is the problem. More than 1000 backends, most of = them >> are simply waiting. >>=20 >>=20 >>=20 >> I don't understand the correlation of shared buffers size and = synchronous_commit. Could you please explain your statement? >>=20 >>=20 >>=20 >> You need to fsync your huge shared buffers any time your database >> performs checkpoint. By default it usually happens too often because >> checkpoint_timeout is 5min by default. Without bbu, on software raid >> that leads to io spike and you commit waits for wal. >>=20 >>=20 >>=20 >> 12.02.2014, =D7 23:37, Ilya Kosmodemiansky = =CE=C1=D0=C9=D3=C1=CC(=C1): >>=20 >> another thing which is arguable - concurrency degree. How many of = your max_connections =3D 4000 are actually running? 4000 definitely = looks like an overkill and they could be a serious source of = concurrency, especially then you have had barrier enabled and software = raid. >>=20 >> Plus for 32Gb of shared buffers with synchronous_commit =3D on = especially on heavy workload one should definitely have bbu, otherwise = performance will be poor. >>=20 >>=20 >> On Wed, Feb 12, 2014 at 8:20 PM, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD= =C9=D2 wrote: >>=20 >>=20 >> Oh, I haven't thought about barriers, sorry. Although I use soft raid = without batteries I have turned barriers off on one cluster shard to = try. >>=20 >> root@rpopdb01e ~ # mount | fgrep data >> /dev/md2 on /var/lib/pgsql/9.3/data type ext4 (rw,noatime,nodiratime) >> root@rpopdb01e ~ # mount -o remount,nobarrier /dev/md2 >> root@rpopdb01e ~ # mount | fgrep data >> /dev/md2 on /var/lib/pgsql/9.3/data type ext4 = (rw,noatime,nodiratime,nobarrier) >> root@rpopdb01e ~ # >>=20 >> 12.02.2014, =D7 21:56, Ilya Kosmodemiansky = =CE=C1=D0=C9=D3=C1=CC(=C1): >>=20 >> My question was actually about barrier option, by default it is = enabled on RHEL6/ext4 and could cause serious bottleneck on io before = disks are actually involved. What says mount without arguments? >>=20 >> On Feb 12, 2014, at 18:43, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD=C9=D2= wrote: >>=20 >> root@rpopdb01e ~ # fgrep data /etc/fstab >> UUID=3Df815fd3f-e4e4-43a6-a6a1-bce1203db3e0 /var/lib/pgsql/9.3/data = ext4 noatime,nodiratime 0 1 >> root@rpopdb01e ~ # >>=20 >> According to iostat the disks are not the bottleneck. >>=20 >> 12.02.2014, =D7 21:30, Ilya Kosmodemiansky = =CE=C1=D0=C9=D3=C1=CC(=C1): >>=20 >> Hi Vladimir, >>=20 >> Just in case: how is your ext4 mount? >>=20 >> Best regards, >> Ilya >>=20 >> On Feb 12, 2014, at 17:59, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD=C9=D2= wrote: >>=20 >> Hi all. >>=20 >> Today I have started getting errors like below in logs (seems that I = have not changed anything for last week). When it happens the db gets = lots of connections in state active, eats 100% cpu and clients get = errors (due to timeout). >>=20 >> 2014-02-12 15:44:24.562 = MSK,"rpop","rpopdb_p6",30061,"localhost:58350",52fb5e53.756d,1,"SELECT = waiting",2014-02-12 15:43:15 = MSK,143/264877,1002850566,LOG,00000,"process 30061 still waiting for = ExclusiveLock on extension of relation 26118 of database 24590 after = 1000.082 ms",,,,,"SQL statement ""insert into rpop.rpop_imap_uidls = (folder_id, uidl) values (i_folder_id, i_uidl)"" >>=20 >> I have read several topics [1, 2, 3, 4] with similar problems but = haven't find a good solution. Below is some more diagnostics. >>=20 >> I am running PostgreSQL 9.3.2 installed from RPM packages on RHEL = 6.4. Host is running with the following CPU (32 cores) and memory: >>=20 >> root@rpopdb01e ~ # fgrep -m1 'model name' /proc/cpuinfo >> model name : Intel(R) Xeon(R) CPU E5-2660 0 @ 2.20GHz >> root@rpopdb01e ~ # free -m >> total used free shared buffers = cached >> Mem: 129028 123558 5469 0 135 = 119504 >> -/+ buffers/cache: 3918 125110 >> Swap: 16378 0 16378 >> root@rpopdb01e ~ # >>=20 >> PGDATA lives on RAID6 array of 8 ssd-disks with ext4, iostat and atop = say the disks are really free. Right now PGDATA takes only 95G. >> The settings changed in postgresql.conf are here [5]. >>=20 >> When it happens the last query from here [6] shows that almost all = queries are waiting for ExclusiveLock, but they do a simple insert. >>=20 >> (extend,26647,26825,,,,,,,) | 5459 | ExclusiveLock | 1 | = (extend,26647,26825,,,,,,,) | 8053 | ExclusiveLock | 5459,8053 >> (extend,26647,26828,,,,,,,) | 5567 | ExclusiveLock | 1 | = (extend,26647,26828,,,,,,,) | 5490 | ExclusiveLock | 5567,5490 >> (extend,24584,25626,,,,,,,) | 5611 | ExclusiveLock | 1 | = (extend,24584,25626,,,,,,,) | 3963 | ExclusiveLock | 5611,3963 >>=20 >> I have several databases running on one host with one postmaster = process and ExclusiveLock is being waited by many oids. I suppose the = only common thing for all of them is that they are bigger than others = and they almost do not get updates and deletes (only inserts and reads). = Some more info about one of such tables is here [7]. >>=20 >> I have tried to look at the source code = (src/backend/access/heap/hio.c) to understand when the exclusive lock = can be taken, but I could only read comments :) I have also examined FSM = for this tables and their indexes and found that for most of them there = are free pages but there are, for example, such cases: >>=20 >> rpopdb_p0=3D# select count(*) from pg_freespace('rpop.rpop_uidl') = where avail !=3D 0; >> count >> -------- >> 115953 >> (1 row) >>=20 >> rpopdb_p0=3D# select count(*) from pg_freespace('rpop.pk_rpop_uidl') = where avail !=3D 0; >> count >> ------- >> 0 >> (1 row) >>=20 >> rpopdb_p0=3D# \dS+ rpop.rpop_uidl >> Table "rpop.rpop_uidl" >> Column | Type | Modifiers | Storage | Stats target = | Description >> = --------+------------------------+-----------+----------+--------------+--= ----------- >> popid | bigint | not null | plain | = | >> uidl | character varying(200) | not null | extended | = | >> Indexes: >> "pk_rpop_uidl" PRIMARY KEY, btree (popid, uidl) >> Has OIDs: no >>=20 >> rpopdb_p0=3D# >>=20 >>=20 >> My questions are: >> 1. Do we consume 100% cpu (in system) trying to get page from FSM? Or = does it happen during exclusive lock acquiring? How can I dig it? >> 2. How much space do we extend to the relation when we get exclusive = lock on it? >> 3. Why extended page is not visible for other backends? >> 4. Is there any possibility of situation where backend A got = exclusive lock on some relation to extend it. Then OS CPU scheduler made = a context switch to backend B while backend B is waiting for exclusive = lock on the same relation. And so on for many backends. >> 5. (and the main question) what can I do to get rid of such = situations? It is a production cluster and I do not have any ideas what = to do with this situation :( Any help would be really appropriate. >>=20 >> [1] = http://www.postgresql.org/message-id/8bca3aa10906011613l8ac2423h8153bbd251= 3dc159@mail.gmail.com >> [2] = http://pgsql.performance.narkive.com/IrkPbl3f/postgresql-9-2-3-performance= -problem-caused-exclusive-locks >> [3] http://www.postgresql.org/message-id/50A2C93E.9070607@dalibo.com >> [4] = http://www.postgresql.org/message-id/CAL_0b1sypYeOyNkYNV95nNV2d+4jXTug3HkK= F6FahfW7Gvgb_Q@mail.gmail.com >> [5] http://pastebin.com/raw.php?i=3DBd40Vn6h >> [6] http://wiki.postgresql.org/wiki/Lock_dependency_information >> [7 http://pastebin.com/raw.php?i=3DeGrtG524] >>=20 >> -- >> Vladimir >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >> -- >> Vladimir >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >> -- >> =E4=C1 =D0=D2=C5=C2=D5=C4=C5=D4 =D3 =D7=C1=CD=C9 =D3=C9=CC=C1... >> http://simply.name >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >> -- >> Vladimir >>=20 >>=20 >>=20 >>=20 >>=20 >>=20 >> -- >> Vladimir >>=20 >>=20 >>=20 >>=20 -- =E4=C1 =D0=D2=C5=C2=D5=C4=C5=D4 =D3 =D7=C1=CD=C9 =D3=C9=CC=C1... http://simply.name --Apple-Mail=_6E197BF0-4FC2-403B-85E2-601620910D20 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=koi8-r hydrobiont@gmail.com> = =CE=C1=D0=C9=D3=C1=CC(=C1):
Vladimir,

And, any effect on your = problem?

It worked without problems = longer than previous configuration but repeated again several minutes = ago :(


On Thu, Feb 13, 2014 at = 9:35 AM, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD=C9=D2 <root@simply.name> = wrote:
I have limited max connections to = 1000, reduced shared buffers to 8G and restarted = postgres.

1000 is still to much in most cases. With = pgbouncer in transaction
pooling mode normaly pool size 8-32, = max_connections =3D 100 (default
value) and client_connections = 500-1500 looks more = reasonable.

Clients for this db are = plproxy hosts. As far as I know plproxy can work only with statement = pooling.



I have also noticed that = this big tables stopped vacuuming automatically a couple of weeks ago. = It could be the reason of the problem, I will now try to tune autovacuum = parameters to turn it back. But yesterday I ran "vacuum analyze" for all = relations manually but that did not help.

How do = your autovacuum parameters look like = now?

They were all default except = for vacuum_defer_cleanup_age =3D 100000. I have = increased autovacuum_max_workers =3D 20 because I have 10 databases = with about 10 tables each. That did not make better (I haven't seen more = than two auto vacuum workers simultaneously). Then I have tried to = set vacuum_cost_limit =3D 1000. Still not vacuuming big tables. = Right now the parameters look like = this:

root@rpopdb01e ~ # fgrep vacuum = /var/lib/pgsql/9.3/data/conf.d/postgresql.conf 
#vacuum_cos= t_delay =3D 0                 =  # 0-100 milliseconds
#vacuum_cost_page_hit =3D 1   =             # 0-10000 = credits
#vacuum_cost_page_miss =3D 10       =       # 0-10000 credits
#vacuum_cost_page_dirty = =3D 20            # 0-10000 = credits
vacuum_cost_limit =3D 1000         =        # 1-10000 = credits
vacuum_defer_cleanup_age =3D 100000     =   # number of xacts by which cleanup is = delayed
autovacuum =3D on           =               # Enable autovacuum = subprocess?  'on'
log_autovacuum_min_duration =3D 0 =         # -1 disables, 0 logs all actions = and
autovacuum_max_workers =3D 20         =     # max number of autovacuum = subprocesses
#autovacuum_naptime =3D 1min       =        # time between autovacuum = runs
#autovacuum_vacuum_threshold =3D 50       = # min number of row updates before
        =                     =             # = vacuum
#autovacuum_analyze_threshold =3D 50     =  # min number of row updates = before
#autovacuum_vacuum_scale_factor =3D 0.2   # = fraction of table size before = vacuum
#autovacuum_analyze_scale_factor =3D 0.1  # = fraction of table size before = analyze
#autovacuum_freeze_max_age =3D 200000000  # = maximum XID age before forced = vacuum
#autovacuum_vacuum_cost_delay =3D 20ms    # = default vacuum cost delay for
        =                     =             # autovacuum, in = milliseconds;
              =                     =       # -1 means use = vacuum_cost_delay
#autovacuum_vacuum_cost_limit =3D -1   =    # default vacuum cost limit for
    =                     =                 # autovacuum, -1 = means use
              =                     =       # = vacuum_cost_limit
#vacuum_freeze_min_age =3D = 50000000
#vacuum_freeze_table_age =3D = 150000000
root@rpopdb01e ~ #


13.02.2014, =D7 0:14, Ilya = Kosmodemiansky <hydrobiont@gmail.com> = =CE=C1=D0=C9=D3=C1=CC(=C1):

On Wed, Feb 12, 2014 at 8:57 PM, = =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD=C9=D2 <root@simply.name> = wrote:


Yes, this is legacy, I will fix it. We had lots of = inactive connections but right now we use pgbouncer for this. When the = workload is normal we have some kind of 80-120 backends. Less than 10 of = them are in active state. Having problem with locks we get lots of = sessions (sometimes more than 1000 of them are in active state). = According to vmstat the number of context switches is not so big (less = than 20k), so I don't think it is the main reason. Yes, it can aggravate = the problem, but imho not create it.



I'am afraid that is = the problem. More than 1000 backends, most of them
are simply = waiting.



I don't understand the correlation of shared = buffers size and synchronous_commit. Could you please explain your = statement?



You need to fsync your huge shared buffers any = time your database
performs checkpoint. By default it usually happens = too often because
checkpoint_timeout is 5min by default. Without bbu, = on software raid
that leads to io spike and you commit waits for = wal.



12.02.2014, =D7 23:37, Ilya Kosmodemiansky <hydrobiont@gmail.com> = =CE=C1=D0=C9=D3=C1=CC(=C1):

another thing which is arguable - = concurrency degree. How many of your max_connections =3D 4000 are = actually running?  4000 definitely looks like an overkill and they = could be a serious source of concurrency, especially then you have had = barrier enabled and software raid.

Plus for 32Gb of shared = buffers with synchronous_commit =3D on especially on heavy workload one = should definitely have bbu, otherwise performance will be = poor.


On Wed, Feb 12, 2014 at 8:20 PM, =E2=CF=D2=CF=C4=C9=CE = =F7=CC=C1=C4=C9=CD=C9=D2 <root@simply.name> = wrote:


Oh, I haven't thought about barriers, sorry. Although = I use soft raid without batteries I have turned barriers off on one = cluster shard to try.

root@rpopdb01e ~ # mount | fgrep = data
/dev/md2 on /var/lib/pgsql/9.3/data type ext4 = (rw,noatime,nodiratime)
root@rpopdb01e ~ # mount -o remount,nobarrier = /dev/md2
root@rpopdb01e ~ # mount | fgrep data
/dev/md2 on = /var/lib/pgsql/9.3/data type ext4 = (rw,noatime,nodiratime,nobarrier)
root@rpopdb01e ~ = #

12.02.2014, =D7 21:56, Ilya Kosmodemiansky <hydrobiont@gmail.com> = =CE=C1=D0=C9=D3=C1=CC(=C1):

My question was actually about = barrier option, by default it is enabled on RHEL6/ext4 and could cause = serious bottleneck on io before disks are actually involved. What says = mount without arguments?

On Feb 12, 2014, at 18:43, =E2=CF=D2=CF=C4= =C9=CE =F7=CC=C1=C4=C9=CD=C9=D2 <root@simply.name> = wrote:

root@rpopdb01e ~ # fgrep data = /etc/fstab
UUID=3Df815fd3f-e4e4-43a6-a6a1-bce1203db3e0 = /var/lib/pgsql/9.3/data ext4 noatime,nodiratime 0 1
root@rpopdb01e ~ = #

According to iostat the disks are not the = bottleneck.

12.02.2014, =D7 21:30, Ilya Kosmodemiansky <hydrobiont@gmail.com> = =CE=C1=D0=C9=D3=C1=CC(=C1):

Hi Vladimir,

Just in case: how = is your ext4 mount?

Best regards,
Ilya

On Feb 12, 2014, = at 17:59, =E2=CF=D2=CF=C4=C9=CE =F7=CC=C1=C4=C9=CD=C9=D2 <root@simply.name> = wrote:

Hi all.

Today I have started getting errors like = below in logs (seems that I have not changed anything for last week). = When it happens the db gets lots of connections in state active, eats = 100% cpu and clients get errors (due to timeout).

2014-02-12 = 15:44:24.562 = MSK,"rpop","rpopdb_p6",30061,"localhost:58350",52fb5e53.756d,1,"SELECT = waiting",2014-02-12 15:43:15 = MSK,143/264877,1002850566,LOG,00000,"process 30061 still waiting for = ExclusiveLock on extension of relation 26118 of database 24590 after = 1000.082 ms",,,,,"SQL statement ""insert into rpop.rpop_imap_uidls = (folder_id, uidl) values (i_folder_id, i_uidl)""

I have read = several topics [1, 2, 3, 4] with similar problems but haven't find a = good solution. Below is some more diagnostics.

I am running = PostgreSQL 9.3.2 installed from RPM packages on RHEL 6.4. Host is = running with the following CPU (32 cores) and = memory:

root@rpopdb01e ~ # fgrep -m1 'model name' = /proc/cpuinfo
model name : Intel(R) Xeon(R) CPU E5-2660 0 @ = 2.20GHz
root@rpopdb01e ~ # free -m
=            total =       used =       free     shared =    buffers     cached
Mem: =        129028 =     123558       5469 =          0 =        135 =     119504
-/+ buffers/cache: =       3918 =     125110
Swap: =        16378 =          0 =      16378
root@rpopdb01e ~ #

PGDATA = lives on RAID6 array of 8 ssd-disks with ext4, iostat and atop say the = disks are really free. Right now PGDATA takes only 95G.
The settings = changed in postgresql.conf are here [5].

When it happens the last = query from here [6] shows that almost all queries are waiting for = ExclusiveLock, but they do a simple = insert.

(extend,26647,26825,,,,,,,) | =        5459 | ExclusiveLock | =     1 | (extend,26647,26825,,,,,,,) | 8053 | = ExclusiveLock | 5459,8053
(extend,26647,26828,,,,,,,) | =        5567 | ExclusiveLock | =     1 | (extend,26647,26828,,,,,,,) | 5490 | = ExclusiveLock | 5567,5490
(extend,24584,25626,,,,,,,) | =        5611 | ExclusiveLock | =     1 | (extend,24584,25626,,,,,,,) | 3963 | = ExclusiveLock | 5611,3963

I have several databases running on one = host with one postmaster process and ExclusiveLock is being waited by = many oids. I suppose the only common thing for all of them is that they = are bigger than others and they almost do not get updates and deletes = (only inserts and reads). Some more info about one of such tables is = here [7].

I have tried to look at the source code = (src/backend/access/heap/hio.c) to understand when the exclusive lock = can be taken, but I could only read comments :) I have also examined FSM = for this tables and their indexes and found that for most of them there = are free pages but there are, for example, such = cases:

rpopdb_p0=3D# select count(*) from = pg_freespace('rpop.rpop_uidl') where avail !=3D = 0;
count
--------
115953
(1 row)

rpopdb_p0=3D# select = count(*) from pg_freespace('rpop.pk_rpop_uidl') where avail !=3D = 0;
count
-------
   0
(1 = row)

rpopdb_p0=3D# \dS+ rpop.rpop_uidl
=             &n= bsp;           &nbs= p;    Table "rpop.rpop_uidl"
Column | =          Type =          | Modifiers | = Storage  | Stats target | = Description
--------+------------------------+-----------+----------+--= ------------+-------------
popid  | bigint =             &n= bsp;   | not null  | plain    | =             &n= bsp;|
uidl   | character varying(200) | not null  | = extended | =             &n= bsp;|
Indexes:
  "pk_rpop_uidl" PRIMARY KEY, btree = (popid, uidl)
Has OIDs: no

rpopdb_p0=3D#


My = questions are:
1. Do we consume 100% cpu (in system) trying to get = page from FSM? Or does it happen during exclusive lock acquiring? How = can I dig it?
2. How much space do we extend to the relation when we = get exclusive lock on it?
3. Why extended page is not visible for = other backends?
4. Is there any possibility of situation where = backend A got exclusive lock on some relation to extend it. Then OS CPU = scheduler made a context switch to backend B while backend B is waiting = for exclusive lock on the same relation. And so on for many = backends.
5. (and the main question) what can I do to get rid of such = situations? It is a production cluster and I do not have any ideas what = to do with this situation :( Any help would be really = appropriate.

[1] http://www.postgresql.org/message-id/8bca3a= a10906011613l8ac2423h8153bbd2513dc159@mail.gmail.com
[2] http://pgsql.performance.narkive.= com/IrkPbl3f/postgresql-9-2-3-performance-problem-caused-exclusive-locks
[3] = http://www.postgresql.org/message-id/50A2C93E.9070607@dalibo.com
[4= ] http://www.postgresql.org/message-i= d/CAL_0b1sypYeOyNkYNV95nNV2d+4jXTug3HkKF6FahfW7Gvgb_Q@mail.gmail.com[5] http://pastebin.com/raw.= php?i=3DBd40Vn6h
[6] http:= //wiki.postgresql.org/wiki/Lock_dependency_information
[7 http://pastebin.com/raw= .php?i=3DeGrtG524]

--
Vladimir






--=
Vladimir






--
=E4=C1 =D0=D2=C5=C2=D5=C4=C5= =D4 =D3 =D7=C1=CD=C9 =D3=C9=CC=C1...
http://simply.name





=


--
Vladimir






--
Vladimir




--
=E4=C1 = =D0=D2=C5=C2=D5=C4=C5=D4 =D3 =D7=C1=CD=C9 =D3=C9=CC=C1...




= --Apple-Mail=_6E197BF0-4FC2-403B-85E2-601620910D20--