Re: [GENERAL] Concurrency problem building indexes

On 4/25/06 9:58 AM, "Tom Lane" <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> I can't think of any effect in the PG code that would make CREATE INDEX
> commands tend to converge rather than diverge, so maybe there is some
> external effect here. Wes, is your machine a dual processor by any
> chance? Which OS X version exactly?

No, I'm running on a single processor powerbook. I currently am running OS
X 10.4.5 on this system, 1GB memory.

A while back, I saw a posting (I think from Tom) to the effect of index
creation converging due to disk caching. It was along the lines of the
slower index would be reading from disk data cached by the first index
creation's read. When the faster creation went out to read from disk, the
one reading from memory could catch up. Possible?

Below is the (mostly psql) output from the creation script. Timing is
enabled. It's a bit difficult to follow because of the multiprocessing.
The index build script is perl, using popen to talk to psql. $|=1 is set on
the command pipe to flush each command to the process. I can provide that
if you want. If needed I could rewrite it using DBI to get easier to read
logging.

This is 6 tables, and I get three errors. The header table has 3 indexes,
and the detail table has 4.

Wes

In buildIndex type=header date=20050904 which=1
939: header date <<<<<----- The number is the PID of the child process
939: header msgid
\timing
Timing is on.
create index header_i_date_20050904
on header_20050904 (mdate) TABLESPACE indexes;
header 1 forked 939
In buildIndex type=header date=20050904 which=2
942: header originator
\timing
Timing is on.
create index header_i_originator_20050904
on header_20050904 (originator) TABLESPACE indexes;
header 2 forked 942
Waiting for index builds to complete
CREATE INDEX
Time: 79.463 ms
\q
ERROR: tuple concurrently updated
create index header_i_msgid_20050904
on header_20050904 (messageid) TABLESPACE indexes;
942 completed.
CREATE INDEX
Time: 7.125 ms
\q
939 completed.
header 1 forked 946
header 2 forked 947
Waiting for index builds to complete
In buildIndex type=header date=20050905 which=1
In buildIndex type=header date=20050905 which=2
946: header date
946: header msgid
947: header originator
\timing
Timing is on.
create index header_i_originator_20050905
on header_20050905 (originator) TABLESPACE indexes;
\timing
Timing is on.
create index header_i_date_20050905
on header_20050905 (mdate) TABLESPACE indexes;
CREATE INDEX
Time: 444.957 ms
create index header_i_msgid_20050905
on header_20050905 (messageid) TABLESPACE indexes;
CREATE INDEX
Time: 569.063 ms
\q
947 completed.
CREATE INDEX
Time: 293.467 ms
\q
946 completed.
header 1 forked 953
In buildIndex type=header date=20050906 which=1
In buildIndex type=header date=20050906 which=2
header 2 forked 954
Waiting for index builds to complete
953: header date
953: header msgid
954: header originator
\timing
Timing is on.
create index header_i_originator_20050906
on header_20050906 (originator) TABLESPACE indexes;
\timing
Timing is on.
create index header_i_date_20050906
on header_20050906 (mdate) TABLESPACE indexes;
CREATE INDEX
Time: 1048.094 ms
create index header_i_msgid_20050906
on header_20050906 (messageid) TABLESPACE indexes;
ERROR: tuple concurrently updated
\q
954 completed.
CREATE INDEX
Time: 566.794 ms
\q
953 completed.
In buildIndex type=detail date=20050904 which=1
960: detail originator
960: detail date
\timing
Timing is on.
create index detail_i_originator_20050904
on detail_20050904 (originator) TABLESPACE indexes;
detail 1 forked 960
In buildIndex type=detail date=20050904 which=2
963: detail recipient
963: detail msgid
\timing
Timing is on.
create index detail_i_recipient_20050904
on detail_20050904 (recipient) TABLESPACE indexes;
CREATE INDEX
Time: 11.679 ms
create index detail_i_msgid_20050904
on detail_20050904 (messageid) TABLESPACE indexes;
CREATE INDEX
Time: 4.952 ms
\q
detail 2 forked 963
Waiting for index builds to complete
963 completed.
CREATE INDEX
Time: 123.106 ms
create index detail_i_date_20050904
on detail_20050904 (mdate) TABLESPACE indexes;
CREATE INDEX
Time: 5.724 ms
\q
960 completed.
In buildIndex type=detail date=20050905 which=1
967: detail originator
967: detail date
\timing
Timing is on.
create index detail_i_originator_20050905
on detail_20050905 (originator) TABLESPACE indexes;
detail 1 forked 967
In buildIndex type=detail date=20050905 which=2
971: detail recipient
971: detail msgid
\timing
Timing is on.
create index detail_i_recipient_20050905
on detail_20050905 (recipient) TABLESPACE indexes;
detail 2 forked 971
Waiting for index builds to complete
CREATE INDEX
Time: 1223.597 ms
create index detail_i_date_20050905
on detail_20050905 (mdate) TABLESPACE indexes;
ERROR: tuple concurrently updated
create index detail_i_msgid_20050905
on detail_20050905 (messageid) TABLESPACE indexes;
CREATE INDEX
Time: 629.056 ms
\q
967 completed.
CREATE INDEX
Time: 568.197 ms
\q
971 completed.
In buildIndex type=detail date=20050906 which=1
975: detail originator
975: detail date
\timing
Timing is on.
create index detail_i_originator_20050906
on detail_20050906 (originator) TABLESPACE indexes;
detail 1 forked 975
In buildIndex type=detail date=20050906 which=2
978: detail recipient
978: detail msgid
detail 2 forked 978
Waiting for index builds to complete
\timing
Timing is on.
create index detail_i_recipient_20050906
on detail_20050906 (recipient) TABLESPACE indexes;
CREATE INDEX
Time: 2680.001 ms
create index detail_i_date_20050906
on detail_20050906 (mdate) TABLESPACE indexes;
CREATE INDEX
Time: 2675.191 ms
create index detail_i_msgid_20050906
on detail_20050906 (messageid) TABLESPACE indexes;
CREATE INDEX
Time: 2022.232 ms
\q
CREATE INDEX
Time: 1910.771 ms
\q
978 completed.
975 completed.