BUG #15460: Error while creating index or constraint

On Fri, Oct 26, 2018 at 10:32 AM PG Bug reporting form
<noreply@postgresql.org> wrote:

On large tables I get an error on:

CREATE INDEX nx_tablename ON tablename USING btree (col1); col1 being an
integer
and
ALTER TABLE ONLY tablename ADD CONSTRAINT pk_tablename PRIMARY KEY (col1,
col2); col1 and col2 both integer

First noticed that with pg_restore (from a pg_dump from PG10)
pg_restore: [archiver (db)] Error while PROCESSING TOC:
pg_restore: [archiver (db)] Error from TOC entry 14005; 1259 546886907 INDEX
nx_tablename postgres
pg_restore: [archiver (db)] could not execute query: ERROR: could not
determine
size of temporary file "0"
Command was: CREATE INDEX nx_tablename ON tablename USING btree
(col1);

I initially suspected that this was caused by commit 445e31bdc74. This
commit made the parallel CREATE INDEX leader call BufFileSize(),
rather than having each worker call it themselves. It is where the
error message from Paul actually originated from. The commit also
changed BufFileSize() so that it would lseek(), rather than just
passing filesize metadata through shared memory.

I'm not sure what the exact problem might be, because I can't see why
the BufFileSize() thing would fail, even on Windows. I think that
using lseek() + SEEK_END to get the size of a file may only work on
POSIX, and yet I can see the same pattern in much older code (e.g.,
_mdnblocks()). I don't have a Windows machine, and the spec seems
rather hard to read here.

I have a strong suspicion that going back to passing the size through
shared memory (i.e. partially reverting 445e31bdc74) would make the
problem go away, but I won't do that until I actually understand
what's going on.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 11:41 AM Peter Geoghegan <pg@bowt.ie> wrote:

I have a strong suspicion that going back to passing the size through
shared memory (i.e. partially reverting 445e31bdc74) would make the
problem go away, but I won't do that until I actually understand
what's going on.

BufFileOpenShared()/SharedFileSetOpen() is allowed to fail in the
event of no file (an ENOENT) within PathNameOpenTemporaryFile(). OTOH,
BufFileSize() can throw an error due to the same condition following
445e31bdc74, which is what we see here. If it's okay in the first
function, why shouldn't it be okay in the second function, which is
called shortly afterwards? That's where Paul's ERRCODE_UNDEFINED_FILE
actually comes from. ISTM that only one of those assumptions can be
correct.

I thought that parallel CREATE INDEX didn't need to rely on this
ENOENT-is-okay business, and that that was just there for parallel
hash join, which is why I didn't complain when 445e31bdc74 went in. It
now seems like logtape.c could correctly rely on ENOENT-is-okay,
though. I think that temporary file "0" is almost always the
leader-as-worker fileset, which may be relevant.

Paul: Does varying whether an index is unique or not change the
outcome of any of your failing test cases?

Does anyone see a way in which the logtape.c + shared buffile stuff
could come to rely on assuming that an ENOENT case relates to an empty
worker BufFile? I suppose it's also possible that there is a bug that
partially reverting 445e31bdc74 would only mask, though that seems
less likely.

--
Peter Geoghegan

It happens with both unique and non-unique index.
When I disable virusscanner I also get the error, but settin g the max_parallel_workers to 0 does let me create the index

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 13:27
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
Cc: Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 11:41 AM Peter Geoghegan <pg@bowt.ie> wrote:

I have a strong suspicion that going back to passing the size through
shared memory (i.e. partially reverting 445e31bdc74) would make the
problem go away, but I won't do that until I actually understand
what's going on.

BufFileOpenShared()/SharedFileSetOpen() is allowed to fail in the event of no file (an ENOENT) within PathNameOpenTemporaryFile(). OTOH,
BufFileSize() can throw an error due to the same condition following 445e31bdc74, which is what we see here. If it's okay in the first function, why shouldn't it be okay in the second function, which is called shortly afterwards? That's where Paul's ERRCODE_UNDEFINED_FILE actually comes from. ISTM that only one of those assumptions can be correct.

I thought that parallel CREATE INDEX didn't need to rely on this ENOENT-is-okay business, and that that was just there for parallel hash join, which is why I didn't complain when 445e31bdc74 went in. It now seems like logtape.c could correctly rely on ENOENT-is-okay, though. I think that temporary file "0" is almost always the leader-as-worker fileset, which may be relevant.

