Subject: tds_fdw : Severe performance degradation from postgresql 10.23 to 16.4

From: Achilleas Mantzios <[email-masked]>
Date: Fri, 8 Nov 2024 21:32:26 +0200

Dear All,

we have hit a serious performance regression going from 10.23 → 16.4 as 
far as tds_fdw (MS SQL) FDW is concerned. To cut the long story short, I 
recreated the good fast “old” (pgsql 10) setup on the same vm as the 
slow “new” (pgsql 16). Here is the bug report on github :

https://github.com/tds-fdw/tds_fdw/issues/371

All environment on the two pgsql clusters is shared (freetds version, 
tds_fdw, gcc, llvm). Only thing differs are pgsql versions. The speed on 
the old pgsql 10.23 is about 10 to 20 times higher than pgsql 16.4 . 
|Setting client_min_messages TO debug3 does yield identical output on 
the two systems.
|

The new pgsql 16.4 shows 100% CPU usage during the query execution.

I know we are pretty much alone with this, but it would be very nice if 
anyone could help, see smth we are missing or guide us via the right path.

---

From: Tomas Vondra <[email-masked]>
Date: Sat, 9 Nov 2024 11:49:34 +0100

On 11/8/24 20:32, Achilleas Mantzios wrote:
> the old pgsql 10.23 is about 10 to 20 times higher than pgsql 16.4 . |
> Setting client_min_messages TO debug3 does yield identical output on the
> two systems.
> |
> 

I have little experience with tds_fdw, and can't investigate that
locally. But it might be interesting to compare CPU profiles for the two
(slow and fast) cases. Chances are the difference will be an indication
regarding what got that slower. It might be something in PG or in the
FDW, hard to say.

regards

-- 
Tomas Vondra

---

From: Achilleas Mantzios <[email-masked]>
Date: Sat, 9 Nov 2024 16:05:32 +0200

> regarding what got that slower. It might be something in PG or in the
Thank you Tomas, do you have linux-perf in mind? How could we get the 
CPU profiles of the two ?  Just in case it was not clear, the tests were 
done on the same VM, at the same time, having the two DBs listening on 
different ports. Kinda spooky from my part to do that on the production 
system, but I wanted everything to be the same (latency to/from the ms 
sql, etc) except the pgsql version, to prove my assumption, and it seems 
pgsql version is what makes the difference (in conjunction of course 
with tds_fdw ) .

---

From: Achilleas Mantzios <[email-masked]>
Date: Sat, 9 Nov 2024 16:08:58 +0200

Στις 9/11/24 16:05, ο/η Achilleas Mantzios έγραψε:
> CPU profiles of the two ?  Just in case it was not clear, the tests 
> were done on the same VM, at the same time, having the two DBs 
> listening on different ports. Kinda spooky from my part to do that on 
> the production system, but I wanted everything to be the same (latency 
> to/from the ms sql, etc) except the pgsql version, to prove my 
> assumption, and it seems pgsql version is what makes the difference 
> (in conjunction of course with tds_fdw ) .
Meaning there are CPP directives in the tds_fdw source making it behave 
differently according to the Postgresql version. The two tds_fdw's have 
the same version.

---

From: Tomas Vondra <[email-masked]>
Date: Sat, 9 Nov 2024 16:41:26 +0100

> pgsql version is what makes the difference (in conjunction of course

Yes, I mean linux-perf. There's a wikipage with some basic instructions:

  https://wiki.postgresql.org/wiki/Profiling_with_perf

But in short, I'd do this:

1) use pg_backend_pid() to get PID of the backend

    SELECT pg_backend_pid();

2) start recording profile for that PID, say for 1 minute

    perf record -g -p $PID -- sleep 60

3) run the query in a loop

    SELECT count(*) as foo FROM mssql_bdynacom."ACDOC" \watch 1

4) once the recording stops, generate report

    perf report > report.txt

Do this for both versions, share the output txt files. You may need to
install additional packages with debug symbols to get better profiles,
and stuff like that.

Also, don't forget to share the explain plans.

regard

-- 
Tomas Vondra

---

From: Achilleas Mantzios <[email-masked]>
Date: Sun, 10 Nov 2024 11:45:41 +0200

> Also, don't forget to share the explain plans.
Thank you Tomas, as soon as I get my hands on the new VM I will do as 
you suggested and report back.

---

From: Achilleas Mantzios - cloud <[email-masked]>
Date: Tue, 12 Nov 2024 12:37:27 +0200

