Re: Change the csv log to 'key:value' to facilitate the user to understanding and processing of logs

[hubert depesz lubaczewski]

On Tue, Mar 15, 2022 at 09:31:19AM +0800, lupeng wrote:
> Dear Hackers
> When I audit the Postgresql database recently, I found that after
> configuring the log type as csv, the output log content is as follows:
> "database ""lp_db1"" does not exist","DROP DATABASE
> lp_db1;",,"dropdb, dbcommands.c:841","","client backend",,0 It is very
> inconvenient to understand the real meaning of each field. And in the
> log content，" is escaped as "", which is not friendly to regular
> expression matching. Therefore, I want to modify the csv log function,
> change its format to key:value, assign the content of the non-existing
> field to NULL, and at the same time, " will be escaped as  \" in the
> log content. After the modification, the above log format is as
> follows: Log_time:"2022-03-15 09:17:55.289
> CST",User_name:"postgres",Database_name:"lp_db",Process_id:"17995",Remote_host:"192.168.88.130",Remote_port:"38402",Line_number:
> "622fe941.464b",PS_display:"DROP
> DATABASE",Session_start_timestamp:"2022-03-15 09:17:53
> CST",Virtual_transaction_id:"3/2",Transaction_id:"NULL",Error_severity:"ERROR",SQL_state_code
> :"3D000",Errmessage:"database \"lp_db1\" does not
> exist",Errdetail:"NULL",Errhint:"NULL",Internal_query:"NULL",Internal_pos:"0",Errcontext:"NULL",User_query
> :"DROP DATABASE lp_db1;",Cursorpos:"NULL",File_location:"dropdb,
> dbcommands.c:841",Application_name:"NULL",Backend_type:"client
> backend",Leader_PID:"0",Query_id:"0"

CSV format is well documented
(https://www.postgresql.org/docs/current/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-CSVLOG).

If you want named fields you can wait for pg15 and its jsonlog
(https://www.depesz.com/2022/01/17/waiting-for-postgresql-15-introduce-log_destinationjsonlog/).

I, for one, wouldn't want to have to deal with field names repeated in
every single record.

depesz

Re: [PG13] Planning (time + buffers) data structure in explain plan (format text)

[hubert depesz lubaczewski]

On Fri, Aug 21, 2020 at 07:54:13AM +0200, Pierre Giraud wrote:
> It looks good to me too. Thanks a lot!
> Let's not forget to notify Hubert (depesz) once integrated.

Thanks a lot, and sorry for not responding earlier - vacation.

Best regards,

depesz

Re: Is there a "right" way to test if a database is empty?

[hubert depesz lubaczewski]

On Wed, Jan 17, 2018 at 05:47:16PM +0200, Graham Leggett wrote:
> I need to test whether a database is empty, in other words “createdb”
> has been executed but no data of any kind appears in that database.
> What is the correct postgresql way to do this?

There is none, because it highly depends on how you'll define empty.

Please note that even directly after "create database x;" your db might
not be empty, if you had some things created earlier in template1.

Best regards,

depesz

Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}

[hubert depesz lubaczewski]

On Mon, Oct 30, 2023 at 10:45:05AM +0900, Michael Paquier wrote:
> On Fri, Oct 27, 2023 at 04:58:20PM +0300, Nazir Bilal Yavuz wrote:
> > I think switching it to 'shared' makes sense. That shouldn't confuse
> > existing monitoring queries much as the numbers won't change, right?
> > Also, if we keep 'shared/local' there could be similar complaints to
> > this thread in the future; so, at least adding comments can be
> > helpful.
> 
> The problem is that it may impact existing tools that do explain
> output deparsing.  One of them is https://explain.depesz.com/ that
> Hubert Depesz Lubaczewski has implemented, and it would be sad to
> break anything related to it.
> 
> I am adding Hubert in CC for comments about changing this
> "shared/local" to "shared" on a released branch.  Knowing that
> "shared" and "local" will need to be handled as separate terms in 17~
> anyway, perhaps that's not a big deal, but let's be sure.

Hi,
some things will definitely break, but that's 100% OK. The change seems
needed, and I can update my parser to deal with it :)

