0

I'm using MySQL 5.6 and executing a transaction on 3 tables (from ~300.000 to ~3 million rows). I'm doing some SELECTs and some INSERTs (less than 20) and then a COMMIT.

I'm creating a new book, its chapters and authors.

At times the transaction takes up to 12 seconds to complete. Debugging which statement is the bottleneck, it seems to be the COMMIT. All the others take a few milliseconds.

To be sure that I was not waiting for some code running on the application or some lock in the db I've added a wait_timeout and a lock_wait_timeout:

SET SESSION wait_timeout = 6
SET SESSION lock_wait_timeout = 6

START TRANSACTION

SELECT * FROM country t0 WHERE t0.iso2_code = 'IT' LIMIT 1
SELECT * FROM language t0 WHERE t0.iso2_code = 'it' LIMIT 1
SELECT * FROM book t0 WHERE t0.book_number = 'XX2293494FFKEOE' LIMIT 1

INSERT INTO book (title, isbn, pages, publisher, fk_language, book_number) VALUES ('my super title', '123456789012', 500, 'Publisher inc.', 1, 'XX2293494FFKEOE');

INSERT INTO book_author (first_name, middle_name, last_name, fk_country, fk_book) VALUES ('abc', NULL, 'xyz', 1, 1);
INSERT INTO book_author (first_name, middle_name, last_name, fk_country, fk_book) VALUES ('dfr', NULL, 'oiu', 2, 1);

INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 2, 1, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 3, 1, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 1, 2, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 5, 2, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 6, 2, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 6, 1, 'https://gist.github.com/...');
...

SELECT * FROM book t0 WHERE t0.id_book = 1;

COMMIT

After putting the timeouts in place, I've seen transactions still taking up to 12 seconds and neither of the two timeouts is triggered.

What could be the cause of this behaviour?


Some more information for context:

  • the tables have indexes and foreign keys: between 7 ansd 10 FK and 1 or 2 indexes each.
  • I'm not able to reproduce the behaviour in local
  • there is no specific timing for this problem to appear (I got it at random timings of the day/night)
  • ANALYZE TABLE ... on all three tables got me all OK (on a replica of the live db)
  • I'm aware of innodb_flush_log_at_trx_commit and innodb_flush_log_at_timeout but I didn't try changing them before having a good reason

Thanks in advance for any suggestion/idea


Add SHOW CREATE TABLE