Paul: Does varying whether an index is unique or not change the outcome of any of your failing test cases?

Does anyone see a way in which the logtape.c + shared buffile stuff could come to rely on assuming that an ENOENT case relates to an empty worker BufFile? I suppose it's also possible that there is a bug that partially reverting 445e31bdc74 would only mask, though that seems less likely.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 12:45 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

It happens with both unique and non-unique index.
When I disable virusscanner I also get the error, but settin g the max_parallel_workers to 0 does let me create the index

Thanks for trying that out. This confirms that parallel CREATE INDEX
is involved.

Is it possible for you to provide me with a dump of the data, or a
minimal test case? You can provided it to me off-list if that's
easier, possibly using Google drive or something. I realize that the
amount of data involved here isn't trivial, so this may be difficult.

I'm a little suspicious of the fact that your table is probably
aligned to certain boundaries, since it consists only of
integers/bigints. Maybe that's just a coincidence, though.

Thanks
--
Peter Geoghegan

Well I also saw it on uuids and possibly enum.
One of the tables is a materialized view with 550161114 records consisting of 2 uuid-colums and 2 enum columns.
Total size is 34 GB...

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 13:53
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 12:45 PM Paul van der Linden <paul.vanderlinden@mapcreator.eu> wrote:

It happens with both unique and non-unique index.
When I disable virusscanner I also get the error, but settin g the
max_parallel_workers to 0 does let me create the index

Thanks for trying that out. This confirms that parallel CREATE INDEX is involved.

Is it possible for you to provide me with a dump of the data, or a minimal test case? You can provided it to me off-list if that's easier, possibly using Google drive or something. I realize that the amount of data involved here isn't trivial, so this may be difficult.

I'm a little suspicious of the fact that your table is probably aligned to certain boundaries, since it consists only of integers/bigints. Maybe that's just a coincidence, though.

Thanks
--
Peter Geoghegan

On Mon, Oct 29, 2018 at 12:53 PM Peter Geoghegan <pg@bowt.ie> wrote:

Is it possible for you to provide me with a dump of the data, or a
minimal test case? You can provided it to me off-list if that's
easier, possibly using Google drive or something. I realize that the
amount of data involved here isn't trivial, so this may be difficult.

It might also be helpful to see if amcheck shows any problems with the
indexes you can create without error. You could run:

CREATE EXTENSION amcheck;

SELECT bt_index_check(index => c.oid, heapallindexed => true),
c.relname,
c.relpages
FROM pg_index i
JOIN pg_opclass op ON i.indclass[0] = op.oid
JOIN pg_am am ON op.opcmethod = am.oid
JOIN pg_class c ON i.indexrelid = c.oid
JOIN pg_namespace n ON c.relnamespace = n.oid
WHERE am.amname = 'btree'
-- Don't check temp tables, which may be from another session:
AND c.relpersistence != 't'
-- Function may throw an error when this is omitted:
AND c.relkind = 'i' AND i.indisready AND i.indisvalid
ORDER BY c.relpages DESC;

Hopefully this won't find any problems/raise any errors, but if it
does then they'll likely be relevant. It might take several minutes to
run the query, or maybe even several hour if there is lots of data.
You may have to use your own judgement when it comes to determining
what's worth checking, and what you don't have time to check (e.g.,
add something extra to the where clause, so that only some indexes get
checked). I'm suggesting this because it isn't very much work, and may
shed some light on the problem. Though the likelihood is that it won't
find anything wrong.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 1:01 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

Well I also saw it on uuids and possibly enum.
One of the tables is a materialized view with 550161114 records consisting of 2 uuid-colums and 2 enum columns.
Total size is 34 GB...

Another thing that could be helpful is if you "set trace_sort = on"
within your session/pgAdmin, and showed us log output from the start
of the failing CREATE INDEX to the point that it fails. You may or may
not want to "set client_min_messages = LOG" while you're at it, since
that will send LOG output to the client, which may be more convenient.

Thanks
--
Peter Geoghegan

Amcheck is still running.
Trace_sort is attached

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 14:26
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 1:01 PM Paul van der Linden <paul.vanderlinden@mapcreator.eu> wrote:

Well I also saw it on uuids and possibly enum.
One of the tables is a materialized view with 550161114 records consisting of 2 uuid-colums and 2 enum columns.
Total size is 34 GB...