Best regards,

depesz

Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}

[hubert depesz lubaczewski]

On Tue, Oct 31, 2023 at 08:17:52AM +0900, Michael Paquier wrote:
> Thanks for the input.  I was looking yesterday if this code was
> available somewhere, but couldn't find it..  Until this morning:
> https://gitlab.com/depesz/explain.depesz.com.git

Well, the parser itself is https://gitlab.com/depesz/Pg--Explain/ :)

> And..  It looks like things would become better if we change
> "shared/local" to "shared", because the parsing code seems to have an
> issue once you add a '/'.  All the fields in I/O Timings are
> considered as part of a Node, and they're just included in the output.
> Now, pasting a plan that includes "shared/local" drops entirely the
> string from the output result, so some information is lost.  In short,
> imagine that we have the following string in a node:
> I/O Timings: shared/local write=23.77
> 
> This would show up like that, meaning that the context where the
> write/read timings happened is lost:
> I/O Timings: write=23.77
> 
> If we switch back to "shared", the context would be kept around.  Of
> course, this does not count for all the parsers that may be out
> there, but at least that's something.

Well, if it's possible to deduce what is the meaning in given line,
I can add the logic to do the deduction to parser.

Also, I want to say that I appreciate being looped in the discussion.

Best regards,

depesz

Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}

[hubert depesz lubaczewski]

> > Well, if it's possible to deduce what is the meaning in given line,
> > I can add the logic to do the deduction to parser.
> > Also, I want to say that I appreciate being looped in the discussion.
> I lost sight of this thread, so my apologies for the delay.  The patch
> to fix the description of the EXPLAIN field has now been applied to
> v15 and v16.

Thanks. Will do my best to update the parser soon.

Best regards,

depesz

Re: Is there any plan to support online schem change in postgresql?

[hubert depesz lubaczewski]

On Tue, Oct 11, 2022 at 05:43:03PM +0800, jiye wrote:
> As we know postgres using high level lock when do alter table or other ddl 
> commands,
> It will block any dml operation, while it also will block by long term dml 
> operation.

Most of the things can be already done in non-blocking (or almost
non-blocking way) if you just do it in a way that takes concurrency into
account.

Specifically - I have no problem adding/deleting columns.

Best regards,

depesz

Re: Re: Is there any plan to support online schem change in postgresql?

[hubert depesz lubaczewski]

On Tue, Oct 11, 2022 at 08:31:53PM +0800, jiye wrote:
> But, as follow, if txn1 not commit (just like long term readonly txn), it 
> will block txn2's ddl job,  why alt add/drop column can not concurrently with 
> read only access?
> txn1： long term txn not commit access t1.
> txn2 waiting txn1 to commit or abort.
> txn3 wait txn2...

1. Please don't share code as screenshots.
2. If I understand your text above correctly, then the solution is
   trivial:
   
https://www.depesz.com/2019/09/26/how-to-run-short-alter-table-without-long-locking-concurrent-queries/

depesz

Pg stuck at 100% cpu, for multiple days

[hubert depesz lubaczewski]

Hi,

Originally I posted it on -general, but Joe Conway suggested I repost in
here for greater visibility...

We hit a problem with Pg 12.6 (I know, we should upgrade, but that will
take long time to prepare).

Anyway - it's 12.6 on aarm64.
Couple of days there was replication slot started, and now it seems to
be stuck.

=# select * from pg_stat_activity  where pid = 22697 \gx
─[ RECORD 1 ]┬──
datid│ 16591
datname  │ canvas
pid  │ 22697
usesysid │ 16505
usename  │ 
application_name │ PostgreSQL JDBC Driver
client_addr  │ 
client_hostname  │ [null]
client_port  │ 43160
backend_start│ 2021-08-18 02:12:05.758297+00
xact_start   │ [null]
query_start  │ 2021-08-18 02:12:05.772271+00
state_change │ 2021-08-18 02:12:05.773428+00
wait_event_type  │ [null]
wait_event   │ [null]
state│ active
backend_xid  │ [null]
backend_xmin │ [null]
query│ SELECT COUNT(1) FROM pg_publication WHERE pubname = 'cdc'
backend_type │ walsender

