TravisCI: slow query on MySQL during applying migrations

[php-coder]

2017-09-04 17:52:29.974  INFO 16812 --- [ootstrap.main()] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@7a61206e: startup date [Mon Sep 04 17:52:24 UTC 2017]; root of context hierarchy
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:32.806  WARN 16812 --- [ootstrap.main()] liquibase                                : modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case
2017-09-04 17:52:33.713  INFO 16812 --- [ootstrap.main()] MySQL                                    : SLOW QUERY created: Mon Sep 04 17:52:33 UTC 2017 duration: 551 connection: 40 statement: 108 resultset: 0 message: Slow query (exceeded 500 ms, duration: 551 ms):INSERT INTO mystamps.DATABASECHANGELOG (ID, AUTHOR, FILENAME, DATEEXECUTED, ORDEREXECUTED, MD5SUM, DESCRIPTION, COMMENTS, EXECTYPE, CONTEXTS, LABELS, LIQUIBASE, DEPLOYMENT_ID) VALUES ('create-user-coder', 'php-coder', 'classpath:/liquibase/initial-state.xml', NOW(), 19, '7:da1bd6f4617687ae13c85de8d4df570a', 'sqlFile', '', 'EXECUTED', 'test-data', NULL, '3.5.3', '4547552647')
2017-09-04 17:52:33.731  WARN 16812 --- [ootstrap.main()] MySQL                                    : Slow query explain results for 'INSERT INTO mystamps.DATABASECHANGELOG (ID, AUTHOR, FILENAME, DATEEXECUTED, ORDEREXECUTED, MD5SUM, DESCRIPTION, COMMENTS, EXECTYPE, CONTEXTS, LABELS, LIQUIBASE, DEPLOYMENT_ID) VALUES ('create-user-coder', 'php-coder', 'classpath:/liquibase/initial-state.xml', NOW(), 19, '7:da1bd6f4617687ae13c85de8d4df570a', 'sqlFile', '', 'EXECUTED', 'test-data', NULL, '3.5.3', '4547552647')' :
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: NULL
         type: NULL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: NULL
        Extra: No tables used
2017-09-04 17:52:36.713  INFO 16812 --- [ootstrap.main()] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2017-09-04 17:52:36.741  INFO 16812 --- [ootstrap.main()] application                              : Initializing Spring FrameworkServlet 'dispatcherServlet'
2017-09-04 17:52:36.741  INFO 16812 --- [ootstrap.main()] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization started
2017-09-04 17:52:36.756  INFO 16812 --- [ootstrap.main()] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization completed in 15 ms

Example build log: https://travis-ci.org/php-coder/mystamps/jobs/271780074

[php-coder]

At this time I'm thinking about setting innodb_flush_log_at_trx_commit=2.

See: https://stackoverflow.com/a/4139425/352708 and https://dba.stackexchange.com/questions/29963/dynamic-change-to-innodb-flush-log-at-trx-commit

The current value is 1:

$ mysql -u root -e "SHOW VARIABLES LIKE 'innodb_flush_log_at_trx_commit';";
Variable_name	Value
innodb_flush_log_at_trx_commit	1

See https://travis-ci.org/php-coder/mystamps/builds/271858346

[php-coder]

$ mysql -u root -e "SHOW ENGINE INNODB STATUS\G;";
*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2017-09-04 22:33:26 7f7001fd0700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 5 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 46 srv_active, 0 srv_shutdown, 324 srv_idle
srv_master_thread log flush and writes: 370
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 457
OS WAIT ARRAY INFO: signal count 528
Mutex spin waits 162, rounds 3770, OS waits 118
RW-shared spins 302, rounds 9841, OS waits 327
RW-excl spins 1, rounds 851, OS waits 11
Spin rounds per wait: 23.27 mutex, 32.59 RW-shared, 851.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 5557
Purge done for trx's n:o < 5557 undo n:o < 0 state: running but idle
History list length 540
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 42, OS thread handle 0x7f7001fd0700, query id 8949 localhost root init
SHOW ENGINE INNODB STATUS
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
365 OS file reads, 2831 OS file writes, 1686 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 4002170
Log flushed up to   4002170
Pages flushed up to 4002170
Last checkpoint at  4002170
0 pending log writes, 0 pending chkp writes
990 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 252926
Buffer pool size   8192
Free buffers       7207
Database pages     983
Old database pages 342
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 224, created 759, written 1136
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 983, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 1772, id 140118937560832, state: sleeping
Number of rows inserted 293, updated 29, deleted 2, read 3619
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

From https://travis-ci.org/php-coder/mystamps/builds/271856367

[php-coder]

It didn't help: https://travis-ci.org/php-coder/mystamps/builds/271861984

[php-coder]

In the upcoming updates innodb_flush_log_at_trx_commit will be set to 1 (see travis-ci/travis-cookbooks@4642454). So, there is a chance that this bug will gone.

[php-coder]

As I thought, the slow query disappears. Last 5 builds don't have it, but complain about another slow query:

2017-09-08 10:10:31.312 INFO 3917 --- [ootstrap.main()] MySQL : SLOW QUERY created: Fri Sep 08 10:10:31 UTC 2017 duration: 630 connection: 40 statement: 152 resultset: 0 message: Slow query (exceeded 500 ms, duration: 630 ms):ALTER TABLE mystamps.series ADD CONSTRAINT fk_series_category_id FOREIGN KEY (category_id) REFERENCES mystamps.categories (id)

Log is here: https://travis-ci.org/php-coder/mystamps/jobs/273239342

[php-coder]

I haven't seen it for a long time, so I'm closing it.

[php-coder]

Closing.