JDBC Driver shows erratic behavior when filtering on CURRENT_DATE

[arjenpeters]

Hello all,

I have been encountering an issue whereby I see erratic behavior on a particular query that runs through the JDBC driver.

For the sake of clarification, we have two types applications involved here:

1. AppX is a Java based application which has a built-in query tool. It's directly connected to PostgreSQL db of version 12.14 which is hosted on CentOS Linux 7.9.2009. The data needs to be queried from here.
2. External tools that can be used to query data. In this case, we are using DbVisualizer and KNIME (open-source ETL tool build on Java). We connect to the db of AppX externally via PostgreSQL JDBC Driver 42.7.3

In AppX, there are two tables: part and part_fa_entity which are joined by the mutal field partno. In the part table, there is field called mutation which is an integer date based on 1971-12-31. In this use case, we only want to query records from the parts table where the mutation is within a certain range, calculated by (p.mutation >= (CURRENT_DATE - '1971-12-31'::date)-27)

What we notice is that from the external tools, the query returns an incorrect result based on the value and the position of that filter.

For one particular partno in the table part, there are two records.

Accordingly, for both partno's there is also an entry in part_fa_entity table with unique values.

The corresponding query is as follows:

SELECT
  p.partseqno_i
, p.partno
, p.partmatch
, pfe.average_price
, pfe.sales_price
, pfe.purch_price
, pfe.average_price_2
, pfe.avg_repair_cost
, pfe.average_price_func
, pfe.fsv
, pfe.fsv_func
, p.status

FROM part p
LEFT JOIN part_fa_entity pfe ON (p.partno = pfe.partno)
WHERE 1=1
AND (p.mutation >= (CURRENT_DATE - '1971-12-31'::date)-27)
ORDER BY p.partno

What happens is the following:

When we query (p.mutation >= (CURRENT_DATE - '1971-12-31'::date)-28) and filter for the partno via the search option in DbVisualizer/KNIME, the output is correct.

When we query (p.mutation >= (CURRENT_DATE - '1971-12-31'::date)-27) and filter for the partno via the search option in DbVisualizer/KNIME, the output is incorrect due to missing data on one of the records.

Hereafter, we deployed EXPLAIN ANALYSE for both cases to see what's is going on in the background. Most notably;

For the correct result with -28 days, it's using a Hash Right Join.

For the incorrect result with -27 days, it's using a Nested Loop Left Join.

To make matters worse, when we take the working -28 query and add another WHERE statement which filters directly on the subject partno, it now also starts to generate the incorrect result.

To add to the confusing, whenever we take the "incorrect" -27 query move the current date filter to the LEFT JOIN, this one now starts output the correct result.

Me and my team are completely puzzled by this and are unable to understand what makes the data to come out of query incorrectly. The reason for coming to this place is that the build-in query tool of AppX is consistantly generting the correct results and all of the records show correctly in the build-in database explore there. We therefore have a strong suspicion that the issue resides somewhere in the JDBC driver.

Interesantly enough, upon analysing the query plan, AppX also chooses to go the Hash Right Join and Nested Loop Left Join route based on the number of days but as mentioned, output the data correctly.

As such, we are hoping that someone is able to help us understand what exactly is root cause of the behavior we are seeing here, if the dev team of the driver is the right one to contact and more importantly, what action we can take to consistantly get the correct data out of the database.

Thanks in advance for your time and effort helping us!

[davecramer]

any chance you can see the logs on the server to see what the query is ?
Also https://www.postgresql.org/docs/12/release-12-18.html#id-1.11.6.5.6 has some partition issues

[arjenpeters]

That will be quite a challange unfortunately since it's all third-party hosted and access is restricted.

That issue as per the link definitely sounds like something although that still wouldn't really explain why the issue is only occurring whenever the query goes via the JDBC.

[davecramer]

That's unfortunate.

Can you paste the explain output in text please

[arjenpeters]

Sure!

JDBC - Nested Loop

Sort  (cost=1071.31..1071.60 rows=114 width=83) (actual time=2.894..2.912 rows=330 loops=1)
  Sort Key: p.partno
  Sort Method: quicksort  Memory: 70kB
  ->  Nested Loop Left Join  (cost=9.46..1067.42 rows=114 width=83) (actual time=0.082..2.446 rows=330 loops=1)
        ->  Bitmap Heap Scan on part p  (cost=9.18..295.79 rows=114 width=29) (actual time=0.064..0.502 rows=330 loops=1)
              Recheck Cond: (mutation >= ((CURRENT_DATE - '1971-12-31'::date) - 28))
              Heap Blocks: exact=181
              ->  Bitmap Index Scan on i_42609  (cost=0.00..9.15 rows=114 width=0) (actual time=0.041..0.041 rows=344 loops=1)
                    Index Cond: (mutation >= ((CURRENT_DATE - '1971-12-31'::date) - 28))
        ->  Index Scan using i_39773 on part_fa_entity pfe  (cost=0.29..6.76 rows=1 width=65) (actual time=0.005..0.005 rows=1 loops=330)
              Index Cond: ((partno)::text = (p.partno)::text)
