hung backends stuck in spinlock heavy endless loop

Hi,

On 2015-01-13 16:29:51 -0600, Merlin Moncure wrote:

On my workstation today (running vanilla 9.4.0) I was testing some new
code that does aggressive parallel loading to a couple of tables. It
ran ok several dozen times and froze up with no external trigger.
There were at most 8 active backends that were stuck (the loader is
threaded to a cap) -- each query typically resolves in a few seconds
but they were hung for 30 minutes+.

Interesting.

Had to do restart immediate as
backends were not responding to cancel...but I snapped a 'perf top'
before I did so. The results were interesting so I'm posting them
here. So far I have not been able to reproduce...FYI

Can you compile postgres with -fno-omit-frame-pointer? Then, when this
happens the next time, you can take a perf record -g, which will tell us
which lock the contention is at.

61.03% postgres [.] s_lock
13.56% postgres [.] LWLockRelease
10.11% postgres [.] LWLockAcquire

That profile looks like it might end up being helped by the lwlock
and/or freelist changes in 9.5.

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 4:33 PM, Andres Freund <andres@2ndquadrant.com> wrote:

Hi,

On 2015-01-13 16:29:51 -0600, Merlin Moncure wrote:

On my workstation today (running vanilla 9.4.0) I was testing some new
code that does aggressive parallel loading to a couple of tables. It
ran ok several dozen times and froze up with no external trigger.
There were at most 8 active backends that were stuck (the loader is
threaded to a cap) -- each query typically resolves in a few seconds
but they were hung for 30 minutes+.

Interesting.

Had to do restart immediate as
backends were not responding to cancel...but I snapped a 'perf top'
before I did so. The results were interesting so I'm posting them
here. So far I have not been able to reproduce...FYI

Can you compile postgres with -fno-omit-frame-pointer? Then, when this
happens the next time, you can take a perf record -g, which will tell us
which lock the contention is at.

will do, and I'll loop it for a while and see if I can get it to re-occur.

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 2:29 PM, Merlin Moncure <mmoncure@gmail.com> wrote:

On my workstation today (running vanilla 9.4.0) I was testing some new
code that does aggressive parallel loading to a couple of tables.

Could you give more details, please? For example, I'd like to see
representative data, or at least the table definitions involved. Do
you have any idea what index is involved with the _bt_compare() calls
above? I'm curious as to what its definition is.

You might also consider using my B-Tree verification tool on a
preserved data directory:
/messages/by-id/CAM3SWZRK2YxKegj94_2wKs_vbEMJeHc1yE23ECsS01wRAKzkjg@mail.gmail.com

I'm inclined to think that this is a livelock, and so the problem
isn't evident from the structure of the B-Tree, but it can't hurt to
check. The tool is bleeding edge, so don't use it in production.

Thanks
--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2015-01-13 15:17:15 -0800, Peter Geoghegan wrote:

I'm inclined to think that this is a livelock, and so the problem
isn't evident from the structure of the B-Tree, but it can't hurt to
check.

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 5:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

On 2015-01-13 15:17:15 -0800, Peter Geoghegan wrote:

I'm inclined to think that this is a livelock, and so the problem
isn't evident from the structure of the B-Tree, but it can't hurt to
check.

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I think I've got it to pop again. s_lock is only showing 35%
(increasing very slowly if at all) but performance is mostly halted.
Frame pointer is compiled out. perf report attached.

merlin