=# select pg_current_wal_lsn(), pg_size_pretty( pg_current_wal_lsn() - 
sent_lsn), * from pg_stat_replication where pid = 22697 \gx
─[ RECORD 1 ]──┬──
pg_current_wal_lsn │ 1B14/718EA0B8
pg_size_pretty │ 290 GB
pid│ 22697
usesysid   │ 16505
usename│ 
application_name   │ PostgreSQL JDBC Driver
client_addr│ 
client_hostname│ [null]
client_port│ 43160
backend_start  │ 2021-08-18 02:12:05.758297+00
backend_xmin   │ [null]
state  │ streaming
sent_lsn   │ 1ACC/D8689A8
write_lsn  │ 1ACC/D527BD8
flush_lsn  │ 1ACC/C97DF48
replay_lsn │ 1ACC/C97DF48
write_lag  │ 00:00:00.257041
flush_lag  │ 00:00:01.26665
replay_lag │ 00:00:01.26665
sync_priority  │ 0
sync_state │ async
reply_time │ 1999-12-21 03:15:13.449225+00

top shows the process using 100% of cpu. I tried strace'ing, but strace doesn't
show *anything* - it just sits there.

Got backtrace:

~# gdb --pid=22697 --batch -ex backtrace
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".
hash_seq_search (status=status@entry=0xdd90f380) at 
./build/../src/backend/utils/hash/dynahash.c:1448
1448./build/../src/backend/utils/hash/dynahash.c: No such file or directory.
#0  hash_seq_search (status=status@entry=0xdd90f380) at 
./build/../src/backend/utils/hash/dynahash.c:1448
#1  0xc3042060 in RelfilenodeMapInvalidateCallback (arg=, relid=105496194) at ./build/../src/backend/utils/cache/relfilenodemap.c:64
#2  0xc3033aa4 in LocalExecuteInvalidationMessage (msg=0x9b66eec8) 
at ./build/../src/backend/utils/cache/inval.c:595
#3  0xc2ec8274 in ReorderBufferExecuteInvalidations (rb=0xc326bb00 
, txn=0xc326b998 , txn=0xc326b998 
) at 
./build/../src/backend/replication/logical/reorderbuffer.c:2149
#4  ReorderBufferCommit (rb=0xc326bb00 , 
xid=xid@entry=2668396569, commit_lsn=187650393290540, end_lsn=, 
commit_time=commit_time@entry=683222349268077, origin_id=origin_id@entry=0, 
origin_lsn=origin_lsn@entry=0) at 
./build/../src/backend/replication/logical/reorderbuffer.c:1770
#5  0xc2ebd314 in DecodeCommit (xid=2668396569, parsed=0xdd90f7e0, 
buf=0xdd90f960, ctx=0xf5d396a0) at 
./build/../src/backend/replication/logical/decode.c:640
#6  DecodeXactOp (ctx=ctx@entry=0xf5d396a0, buf=0xdd90f960, 
buf@entry=0xdd90f9c0) at 
./build/../src/backend/replication/logical/decode.c:248
#7  0xc2ebd42c in LogicalDecodingProcessRecord (ctx=0xf5d396a0, 
record=0xf5d39938) at 
./build/../src/backend/replication/logical/decode.c:117
#8  0xc2ecfdfc in XLogSendLogical () at 
./build/../src/backend/replication/walsender.c:2840
#9  0xc2ed2228 in WalSndLoop (send_data=send_data@entry=0xc2ecfd98 
) at ./build/../src/backend/replication/walsender.c:2189
#10 0xc2ed2efc in StartLogicalReplication (cmd=0xf5d175a8) at 
./build/../src/backend/replication/walsender.c:1133
#11 exec_replication_command (cmd_string=cmd_string@entry=0xf5c0eb00 
"START_REPLICATION SLOT cdc LOGICAL 1A2D/4B3640 (\"proto_version\" '1', 
\"publication_names\" 'cdc')") at 
./build/../src/backend/replication/walsender.c:1549
#12 0xc2f258a4 in PostgresMain (argc=, 
argv=argv@entry=0xf5c78cd8, dbname=, username=) at ./build/../src/backend/tcop/postgres.c:4257
#13 0xc2eac338 in BackendRun (port=0xf5c68070, port=0xf5c68070) 
at ./build/../src/backend/postmaster/postmaster.c:4484
#14 BackendStartup (port=0xf5c68070) at 
./build/../src/backend/postmaster/postmaster.c:4167
#15 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1725
#16 0xc2ead364 in PostmasterMain (argc=, argv=) at ./build/../src/backend/postmaster/postmaster