Another thing that could be helpful is if you "set trace_sort = on"
within your session/pgAdmin, and showed us log output from the start of the failing CREATE INDEX to the point that it fails. You may or may not want to "set client_min_messages = LOG" while you're at it, since that will send LOG output to the client, which may be more convenient.

Thanks
--
Peter Geoghegan

On Mon, Oct 29, 2018 at 1:44 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

Amcheck is still running.
Trace_sort is attached

This first line looks like it might be interesting:

LOG: could not rmdir directory
"base/pgsql_tmp/pgsql_tmp5088.0.sharedfileset": Directory not empty
ERROR: could not determine size of temporary file "0"

I suppose that this could actually just be a result of the ERROR; the
exact order isn't a reliable indicator of the sequence of events
across processes (A useful log_line_prefix setting might clear this up
if you collect the trace_sort output again).

Can you show me the contents of the directory that we fail to rmdir
here? Their names, and their size. The directory should remain around
until you restart the server, since the usual error cleanup path
doesn't successfully finish here.

Thanks
--
Peter Geoghegan

On Mon, Oct 29, 2018 at 2:11 PM Peter Geoghegan <pg@bowt.ie> wrote:

I suppose that this could actually just be a result of the ERROR; the
exact order isn't a reliable indicator of the sequence of events
across processes (A useful log_line_prefix setting might clear this up
if you collect the trace_sort output again).

For example, this log_line_prefix will show process PID, and a timestamp:

log_line_prefix='%p/%t '

--
Peter Geoghegan

