Re: Mysterious performance degradation in exceptional cases - Mailing list pgsql-general

El día Mittwoch, September 14, 2022 a las 10:31:26 +0200, Matthias Apitz escribió:

> 
> We have a C-written application server which uses ESQL/C on top
> of PostgreSQL 13.1 on Linux. The application in question always serves
> the same search in a librarian database, given to the server
> as commands over the network, login into the application and doing
> a search:
> 
> SLNPServerInit
> User:zfl
> SLNPEndCommand
> 
> SLNPSearch
> HitListName:Zfernleihe
> Search:1000=472214284
> SLNPEndCommand
> 
> To fulfill the search, the application server has to do some 100
> ESQL/C calls and all this should not take longer than 1-2 seconds, and
> normally it does not take longer. But, in some situations it takes
> longer than 180 seconds, in 10% of the cases. The other 90% are below 2 seconds,
> i.e. this is digital: Or 2 seconds, or more than 180 seconds, no values between.
> 
> ...

After weeks of silence, the problem showed up again. I was wrong saying
"some 100 of ESQL/C", because I had forgotten that the main initialization is
done only once in the master daemon of the application server and every
such connect spawns a new short living child and this only executes only
16 calls to the DBLAYER:

DBCEXIT|N|sisisinst|RDIR|4|21.10.2022 06:08:25:594
DBCEXIT|N|adm_partab|RDIR|2|21.10.2022 06:08:25:597
DBCEXIT|N|adm_partab|RDIR|1|21.10.2022 06:08:25:598
DBCEXIT|N|adm_partab|RDIR|0|21.10.2022 06:08:25:599
DBCEXIT|N|adm_partab|RDIR|0|21.10.2022 06:08:25:600
DBCEXIT|N|adm_partab|RDIR|0|21.10.2022 06:08:25:601
DBCEXIT|N|adm_partab|RDIR|0|21.10.2022 06:08:25:602
DBCEXIT|N|d12termfkt|RWHR|1|21.10.2022 06:08:25:630
DBCEXIT|N|d12termfkt|RWHR|2|21.10.2022 06:08:25:632
DBCEXIT|N|d601biblpar|RALL|3|21.10.2022 06:08:25:636
DBCEXIT|N|d06vw|RDIR|1|21.10.2022 06:08:25:637
DBCEXIT|N|titel_worte|RDIR|13|21.10.2022 06:08:25:660
DBCEXIT|N|titel_worte|FETCH|0|21.10.2022 06:08:25:660
DBCEXIT|N|d14zweigsicht|RWHR|1|21.10.2022 06:08:25:662
DBCEXIT|W|titel_daten|COUNT|183875|21.10.2022 06:11:29:538
                            ^^^^^^

'RDIR' means a SELECT with a key, ... 'COUNT' executes a 

SELECT count(*) from titel_daten

The 5th column gives the duration in/below the DBLAYER in milliseconds, in
the above case 183875, i.e. 183 seconds. The table in question titel_daten
has 5830370 rows. I did it right now with psql and it takes a second
only:

sisis=# select count(*) from titel_daten;
  count  
---------
 5827383
(1 row)

What could be a reason for 183 seconds, sometimes not always?

Thanks

    matthias
 

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!