35.82% postgres [.] s_lock
23.71% postgres [.] tas
14.01% postgres [.] tas
6.82% postgres [.] spin_delay
5.93% postgres [.] LWLockRelease
4.36% postgres [.] LWLockAcquireCommon
2.34% postgres [.] FunctionCall2Coll
1.79% postgres [.] _bt_compare
0.80% postgres [.] LockBuffer
0.52% postgres [.] btoidcmp
0.49% postgres [.] ReleaseAndReadBuffer
0.47% postgres [.] _bt_moveright
0.36% postgres [.] _bt_checkpage
0.36% postgres [.] _bt_relandgetbuf
0.20% perf [.] 0x000000000004312a
0.19% postgres [.] LWLockAcquire
0.13% libv8.so [.] 0x00000000001bbbe0
0.11% libc-2.17.so [.] 0x0000000000151134
0.09% libwebkit.so [.] 0x000000000106ccb7
0.05% libgdk_pixbuf-2.0.so.0.2800.1 [.] 0x00000000000139c7
0.04% Xorg [.] 0x00000000000efb00
0.03% libglib-2.0.so.0.3800.1 [.] 0x00000000000876a2
0.03% [kernel] [k] __ticket_spin_lock
0.02% perf-12966.map [.] 0x00000625db944621
0.02% libskia.so [.] 0x000000000021d15f
0.02% libcairo.so.2.11200.16 [.] 0x000000000002440b
0.02% libpthread-2.17.so [.]
__pthread_mutex_unlock_usercnt
0.02% [kernel] [k]
copy_user_enhanced_fast_string
0.02% radeon_drv.so [.] 0x0000000000045002
0.02% libpthread-2.17.so [.] pthread_mutex_lock
0.02% [kernel] [k] fget_light
0.01% [kernel] [k] __schedule
0.01% libexa.so [.] 0x0000000000006e1d
0.01% libgdk-x11-2.0.so.0.2400.20 [.] 0x000000000002f0b0
0.01% libvte.so.9.2800.2 [.] 0x0000000000039028
0.01% [radeon] [k] r100_mm_rreg
0.01% [kernel] [k] xhci_irq
0.01% [kernel] [k] native_write_msr_safe
0.01% [kernel] [k]
update_cfs_rq_blocked_load
0.01% libglib-2.0.so.0.3800.1 [.] g_hash_table_lookup
0.01% libgobject-2.0.so.0.3800.1 [.]
g_type_check_instance_is_a
Press '?' for help on key bindings

On 2015-01-13 17:39:09 -0600, Merlin Moncure wrote:

On Tue, Jan 13, 2015 at 5:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

On 2015-01-13 15:17:15 -0800, Peter Geoghegan wrote:

I'm inclined to think that this is a livelock, and so the problem
isn't evident from the structure of the B-Tree, but it can't hurt to
check.

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I think I've got it to pop again. s_lock is only showing 35%
(increasing very slowly if at all) but performance is mostly halted.
Frame pointer is compiled out. perf report attached.

35.82% postgres [.] s_lock
23.71% postgres [.] tas
14.01% postgres [.] tas
6.82% postgres [.] spin_delay
5.93% postgres [.] LWLockRelease
4.36% postgres [.] LWLockAcquireCommon

Interesting. This profile looks quite different?

What kind of hardware is this on?

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 3:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I'm not saying you're wrong, but the breakdown of _bt_moveright()
relative to _bt_relandgetbuf() calls seems a bit fishy to me.

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 5:49 PM, Peter Geoghegan <pg@heroku.com> wrote:

On Tue, Jan 13, 2015 at 3:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I'm not saying you're wrong, but the breakdown of _bt_moveright()
relative to _bt_relandgetbuf() calls seems a bit fishy to me.

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

hm, this is hand compiled now, I bet the symbols are wrong.

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2015-01-13 15:49:33 -0800, Peter Geoghegan wrote:

On Tue, Jan 13, 2015 at 3:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I'm not saying you're wrong, but the breakdown of _bt_moveright()
relative to _bt_relandgetbuf() calls seems a bit fishy to me.

The hierarchical profile definitely doesn't look like my guess was
right.

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

Well, we do a _bt_moveright pretty early on, so that actually might be
cache misses we're primarily seing.

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 5:42 PM, Andres Freund <andres@2ndquadrant.com> wrote:

On 2015-01-13 17:39:09 -0600, Merlin Moncure wrote:

On Tue, Jan 13, 2015 at 5:21 PM, Andres Freund <andres@2ndquadrant.com> wrote:

On 2015-01-13 15:17:15 -0800, Peter Geoghegan wrote:

I'm inclined to think that this is a livelock, and so the problem
isn't evident from the structure of the B-Tree, but it can't hurt to
check.

My guess is rather that it's contention on the freelist lock via
StrategyGetBuffer's. I've seen profiles like this due to exactly that
before - and it fits to parallel loading quite well.

I think I've got it to pop again. s_lock is only showing 35%
(increasing very slowly if at all) but performance is mostly halted.
Frame pointer is compiled out. perf report attached.

35.82% postgres [.] s_lock
23.71% postgres [.] tas
14.01% postgres [.] tas
6.82% postgres [.] spin_delay
5.93% postgres [.] LWLockRelease
4.36% postgres [.] LWLockAcquireCommon

