Why is the same query on MariaDB taking more time when run via Sequelize from the application versus running it directly on the mysql client or CLI?

user_3639452 0
Viewed 52

For the following MariaDB schema:

meta_schema_version

  • id (int)
  • namespace_id (int)
  • version (varchar(10))
  • schema (longtext)
  • comment (mediumtext)
  • created_at (datetime)

meta

  • id (int) [PK]
  • meta_id (int)
  • version_num (int)
  • meta_schema_version_id (int) - [FK to meta_schema_version]
  • tag (varchar(30))
  • tag_value (varchar(100))
  • meta (longtext)
  • comment (mediumtext)
  • is_deleted (tinyint(1))
  • updated_at (datetime)
  • updated_by (varchar(100))

Following are the indexes on the meta table:

  • id - primary key - BTREE - unique
  • meta_schema_version_id - foreign key - BTREE - not unique
  • idx_config_id - BTREE - not unique

There are more than a million records in the meta table.

I am using Sequelize to fetch a paginated list like this:

metas = await this.meta.findAndCountAll({
                attributes: ['id', 'tag', 'tagValue', ...versionAttribute],
                include: [
                  {
                    model: MetaSchemaVersion,
                    attributes: ['version'],
                  },
                ],
                where: {
                  metaSchemaVersionId: schemaVersion.id,
                  isDeleted: {
                    [Op.eq]: 0,
                  },
                },
                limit,
                offset,
              });

Sequelize logs the following 2 queries corresponding to the above function: query 1:

SELECT  count(*) AS `count`
    FROM  `meta` AS `Meta`
    WHERE  `Meta`.`meta_schema_version_id` = 1
      AND  `Meta`.`is_deleted` = 0

query 2:

SELECT  `id`, `tag`, `tag_value` AS `tagValue`,
        `comment`, `updated_at` AS `updatedAt`,
        `updated_by` AS `updatedBy`,
        `meta_schema_version_id` AS `metaSchemaVersionId`,
        `meta`
    FROM  `meta` AS `Meta`
    WHERE  `Meta`.`meta_schema_version_id` = 1
      AND  `Meta`.`is_deleted` = 0
    LIMIT  0, 10

I have enabled slow query logs with a very low long_query_time of 0.0001

The query time on the slow query logs comes up as:

  • query 1: 00:00:00.612878
  • query 2: 00:00:00.894041

The same queries when run directly on the CLI show the query time as ~00:00:00.0005 for both queries

Why is there such a big difference in query time when run directly on the CLI vs via the Sequelize ORM?

SHOW PROFILE on the slow query gives the following response

[
  { Status: 'Starting', Duration: '0.000026' },
  { Status: 'Opening tables', Duration: '0.000025' },
  { Status: 'System lock', Duration: '0.000003' },
  { Status: 'table lock', Duration: '0.000004' },
  { Status: 'Opening tables', Duration: '0.000002' },
  { Status: 'After opening tables', Duration: '0.000100' },
  { Status: 'closing tables', Duration: '0.000003' },
  { Status: 'Unlocking tables', Duration: '0.000003' },
  { Status: 'closing tables', Duration: '0.000073' },
  { Status: 'checking permissions', Duration: '0.000005' },
  { Status: 'Opening tables', Duration: '0.000013' },
  { Status: 'After opening tables', Duration: '0.000004' },
  { Status: 'System lock', Duration: '0.000004' },
  { Status: 'table lock', Duration: '0.000006' },
  { Status: 'init', Duration: '0.000033' },
  { Status: 'Optimizing', Duration: '0.000018' },
  { Status: 'Statistics', Duration: '0.000074' },
  { Status: 'Preparing', Duration: '0.000024' },
  { Status: 'Executing', Duration: '0.000002' },
  { Status: 'Sending data', Duration: '0.880704' },
  { Status: 'End of update loop', Duration: '0.000016' },
  { Status: 'Query end', Duration: '0.000003' },
  { Status: 'Commit', Duration: '0.000005' },
  { Status: 'closing tables', Duration: '0.000003' },
  { Status: 'Unlocking tables', Duration: '0.000002' },
  { Status: 'closing tables', Duration: '0.000043' },
  { Status: 'Starting cleanup', Duration: '0.000003' },
  { Status: 'Freeing items', Duration: '0.000010' },
  { Status: 'Updating status', Duration: '0.000015' },
  { Status: 'Logging slow query', Duration: '0.000006' },
  { Status: 'Opening tables', Duration: '0.000016' },
  { Status: 'System lock', Duration: '0.000002' },
  { Status: 'table lock', Duration: '0.000003' },
  { Status: 'Opening tables', Duration: '0.000002' },
  { Status: 'After opening tables', Duration: '0.000059' },
  { Status: 'closing tables', Duration: '0.000002' },
  { Status: 'Unlocking tables', Duration: '0.000002' },
  { Status: 'closing tables', Duration: '0.000005' },
  { Status: 'Reset for next command', Duration: '0.000238' }
]

Update 1: The queries mentioned in my original post are incorrect. I had commented the join part in the ORM code when I copied the SQL queries. The correct queries are:

query 1:

SELECT count(Meta.id) AS count FROM meta AS Meta LEFT OUTER JOIN meta_schema_version AS metaSchemaVersion ON Meta.meta_schema_version_id = metaSchemaVersion.id WHERE Meta.meta_schema_version_id = 1 AND Meta.is_deleted = 0;

query 2:

SELECT Meta.id, Meta.tag, Meta.tag_value AS tagValue, Meta.comment, Meta.updated_at AS updatedAt, Meta.updated_by AS updatedBy, Meta.meta_schema_version_id AS metaSchemaVersionId, Meta.meta, metaSchemaVersion.id AS metaSchemaVersion.id, metaSchemaVersion.version AS metaSchemaVersion.version FROM meta AS Meta LEFT OUTER JOIN meta_schema_version AS metaSchemaVersion ON Meta.meta_schema_version_id = metaSchemaVersion.id WHERE Meta.meta_schema_version_id = 1 AND Meta.is_deleted = 0 LIMIT 0, 20;
sequelize.js mariadb node.js orm mysql
1 Answers

This may benefit Meta for both Queries:

INDEX(meta_schema_version_id, is_deleted)   -- (the column order does not matter)

However, a LIMIT without an ORDER BY will give you whatever row it happens to want to give you. If you add ORDER BY, I need to reanalyzed the optimal INDEX

(I have a very negative opinion of Profile. Notice how nearly all the time is in the cryptic "Sending data". This is common.)

same queries when run directly on the CLI

There are two possible reasons for that. I recommend that you run the query as

SELECT SQL_NO_CACHE ...`
  • That avoids the "query cache", wherein the query and its results are cached; as second run will be essentially instantaneous, such as 00:00:00.0005.
  • Or... The first run may have fetched lots of data from disk, thereby making the second run much faster because of the data being cached in RAM.

So, add that flag, run the query twice, take the second timing.

I am making the request from the app server on my local dev machine.

One way to test the network latency (overhead) is to time the trivial SELECT 1; query.

Query 1 must scan the whole table. With my Index, it will, instead, scan part of the Index.

Query 2, without an ORDER BY, scans the table until it finds 10 rows that match the WHERE clause.

user_17668310
Related