>> Also, don't forget to share the explain plans.

Hi Tomas,

By trying to reproduce the situation on the clone vm , we failed 
creating a fast postgresql 10 setup, so we just created a slow 
postgresql 10. So we thought comparing the slow 10 (on the clone) with 
the fast 10 (on the prod system, on port 5410), which maybe more 
interesting as now we are comparing :

- same vm specs (Intel(R) Xeon(R) Gold 6226R CPU @ 2.90GHz , 64GB , SSD)

- same os (Linux smadb 6.7.12+bpo-amd64 #1 SMP PREEMPT_DYNAMIC Debian 
6.7.12-1~bpo12+1 (2024-05-06) x86_64 GNU/Linux)

- same pgsql versions (10.23 )

- same setup on the tds_fdw (2.0.4, loaded from identical dump)

Here are the explain outputs for both which look identical :

*slow pgsql10 : *

postgres@smadb-clone:~$ /usr/local/pgsql10/bin/psql -p 5410 tds
psql (10.23)
Type "help" for help.

postgres@[local]/tds=5410# \dx tds_fdw
                                          List of installed extensions
  Name   | Version | Schema | 
                                    Description
---------+---------+--------+----------------------------------------------------------------------------------- 

tds_fdw | 2.0.4   | public | Foreign data wrapper for querying a TDS 
database (Sybase or Microsoft SQL Server)
(1 row)

postgres@[local]/tds=5410# \timing
Timing is on.
postgres@[local]/tds=5410# EXPLAIN (ANALYZE, BUFFERS) select count(*) 
from mssql_bdynacom."ACDOC" ;
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
WARNING:  Table definition mismatch: Foreign source has column named , 
but target table does not. Column will be ignored.
                                                              QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------- 

Aggregate  (cost=168334139.12..168334139.13 rows=1 width=8) (actual 
time=14580.974..14580.975 rows=1 loops=1)
   ->  Foreign Scan on "ACDOC"  (cost=200.00..168329931.30 rows=1683130 
width=0) (actual time=13.989..14445.091 rows=1683130 loops=1)
Planning time: 14144.782 ms
Execution time: 14633.792 ms
(4 rows)

Time: 28779.099 ms (00:28.779)

-- single run

postgres@[local]/tds=5410# select count(*) from mssql_bdynacom."ACDOC" ;
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
WARNING:  Table definition mismatch: Foreign source has column named , 
but target table does not. Column will be ignored.
  count
---------
1683135
(1 row)

Time: 28740.634 ms (00:28.741)

*fast pgsql10 :*

pgsql10@smadb:~$ psql -p 5410 tds
psql (10.23)
Type "help" for help.

pgsql10@[local]/tds=5410# \dx tds_fdw
                                          List of installed extensions
  Name   | Version | Schema | 
                                    Description
---------+---------+--------+----------------------------------------------------------------------------------- 

tds_fdw | 2.0.4   | public | Foreign data wrapper for querying a TDS 
database (Sybase or Microsoft SQL Server)
(1 row)

pgsql10@[local]/tds=5410# \timing
Timing is on.
pgsql10@[local]/tds=5410# EXPLAIN (ANALYZE, BUFFERS) select count(*) 
from mssql_bdynacom."ACDOC" ;
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
WARNING:  Table definition mismatch: Foreign source has column named , 
but target table does not. Column will be ignored.
                                                            QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------- 

Aggregate  (cost=168334339.15..168334339.16 rows=1 width=8) (actual 
time=915.693..915.694 rows=1 loops=1)
   ->  Foreign Scan on "ACDOC"  (cost=200.00..168330131.32 rows=1683132 
width=0) (actual time=8.520..824.909 rows=1683132 loops=1)
Planning time: 201.217 ms
Execution time: 917.305 ms
(4 rows)

Time: 1119.045 ms (00:01.119)

-- single run

pgsql10@[local]/tds=5410# select count(*) from mssql_bdynacom."ACDOC" ;
NOTICE:  tds_fdw: Query executed correctly
NOTICE:  tds_fdw: Getting results
WARNING:  Table definition mismatch: Foreign source has column named , 
but target table does not. Column will be ignored.
  count
---------
1683135
(1 row)

Time: 1743.575 ms (00:01.744)

We run perf on both systems for 90 seconds to make sure that it included 
at least two runs of the slow system, and we attach both outputs. We run 
perf as :