Planning Time: 0.418 ms
Execution Time: 2.971 ms

JDBC - Hash Right

Sort  (cost=1352.35..1352.94 rows=238 width=83) (actual time=5.214..5.236 rows=345 loops=1)
  Sort Key: p.partno
  Sort Method: quicksort  Memory: 73kB
  ->  Hash Right Join  (cost=472.00..1342.95 rows=238 width=83) (actual time=0.654..4.714 rows=345 loops=1)
        Hash Cond: ((pfe.partno)::text = (p.partno)::text)
        ->  Seq Scan on part_fa_entity pfe  (cost=0.00..837.27 rows=12827 width=65) (actual time=0.009..2.191 rows=12827 loops=1)
        ->  Hash  (cost=469.03..469.03 rows=238 width=29) (actual time=0.623..0.624 rows=345 loops=1)
              Buckets: 1024  Batches: 1  Memory Usage: 30kB
              ->  Bitmap Heap Scan on part p  (cost=18.14..469.03 rows=238 width=29) (actual time=0.073..0.532 rows=345 loops=1)
                    Recheck Cond: (mutation >= ((CURRENT_DATE - '1971-12-31'::date) - 29))
                    Heap Blocks: exact=186
                    ->  Bitmap Index Scan on i_42609  (cost=0.00..18.08 rows=238 width=0) (actual time=0.049..0.049 rows=359 loops=1)
                          Index Cond: (mutation >= ((CURRENT_DATE - '1971-12-31'::date) - 29))
Planning Time: 0.304 ms
Execution Time: 5.292 ms

Below are the two different versions that AppX uses.
Nested Loop

Sort  (cost=1071.31..1071.60 rows=114 width=83) (actual time=3.083..3.102 rows=330 loops=1)
  Output: p.partseqno_i, p.partno, p.partmatch, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.average_price_func, pfe.fsv, pfe.fsv_func, p.status
  Sort Key: p.partno
  Sort Method: quicksort  Memory: 71kB
  ->  Nested Loop Left Join  (cost=9.46..1067.42 rows=114 width=83) (actual time=0.069..2.471 rows=330 loops=1)
        Output: p.partseqno_i, p.partno, p.partmatch, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.average_price_func, pfe.fsv, pfe.fsv_func, p.status
        ->  Bitmap Heap Scan on .part p  (cost=9.18..295.79 rows=114 width=29) (actual time=0.054..0.308 rows=330 loops=1)
              Output: p.min_safety_stock, p.manual_safety_stock, p.extended_stateno_i, p.partno, p.partmatch, p.partseqno_i, p.description, p.remarks, p.specification, p.ata_chapter, p.vendor, p.weight, p.storetime, p.alert_qty, p.measure_unit, p.waste_code, p.reord_level, p.safety_stock, p.max_purch, p.ac_typ, p.mat_class, p.mat_type, p.country_origin, p.reorder, p.tool, p.repairable, p.avg_ta_time, p.default_supplier, p.default_repair, p.special_contract, p.fixed_asset, p.reorder_last_mutator, p.reorder_last_mutation, p.max_shop_visit, p.shop_visit_reset_condition, p.special_measure_unit, p.manufacturer, p.pma, p.resource_type_id, p.counter_template_groupno_i, p.mutation, p.mutator, p.status, p.mutation_time, p.created_by, p.created_date
              Recheck Cond: (p.mutation >= ((CURRENT_DATE - `1971-12-31`::date) - 28))
              Heap Blocks: exact=181
              ->  Bitmap Index Scan on i_42609  (cost=0.00..9.15 rows=114 width=0) (actual time=0.033..0.034 rows=341 loops=1)
                    Index Cond: (p.mutation >= ((CURRENT_DATE - `1971-12-31`::date) - 28))
        ->  Index Scan using i_39773 on .part_fa_entity pfe  (cost=0.29..6.76 rows=1 width=65) (actual time=0.005..0.006 rows=1 loops=330)
              Output: pfe.part_fa_entityno_i, pfe.partno, pfe.entityno_i, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.avg_repair_cost_func, pfe.fa_qty, pfe.fa_open_iv_qty, pfe.fa_start_qty, pfe.fa_start_price, pfe.fa_start_price_2, pfe.mutation, pfe.mutator, pfe.status, pfe.mutation_time, pfe.created_by, pfe.created_date, pfe.average_price_func, pfe.fa_start_price_func, pfe.fsv, pfe.fsv_func
              Index Cond: ((pfe.partno)::text = (p.partno)::text)