Interesting. This profile looks quite different?

yep, it's very stable, and the database is approximately frozen.

What kind of hardware is this on?

linux on crap workstation box, except I have good ssd (intel 3500).

model name : Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz

top - 17:44:00 up 11 days, 6:25, 15 users, load average: 6.94, 6.97, 5.73
Tasks: 259 total, 8 running, 250 sleeping, 0 stopped, 1 zombie
%Cpu0 : 95.7 us, 0.0 sy, 0.0 ni, 4.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 93.5 us, 2.2 sy, 0.0 ni, 4.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu2 : 95.7 us, 0.0 sy, 0.0 ni, 4.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu3 : 93.6 us, 2.1 sy, 0.0 ni, 4.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 8131028 total, 7977608 used, 153420 free, 21424 buffers
KiB Swap: 8340476 total, 1884900 used, 6455576 free, 5201188 cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
32492 mmoncure 20 0 175m 12m 9040 R 64.0 0.2 9:28.42 postgres
32367 mmoncure 20 0 175m 12m 9128 R 57.3 0.2 9:35.87 postgres
31792 mmoncure 20 0 175m 92m 88m R 52.9 1.2 9:57.50 postgres
32725 mmoncure 20 0 175m 13m 9852 R 52.9 0.2 9:08.50 postgres
31899 mmoncure 20 0 179m 104m 97m R 50.7 1.3 9:49.51 postgres
32368 mmoncure 20 0 175m 12m 9200 R 50.7 0.2 9:33.77 postgres
31282 mmoncure 20 0 184m 152m 140m R 46.3 1.9 10:26.29 postgres
666 mmoncure 20 0 20640 1684 1116 R 2.2 0.0 0:00.01 top

Some more information what's happening:
This is a ghetto logical replication engine that migrates data from
sql sever to postgres, consolidating a sharded database into a single
set of tables (of which there are only two). There is only one index
on the destination table, and it's composite int,int in both cases.

A single source table is replicated in a single transaction, and it's
staged to a set of two temp tables, one for deletes, one for inserts.
I log each step in the database. Here are the times:

cds2=# select cdsruntableid, finished - started, inserted from
cdsruntable where cdsrunid = 62 order by started;
cdsruntableid │ ?column? │ inserted
───────────────┼─────────────────┼──────────
833 │ 00:00:33.24044 │ 11860
834 │ 00:00:35.44981 │ 19099
835 │ 00:02:01.725186 │ 530923
836 │ 00:01:29.578811 │ 211737
838 │ 00:01:17.393461 │ 64258
837 │ 00:00:56.849106 │ 227844
839 │ 00:02:12.016504 │ 630309
840 │ 00:00:00.00111 │
841 │ 00:01:09.058806 │ 155309
842 │ 00:01:54.723747 │ 704422
843 │ 00:01:14.965304 │
844 │ 00:00:45.410953 │ 59934
845 │ 00:00:34.302632 │ 14848
846 │ 00:00:46.913832 │ 89893
848 │ 00:05:22.155189 │ 2410622
847 │ 00:01:25.199141 │ 268157
849 │ 00:01:16.168352 │ 117511
850 │ 00:00:34.809862 │ 1175
851 │ 00:01:12.565397 │ 67214
852 │ 00:01:03.734776 │ 20129
853 │ 00:00:41.038456 │ 62765
854 │ 00:01:03.478917 │ 14967
855 │ 00:00:33.88803 │ 6901
856 │ 00:00:36.381886 │ 6670
857 │ 00:00:36.626623 │ 8268
858 │ 00:01:14.391584 │ 363448
859 │ 00:01:44.619005 │ 533395
860 │ 00:01:02.042255 │ 212202
861 │ 00:00:00.001065 │
863 │ 00:00:58.265506 │ 215234
862 │ 00:02:45.572635 │ 827941
865 │ 00:01:28.049165 │ 241020
864 │ 00:01:51.465643 │ 531012
866 │ 00:01:20.273391 │ 419357
868 │ 00:01:25.479443 │ 294262
869 │ 00:00:46.400825 │ 46136
870 │ 00:00:42.337286 │ 25934
871 │ 00:00:48.350152 │ 91375
872 │ 00:00:00.001743 │
873 │ 00:01:04.596749 │ 199744
876 │ 00:01:15.210301 │ 276276
877 │ 00:02:36.447723 │ 1693887
878 │ 00:00:55.925104 │ 36938
879 │ 00:00:00.016874 │
882 │ 00:00:50.479248 │ 171901
881 │ │
884 │ │
883 │ │
867 │ │
874 │ │
875 │ │
880 │ │
(52 rows)

