Thread: temp_file_limit?

On Sun, Dec 18, 2022 at 12:48:03PM +0100, Frits Jalvingh wrote:
> Hi list,
> 
> I have a misbehaving query which uses all available disk space and then
> terminates with a "cannot write block" error. To prevent other processes
> from running into trouble I've set the following:
> 
> temp_file_limit = 100GB

> The comment in the file states that this is a per-session parameter, so
> what is going wrong here?

Do you mean the comment in postgresql.conf ?

commit d1f822e58 changed to say that temp_file_limit is actually
per-process and not per-session.

Could you send the query plan, preferably "explain analyze" (if the
query finishes sometimes) ?

log_temp_files may be helpful here.

> The query does parallelize and uses one parallel worker while executing,
> but it does not abort when the temp file limit is reached:
> 
> 345G pgsql_tmp
> 
> It does abort way later, after using around 300+ GB:
> [53400] ERROR: temporary file size exceeds temp_file_limit (104857600kB)
> Where: parallel worker

Are you sure the 345G are from only one instance of the query ?
Or is it running multiple times, or along with other queries writing
100GB of tempfiles.

It seems possible that it sometimes runs with more than one parallel
worker.  Also, are there old/stray tempfiles there which need to be
cleaned up?

-- 
Justin

Frits Jalvingh <jal@etc.to> writes:
> Just to be clear: my real question is: why is temp_file_limit not working
> at the specified size?

I've not looked at that code lately, but I strongly suspect that
it's implemented in such a way that it's a per-process limit, not a
per-session limit.  So each parallel worker could use up that much
space.

It's also possible that you've found an actual bug, but without
a reproducer case nobody's going to take that possibility too
seriously.  We're unlikely to accept "the limit should work
across multiple processes" as a valid bug though.  That would
require a vastly more complicated implementation.

            regards, tom lane

On Sun, Dec 18, 2022 at 06:29:41PM +0100, Frits Jalvingh wrote:
> Just to be clear: my real question is: why is temp_file_limit not
> working at the specified size? Because this is my real problem: when a
> query is dying like this it will also kill other queries because these
> are also running out of space. Even when the limit is per-process it
> should not have exceeded 200GB imo.

What OS and filesystem are in use ?

Could you list the tmpdir when it's getting huge?  The filenames include
the PID, which would indicate if there's another procecss involved, or a
bug allowed it to get huge.
sudo du --max=2 -mx ./pgsql_tmp |sort -nr

BTW, pg_ls_tmpdir() hides directories, so you shouldn't rely on it for
listing temporary directories...

One possibility is that there are files in the tmpdir, which have been
unlinked, but are still opened, so their space hasn't been reclaimed.
You could check for that by running lsof -nn |grep pgsql_tmp Any deleted
files would say things like 'DEL|deleted|inode|no such'

> BTW, if that limit is really per process instead of per
> session/query then that is a Very Bad Thing(tm), because this makes the
> limit effectively worthless - if a query can spawn 8 parallel processes
> then you can suddenly, without any form of control, again fill up that disk.

8 is the default value of max_worker_processes and max_parallel_workers,
but 2 is the default value of max_parallel_workers_per_gather.  You're
free the change the default value to balance it with the temp_file_limit
(as suggested by the earlier-mentioned commit).

-- 
Justin

On Mon, Dec 19, 2022 at 9:11 AM Justin Pryzby <pryzby@telsasoft.com> wrote:
> On Sun, Dec 18, 2022 at 06:29:41PM +0100, Frits Jalvingh wrote:
> > Just to be clear: my real question is: why is temp_file_limit not
> > working at the specified size? Because this is my real problem: when a
> > query is dying like this it will also kill other queries because these
> > are also running out of space. Even when the limit is per-process it
> > should not have exceeded 200GB imo.