Planning Time: 0.361 ms
Execution Time: 3.157 ms

Hash Join

Sort  (cost=1352.35..1352.94 rows=238 width=83) (actual time=5.361..5.384 rows=345 loops=1)
  Output: p.partseqno_i, p.partno, p.partmatch, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.average_price_func, pfe.fsv, pfe.fsv_func, p.status
  Sort Key: p.partno
  Sort Method: quicksort  Memory: 73kB
  ->  Hash Right Join  (cost=472.00..1342.95 rows=238 width=83) (actual time=0.594..4.669 rows=345 loops=1)
        Output: p.partseqno_i, p.partno, p.partmatch, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.average_price_func, pfe.fsv, pfe.fsv_func, p.status
        Inner Unique: true
        Hash Cond: ((pfe.partno)::text = (p.partno)::text)
        ->  Seq Scan on amos.part_fa_entity pfe  (cost=0.00..837.27 rows=12827 width=65) (actual time=0.006..1.581 rows=12827 loops=1)
              Output: pfe.part_fa_entityno_i, pfe.partno, pfe.entityno_i, pfe.average_price, pfe.sales_price, pfe.purch_price, pfe.average_price_2, pfe.avg_repair_cost, pfe.avg_repair_cost_func, pfe.fa_qty, pfe.fa_open_iv_qty, pfe.fa_start_qty, pfe.fa_start_price, pfe.fa_start_price_2, pfe.mutation, pfe.mutator, pfe.status, pfe.mutation_time, pfe.created_by, pfe.created_date, pfe.average_price_func, pfe.fa_start_price_func, pfe.fsv, pfe.fsv_func
        ->  Hash  (cost=469.03..469.03 rows=238 width=29) (actual time=0.564..0.566 rows=345 loops=1)
              Output: p.partseqno_i, p.partno, p.partmatch, p.status
              Buckets: 1024  Batches: 1  Memory Usage: 30kB
              ->  Bitmap Heap Scan on amos.part p  (cost=18.14..469.03 rows=238 width=29) (actual time=0.075..0.488 rows=345 loops=1)
                    Output: p.partseqno_i, p.partno, p.partmatch, p.status
                    Recheck Cond: (p.mutation >= ((CURRENT_DATE - `1971-12-31`::date) - 29))
                    Heap Blocks: exact=186
                    ->  Bitmap Index Scan on i_42609  (cost=0.00..18.08 rows=238 width=0) (actual time=0.035..0.035 rows=356 loops=1)
                          Index Cond: (p.mutation >= ((CURRENT_DATE - `1971-12-31`::date) - 29))
Planning Time: 0.379 ms
Execution Time: 5.443 ms

[davecramer]

Are both using the pgjdbc driver ?

[arjenpeters]

DbVisualizer and KNIME use either 42.7.3, 42.2.0 or 42.3.5 but all with the same undesired result.

[davecramer]

OK, so the only thing that is different about the JDBC driver is that we use the V3Protocol, you can try adding preferQueryMode=simple to the connection string.
We also set the timezone to the clients timezone which may effect your results

[arjenpeters]

Thanks for the advice and the help so far!

Unfortuantely after trying every possible way of adding the parameter to the connection string, it did not chance the outcome. Clients and db are in the same timezone as well.

[davecramer]

Hmm OK, can you send me the explain outputs in text form?
Also the table definitions ?

[arjenpeters]

Sure, see attached files.

analyse explain.txt
part.xlsx
part_fa_entity.xlsx

[davecramer]

So I posted a summary of this on pgsql-hackers https://www.postgresql.org/message-id/CADK3HHLiv-btGRshBhum0sSOM0VaoE9ottzPi-S3sRMNBKKV9A@mail.gmail.com I'd suggest you reply with more information

[arjenpeters]

Thanks Dave! To be honest I have nothing more to report other than everything already posted in here (am also unfamiliar with this mailing system and how to respond to a current thread). If there is a specific question I can definitely try to help.

[tvondra]

FWIW I did respond in the pgsql-hackers that I suspect this might be consistent with corrupted index. That'd be consistent with the erratic behavior you see after switching from seqscan to index scan, where the index is "missing" some of the keys (or can't find them for whatever reason). Hard to know for sure, of course.

I'd try a couple things:

1. set enable_nestloop=off, see if the results get correct

2. try bt_index_check on i_39773, might notice some corruption

3. rebuild the index

[arjenpeters]

Hi @tvondra

I did in fact saw it! The way this PG mailing list works still haunted me a bit and I didn't want screw things up. Thanks a lot for your help and insights in this matter.

[davecramer]

You would have to subscribe to the mailing list.
You could respond to David Rowley's response with more information.

In the meantime, would it be possible to replicate this system temporarily so that we could see the postgresql logs, or ask the service provider for them ?

[davecramer]

thanks @tvondra appreciate you helping out