Re: Can we get rid of repeated queries from pg_dump?

[hubert depesz lubaczewski]

On Mon, Aug 30, 2021 at 08:11:00PM -0400, Tom Lane wrote:
> [ redirecting to -hackers ]
> 
> I wrote:
> > I experimented with the attached, very quick-n-dirty patch to collect
> > format_type results during the initial scan of pg_type, instead.  On the
> > regression database in HEAD, it reduces the number of queries pg_dump
> > issues from 3260 to 2905; but I'm having a hard time detecting any net
> > performance change.
> 
> I decided that that patch wasn't too safe, because it applies
> format_type() to pg_type rows that we have no reason to trust the
> longevity of.  I think it could fall over if some concurrent process
> were busy dropping a temp table, for example.
> 
> So here's a version that just does plain caching of the results
> of retail getFormattedTypeName() calls.  This visibly adds no
> queries that were not done before, so it should be safe enough.
> And there can't be any cases that it makes slower, either.

Hi,
tested it in my case, and it reduced query count to 4261.

Which is great.

But, I also looked closer into the pg_proc queries and extensions.
And - most functions come from relatively standard extensions:
- postgis 1246 functions
- btree_gist  179 functions
- btree_gin   87 functions
- hstore  58 functions

My point in here is that potential optimizations regarding queries for
pg_proc might speed up dumps for more people - as they might use things
like postgis, but never realized that it can be much faster.

Best regards,

depesz

Re: Pg stuck at 100% cpu, for multiple days

[hubert depesz lubaczewski]

On Mon, Aug 30, 2021 at 09:09:20PM +0200, Laurenz Albe wrote:
> On Mon, 2021-08-30 at 17:18 +0200, hubert depesz lubaczewski wrote:
> > The thing is - I can't close it with pg_terminate_backend(), and I'd
> > rather not kill -9, as it will, I think, close all other connections,
> > and this is prod server.
> 
> Of course the cause should be fixed, but to serve your immediate need:
> 
> After calling pg_terminate_backend(), you can attach gdb to the backend and 
> then run
> 
>   print ProcessInterrupts()
> 
> That will cause the backend to exit normally without crashing the server.

I got this mail too late, and the decision was made to restart Pg. After
restart all cleaned up nicely.

So, while I can't help more with diagnosing the problem, I think it
might be good to try to figure out what could have happened.

On my end I gathered some more data:
1. the logical replication app is debezium
2. as far as I can tell it was patched against
   https://issues.redhat.com/browse/DBZ-1596
3. app was gone (kubernetes cluister was shut down) in the mean time.
4. the backend was up and running for 12 days, in the tight loop.

depesz

Re: Pg stuck at 100% cpu, for multiple days

[hubert depesz lubaczewski]

On Mon, Aug 30, 2021 at 08:15:24PM -0400, Joe Conway wrote:
> It would be interesting to step through a few times to see if it is really
> stuck in that loop. That would be consistent with 100% CPU and not checking
> for interrupts I think.

If the problem will happen again, will do my best to get more
information.

Best regards,

depesz

Re: Pg stuck at 100% cpu, for multiple days

[hubert depesz lubaczewski]

On Tue, Aug 31, 2021 at 04:00:14PM +0530, Amit Kapila wrote:
> One possibility could be there are quite a few DDLs happening in this
> application at some particular point in time which can lead to high

While not impossible, I'd rather say it's not very likely. We don't use
temporary tables, and while there are DB migrations, I don't think they
are often, and definitely don't take many days.

Best regards,

depesz

Re: Can we get rid of repeated queries from pg_dump?

[hubert depesz lubaczewski]