There is a an 8 thread worker that walks that queue in id order and
migrates one source table of data to the destination postgres server.
It's been stuck for quite some time now, and I'm certain that if I
restart the database, and rerun the incremental processing routine, it
would work those last seven tables with no issues (at least that's
what happened last time). It's been bogged with no progress now for a
half hour again, so there's some kind of weird bug here.

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 3:50 PM, Merlin Moncure <mmoncure@gmail.com> wrote:

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

hm, this is hand compiled now, I bet the symbols are wrong.

In case it isn't clear, I think that the proximate cause here may well
be either one (or both) of commits
efada2b8e920adfdf7418862e939925d2acd1b89 and/or
40dae7ec537c5619fc93ad602c62f37be786d161. Probably the latter. I think
that the profile is roughly consistent with that, although I may well
be wrong.

--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 5:54 PM, Peter Geoghegan <pg@heroku.com> wrote:

On Tue, Jan 13, 2015 at 3:50 PM, Merlin Moncure <mmoncure@gmail.com> wrote:

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

hm, this is hand compiled now, I bet the symbols are wrong.

In case it isn't clear, I think that the proximate cause here may well
be either one (or both) of commits
efada2b8e920adfdf7418862e939925d2acd1b89 and/or
40dae7ec537c5619fc93ad602c62f37be786d161. Probably the latter. I think
that the profile is roughly consistent with that, although I may well
be wrong.

I'm out of time for the day, but I'm fairly confident I can reproduce.
I'll see if I can reverse those commits tomorrow and retest (I'm on
development box).

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Merlin Moncure <mmoncure@gmail.com> writes:

On Tue, Jan 13, 2015 at 5:54 PM, Peter Geoghegan <pg@heroku.com> wrote:

In case it isn't clear, I think that the proximate cause here may well
be either one (or both) of commits
efada2b8e920adfdf7418862e939925d2acd1b89 and/or
40dae7ec537c5619fc93ad602c62f37be786d161. Probably the latter. I think
that the profile is roughly consistent with that, although I may well
be wrong.

I'm out of time for the day, but I'm fairly confident I can reproduce.
I'll see if I can reverse those commits tomorrow and retest (I'm on
development box).

I'm not convinced that Peter is barking up the right tree. I'm noticing
that the profiles seem rather skewed towards parser/planner work; so I
suspect the contention is probably on access to system catalogs. No
idea exactly why though.

It would be good to collect a few stack traces from the hung backends,
rather than relying on perf statistics.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2015-01-13 19:05:10 -0500, Tom Lane wrote:

Merlin Moncure <mmoncure@gmail.com> writes:

On Tue, Jan 13, 2015 at 5:54 PM, Peter Geoghegan <pg@heroku.com> wrote:

In case it isn't clear, I think that the proximate cause here may well
be either one (or both) of commits
efada2b8e920adfdf7418862e939925d2acd1b89 and/or
40dae7ec537c5619fc93ad602c62f37be786d161. Probably the latter. I think
that the profile is roughly consistent with that, although I may well
be wrong.

I'm out of time for the day, but I'm fairly confident I can reproduce.
I'll see if I can reverse those commits tomorrow and retest (I'm on
development box).

I'm not convinced that Peter is barking up the right tree. I'm noticing
that the profiles seem rather skewed towards parser/planner work; so I
suspect the contention is probably on access to system catalogs. No
idea exactly why though.

The plan contains plpgsql and exec_stmt_dynexecute(). So it might just
be executing crazy amounts of dynamic statements.

I'm still wondering if this isn'ta different issue to the first one, the
plans do look different.

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 4:05 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

I'm not convinced that Peter is barking up the right tree. I'm noticing
that the profiles seem rather skewed towards parser/planner work; so I
suspect the contention is probably on access to system catalogs. No
idea exactly why though.