It's really the limit for a single file (or virtual file because we
split them on 1GB boundaries, probably well past time we stopped doing
that), but we create many temporary files for various reasons.  One
possibility is that you've hit a case that needs several rounds of
repartitioning (because of a failure to estimate the number of tuples
well), but we can't see that because you didn't show EXPLAIN (ANALYZE)
output (understandably if it runs out of disk space before
completing...).  The parallel hash code doesn't free up the previous
generations' temporary files; it really only needs two generations'
worth concurrently (the one it's reading from and the one it's writing
to).  In rare cases where more generations are needed it could unlink
the older ones -- that hasn't been implemented yet.  If you set
log_temp_files = 0 to log temporary file names, it should be clear if
it's going through multiple rounds of repartitioning, from the names
(...of32..., ...of64..., ...of128..., ...of256..., ...).

On Mon, Dec 19, 2022 at 1:51 PM Thomas Munro <thomas.munro@gmail.com> wrote:
> It's really the limit for a single file

Oops, sorry I take that back.  It should be per process.

On Mon, Dec 19, 2022 at 05:57:42PM +0100, Frits Jalvingh wrote:
> @justin:
> 
> Ran the query again. Top shows the following processes:
>    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+

Thanks

> root@chatelet:/d2/var/lib/postgresql/15/main/base# du --max=2 -mx
> ./pgsql_tmp |sort -nr
> 412021 ./pgsql_tmp/pgsql_tmp650830.3.fileset
> 412021 ./pgsql_tmp
> ^^^ a few seconds after this last try the query aborted:
> ERROR:  temporary file size exceeds temp_file_limit (104857600kB)
> 
> One possibility is that there are files in the tmpdir, which have been
> > unlinked, but are still opened, so their space hasn't been reclaimed.
> > You could check for that by running lsof -nn |grep pgsql_tmp Any deleted
> > files would say things like 'DEL|deleted|inode|no such'
>
> I do not really understand what you would like me to do, and when. The disk
> space is growing, and it is actual files under pgsql_tmp?

Run this during the query as either postgres or root:
| lsof -nn |grep pgsql_tmp |grep -E 'DEL|deleted|inode|no such'

Any files it lists would be interesting to know about.

> Hope this tells you something, please let me know if you would like more
> info, and again - thanks!

I think Thomas' idea is more likely.  We'd want to know the names of
files being written, either as logged by log_temp_files or from 
| find pgsql_tmp -ls
during the query.

-- 
Justin

On Mon, Dec 19, 2022 at 06:27:57PM +0100, Frits Jalvingh wrote:
> I have listed the files during that run,

> 213M -rw------- 1 postgres postgres 213M dec 19 17:46 i100of128.p0.0
> 207M -rw------- 1 postgres postgres 207M dec 19 17:46 i100of128.p1.0
> 210M -rw------- 1 postgres postgres 210M dec 19 17:49 i100of256.p0.0
> 211M -rw------- 1 postgres postgres 211M dec 19 17:49 i100of256.p1.0
> 188M -rw------- 1 postgres postgres 188M dec 19 17:53 i100of512.p0.0
[...]

I think that proves Thomas' theory.  I'm not sure how that helps you,
though...

On Mon, Dec 19, 2022 at 01:51:33PM +1300, Thomas Munro wrote:
> One possibility is that you've hit a case that needs several rounds of
> repartitioning (because of a failure to estimate the number of tuples
> well), but we can't see that because you didn't show EXPLAIN (ANALYZE)
> output (understandably if it runs out of disk space before
> completing...).  The parallel hash code doesn't free up the previous
> generations' temporary files; it really only needs two generations'
> worth concurrently (the one it's reading from and the one it's writing
> to).  In rare cases where more generations are needed it could unlink
> the older ones -- that hasn't been implemented yet.  If you set
> log_temp_files = 0 to log temporary file names, it should be clear if
> it's going through multiple rounds of repartitioning, from the names
> (...of32..., ...of64..., ...of128..., ...of256..., ...).

-- 
Justin Pryzby
System Administrator
Telsasoft
+1-952-707-8581