On Tue, Aug 31, 2021 at 03:06:25PM -0400, Tom Lane wrote:
> Agreed, but as I said upthread, fixing that looks like it will be
> rather invasive.  Meanwhile, I went ahead and pushed the two
> simple improvements discussed so far.

Great. Thank you very much.

Best regards,

depesz

Segfault when restoring -Fd dump on current HEAD

[hubert depesz lubaczewski]

Hi,
I did upgrade of my test pg. Part of this is pg_dump -Fd of each
database, then upgrade binaries, then initdb, and pg_restore.

But - I can't restore any database that has any data - I get segfaults.

For example, with gdb:

=$ gdb --args pg_restore -v -C -Fd 
backup-20190225074600.10361-db-depesz.dump
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
.   
Find the GDB manual and other documentation resources online at:
.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from pg_restore...done. 
(gdb) run   

Starting program: /home/pgdba/work/bin/pg_restore -v -C -Fd 
backup-20190225074600.10361-db-depesz.dump
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".  

--  

 
-- PostgreSQL database dump 
 
--  
 
 
-- Dumped from database version 12devel
-- Dumped by pg_dump version 12devel

-- Started on 2019-02-25 07:46:01 CET

SET statement_timeout = 0;
SET lock_timeout = 0;
SET idle_in_transaction_session_timeout = 0;
SET client_encoding = 'UTF8';
SET standard_conforming_strings = on;
SELECT pg_catalog.set_config('search_path', '', false);
SET check_function_bodies = false;
SET client_min_messages = warning;
SET row_security = off;

pg_restore: creating DATABASE "depesz"
--
-- TOC entry 2148 (class 1262 OID 16631)
-- Name: depesz; Type: DATABASE; Schema: -; Owner: depesz
--

CREATE DATABASE depesz WITH TEMPLATE = template0 ENCODING = 'UTF8' LC_COLLATE = 
'en_US.UTF-8' LC_CTYPE = 'en_US.UTF-8';


ALTER DATABASE depesz OWNER TO depesz;

pg_restore: connecting to new database "depesz"
\connect depesz

SET statement_timeout = 0;
SET lock_timeout = 0;
SET idle_in_transaction_session_timeout = 0;
SET client_encoding = 'UTF8';
SET standard_conforming_strings = on;
SELECT pg_catalog.set_config('search_path', '', false);
SET check_function_bodies = false;
SET client_min_messages = warning;
SET row_security = off;

pg_restore: creating TABLE "public.test"
SET default_tablespace = '';

SET default_with_oids = false;

--
-- TOC entry 196 (class 1259 OID 16632)
-- Name: test; Type: TABLE; Schema: public; Owner: depesz
--

CREATE TABLE public.test (
i integer
);


ALTER TABLE public.test OWNER TO depesz;

--
-- TOC entry 2142 (class 0 OID 16632)
-- Dependencies: 196
-- Data for Name: test; Type: TABLE DATA; Schema: public; Owner: depesz
-- File: 2142.dat
--


Program received signal SIGSEGV, Segmentation fault.
0xd99c in _printTocEntry (AH=AH@entry=0x5577e350, 
te=te@entry=0x557844a0, isData=isData@entry=true) at 
pg_backup_archiver.c:3636
3636pg_backup_archiver.c: No such file or directory.
(gdb) bt
#0  0xd99c in _printTocEntry (AH=AH@entry=0x5577e350, 
te=te@entry=0x557844a0, isData=isData@entry=true) at 
pg_backup_archiver.c:3636
#1  0xe41d in restore_toc_entry (AH=AH@entry=0x5577e350, 
te=te@entry=0x557844a0, is_parallel=is_parallel@entry=false) at 
pg_backup_archiver.c:852
#2  0xeebb in RestoreArchive (AHX=0x5577e350) at 
pg_backup_archiver.c:675
#3  0xaaab in main (argc=5, argv=) at 
pg_restore.c:432
(gdb)

if you'd need the dump to investigate - it's available here:
https://www.depesz.com/wp-content/uploads/2019/02/bad.dump.tar.gz

Unfortunately I don't have previous binaries, but I refreshed previously
around a week ago.

Best regards,

depesz

