MySQL Forums
Forum List  »  NDB clusters

Re: Waiting for commit lock
Posted by: Mouhsen Ibrahim
Date: July 14, 2017 12:03PM

Hi,

I tried to isolate the server from my web cluster and do not forward queries to it there was only a periodic backup which runs on the server once each an hour and it looks like this was the problem here is the backup command:

"mysqldump -uroot -p --single-transaction --master-data=2 --flush-logs db_name > db_name.sql"

once I removed --flush-logs it worked just fine without any problems, here is the output of SHOW PROCESSLIST when the backup is trying to run with the option --flush-logs enabled:

mysql> show full processlist;
+-------+-------------+-----------+------------+---------+------+-------------------------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-------+-------------+-----------+------------+---------+------+-------------------------+-----------------------+
| 1 | system user | | | Daemon | 7 | Waiting for commit lock | NULL |
| 17108 | root | localhost | db_name | Query | 0 | starting | show full processlist |
| 17131 | root | localhost | NULL | Refresh | 8 | starting | NULL |
| 17132 | exporter | localhost | NULL | Query | 5 | starting | SHOW BINARY LOGS |
| 17133 | exporter | localhost | NULL | Query | 0 | starting | SHOW BINARY LOGS |
+-------+-------------+-----------+------------+---------+------+-------------------------+-----------------------+
5 rows in set (0.00 sec)

exporter is the database user used by prometheus mysqld exporter.

I killed the mysqldump process nothing changed in the output of SHOW PROCESSLIST and this line appeared in the error log

2017-07-14T17:41:14.543952Z 17124 [Note] Aborted connection 17124 to db: 'db_name' user: 'root' host: 'localhost' (Got an error writing communication packets)

When I tried to kill the server using "service mysql.server stop" these lines appeared in the error log:

2017-07-14T17:43:16.743368Z 0 [Note] Giving 24 client threads a chance to die gracefully
2017-07-14T17:43:16.743447Z 0 [Note] Shutting down slave threads
2017-07-14T17:43:17.696696Z 0 [Note] NDB Util: Stopped
2017-07-14T17:43:18.744491Z 0 [Note] Forcefully disconnecting 23 remaining clients
2017-07-14T17:43:18.744525Z 0 [Warning] /usr/local/mysql/bin/mysqld: Forcing close of thread 17151 user: 'exporter' (THIS LINE REPEATED MANY TIMES WITH DIFFERENT THREAD ID)

2017-07-14T17:43:18.745070Z 0 [Note] Event Scheduler: Purging the queue. 0 events

But the server did not shutdown, I waited few minutes and nothing happened so I killed the server with "pkill -9 mysqld"

After that I started the mysql server with "service mysql.server start" and these lines appeared in the error log

