Re: 2x slowdown of JDBC driver 42.3.0+

On Sun, 27 Feb 2022 at 08:49, Stanislav Bashkyrtsev <
stanislav(dot)bashkirtsev(at)gmail(dot)com> wrote:

> I have performance tests written in Gatling. These are system tests (they
> send HTTP requests against a running app). Each time I run tests with the
> older version (42.2.5), the speed is increased 2x.
>
> I've logged the SQL queries that the test generates during 1 of such
> requests:
>
> select processing0_.ID as id1_9_, processing0_.NAME as name2_9_, processing0_.ENABLED as enabled3_9_, processing0_.APPLIED_TO_FILTER as applied_4_9_, processing0_.ALIGNMENT as alignmen5_9_, processing0_.METHOD as method6_9_ from PROCESSING_METHODS processing0_ where processing0_.ENABLED=true
> insert into INJECTIONS (NAME, INLET_METHOD, MS_METHOD, TIME_START, TIME_END, JOB_ID, BED, PLATE_SIZE, COORDINATES, ACQUIRED_TIME, CREATION_TIME, INSTRUMENT, BATCH, METHOD, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into DETECTOR_RUNS (TYPE, ION_MODE, TIME_START, TIME_END, SCAN_WINDOW_MIN, SCAN_WINDOW_MAX, SCAN_COMPRESSION, SEQ_NUM, ALIGN, DOMAIN, SCANS, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into DETECTOR_RUNS (TYPE, ION_MODE, TIME_START, TIME_END, SCAN_WINDOW_MIN, SCAN_WINDOW_MAX, SCAN_COMPRESSION, SEQ_NUM, ALIGN, DOMAIN, SCANS, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into SUBSTANCES (COLOR, ALIAS, MF, EMW, STRUCTURE, ID) values (?, ?, ?, ?, ?, ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into CHROMATOGRAMS (DETECTOR_RUN, SIGNAL, TOTAL_SIGNAL, AREA, MIN_SIGNAL_INTENSITY, MAX_SIGNAL_INTENSITY, DETECTED_PEAKS_RANGE_LIST, BASELINE_ANCHORS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, 'total', ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into CHROMATOGRAMS (DETECTOR_RUN, SIGNAL, TOTAL_SIGNAL, AREA, MIN_SIGNAL_INTENSITY, MAX_SIGNAL_INTENSITY, DETECTED_PEAKS_RANGE_LIST, BASELINE_ANCHORS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, 'total', ?)
> insert into BLOBS (DATA, TYPE, ID) values (?, ?, ?)
> insert into CHROMATOGRAMS (DETECTOR_RUN, SIGNAL, TOTAL_SIGNAL, AREA, MIN_SIGNAL_INTENSITY, MAX_SIGNAL_INTENSITY, DETECTED_PEAKS_RANGE_LIST, BASELINE_ANCHORS, SUBSTANCE, ION_MODE, MOLECULAR_MASSES, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'substance', ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> insert into BLOBS (TYPE, DATA, ID) values (?, ?, ?)
> insert into PEAKS (CHROMATOGRAM, RT_IDX, START_IDX, END_IDX, SUBSTANCE, AREA, AREA_PERCENT, SIGNAL, BPM, RT_MINUTES, START_MINUTES, END_MINUTES, MODIFIED_MANUALLY, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> update PROCESSING_METHODS set NAME=?, ENABLED=?, APPLIED_TO_FILTER=?, ALIGNMENT=?, METHOD=? where ID=?
> update PROCESSING_METHODS set NAME=?, ENABLED=?, APPLIED_TO_FILTER=?, ALIGNMENT=?, METHOD=? where ID=?
> update PROCESSING_METHODS set NAME=?, ENABLED=?, APPLIED_TO_FILTER=?, ALIGNMENT=?, METHOD=? where ID=?
> update PROCESSING_METHODS set NAME=?, ENABLED=?, APPLIED_TO_FILTER=?, ALIGNMENT=?, METHOD=? where ID=?
> update DETECTOR_RUNS set INJECTION=? where ID=?
> update DETECTOR_RUNS set INJECTION=? where ID=?
> insert into Injection_substances (INJECTION, SUBSTANCE) values (?, ?)
> update CHROMATOGRAMS set INJECTION=? where ID=?
> update CHROMATOGRAMS set INJECTION=? where ID=?
> update CHROMATOGRAMS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
> update PEAKS set INJECTION=? where ID=?
>
>
So do you know which one of these operations is slower?
Do you have access to the server logs ?

Dave Cramer
www.postgres.rocks

>
> On Sun, Feb 27, 2022 at 4:06 PM Dave Cramer <davecramer(at)postgres(dot)rocks>
> wrote:
>
>> Perhaps you could share how you are measuring this?
>>
>> On Sun, Feb 27, 2022, 7:09 AM Stanislav Bashkyrtsev <
>> stanislav(dot)bashkirtsev(at)gmail(dot)com> wrote:
>>
>>> When upgrading to any version of JDBC driver starting with 42.3.0 my performance
>>> tests that are heavy on inserting records (and lots of blobs by the
>>> way) show 2x slow down. I couldn't find anything suspicious in the changelog,
>>> so if anyone can give me the directions on how to research/troubleshoot
>>> this problem, I'd greatly appreciate it.
>>>
>>> PostgreSQL version: 13.2
>>> Operating system: Ubuntu
>>>
>>