sudo perf record -g -p <PID> -- sleep 90

it strikes me that we dont find similarities between the two, but we are 
new to perf.

> Thank you Tomas, as soon 
> as I get my hands on the new VM I will do as you suggested and report 
> back.
>>
>> regard
>>
>
>

---

From: Tomas Vondra <[email-masked]>
Date: Tue, 12 Nov 2024 14:17:53 +0100

On 11/12/24 11:37, Achilleas Mantzios - cloud wrote:
> ...

Not sure, but it seems the slow profile has a lot of writes. Not sure
why. Do both instances have the same work_mem value / available memory,
storatge?

Maybe EXPLAIN VERBOSE would show if the remote query is the same ...

Maybe try setting log_temp_files=0 before running the query. Writing the
foreign scan result set into a temp file could be happening on one of
the machines only.

regards

-- 
Tomas Vondra

---

From: Achilleas Mantzios <[email-masked]>
Date: Tue, 12 Nov 2024 20:24:09 +0200

> why. Do both instances have the same work_mem value / available memory,
In fact the plain vanilla installation, with all the defaults, runs this 
fast, please read further.
> foreign scan result set into a temp file could be happening on one of

No temp files, the remote query shown by EXPLAIN (... VERBOSE) and ms 
sql it self is :

Remote query: SELECT NULL FROM [db_ro_non_delosnav].[ACDOC]

Aggregate  (cost=168359742.33..168359742.34 rows=1 width=8) (actual 
time=15100.248..15100.250 rows=1 loops=1)
   Output: count(*)
   ->  Foreign Scan on mssql_bdynacom."ACDOC" 
  (cost=200.00..168355533.86 rows=1683386 width=100) (actual 
time=3.783..14967.029 rows=1683386 loops=1)
         Output: "ID", "DOC_TYPE", "PARAST", "TRNS_DATE", "VIA_MNG", 
"VIA_MNG_ID", "FL_UPD", "NOTES", "REM_DATE", "REM_CLS", "OPN_CLS", 
"ACSITE_ID", "USERS_ID", "LAST_UPD_DA
TE", "LAST_UPD_USERS_ID", "OTH_TYPE", "OTH_TYPE_DESC", "OTH_APPL", 
"FL_PRN", "CREATE_DATE", "LOG_NOTE", "PER_ID", "ACDEPT_ID", "FL_DLT", 
"CMP_ID", "INTPER_ID", "FL_INT_TRNCL
S", "FL_ACTV", "OLD_ACDEPT_ID", "OLD_USERS_ID", "OLD_TRNS_DATE", 
"OLD_FL_UPD_DATE", "FL_FNLZ", "ERROR_NOTES", "FL_ATTCH", "OPDOC_ID", 
"FL_ONHOLD", "ONHOLD_NOTES", "FL_RVS",
"RVS_DOC_ID", "FL_REV", "REV_NO", "REV_DOC_ID", "REV_NOTES", "REV_DATE", 
"REV_USER_ID", "FL_PROT", "INTGR_DOC_ID", "INTGR_DOC_TP", "P_DOC_ID", 
"FL_OPN", "FL_MDL", "USERUPDAC
C_ID", "DATE_UPDACC", "USERIN_ID", "USERUPD_ID", "DATE_IN", "DATE_UPD", 
"DOC_SUBTYPE", "DOC_REF", "FRTRN_TYPE", "FL_ACC", "ATCH_DIR", 
"ATCH_REM", "KEYID", "OTH_APPL1", "RGST
R_ID", "ACDOC_LIST_NO", "EXEC_DATE", "EXEC_USER_ID", "EXEC_NOTES", 
"CNL_EXEC_DATE", "CNL_EXEC_USER_ID", "FL_EXEC", "CNL_EXEC_NOTES", 
"LOG_NOTE1", "USERREUPDACC_ID", "DATE_RE
UPDACC", "P_ACDOC_ID", "FL_AUTHORITY_APRV", "FL_APPROVE_TYPE", 
"FL_NOTINCLUDE_INAUTH", "FL_NO_OTHERCURRENCY", "FL_WFSTATUS", "FL_APRV", 
"USRACTV_LOG_ID", "USERIN_DNAME", "US
ERUPD_DNAME", "UROLEIN_ID", "UROLEIN_NAME", "UDEPTIN_ID", 
"UDEPTIN_NAME", "FL_LOAD_5805", "UROLEUPD_ID", "UROLEUPD_NAME", 
"CNTRY_ID", fl_togetback, "FULLPATH", "FL_UPD_OLD",
"FL_REOINTG", "FL_OINTGR_RESEND"
         Remote query: SELECT NULL FROM [db_ro_non_delosnav].[ACDOC]