2017-07-14T17:44:55.153195Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-07-14T17:44:55.153368Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2017-07-14T17:44:55.153392Z 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.7.17-ndb-7.5.5-cluster-gpl-log) starting as process 16336 ...
2017-07-14T17:44:55.180516Z 0 [Note] InnoDB: PUNCH HOLE support not available
2017-07-14T17:44:55.180559Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-07-14T17:44:55.180704Z 0 [Note] InnoDB: Uses event mutexes
2017-07-14T17:44:55.180727Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2017-07-14T17:44:55.180736Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-07-14T17:44:55.180749Z 0 [Note] InnoDB: Using Linux native AIO
2017-07-14T17:44:55.181163Z 0 [Note] InnoDB: Number of pools: 1
2017-07-14T17:44:55.181422Z 0 [Note] InnoDB: Using CPU crc32 instructions
2017-07-14T17:44:55.183888Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2017-07-14T17:44:55.197089Z 0 [Note] InnoDB: Completed initialization of buffer pool
2017-07-14T17:44:55.200086Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-07-14T17:44:55.217044Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-07-14T17:44:55.219201Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 167737614
2017-07-14T17:44:55.219245Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 167737623
2017-07-14T17:44:55.219550Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 167737623
2017-07-14T17:44:55.219568Z 0 [Note] InnoDB: Database was not shutdown normally!
2017-07-14T17:44:55.219577Z 0 [Note] InnoDB: Starting crash recovery.
2017-07-14T17:44:55.235955Z 0 [Note] InnoDB: Last MySQL binlog file position 0 91061298, file name mysql-bin.000278
2017-07-14T17:44:55.347578Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-07-14T17:44:55.347607Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-07-14T17:44:55.347659Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-07-14T17:44:55.385945Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-07-14T17:44:55.387185Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2017-07-14T17:44:55.387206Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2017-07-14T17:44:55.388206Z 0 [Note] InnoDB: Waiting for purge to start
2017-07-14T17:44:55.438377Z 0 [Note] InnoDB: 5.7.17 started; log sequence number 167737623
2017-07-14T17:44:55.439257Z 0 [Note] InnoDB: Loading buffer pool(s) from /usr/local/mysql-cluster-gpl-7.5.5-linux-glibc2.5-x86_64/data/ib_buffer_pool
2017-07-14T17:44:55.439563Z 0 [Note] Plugin 'FEDERATED' is disabled.
2017-07-14T17:44:55.446097Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170714 20:44:55
2017-07-14T17:44:55.446266Z 0 [Note] NDB: Changed global value of binlog_format from STATEMENT to MIXED
2017-07-14T17:44:55.655164Z 0 [Note] NDB: NodeID is 14, management server '192.168.2.29:1186'
2017-07-14T17:44:56.055794Z 0 [Note] NDB[0]: NodeID: 14, all storage nodes connected
2017-07-14T17:44:56.055941Z 0 [Note] NDB Binlog: Starting...
2017-07-14T17:44:56.056049Z 0 [Note] NDB Util: Starting...
2017-07-14T17:44:56.056066Z 1 [Note] NDB Binlog: Started
2017-07-14T17:44:56.056123Z 1 [Note] NDB Binlog: Setting up
2017-07-14T17:44:56.056170Z 0 [Note] NDB Index Stat: Starting...
2017-07-14T17:44:56.056196Z 0 [Note] NDB Index Stat: Wait for server start completed
2017-07-14T17:44:56.056214Z 2 [Note] NDB Util: Wait for server start completed
2017-07-14T17:44:56.056295Z 1 [Note] NDB Binlog: Created schema Ndb object, reference: 0x8004000e, name: 'Ndb Binlog schema change monitoring'
2017-07-14T17:44:56.056378Z 1 [Note] NDB Binlog: Created injector Ndb object, reference: 0x8005000e, name: 'Ndb Binlog data change monitoring'
2017-07-14T17:44:56.056394Z 1 [Note] NDB Binlog: Setup completed
2017-07-14T17:44:56.056400Z 1 [Note] NDB Binlog: Wait for server start completed
2017-07-14T17:44:56.162344Z 0 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
2017-07-14T17:44:56.162365Z 0 [Note] Starting crash recovery...
2017-07-14T17:44:56.162390Z 0 [Note] Crash recovery finished.
2017-07-14T17:44:56.166564Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2017-07-14T17:44:56.166834Z 0 [Note] Server hostname (bind-address): '192.168.2.22'; port: 3306
2017-07-14T17:44:56.166861Z 0 [Note] - '192.168.2.22' resolves to '192.168.2.22';
2017-07-14T17:44:56.166891Z 0 [Note] Server socket created on IP: '192.168.2.22'.
2017-07-14T17:44:56.196505Z 0 [Note] Event Scheduler: Loaded 0 events
2017-07-14T17:44:56.196839Z 0 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.7.17-ndb-7.5.5-cluster-gpl-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Cluster Community Server (GPL)
2017-07-14T17:44:56.196920Z 0 [Note] NDB Index Stat: Wait for cluster to start
2017-07-14T17:44:56.196940Z 2 [Note] NDB Util: Wait for cluster to start
2017-07-14T17:44:56.196958Z 1 [Note] NDB Binlog: Check for incidents
2017-07-14T17:44:56.197006Z 0 [Note] NDB Index Stat: Started
2017-07-14T17:44:56.197018Z 1 [ERROR] mysqld startup An incident event has been written to the binary log which will stop the slaves.
2017-07-14T17:44:56.197046Z 2 [Note] NDB Binlog: Ndb tables initially read only.
2017-07-14T17:44:56.197060Z 2 [Note] NDB Util: Started
2017-07-14T17:44:56.197144Z 0 [Note] NDB Index Stat: created Ndb object 'Ndb Index Stat', ref: 0x8007000e
2017-07-14T17:44:56.201297Z 1 [Note] NDB Binlog: Wait for cluster to start
2017-07-14T17:44:56.267611Z 1 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_schema
2017-07-14T17:44:56.270778Z 1 [Note] NDB Binlog: logging ./mysql/ndb_schema (UPDATED,USE_WRITE)
2017-07-14T17:44:56.273388Z 1 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_apply_status
2017-07-14T17:44:56.274939Z 1 [Note] NDB Binlog: logging ./mysql/ndb_apply_status (UPDATED,USE_WRITE)
2017-07-14T17:44:56.275072Z 1 [Note] NDB: Cleaning stray tables from database 'fastestcow'
2017-07-14T17:44:56.280746Z 1 [Note] NDB: Cleaning stray tables from database 'ndbinfo'
2017-07-14T17:44:56.282739Z 1 [Note] NDB: Cleaning stray tables from database 'performance_schema'
2017-07-14T17:44:56.284467Z 1 [Note] NDB: Cleaning stray tables from database 'sys'
2017-07-14T17:44:56.286433Z 1 [Note] NDB: Cleaning stray tables from database 'tes'
2017-07-14T17:44:56.287523Z 1 [Note] NDB: Cleaning stray tables from database 'test'
2017-07-14T17:44:56.303860Z 1 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$db_name/table_name
2017-07-14T17:44:56.304998Z 1 [Note] NDB Binlog: logging ./db_name/table_name (UPDATED,USE_WRITE) (THESETWO LINES REPEATED FOR ALL TABLES IN DB_NAME DATABASE)
2017-07-14T17:44:56.974611Z 1 [Note] NDB Binlog: Wait for first event
2017-07-14 20:44:56 [NdbApi] INFO -- Flushing incomplete GCI:s < 4726114/8
2017-07-14 20:44:56 [NdbApi] INFO -- Flushing incomplete GCI:s < 4726114/8
2017-07-14T17:44:56.974672Z 1 [Note] NDB Binlog: starting log at epoch 4726114/8
2017-07-14T17:44:56.974679Z 1 [Note] NDB Binlog: Got first event
2017-07-14T17:44:56.974684Z 1 [Note] NDB Binlog: ndb tables writable
2017-07-14T17:44:56.975387Z 1 [Note] NDB Binlog: Startup and setup completed
2017-07-14T17:44:56.976301Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2017-07-14T17:44:56.976330Z 0 [Note] Beginning of list of non-natively partitioned tables
2017-07-14T17:44:56.995210Z 1 [Note] NDB Schema dist: Data node: 12 reports subscribe from node 15, subscriber bitmask 00000c000
2017-07-14T17:44:56.995239Z 1 [Note] NDB Schema dist: Data node: 13 reports subscribe from node 15, subscriber bitmask 00000c000
2017-07-14T17:44:57.045235Z 0 [Note] End of list of non-natively partitioned tables

After this the server is back online, maybe this line is important in the error log
2017-07-14T17:44:56.197018Z 1 [ERROR] mysqld startup An incident event has been written to the binary log which will stop the slaves.

Thanks for your help.

Options: ReplyQuote


Subject
Views
Written By
Posted
150
July 12, 2017 03:27AM
Re: Waiting for commit lock
66
July 14, 2017 12:03PM
50
July 16, 2017 03:19AM


Sorry, only registered users may post in this forum.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.