On Sun, Dec 18, 2022 at 06:29:41PM +0100, Frits Jalvingh wrote:
> By itself I'm used to bad query performance in Postgresql; our application
> only does bulk queries and Postgres quite often makes terrible plans for
> those, but with set enable_nestloop=false set always most of them at least
> execute. The remaining failing queries are almost 100% caused by bad join
> sequences; I plan to work around those by forcing the join order from our
> application. For instance, the exact same query above can also generate the
> following plan (this one was created by manually setting
> join_collapse_limit = 1, but fast variants also occur quite often when
> disabling parallelism):

I, too, ended up setting enable_nestloop=false for our report queries,
to avoid the worst-case plans.

But you should also try to address the rowcount misestimates.  This
underestimates the rowcount by a factor of 69 (or 138 in the plan you
sent today):

| (soort = 'MSL'::text) AND (code = 'DAE'::text)

If those conditions are correlated, you can improve the estimate by
adding extended stats object.

| CREATE STATISTICS s_h_sturingslabel_ssm_stats soort,code FROM s_h_sturingslabel_ssm; ANALYZE s_h_sturingslabel_ssm;

Unfortunately, stats objects currently only improve scans, and not
joins, so that might *improve* some queries, but it won't resolve the
worst problems:

| Hash Join (cost=22,832.23..44,190.21 rows=185 width=47) (actual time=159.725..2,645,634.918 rows=28,086,472,886
loops=1)
 

Maybe you can improve that by adjusting the stats target or ndistinct...

-- 
Justin

On Tue, Dec 20, 2022 at 8:59 AM Frits Jalvingh <jal@etc.to> wrote:
> @ranier
> These files ONLY exist during the query. They get deleted as soon as the query terminates, by Postgres itself. Once
thequery terminates pgsql_tmp is completely empty. Considering what Thomas said (and the actual occurrence of the files
hementioned) this does seem to be the more likely cause to me. 

I'm working on some bug fixes near this area at the moment, so I'll
also see if I can figure out how to implement the missing eager
cleanup of earlier generations.  It's still a pretty bad scenario once
you reach it (repartitioning repeatedly, that is) and the solution to
that it probably much harder, but it's obviously not great to waste
temporary disk space like that.  BTW you can disable just parallel
hash with enable_parallel_hash=false.

On Mon, Dec 19, 2022 at 09:10:27PM +0100, Frits Jalvingh wrote:
> @justin
> 
> I tried the create statistics variant and that definitely improves the
> estimate, and with that one of the "bad" cases (the one with the 82 minute
> plan) now creates a good plan using only a few seconds.
> That is a worthwhile path to follow. A bit hard to do, because those
> conditions can be anything, but I can probably calculate the ones used per
> customer and create those correlation statistics from that... It is
> definitely better than tweaking the "poor man's query hints" enable_xxxx
> 8-/ which is really not helping with plan stability either.
> 
> That will be a lot of work, but I'll let you know the results ;)

Yeah, if the conditions are arbitrary, then it's going to be more
difficult.  Hopefully you don't have too many columns.  :)

I suggest enabling autoexplain and monitoring for queries which were
slow, and retroactively adding statistics to those columns which are
most-commonly queried, and which have correlations (which the planner
doesn't otherwise know about).

You won't want to have more than a handful of columns in a stats object
(since it requires factorial(N) complexity), but you can have multiple
stats objects with different combinations of columns (and, in v14,
expressions).  You can also set a lower stats target to make the cost a
bit lower.

You could try to check which columns are correlated, either by running:
| SELECT COUNT(1),col1,col2 FROM tbl GROUP BY 2,3 ORDER BY 1;
for different combinations of columns.

Or by creating a tentative/experimental stats object on a handful of
columns at a time for which you have an intuition about their
correlation, and then checking the calculated dependencies FROM
pg_stats_ext.  You may need to to something clever to use that for
arbitrarily columns.  Maybe this is a start.
| SELECT dep.value::float, tablename, attnames, dep.key, exprs FROM (SELECT
(json_each_text(dependencies::text::json)).*AS dep, * FROM pg_stats_ext)dep WHERE dependencies IS NOT NULL ORDER BY 1
DESC; -- AND regexp_count(key, ',') < 2
 

-- 
Justin