Query Identifier: 6812542821581303630
Planning Time: 14029.724 ms
JIT:
   Functions: 2
   Options: Inlining true, Optimization true, Expressions true, 
Deforming true
   Timing: Generation 0.168 ms, Inlining 2.087 ms, Optimization 3.301 
ms, Emission 3.564 ms, Total 9.121 ms
Execution Time: 15102.803 ms
(12 rows)

I gather this is how it computes the plan.

I think we have narrowed down the problem, and this is extremely strange :

It is not a matter of pgsql version 10 or 16, it is a matter of the 
postgres user, the user that owns the data dir(s) and the user of the 
postgres process. We  reproduced both the problem and the solution with 
all combinations of versions.

To sum it up :

Our sysadm created the system debian Debian GNU/Linux 12 (bookworm)with 
postgres as user 1000. Now at some point we realized that whenever we 
run a pgsql cluster with another user (I found that after spending two 
good days testing), the above query runs in about 1 second. With user 
postgres 1000 in 30 seconds. As you saw the perf output are completely 
different.

On the test VM, we removed the postgres user, recreated with uid=1003, 
chown -R all the mount points + table spaces, started postgres with the 
new postgres user , and bingo . The chown -R on the 5TB is instant... 
just saying ...

We are puzzled what can be causing this. Tomorrow we dig into GDB , 
*trace and the like.

If this rings any bells we would be more than grateful to know.

Also, the worse, is the suspicion that maybe our whole infra performance 
is affected. We hope it is only free-tds and tds_fdw .

---

From: Tom Lane <[email-masked]>
Date: Tue, 12 Nov 2024 14:37:36 -0500

> postgres 1000 in 30 seconds. As you saw the perf output are completely 

Don't recall details offhand, but in some situations where the calling
SQL user doesn't have permissions to read particular columns, the
planner will not consult statistics for those columns.  That can lead
to a different, less optimal plan being used.  Maybe something like
that is happening here?

			regards, tom lane

---

From: Tomas Vondra <[email-masked]>
Date: Tue, 12 Nov 2024 22:46:14 +0100

> to a different, less optimal plan being used.  Maybe something like

I don't know, the query is pretty trivial, and the estimates seemed
exactly the same in both cases. And it shouldn't affect how the query
gets planned on the MSSQL side.

But this seems really strange:

It's not about the execution, it's about the planning. I have no idea
why should the planning take this long, except maybe for waiting for a
lock, or something like that. But that's not really consistent with the
profile ... it's weird.

I'm not familiar with tds_fdw, but I see there are a bunch of table
options [1] that might affect this, namely:

* use_remote_estimate
* local_tuple_estimate
* row_estimate_method (defaults to 'execute')

Are you sure these are set to the same value on both machines?

Wild random guesses:

1) Could you try running the query with jit=off?

2) Did you run ANALYZE on the foreign table? Could matter when not using
remote estimates (use_remote_estimate=false).

3) Could it be some sort of memory pressure/swapping? But that would
look different in the profile, AFAIK.

regards

[1] https://github.com/tds-fdw/tds_fdw/blob/master/ForeignTableCreation.md

-- 
Tomas Vondra

---

From: Achilleas Mantzios - cloud <[email-masked]>
Date: Wed, 13 Nov 2024 09:14:18 +0200

> to a different, less optimal plan being used.  Maybe something like

Thank you Tom,

In all runs of this query the user is postgres (superuser). Besides, 
this is just a simple query run on a FOREIGN TABLE living in a MS SQL 
Server.

---

From: Achilleas Mantzios - cloud <[email-masked]>
Date: Wed, 13 Nov 2024 10:45:58 +0200

Dear All

false alert, I run strace and it was obvious the slow one was producing 
huge debug output, while the fast one did not. It was not even a tds_fdw 
issue. It was freetds. Turned out we have forgotten enabled debugging 
inside the freetds configuration. You will ask me we did I get this 
effect of debugging only when run with user "postgres" ? Because 
/tmp/freetds.log belonged to postgres!

I changed owner to nobody:nogroup and dont even need to restart postgres. !!

I am sorry for all the noise.

Thank you so much for your prompts !!