Re: Segfault when restoring -Fd dump on current HEAD

[hubert depesz lubaczewski]

On Mon, Feb 25, 2019 at 08:45:39AM +0100, hubert depesz lubaczewski wrote:
> Hi,
> I did upgrade of my test pg. Part of this is pg_dump -Fd of each
> database, then upgrade binaries, then initdb, and pg_restore.

Sorry, please disregard this problem.

Error was sitting on a chair.

Best regards,

depesz

Re: BUG #16171: Potential malformed JSON in explain output

[hubert depesz lubaczewski]

On Sun, Feb 02, 2020 at 11:48:32AM -0500, Tom Lane wrote:
> > Does that prevent backpatching this, or are we Ok with EXPLAIN text output 
> > not
> > being stable across minors?  AFAICT Pg::Explain still works fine with this
> > change, but mileage may vary for other parsers.
> I'm not sure about that either.  It should be a clear win for parsers
> of the non-text formats, because now we're generating valid
> JSON-or-whatever where we were not before.  But it's not too hard to
> imagine that someone's ad-hoc parser of text output would break,
> depending on how much it relies on field order rather than indentation
> to make sense of things.

Change looks reasonable to me.

Interestingly Pg::Explain doesn't handle either current JSON output in
this case (as it's not a valid JSON), nor the new one - but this can be
fixed easily.

Best regards,

depesz

xact_start meaning when dealing with procedures?

[hubert depesz lubaczewski]

Hi
I just noticed that when I called a procedure that commits and rollbacks
- the xact_start in pg_stat_activity is not updated. Is it intentional?

I'm on newest 12devel, built today.

Best regards,

depesz

xact_start meaning when dealing with procedures?

[hubert depesz lubaczewski]

Hi
I just noticed that when I called a procedure that commits and rollbacks
- the xact_start in pg_stat_activity is not updated. Is it intentional?

I'm on newest 12devel, built today.

Best regards,

depesz

-- 
Hubert Lubaczewski (depesz) | DBA
hlubaczew...@instructure.com
Instructure.com

Re: [PATCH] Add extra statistics to explain for Nested Loop

[hubert depesz lubaczewski]

On Sat, Oct 17, 2020 at 12:26:08PM +0800, Julien Rouhaud wrote:
> >> -   ->  Nested Loop (actual rows=N loops=N)
> >> +  ->  Nested Loop (actual min_rows=0 rows=0 max_rows=0 
> >> loops=2)
> > This interface is ok - there is not too much space for creativity.
> Yes I also think it's ok. We should also consider usability for tools
> like explain.depesz.com, I don't know if the current output is best.
> I'm adding Depesz and Pierre which are both working on this kind of
> tool for additional input.

Thanks for heads up. This definitely will need some changes on my side,
but should be easy to handle.

Best regards,

depesz

explain analyze output with parallel workers - question about meaning of information for explain.depesz.com

[hubert depesz lubaczewski]

Hi,

up to parallel executions, when we had node in explain analyze showing
"loops=x" with x more than 1, it meant that the "actual time" had to be
multiplied by loops to get real time spent in a node.

For example, check step 13 in https://explain.depesz.com/s/gNBd

It shows time of 3ms, but loops of 1873, so the actual time is ~ 5600ms.

But with parallel execution it seems to be no longer the case.

For example:
https://explain.depesz.com/s/LTMp
or
https://explain.depesz.com/s/QHRi

It looks that the actual time is really actual time, and loops is
"worker nodes + 1".

Is that really the case? Should I, for explain.depesz.com, when dealing
with partial* and parallel* nodes, use "loops=1" for calculation of
exclusive/inclusive time? always? some other nodes?

or am I missing something in here?

Best regards,

depesz

Re: explain analyze output with parallel workers - question about meaning of information for explain.depesz.com

[hubert depesz lubaczewski]

On Sat, Nov 25, 2017 at 07:08:03AM +0530, Amit Kapila wrote:
> > For example, check step 13 in https://explain.depesz.com/s/gNBd
> >
> > It shows time of 3ms, but loops of 1873, so the actual time is ~ 5600ms.
> >
> > But with parallel execution it seems to be no longer the case.
> >
> > For example:
> > https://explain.depesz.com/s/LTMp
> > or
> > https://explain.depesz.com/s/QHRi
> > Should I, for explain.depesz.com, when dealing
> > with partial* and parallel* nodes, use "loops=1" for calculation of
> > exclusive/inclusive time? always? some other nodes?
> >
> 
> I am not sure what exactly inclusive or exclusive means, but for
> parallel nodes, total stats are accumulated so you are seeing loops as
> 'worker nodes + 1'.  Now, as presumably workers run parallelly, so I
> think the actual time will be what will be shown in the node not
> actual time * nloops.

Please check the plans:
https://explain.depesz.com/s/gNBd (step 13)
and https://explain.depesz.com/s/LTMp (step 3)

Inclusive time is basically "loops * actual time", so for Index Scan,
which had 1873 loops and actual time of 3.002..3.016, we got 1873
* 3.016 = 5648.968ms.

In case of parallel workers it looks like the inclusive time is
basically the upper value from actual time.

The question now is: how can I tell which nodes should use "actual_time
* 1" and which "actual_time * loops" time?

Anything "below" "Gather"?
Anything starting with "Partial?"
Anything starting with "Parallel"?
Anything with "Worker" in node "description" in explain?

depesz

Re: explain analyze output with parallel workers - question about meaning of information for explain.depesz.com

[hubert depesz lubaczewski]

On Mon, Nov 27, 2017 at 05:24:49PM +0530, Amit Kapila wrote:
> I think it is "actual_time * 1" for anything below Gather.

Well, I think I found another problem.

Please take a look at:
https://explain.depesz.com/s/Bs8c

Node 15 is Gather with loops = 2974 (because it was ran by nested loop).

There were 4 workers, so 5 threads working, but the loops on parallel
seq scan is 17.698 million ?!

The problem is that for explain.depesz.com I'm calculating how much time
pg actually spent doing given thing.

So, if an operation has actual time of 1ms, but 100 loops, it took
100ms.

In case of parallel operations it looks like I can't realistically find
the information anywhere?

In the explain above, we see that Nested loop took, in total, around
2 million miliseconds (step 9).
Out of which, ~ 7000 ms was hash join and it's subnodes.
This leaves most of the time for Gather step, which was called 2974
times with actual time reported as 618ms.
2974 * 618 is 1837932 miliseconds, which seems reasonable.

But then - how much of this time was spent in Parallel Seq Scan in step
#16 ?

2974 * 609ms? Why is loops there 17 million?

Best regards,

depesz

Re: explain analyze output with parallel workers - question about meaning of information for explain.depesz.com

[hubert depesz lubaczewski]

On Tue, Nov 28, 2017 at 12:53:41PM +0530, Amit Kapila wrote:
> Is it possible for you to test the attached patch and see if you are
> still seeing any unexpected values?

well, not really. the explains i had were posted by people on
explain.depesz.com, so i don't have original queries nor their datasets.

Best regards,

depesz

Would it be possible to have parallel archiving?

[hubert depesz lubaczewski]

Hi,
I'm in a situation where we quite often generate more WAL than we can
archive. The thing is - archiving takes long(ish) time but it's
multi-step process and includes talking to remote servers over network.

I tested that simply by running archiving in parallel I can easily get
2-3 times higher throughput.

But - I'd prefer to keep postgresql knowing what is archived, and what
not, so I can't do the parallelization on my own.

So, the question is: is it technically possible to have parallel
archivization, and would anyone be willing to work on it (sorry, my
c skills are basically none, so I can't realistically hack it myself)

Best regards,

depesz

Re: Would it be possible to have parallel archiving?

[hubert depesz lubaczewski]

On Tue, Aug 28, 2018 at 08:33:11AM +0200, Alexander Kukushkin wrote:
> There is the archive_status directory in pg_wal, and if there are
> files with suffixes ".ready", you can archive not only the file which
> was requested, but quite a few more if there are  ".ready" files
> available. After that you have to rename ".ready" to ".done". Postgres
> will not call archive_command for files which already marked as
> ".done".

Ah, I was missing this information. Thanks a lot.

Best regards,

depesz