CREATE TABLE `book` (
  `id_book` int(11) NOT NULL AUTO_INCREMENT,
  `fk_book_metadata` int(11) DEFAULT NULL,
  `fk_book_version_stats` int(11) DEFAULT NULL,
  `fk_sales_reference` int(11) DEFAULT NULL,
  `book_number` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `title` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `isbn` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `pages` int(11) DEFAULT NULL,
  `publisher` varchar(45) COLLATE utf8_unicode_ci DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime NOT NULL,
  `is_done` tinyint(1) DEFAULT 0,
  `is_sigle_author` tinyint(1) DEFAULT 0,
  `fk_language` int(11) DEFAULT NULL,
  PRIMARY KEY (`id_book`),
  UNIQUE KEY `UNIQUE_book_number` (`book_number`),
  KEY `IDX_36D222EE52964B9` (`fk_book_metadata`),
  KEY `IDX_36D222EA9AB5DD2` (`fk_book_version_stats`),
  KEY `IDX_36D222E6324CCCB` (`fk_sales_reference`),
  KEY `IDX_36D222E6324AC4B` (`fk_language`),
  CONSTRAINT `FK_36D222E6324CCCB` FOREIGN KEY (`fk_book_metadata`) REFERENCES `book_metadata` (`id_book_metadata`),
  CONSTRAINT `FK_36D222EA9AB5DD2` FOREIGN KEY (`fk_book_version_stats`) REFERENCES `book_version_stats` (`id_book_version_stats`),
  CONSTRAINT `FK_36D222EE52964B9` FOREIGN KEY (`fk_sales_reference`) REFERENCES `sales_reference` (`id_sales_reference`),
  CONSTRAINT `FK_36D222E6324AC4B` FOREIGN KEY (`fk_language`) REFERENCES `language` (`id_language`)
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci


CREATE TABLE `book_chapter` (
  `id_book_chapter` int(11) NOT NULL AUTO_INCREMENT,
  `fk_book` int(11) DEFAULT NULL,
  `fk_book_chapter_status` int(11) DEFAULT NULL,
  `fk_author` int(11) DEFAULT NULL,
  `fk_book_chapter_metadata` int(11) DEFAULT NULL,
  `fk_book_chapter_version_stats` int(11) DEFAULT NULL,
  `fk_book_chapter_version` int(11) DEFAULT NULL,
  `text_location` varchar(512) COLLATE utf8_unicode_ci NOT NULL,
  PRIMARY KEY (`id_book_chapter`),
  KEY `IDX_5DD6A8656A9B8E1A` (`fk_book`),
  KEY `IDX_5DD6A86590FAC10D` (`fk_book_chapter_status`),
  KEY `IDX_5DD6A865AA4FD6BB` (`fk_author`),
  KEY `IDX_5DD6A8657E13E7E6` (`fk_book_chapter_metadata`),
  KEY `IDX_5DD6A8658E1578E3` (`fk_book_chapter_version_stats`),
  KEY `IDX_5DD6A865D8F5679E` (`fk_book_chapter_version`),
  CONSTRAINT `FK_5DD6A8655208F068` FOREIGN KEY (`fk_book`) REFERENCES `book` (`id_book`),
  CONSTRAINT `FK_5DD6A8656A9B8E1A` FOREIGN KEY (`fk_book_chapter_status`) REFERENCES `book_chapter_status` (`id_book_chapter_status`),
  CONSTRAINT `FK_5DD6A8657E13E7E6` FOREIGN KEY (`fk_author`) REFERENCES `author` (`id_author`),
  CONSTRAINT `FK_5DD6A86580A98FC7` FOREIGN KEY (`fk_book_chapter_metadata`) REFERENCES `book_chapter_metadata` (`id_book_chapter_metadata`),
  CONSTRAINT `FK_5DD6A8658E1578E3` FOREIGN KEY (`fk_book_chapter_version_stats`) REFERENCES `book_chapter_version_stats` (`id_book_chapter_version_stats`),
  CONSTRAINT `FK_5DD6A86590FAC10D` FOREIGN KEY (`fk_book_chapter_version`) REFERENCES `book_chapter_version` (`id_book_chapter_version`)
) ENGINE=InnoDB AUTO_INCREMENT=21 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci


CREATE TABLE `book_author` (
  `id_book_author` int(11) NOT NULL AUTO_INCREMENT,
  `fk_country` int(11) DEFAULT NULL,
  `fk_book` int(11) DEFAULT NULL,
  `fk_book_author_metadata` int(11) DEFAULT NULL,
  `fk_book_author_stats` int(11) DEFAULT NULL,
  `first_name` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `middle_name` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `last_name` varchar(255) COLLATE utf8_unicode_ci NOT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime NOT NULL,
  PRIMARY KEY (`id_book_author`),
  KEY `IDX_3E12B079AC8CAED6` (`fk_country`),
  KEY `IDX_6F21A111CC4ECAA9` (`fk_book`),
  KEY `IDX_1A93C236AB1CDEA5` (`fk_book_author_metadata`),
  KEY `IDX_6F21A111CC4E54E1` (`fk_book_author_stats`),
  CONSTRAINT `FK_3E12B079AC8CAED6` FOREIGN KEY (`fk_country`) REFERENCES `country` (`id_country`),
  CONSTRAINT `FK_6F21A111CC4ECAA9` FOREIGN KEY (`fk_book`) REFERENCES `book` (`id_book`),
  CONSTRAINT `FK_1A93C236AB1CDEA5` FOREIGN KEY (`fk_book_author_metadata`) REFERENCES `book_author_metadata` (`id_book_author_metadata`),
  CONSTRAINT `FK_6F21A111CC4E54E1` FOREIGN KEY (`fk_book_author_stats`) REFERENCES `book_author_stats` (`id_book_author_stats`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci


CREATE TABLE `country` (
  `id_country` int(11) NOT NULL AUTO_INCREMENT,
  `iso2_code` varchar(2) COLLATE utf8_unicode_ci NOT NULL,
  `iso3_code` varchar(3) COLLATE utf8_unicode_ci NOT NULL,
  `name` varchar(255) COLLATE utf8_unicode_ci NOT NULL,
  PRIMARY KEY (`id_country`)
) ENGINE=InnoDB AUTO_INCREMENT=161 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;

CREATE TABLE `language` (
  `id_language` int(11) NOT NULL AUTO_INCREMENT,
  `iso2_code` varchar(2) COLLATE utf8_unicode_ci NOT NULL,
  `name` varchar(20) COLLATE utf8_unicode_ci NOT NULL,
  PRIMARY KEY (`id_language`)
) ENGINE=InnoDB AUTO_INCREMENT=21 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;
  • Please provide the statements of the transaction, plus SHOW CREATE TABLE for any tables involved. Maybe we can speed up the SELECTs. (Yeah, yeah, it is stalled on COMMIT, but that could be a red herring.) – Rick James Aug 30 '16 at 0:30
  • @RickJames updated – Filippo De Santis Aug 30 '16 at 9:24
  • book_author -- is that a many:many mapping table? If so, it should not have name, etc. Is it a list of authors? If so, it should not have a book column. – Rick James Aug 30 '16 at 15:33
0

When to come to an active transaction's lifecycle, what do those settings affect ?

wait_timeout

This is the number of seconds the server waits for activity on a noninteractive connection before closing it. In English, it is the length of time a DB Connection will wait for activity (shown as Sleep in the processlist) before the session terminates. All bets are off once a transaction starts, since it is not sleeping.

lock_wait_timeout

According to paragraph 4 of the MySQL Documentation,

The timeout value applies separately for each metadata lock attempt. A given statement can require more than one lock, so it is possible for the statement to block for longer than the lock_wait_timeout value before reporting a timeout error. When lock timeout occurs, ER_LOCK_WAIT_TIMEOUT is reported.

In English, the more locks, the longer the wait. The value for lock_wait_timeout may apply to a series for locks for a single statement. Once this action starts, the timeout window never exists since the action is in progress.

SELECTs within a Transaction

You may find this surprising, but there are rare occasions when SELECTs can lock up tables. I wrote about this 5 years ago (Are InnoDB Deadlocks exclusive to INSERT/UPDATE/DELETE?)

In your case, even if your transaction block never sees a rollback and is always able to commit, the SELECTs your executed with the transaction block require time to generate locks for its own sanity in order to support MVCC and transaction isolation (REPEATABLE READ being the default).

  • Hi Rolando, thanks fo your answer. I may got it wrong but I don't think your explanations fit my problem :( wait_timeout: it's the server killing the connection on its side once the timeout is over and a "wait timeout exceeded" error can be triggered by putting a sleep (in the app) after the transaction started. lock_wait_timeout: I'm not getting errors, and waiting for a lock should pop out in my profiling, but each query runs in a few ms. SELECTs : they take few ms to run (on indexed values), I don't see any wait for lock either. It's only COMMIT taking a lot to complete. – Filippo De Santis Aug 30 '16 at 8:01
  • Almost 3 years ago, I answered this question with this statement I highlighted from the MySQL Docs: The timeout value applies separately for each metadata lock attempt. A given statement can require more than one lock, so it is possible for the statement to block for longer than the lock_wait_timeout value before reporting a timeout error. When lock timeout occurs, ER_LOCK_WAIT_TIMEOUT is reported. This has to still apply since timeout windows do not exist for a running transaction. – RolandoMySQLDBA Jun 3 at 12:20
0

This will speed up the transaction significantly:

INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 2, 1, 'https://gist.github.com/...');
INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location) VALUES (1, 3, 1, 'https://gist.github.com/...');
etc.

Turn into single, batched, input:

INSERT INTO book_chapter (fk_book, fk_book_chapter_status, fk_author, text_location)
    VALUES
        (1, 2, 1, 'https://gist.github.com/...'),
        (1, 3, 1, 'https://gist.github.com/...'),
        ...;

For the SELECTs, country and language need

INDEX(iso2_code)

This particular fix may significantly improve the concurrency.

Why have the SELECTs inside the transaction; I see no use for the results? If there is an UPDATE to them, then see FOR UPDATE.

What is the meaning of SELECT * FROM language t0 WHERE t0.iso2_code = '...' LIMIT 1 for Belgium or Canada (etc), each with two languages.

  • Hi Rick, thanks for your answer. You are basically saying my problem is the queries being slow? Can you elaborate on why this could cause a slow COMMIT statement? Thanks – Filippo De Santis Aug 31 '16 at 7:15
  • It's hard to say -- The COMMIT is where things get finished up, so it could be any of several things. I think of it as a 'red herring', and go back to the statements to see what could be done. Hence, my answer focused on how to speed them up, thereby decreasing the chance of locks/blocks/etc. Indirectly, that may decrease the COMMIT slowness – Rick James Aug 31 '16 at 14:47
  • Hi Rick, for what I understand of the locking mechanism a query get the lock and then it runs. I'm profiling (live) those queries, they take a few milliseconds to run, the only thing that (randomly?) takes a lot of time is the COMMIT statement. At the moment I'm wondering if writing the binlong, releasing the locks and the other operations done at commit time could take that much time... :/ – Filippo De Santis Sep 1 '16 at 13:12
  • Alas, the profiling available tends to lump most of the time in steps like this, but without giving any details. – Rick James Sep 1 '16 at 18:13
  • Sorry, I should have been more specific :) I "profile from the app" issuing the queries, in the sense that I'm logging from the app and not from a mysql profiler. – Filippo De Santis Sep 2 '16 at 7:23

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.