I see no int4cmp() calls at all, but plenty of _bt_compare(), and some
FunctionCall2Coll(). And yet, no _bt_binsrch(). I can see btoidcmp(),
so if I'm right then I guess it's a system catalog index.

I too would like to see a stack trace.

Trivia: pg_attribute_relid_attnam_index has deleted B-Tree pages after
a fresh initdb.
--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 3:54 PM, Andres Freund <andres@2ndquadrant.com> wrote:

I don't remember seeing _bt_moveright() or _bt_compare() figuring so
prominently, where _bt_binsrch() is nowhere to be seen. I can't see a
reference to _bt_binsrch() in either profile.

Well, we do a _bt_moveright pretty early on, so that actually might be
cache misses we're primarily seing.

Still, I see zero references to _bt_binsrch(). Not one. Even if there
was only one non-meta page (i.e. pre-first-root-split), and regardless
of whether this was a read or a write to the B-Tree, there'd still be
some call there as the B-Tree was initially scanned (before _bt_next()
calls, of which I also see none).

--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 3:54 PM, Merlin Moncure <mmoncure@gmail.com> wrote:

Some more information what's happening:
This is a ghetto logical replication engine that migrates data from
sql sever to postgres, consolidating a sharded database into a single
set of tables (of which there are only two). There is only one index
on the destination table, and it's composite int,int in both cases.

Does the logical replication engine perform dynamic DDL at all? Does
it dynamically add columns to the table that everything is being
consolidated to?

--
Peter Geoghegan

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Tue, Jan 13, 2015 at 7:24 PM, Peter Geoghegan <pg@heroku.com> wrote:

On Tue, Jan 13, 2015 at 3:54 PM, Merlin Moncure <mmoncure@gmail.com> wrote:

Some more information what's happening:
This is a ghetto logical replication engine that migrates data from
sql sever to postgres, consolidating a sharded database into a single
set of tables (of which there are only two). There is only one index
on the destination table, and it's composite int,int in both cases.

Does the logical replication engine perform dynamic DDL at all? Does
it dynamically add columns to the table that everything is being
consolidated to?

I let the test burn in all night. It's still exactly where it
was...this is not slow performance, it's stuck.

It works like this:
Dynamically create staging table for inserts/change
Dynamically create staging table for deletes
Dynamically create master table if not present (in this last run, it
was was present)
Dynamically delete from master via delete table
Dynamically delete from master via insert/change table (based on int/int key)
Dynamically insert/select from inserts/change to permanent

There is also some log/tracking information going on in other tables.

Here's a backtrace:

#0 0x0000000000750a97 in spin_delay ()
#1 0x0000000000750b19 in s_lock ()
#2 0x0000000000750844 in LWLockRelease ()
#3 0x0000000000730000 in LockBuffer ()
#4 0x00000000004b2db4 in _bt_relandgetbuf ()
#5 0x00000000004b7116 in _bt_moveright ()
#6 0x00000000004b6e02 in _bt_search ()
#7 0x00000000004b8006 in _bt_first ()
#8 0x00000000004b5aad in btgettuple ()
#9 0x0000000000896656 in FunctionCall2Coll ()
#10 0x00000000004acd55 in index_getnext_tid ()
#11 0x00000000004acfad in index_getnext ()
#12 0x00000000004ac120 in systable_getnext ()
#13 0x0000000000878ce4 in ScanPgRelation ()
#14 0x0000000000879eb1 in RelationBuildDesc ()
#15 0x000000000087bb52 in RelationIdGetRelation ()
#16 0x0000000000495115 in relation_open ()
#17 0x00000000004952f9 in relation_openrv_extended ()
#18 0x000000000049555e in heap_openrv_extended ()
#19 0x000000000057ef0b in parserOpenTable ()
#20 0x000000000056776f in setTargetTable ()
#21 0x000000000053628f in transformDeleteStmt ()
#22 0x000000000053603c in transformStmt ()
#23 0x0000000000535fdb in transformTopLevelStmt ()
#24 0x0000000000535db8 in parse_analyze ()
#25 0x000000000075dd4f in pg_analyze_and_rewrite ()
#26 0x00000000006472a5 in _SPI_execute_plan ()
#27 0x0000000000644551 in SPI_execute ()
#28 0x00007f89b83a8ce7 in exec_stmt_dynexecute () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#29 0x00007f89b83a4c43 in exec_stmt () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#30 0x00007f89b83a495f in exec_stmts () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#31 0x00007f89b83a480a in exec_stmt_block () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#32 0x00007f89b83a2802 in plpgsql_exec_function () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#33 0x00007f89b839cd6a in plpgsql_call_handler () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#34 0x0000000000618805 in ExecMakeTableFunctionResult ()
#35 0x00000000006376ba in FunctionNext ()
#36 0x000000000061f868 in ExecScanFetch ()
#37 0x000000000061f8d7 in ExecScan ()
#38 0x0000000000637a1d in ExecFunctionScan ()
#39 0x0000000000614cfd in ExecProcNode ()
#40 0x0000000000612c32 in ExecutePlan ()
#41 0x00000000006110c3 in standard_ExecutorRun ()
---Type <return> to continue, or q <return> to quit---
#42 0x0000000000610fc5 in ExecutorRun ()
#43 0x0000000000647b02 in _SPI_pquery ()
#44 0x00000000006475e8 in _SPI_execute_plan ()
#45 0x000000000064471d in SPI_execute_plan_with_paramlist ()
#46 0x00007f89b83a85a5 in exec_stmt_execsql () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#47 0x00007f89b83a4c28 in exec_stmt () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#48 0x00007f89b83a495f in exec_stmts () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#49 0x00007f89b83a4429 in exec_stmt_block () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#50 0x00007f89b83a4a5d in exec_stmt () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#51 0x00007f89b83a495f in exec_stmts () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#52 0x00007f89b83a54a5 in exec_stmt_loop () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#53 0x00007f89b83a4aff in exec_stmt () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#54 0x00007f89b83a495f in exec_stmts () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#55 0x00007f89b83a5241 in exec_stmt_if () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#56 0x00007f89b83a4ac9 in exec_stmt () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#57 0x00007f89b83a495f in exec_stmts () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#58 0x00007f89b83a480a in exec_stmt_block () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#59 0x00007f89b83a2802 in plpgsql_exec_function () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#60 0x00007f89b839cd6a in plpgsql_call_handler () from
/home/mmoncure/pg94/lib/postgresql/plpgsql.so
#61 0x0000000000618403 in ExecMakeFunctionResultNoSets ()
#62 0x0000000000618e01 in ExecEvalFunc ()
#63 0x000000000061f0f7 in ExecTargetList ()
#64 0x000000000061f6dd in ExecProject ()
#65 0x0000000000638a03 in ExecResult ()
#66 0x0000000000614c16 in ExecProcNode ()
#67 0x0000000000612c32 in ExecutePlan ()
#68 0x00000000006110c3 in standard_ExecutorRun ()
#69 0x0000000000610fc5 in ExecutorRun ()
#70 0x0000000000764725 in PortalRunSelect ()
#71 0x00000000007643b4 in PortalRun ()
#72 0x000000000075e484 in exec_simple_query ()
#73 0x00000000007626e2 in PostgresMain ()
#74 0x00000000006f463f in BackendRun ()
#75 0x00000000006f3d44 in BackendStartup ()
#76 0x00000000006f075e in ServerLoop ()
#77 0x00000000006efdec in PostmasterMain ()
#78 0x00000000006594ec in main ()

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On Wed, Jan 14, 2015 at 8:03 AM, Merlin Moncure <mmoncure@gmail.com> wrote:

Here's a backtrace:

#0 0x0000000000750a97 in spin_delay ()
#1 0x0000000000750b19 in s_lock ()
#2 0x0000000000750844 in LWLockRelease ()
#3 0x0000000000730000 in LockBuffer ()
#4 0x00000000004b2db4 in _bt_relandgetbuf ()
#5 0x00000000004b7116 in _bt_moveright ()
#6 0x00000000004b6e02 in _bt_search ()
#7 0x00000000004b8006 in _bt_first ()
#8 0x00000000004b5aad in btgettuple ()
#9 0x0000000000896656 in FunctionCall2Coll ()
#10 0x00000000004acd55 in index_getnext_tid ()
#11 0x00000000004acfad in index_getnext ()

There were seven process with that backtrace exact backtrace (except
that randomly they are sleeping in the spinloop). Something else
interesting: autovacuum has been running all night as well. Unlike
the other process however, cpu utilization does not register on top.
I backtraced them as well. They are not identical. One of them looks
like this:

#0 0x00007f89c1b21a97 in semop () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00000000006de073 in PGSemaphoreLock ()
#2 0x000000000074e398 in ProcWaitForSignal ()
#3 0x00000000007302cb in LockBufferForCleanup ()
#4 0x00000000004b699e in btvacuumpage ()
#5 0x00000000004b6627 in btvacuumscan ()
#6 0x00000000004b6389 in btbulkdelete ()
#7 0x00000000008968d7 in FunctionCall4Coll ()
#8 0x00000000004ad196 in index_bulk_delete ()
#9 0x000000000060b9ed in lazy_vacuum_index ()
#10 0x000000000060b019 in lazy_scan_heap ()
#11 0x0000000000609836 in lazy_vacuum_rel ()
#12 0x0000000000609383 in vacuum_rel ()
#13 0x0000000000607e4a in vacuum ()
#14 0x00000000006e2d40 in autovacuum_do_vac_analyze ()
#15 0x00000000006e2127 in do_autovacuum ()
#16 0x00000000006e0f19 in AutoVacWorkerMain ()
#17 0x00000000006e0b06 in StartAutoVacWorker ()
#18 0x00000000006f4fac in StartAutovacuumWorker ()
#19 0x00000000006f4816 in sigusr1_handler ()
#20 <signal handler called>
#21 0x00007f89c1b17dc3 in select () from /lib/x86_64-linux-gnu/libc.so.6
#22 0x00000000006f0619 in ServerLoop ()
#23 0x00000000006efdec in PostmasterMain ()
#24 0x00000000006594ec in main ()

The other autovacuum process (0 cpu usage) looks like this:
#0 0x00007f89c1b17dc3 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00000000008d3ac4 in pg_usleep ()
#2 0x0000000000750b69 in s_lock ()
#3 0x0000000000750844 in LWLockRelease ()
#4 0x0000000000730000 in LockBuffer ()
#5 0x00000000004b2db4 in _bt_relandgetbuf ()
#6 0x00000000004b7116 in _bt_moveright ()
#7 0x00000000004b6e02 in _bt_search ()
#8 0x00000000004b8006 in _bt_first ()
#9 0x00000000004b5aad in btgettuple ()
#10 0x0000000000896656 in FunctionCall2Coll ()
#11 0x00000000004acd55 in index_getnext_tid ()
#12 0x00000000004acfad in index_getnext ()
#13 0x00000000004ac120 in systable_getnext ()
#14 0x0000000000878ce4 in ScanPgRelation ()
#15 0x000000000087bcc4 in RelationReloadIndexInfo ()
#16 0x000000000087c1f1 in RelationClearRelation ()
#17 0x000000000087ca37 in RelationCacheInvalidate ()
#18 0x0000000000875fce in InvalidateSystemCaches ()
#19 0x0000000000741d81 in ReceiveSharedInvalidMessages ()
#20 0x0000000000876080 in AcceptInvalidationMessages ()
#21 0x0000000000745ce3 in LockRelationOid ()
#22 0x000000000049510b in relation_open ()
#23 0x0000000000495359 in heap_open ()
#24 0x0000000000608694 in vac_update_relstats ()
#25 0x000000000060bb98 in lazy_cleanup_index ()
#26 0x000000000060b0b6 in lazy_scan_heap ()
#27 0x0000000000609836 in lazy_vacuum_rel ()
#28 0x0000000000609383 in vacuum_rel ()
#29 0x0000000000607e4a in vacuum ()
#30 0x00000000006e2d40 in autovacuum_do_vac_analyze ()
#31 0x00000000006e2127 in do_autovacuum ()
#32 0x00000000006e0f19 in AutoVacWorkerMain ()
#33 0x00000000006e0b06 in StartAutoVacWorker ()
#34 0x00000000006f4fac in StartAutovacuumWorker ()
#35 0x00000000006f4816 in sigusr1_handler ()
#36 <signal handler called>
#37 0x00007f89c1b17dc3 in select () from /lib/x86_64-linux-gnu/libc.so.6
#38 0x00000000006f0619 in ServerLoop ()
#39 0x00000000006efdec in PostmasterMain ()
#40 0x00000000006594ec in main ()

merlin

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers