Simple query very slow on table with blob sub_type 0 [CORE5086]

[firebird-automations]

Submitted by: Corey Marques (cjmarques)

I have a table with two columns

CREATE TABLE ARTRANS ( RECORDID Integer NOT NULL, DESCRIPTION Blob sub_type 0 );

There is also an index on the table

CREATE UNIQUE INDEX IDX\_ARTRANSRecID ON ARTRANS \(RECORDID\);

There are \~246,000 records

For this test, each blob had 20 bytes.

The following query takes 20 seconds

SELECT a.RECORDID FROM ARTRANS a

Changing the field type from blob to text fixes it.

Here is the output from FlameRobin:

Preparing query: SELECT a.RECORDID FROM ARTRANS a Prepare time: 20.008s Field #⁠01: ARTRANS.RECORDID Alias:RECORDID Type:INTEGER PLAN (A NATURAL)

Executing... Done. 13257 fetches, 0 marks, 76 reads, 0 writes. 0 inserts, 0 updates, 0 deletes, 0 index, 6552 seq. Delta memory: -19204 bytes. Total execution time: 20.025s Script execution finished.

[firebird-automations]

Commented by: Sean Leyne (seanleyne)

Based on my 20 years of running Interbase/Firebird, my feeling is that your "tests" results/methodology is skewed by OS and engine cache. The type of a blob has no impact on performance.

Did you restart your PC / the Firebird engine in between your tests? (to eliminate the cost of loading data/pages into caches from the test results)

What version of the engine are you running? SuperServer (Default install)? SuperClassic? Classic?

[firebird-automations]

Commented by: @dyemanov

If "from blob to text" actually means "to CHAR/VARCHAR" rather than "to BLOB SUBTYPE TEXT", then it's perfectly expected. And this is not a bug, rather the architecture specifics.

[firebird-automations]

Commented by: Attila Molnár (e_pluribus_unum)

BLOBs (DESCRIPTION ) are not stored on the same page with RECORDID, only BLOB is. Extra page fetch needed on the server side and extra roundtrip between server and client to get each blob value.

[firebird-automations]

Commented by: Sean Leyne (seanleyne)

Atila,

Your comments are not completely correct, BLOBs can be stored on the same page as the row data, depending on their size and when they are created (ie. with the row insert or after) if there is enough free space available on the page.

Your comments are also not applicable in this case. The blob field is not referenced in the SQL provided, so it would not be retrieved/accessed for the query.

[firebird-automations]

Commented by: @AlexPeshkoff

First of all it's necessary to understand why prepare takes so long:

Prepare time: 20.008s

And why is it the same as exec:

Total execution time: 20.025s

I do not believe in occasional match...

[firebird-automations]

Commented by: Corey Marques (cjmarques)

Some history.

We first noticed this slow down on a customers machine.

We brought it to a virtual network environment and were able to reproduce it. I then brought it to my machine and kept removing things until it was just the ID and the description.

I upgraded Firebird from 2.5.3 to 2.5.5 and tried it on Classic, Super and Super Classic all with the same results. It was slow both in the application and running the query in FlameRobin. The query returns quick on subsequent queries.

With the full table (25 columns), performance is consistently fast when we remove the blob column.

Also, notice that my query isn't asking for the blob field.. just the recordid.

[firebird-automations]

Commented by: @AlexPeshkoff

I suppose that database with 246,000 records in one table is not too big. Can you make it available?

[firebird-automations]

Commented by: Sean Leyne (seanleyne)

Corey,

Did you mean a *Virtual Machine* environment, instead of virtual network environment?

I wonder if you are seeing exceptionally slow disk performance. As Alex pointed out, 20sec to prepare a query is exceptionally long.

[firebird-automations]

Commented by: Corey Marques (cjmarques)

We testing it in a virtual environment and on local machines. I'm going to make it available.

The database can be downloaded from dropbox here

https://www.dropbox.com/s/t4q2aq7fhmmpfii/SLOWAR.FDB?dl=1

easiest way to reproduce is to open it in flamerobin, do a "Select from..." on the ARTrans table. After the initial query (which runs fine) run this query

SELECT a.RECORDID FROM ARTRANS a

and for us this takes about 20 seconds.

[firebird-automations]

Commented by: @AlexPeshkoff

For me running the query takes about 5 sec, prepare time is close to 0

[firebird-automations]

Commented by: Corey Marques (cjmarques)

5 seconds still seems slow for that query but must faster than mine. Are you on an ssd?

[firebird-automations]

Commented by: @pavel-zotov

I've downloaded database (it's size = 56279040 bytes) and run your query on ordinary PC (cpu 3.0 GHz, ram 2Gb) with slow HDD:

C:\MIX\firebird\QA\fbt-repo\tmp>C:\MIX\firebird\fb25\bin\isql /3255:C:\MIX\firebird\QA\fbt-repo\tmp\c5086.fdb Database: /3255:C:\MIX\firebird\QA\fbt-repo\tmp\c5086.fdb SQL> out tmp.txt; SELECT a.RECORDID FROM ARTRANS a; out; SQL>

This is from trace:

2016-01-30T02:06:29.2830 (7364:011DB38C) ATTACH_DATABASE C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616

2016-01-30T02:06:29.2830 (7364:011DB38C) START_TRANSACTION C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616 (TRA_14, CONCURRENCY | WAIT | READ_WRITE)

2016-01-30T02:06:29.2830 (7364:011DB38C) START_TRANSACTION C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616 (TRA_15, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

2016-01-30T02:07:10.4080 (7364:011DB38C) PREPARE_STATEMENT C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616 (TRA_15, READ_COMMITTED | NO_REC_VERSION | WAIT | READ_WRITE)

Statement 35: ------------------------------------------------------------------------------- SELECT a.RECORDID FROM ARTRANS a ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ PLAN (A NATURAL) 6 ms

2016-01-30T02:07:10.4080 (7364:011DB38C) EXECUTE_STATEMENT_START C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616 (TRA_14, CONCURRENCY | WAIT | READ_WRITE)

Statement 35: ------------------------------------------------------------------------------- SELECT a.RECORDID FROM ARTRANS a ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ PLAN (A NATURAL)

2016-01-30T02:07:18.8460 (7364:011DB38C) EXECUTE_STATEMENT_FINISH C:\MIX\FIREBIRD\QA\FBT-REPO\TMP\C5086.FDB (ATT_5, SYSDBA:NONE, NONE, TCPv4:192.168.43.154) C:\MIX\firebird\fb25\bin\isql.exe:7616 (TRA_14, CONCURRENCY | WAIT | READ_WRITE)

Statement 35: ------------------------------------------------------------------------------- SELECT a.RECORDID FROM ARTRANS a ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ PLAN (A NATURAL) 246804 records fetched 3058 ms, 3014 read(s), 499639 fetch(es)

Table Natural Index Update Insert Delete Backout Purge Expunge *************************************************************************************************************** ARTRANS 246804

As you can see, prepare was instant.

PS.

SQL> show version; ISQL Version: WI-V2.5.6.26965 Firebird 2.5 Server version: Firebird/x86/Windows NT (access method), version "WI-V2.5.6.26965 Firebird 2.5" Firebird/x86/Windows NT (remote server), version "WI-V2.5.6.26965 Firebird 2.5/tcp (csprog)/P12" Firebird/x86/Windows NT (remote interface), version "WI-V2.5.6.26965 Firebird 2.5/tcp (csprog)/P12" on disk structure version 11.2

[firebird-automations]

Commented by: Corey Marques (cjmarques)

I found if you run just the record id query right after opening the connection, it's very fast.. but if you run the first one (below), then the record ID query on the same connection, that's when the slowness happens.

SELECT a.RECORDID, a.DESCRIPTION FROM ARTRANS a

SELECT a.RECORDID FROM ARTRANS a