Directory is empty (when I check after the error occurred, no idea yet (will test) if there's something there during index creation.
And for some reason I'm not able to set the log_line_prefix in my pgAdmin session... ERROR: parameter "log_line_prefix" cannot be changed now

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 15:13
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 2:11 PM Peter Geoghegan <pg@bowt.ie> wrote:

I suppose that this could actually just be a result of the ERROR; the
exact order isn't a reliable indicator of the sequence of events
across processes (A useful log_line_prefix setting might clear this up
if you collect the trace_sort output again).

For example, this log_line_prefix will show process PID, and a timestamp:

log_line_prefix='%p/%t '

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 2:19 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

Directory is empty (when I check after the error occurred, no idea yet (will test) if there's something there during index creation.

There'll definitely be something during index creation, though the
exact directory name will vary per operation.

Do you use temp_tablespaces (easy way to find out is to "show
temp_tablespaces")? There's one directory per temp tablespace, so
maybe you looked in the wrong one?

And for some reason I'm not able to set the log_line_prefix in my pgAdmin session... ERROR: parameter "log_line_prefix" cannot be changed now

That needs to be set in postgresql.conf.

--
Peter Geoghegan

I do see some files now (0.0, 1.0 and 2.0) in that directory.
Not able to restart postgres at the moment because it's also running some other stuff...

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 15:23
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 2:19 PM Paul van der Linden <paul.vanderlinden@mapcreator.eu> wrote:

Directory is empty (when I check after the error occurred, no idea yet (will test) if there's something there during index creation.

There'll definitely be something during index creation, though the exact directory name will vary per operation.

Do you use temp_tablespaces (easy way to find out is to "show temp_tablespaces")? There's one directory per temp tablespace, so maybe you looked in the wrong one?

And for some reason I'm not able to set the log_line_prefix in my
pgAdmin session... ERROR: parameter "log_line_prefix" cannot be
changed now

That needs to be set in postgresql.conf.

--
Peter Geoghegan

Oh, and the bt_index_check just finished without any errors

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 15:23
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 2:19 PM Paul van der Linden <paul.vanderlinden@mapcreator.eu> wrote:

Directory is empty (when I check after the error occurred, no idea yet (will test) if there's something there during index creation.

There'll definitely be something during index creation, though the exact directory name will vary per operation.

Do you use temp_tablespaces (easy way to find out is to "show temp_tablespaces")? There's one directory per temp tablespace, so maybe you looked in the wrong one?

And for some reason I'm not able to set the log_line_prefix in my
pgAdmin session... ERROR: parameter "log_line_prefix" cannot be
changed now

That needs to be set in postgresql.conf.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 2:28 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

I do see some files now (0.0, 1.0 and 2.0) in that directory.
Not able to restart postgres at the moment because it's also running some other stuff...

No need to restart. Just call pg_reload_conf() as a superuser, once
postgresql.conf has the change. That won't be disruptive.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 2:11 PM Peter Geoghegan <pg@bowt.ie> wrote:

This first line looks like it might be interesting:

LOG: could not rmdir directory
"base/pgsql_tmp/pgsql_tmp5088.0.sharedfileset": Directory not empty
ERROR: could not determine size of temporary file "0"

(Thomas Munro is CC'd here.)

I suppose that this could actually just be a result of the ERROR; the
exact order isn't a reliable indicator of the sequence of events
across processes (A useful log_line_prefix setting might clear this up
if you collect the trace_sort output again).

Hmm. So apparently Windows has a habit of setting an ENOTEMPTY errcode
when rmdir'ing a directory that somebody merely has a handle to. It
could just be that somebody has a Windows Explorer window open -- you
still get ENOTEMPTY [1]https://github.com/gruntjs/grunt-contrib-clean/issues/66 -- Peter Geoghegan! Not sure if this is truly relevant to the
problem at hand, but it seems worth being aware of.

[1]: https://github.com/gruntjs/grunt-contrib-clean/issues/66 -- Peter Geoghegan
--
Peter Geoghegan

Hm, the log_line_prefix didn't change a lot in the logs...
And what's worse (but completely unrelated): the performance benefits of upgrading to pg11 don't work for me (having a big number of heavy geocalculations unioned all into one select still doesn't use more than one worker/core...)

-----Original Message-----
From: Peter Geoghegan <pg@bowt.ie>
Sent: maandag 29 oktober 2018 15:31
To: Paul van der Linden <paul.vanderlinden@mapcreator.eu>
Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Heikki Linnakangas <hlinnaka@iki.fi>
Subject: Re: BUG #15460: Error while creating index or constraint

On Mon, Oct 29, 2018 at 2:28 PM Paul van der Linden <paul.vanderlinden@mapcreator.eu> wrote:

I do see some files now (0.0, 1.0 and 2.0) in that directory.
Not able to restart postgres at the moment because it's also running some other stuff...

No need to restart. Just call pg_reload_conf() as a superuser, once postgresql.conf has the change. That won't be disruptive.

--
Peter Geoghegan

On Mon, Oct 29, 2018 at 3:18 PM Paul van der Linden
<paul.vanderlinden@mapcreator.eu> wrote:

Hm, the log_line_prefix didn't change a lot in the logs...

That's because log_line_prefix only appears in the server log. It'll
be necessary to go into the server log to get those extra details.

--
Peter Geoghegan

Peter Geoghegan <pg@bowt.ie> writes:

On Fri, Oct 26, 2018 at 10:32 AM PG Bug reporting form
<noreply@postgresql.org> wrote:

pg_restore: [archiver (db)] could not execute query: ERROR: could not
determine size of temporary file "0"
Command was: CREATE INDEX nx_tablename ON tablename USING btree (col1);

I'm not sure what the exact problem might be, because I can't see why
the BufFileSize() thing would fail, even on Windows.

So there are a couple of things to complain about here with respect
to the error message, regardless of the underlying bug:

* "0" is not a file name. Reporting it is just about useless, and
identifying it as a "file" is a lie. Why aren't we reporting the
actual name of the underlying file? (I realize that we might not
have easy access to that right here. But now that this has been
shown to be reachable in the field, it seems worth doing some extra
work to make the error message useful.)

* We aren't reporting the errno (no %m in the message). By luck,
the errcode_for_file_access() call is enough to let us infer that
it was ENOENT in this case, but in other cases that might not be
enough.

I think that
using lseek() + SEEK_END to get the size of a file may only work on
POSIX, and yet I can see the same pattern in much older code (e.g.,
_mdnblocks()).

Yeah, that works fine on Windows AFAIK. I also note that ENOENT
isn't an error code that lseek() can deliver, anyway, since it works
on an already-open FD. The failure here must be coming from opening
the file.

I'm a little inclined to suspect that the true cause here is workers
not correctly computing the name of this temp file, which is what
led me to complain about the error message. Although a weak spot in
this theory is that it's not clear why they'd not fail later anyway,
unless maybe this particular file never got touched by workers before.

I have a strong suspicion that going back to passing the size through
shared memory (i.e. partially reverting 445e31bdc74) would make the
problem go away, but I won't do that until I actually understand
what's going on.

Sounds like papering over the bug ...

regards, tom lane