0

I have a strange issue, that I hope I can get some help on. I'm not too advanced in Postgresql so maybe I'm missing obvious things as well. Our company is planning to move from Oracle to Postgresql, and we are testing our Java app now with the Postgresql database (9.5) We have a scheduled task that runs every morning. It finished on Oracle in appr. 4.5 hours, but in Postgres it just never ends. First I thought the transaction might not be closed, but checking the logs I found that the queries are running, and the transaction is active, so I guess it is just must slower than on the Oracle db. I read literally hundreds of pages on slow queries, performance issues, high CPU loads etc... but somehow I could not get closer to the issue. What I see: there is a select running in the transaction with a parameter $1 (it's a function or a prepared statement?) When I check the logs, I see this:

2019-01-25 14:38:23.976 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOG: 00000: duration: 642.814 ms 2019-01-25 14:38:23.976 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOCATION: exec_execute_message, postgres.c:2026 2019-01-25 14:38:23.977 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOG: 00000: duration: 0.056 ms 2019-01-25 14:38:23.977 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOCATION: exec_bind_message, postgres.c:1809 2019-01-25 14:38:23.977 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOG: 00000: execute S_1: select FST_FILESTORENO, FST_REFTYPEC, FST_REFC, FST_PIXELX, FST_PIXELY, FST_MMX, FST_MMY, FST_EXTENSION, FST_FSL_FILESTORELOCATIONC, FST_SIZE, FST_MD5_AS_HEX, FST_UPDATE from gsodata.filestore where FST_FILESTORENO=$1 order by FST_UPDATE DESC 2019-01-25 14:38:23.977 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 DETAIL: parameters: $1 = '473544' 2019-01-25 14:38:23.977 CET PostgreSQL JDBC Driver filestore twww1 192.168.5.91(51616) 96645 5c4a7f37.17985 2019-01-25 04:15:03 CET 00000 LOCATION: exec_execute_message, postgres.c:19

I find strange that there are 2 durations for one select. One of them looks ok, the other is pretty slow. But I can't figure out how to know more about that.

I also checked in psql with EXPLAIN but for me it seems normal again:

twww1=> EXPLAIN ANALYZE VERBOSE select FST_FILESTORENO, FST_REFTYPEC, FST_REFC, FST_PIXELX, FST_PIXELY, FST_MMX, FST_MMY, FST_EXTENSION, FST_FSL_FILESTORELOCATIONC, FST_SIZE, FST_MD5_AS_HEX, FST_UPDATE from gsodata.filestore where FST_FILESTORENO=5064716 order by FST_UPDATE DESC;

-[ RECORD 1 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Sort (cost=2.46..2.46 rows=1 width=96) (actual time=0.071..0.071 rows=1 loops=1)

-[ RECORD 2 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Output: fst_filestoreno, fst_reftypec, fst_refc, fst_pixelx, fst_pixely, fst_mmx, fst_mmy, fst_extension, fst_fsl_filestorelocationc, fst_size, fst_md5_as_hex, fst_update

-[ RECORD 3 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Sort Key: filestore.fst_update DESC

-[ RECORD 4 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Sort Method: quicksort Memory: 25kB

-[ RECORD 5 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | -> Index Scan using fst_pk on gsodata.filestore (cost=0.43..2.45 rows=1 width=96) (actual time=0.063..0.063 rows=1 loops=1)

-[ RECORD 6 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Output: fst_filestoreno, fst_reftypec, fst_refc, fst_pixelx, fst_pixely, fst_mmx, fst_mmy, fst_extension, fst_fsl_filestorelocationc, fst_size, fst_md5_as_hex, fst_update

-[ RECORD 7 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Index Cond: (filestore.fst_filestoreno = 5064716)

-[ RECORD 8 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Planning time: 0.113 ms

-[ RECORD 9 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- QUERY PLAN | Execution time: 0.102 ms

Though when I check pg_stat_statements I see this:

postgres=# \x

Expanded display is on.

postgres=# SELECT

(total_time / 1000 / 60) as total_minutes,

(total_time/calls) as average_time,calls,

query

FROM pg_stat_statements

ORDER BY 1 DESC

LIMIT 1;

-[ RECORD 1 ]-+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

total_minutes | 118.602694016667

average_time | 713.042248597193

calls | 9980

query | select FST_FILESTORENO, FST_REFTYPEC, FST_REFC, FST_PIXELX, FST_PIXELY, FST_MMX, FST_MMY, FST_EXTENSION, FST_FSL_FILESTORELOCATIONC, FST_SIZE, FST_MD5_AS_HEX, FST_UPDATE from gsodata.filestore where FST_FILESTORENO=$1 order by FST_UPDATE DESC

So the average time seems to be correlating with the duration time in the logs, though nothing at all can be seen with EXPLAIN.

I would be really grateful if someone could point me in the right direction, as I feel totally lost with this.

Thank you, Tom

  • 2
    "Database Agnostic Code" is a myth. In some cases, you need to re-write the entire app. I'm assuming this problem is for "one SQL statement". Please post SQL statement and PLAN for both Oracle (old DB) and PostgreSQL (new DB). Keep in mind that you may have tune every statement. – Michael Kutz Jan 29 at 16:45
  • Thank you for your help. Finally I could get more details with auto_explain and turned out that a double value was used, instead of integer and instead of the index scan seq scan happened, on a 4 million row table. Now developers are checking the statements and fixing it everywhere. – Tom Feb 2 at 8:47

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.