# Insert takes 13 seconds

**URL:** <https://forums.percona.com/t/insert-takes-13-seconds/2981>\
**Category:** Percona XtraDB Cluster 5.x\
**Created:** [October 2, 2013, 2:50am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981 "2013-10-02T02:50:08Z")\
**Posts on this page:** 8\
**Page:** 1

<div class="post-metadata">

**Author:** ![francoisstark](https://avatars.discourse-cdn.com/v4/letter/f/a698b9/32.png) [@francoisstark](https://forums.percona.com/u/francoisstark)\
**Post date:** [October 2, 2013, 2:50am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/1 "2013-10-02T02:50:08Z")

</div>

From the slow log analysis:

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 2 1

# Exec time 18 13s 13s 13s 13s 13s 0 13s

# Lock time 1 57us 57us 57us 57us 57us 0 57us

# Rows sent 0 0 0 0 0 0 0 0

# Rows examine 0 0 0 0 0 0 0 0

# Rows affecte 4 1 1 1 1 1 0 1

# Rows read 0 0 0 0 0 0 0 0

# Bytes sent 0 13 13 13 13 13 0 13

# Query size 0 321 321 321 321 321 0 321

#---------------------------------------------------------------------------------------------

# SHOW TABLE STATUS FROM ` ***** ` LIKE ‘chat\_messages’\G

# SHOW CREATE TABLE ` ***** `.`chat_messages`\G

INSERT INTO ` ***** `.`chat_messages` (`username`, `profiles_profile_id`, `show_character_id`, `chat_room_id`, `body`, `system`, `prefix`, `to_character_id`, `to_character_name`, `created`) VALUES (‘sdsdfg’, NULL, 49, 3, 'sdfgsdfgxcfgsdfg ', ‘1’, ‘thinks’, NULL, NULL, ‘2013-10-02 08:29:02’)\G

These are all the indexes on the table: [TABLE=“class: wrapper”]  
[TR]  
[TD] [TABLE=“class: ui\_table sortable ui\_columns, width: 1253”]  
[TR=“class: mainbody row1, bgcolor: #F8F8FA”]  
[TD]chat\_messages[/TD]  
[TD]0[/TD]  
[TD]PRIMARY[/TD]  
[TD]1[/TD]  
[TD]id[/TD]  
[TD]A[/TD]  
[TD]28718[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainbody row0, bgcolor: #E8E8EA”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]IND\_ChatMessages\_Created[/TD]  
[TD]1[/TD]  
[TD]created[/TD]  
[TD]A[/TD]  
[TD]28718[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainhigh, bgcolor: #FFFFBB”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]IND\_ChatMessages\_Username[/TD]  
[TD]1[/TD]  
[TD]username[/TD]  
[TD]A[/TD]  
[TD]9572[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]YES[/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainbody row0, bgcolor: #E8E8EA”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]FK\_ChatMessages\_ChatRoomId[/TD]  
[TD]1[/TD]  
[TD]chat\_room\_id[/TD]  
[TD]A[/TD]  
[TD]1[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainbody row1, bgcolor: #F8F8FA”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]IND\_ChatMessages\_Broadcast[/TD]  
[TD]1[/TD]  
[TD]broadcast[/TD]  
[TD]A[/TD]  
[TD]1[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainbody row0, bgcolor: #E8E8EA”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]FK\_ChatMessages\_ProfliesProfileId[/TD]  
[TD]1[/TD]  
[TD]profiles\_profile\_id[/TD]  
[TD]A[/TD]  
[TD]9572[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]YES[/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[TR=“class: mainbody row1, bgcolor: #F8F8FA”]  
[TD]chat\_messages[/TD]  
[TD]1[/TD]  
[TD]FK\_ChatMessages\_ShowCharacterId[/TD]  
[TD]1[/TD]  
[TD]show\_character\_id[/TD]  
[TD]A[/TD]  
[TD]106[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[TD]YES[/TD]  
[TD]BTREE[/TD]  
[TD] [/TD]  
[TD] [/TD]  
[/TR]  
[/TABLE]  
[/TD]  
[/TR]  
[/TABLE]

The system was part of a three way cluster which froze up last Saturday. I had to restart Percona in bootstrap mode to get it up and am still running on one system only, in bootstrap mode. I want to get these slow queries sorted out before getting the cluster back up, because I think it was the main cause for the cluster failure.  
The table has 28718 rows. Any ideas why inserting a new row takes so long?

---

<div class="post-metadata">

**Author:** ![przemek](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/przemek/32/3_2.png) [@przemek](https://forums.percona.com/u/przemek)\
**Post date:** [October 2, 2013, 9:32am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/2 "2013-10-02T09:32:57Z")

</div>

I’ve moved this thread to PXC Cluster category since apparently we are dealing with XtraDB Cluster here, correct?  
This is InnoDB table, right?  
By “froze up” you mean no query could execute on any node during this time?

For that incident the slow log isn’t very much helpful. If you had log\_slow\_verbosity=profiling then maybe we could see more. In this case original slow log entry would be needed.

But this incident should have some corresponding info in the MySQL error logs. Can you check on all 3 nodes if you can see anything meaningful? Also the processlist snapshot from that moment would be helpful. You can capture it automatically if this kind of issue appears with help of [pt-stalk](http://www.percona.com/doc/percona-toolkit/2.2/pt-stalk.html) tool btw.

---

<div class="post-metadata">

**Author:** ![francoisstark](https://avatars.discourse-cdn.com/v4/letter/f/a698b9/32.png) [@francoisstark](https://forums.percona.com/u/francoisstark)\
**Post date:** [October 3, 2013, 12:21am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/3 "2013-10-03T00:21:05Z")

</div>

All these tables are innoBD tables.

The server crashed completely last night. Froze and then it got stuck on GRUB bootloader on reboot and thus the whole site was off for 6 hours. Fixed at 2.30am by on-site engineer. It is an enterprize-class vm with 32GB RAM and 12 cores. Load average: 0.27 and ram usage 1.8GB out of 32GB…

Here is the original slow log of that incident; there were many similar ones:

SET timestamp=1380695355;  
INSERT INTO `####2`.`chat_messages` (`username`, `profiles_profile_id`, `show_character_id`, `chat_room_id`, `body`, `system`, `prefix`, `to_character_id`, `to_character_name`, `created`) VALUES (‘asdfasdfasdf’, NULL, 49, 3, ‘asdfasdfasdfasdf’, ‘1’, ‘thinks’, NULL, NULL, ‘2013-10-02 08:29:02’);

# Time: 131002 8:29:16

# User@Host: [###] @ [10.0.0.3]

# Thread\_id: 1141351 Schema: ### Last\_errno: 0 Killed: 0

# Query\_time: 10.851373 Lock\_time: 0.000059 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1 Rows\_read: 1

# Bytes\_sent: 52

Another example: here is a simple update that took 5 seconds directly after the previous etry:  
SET timestamp=1380695356;  
UPDATE `####2`.`profiles_profiles` SET `latest_activity_type` = ‘chat\_room\_joined’, `modified` = ‘2013-10-02 08:29:05’ WHERE `###2`.`profiles_profiles`.`id` = ‘64’;

# User@Host: [###r] @ [10.0.0.7]

# Thread\_id: 1141366 Schema: ### Last\_errno: 0 Killed: 0

# Query\_time: 5.636290 Lock\_time: 0.000044 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1 Rows\_read: 1

# Bytes\_sent: 52

I did a new slow log capture after the reboot, and some inserts still took 1.4 seconds:

SET timestamp=1380781348;  
INSERT INTO `###2`.`profiles_profiles` (`gender`, `modified`, `created`) VALUES (NULL, ‘2013-10-03 08:22:26’, ‘2013-10-03 08:22:26’);

# User@Host: [###] @ [10.0.0.10]

# Thread\_id: 50302 Schema: ### Last\_errno: 1364 Killed: 0

# Query\_time: 1.423764 Lock\_time: 0.000117 Rows\_sent: 0 Rows\_examined: 0 Rows\_affected: 1 Rows\_read: 0

# Bytes\_sent: 14

SET timestamp=1380781348;  
INSERT INTO `###2`.`profiles_profiles` (`gender`, `modified`, `created`) VALUES (NULL, ‘2013-10-03 08:22:26’, ‘2013-10-03 08:22:26’);

# User@Host: [###r] @ [10.0.0.3]

# Thread\_id: 50295 Schema: ###2 Last\_errno: 1048 Killed: 0

# Query\_time: 0.245315 Lock\_time: 0.000055 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1 Rows\_read: 1

# Bytes\_sent: 52

I was running a cluster, but the other two systems are not part of it anymore - does running in bootstrap mode impact performance?

Current global status:  
±-----------------------------------------±-------------------------------------+  
| Variable\_name | Value |  
±-----------------------------------------±-------------------------------------+  
| Aborted\_clients | 2 |  
| Aborted\_connects | 5 |  
| Binlog\_cache\_disk\_use | 0 |  
| Binlog\_cache\_use | 598 |  
| Binlog\_stmt\_cache\_disk\_use | 0 |  
| Binlog\_stmt\_cache\_use | 0 |  
| Bytes\_received | 72063396 |  
| Bytes\_sent | 490881621 |  
| Com\_admin\_commands | 0 |  
| Com\_assign\_to\_keycache | 0 |  
| Com\_alter\_db | 0 |  
| Com\_alter\_db\_upgrade | 0 |  
| Com\_alter\_event | 0 |  
| Com\_alter\_function | 0 |  
| Com\_alter\_procedure | 0 |  
| Com\_alter\_server | 0 |  
| Com\_alter\_table | 0 |  
| Com\_alter\_tablespace | 0 |  
| Com\_analyze | 0 |  
| Com\_begin | 60 |  
| Com\_binlog | 0 |  
| Com\_call\_procedure | 0 |  
| Com\_change\_db | 15 |  
| Com\_change\_master | 0 |  
| Com\_check | 0 |  
| Com\_checksum | 0 |  
| Com\_commit | 54 |  
| Com\_create\_db | 0 |  
| Com\_create\_event | 0 |  
| Com\_create\_function | 0 |  
| Com\_create\_index | 12 |  
| Com\_create\_procedure | 0 |  
| Com\_create\_server | 0 |  
| Com\_create\_table | 6 |  
| Com\_create\_trigger | 0 |  
| Com\_create\_udf | 0 |  
| Com\_create\_user | 0 |  
| Com\_create\_view | 0 |  
| Com\_dealloc\_sql | 24 |  
| Com\_delete | 102 |  
| Com\_delete\_multi | 8 |  
| Com\_do | 0 |  
| Com\_drop\_db | 0 |  
| Com\_drop\_event | 0 |  
| Com\_drop\_function | 0 |  
| Com\_drop\_index | 0 |  
| Com\_drop\_procedure | 0 |  
| Com\_drop\_server | 0 |  
| Com\_drop\_table | 0 |  
| Com\_drop\_trigger | 0 |  
| Com\_drop\_user | 0 |  
| Com\_drop\_view | 0 |  
| Com\_empty\_query | 0 |  
| Com\_execute\_sql | 24 |  
| Com\_flush | 0 |  
| Com\_grant | 0 |  
| Com\_ha\_close | 0 |  
| Com\_ha\_open | 0 |  
| Com\_ha\_read | 0 |  
| Com\_help | 0 |  
| Com\_insert | 401 |  
| Com\_insert\_select | 19 |  
| Com\_install\_plugin | 0 |  
| Com\_kill | 0 |  
| Com\_load | 6 |  
| Com\_lock\_tables | 0 |  
| Com\_optimize | 0 |  
| Com\_preload\_keys | 0 |  
| Com\_prepare\_sql | 24 |  
| Com\_purge | 0 |  
| Com\_purge\_before\_date | 0 |  
| Com\_release\_savepoint | 0 |  
| Com\_rename\_table | 0 |  
| Com\_rename\_user | 0 |  
| Com\_repair | 0 |  
| Com\_replace | 0 |  
| Com\_replace\_select | 0 |  
| Com\_reset | 0 |  
| Com\_resignal | 0 |  
| Com\_revoke | 0 |  
| Com\_revoke\_all | 0 |  
| Com\_rollback | 6 |  
| Com\_rollback\_to\_savepoint | 0 |  
| Com\_savepoint | 0 |  
| Com\_select | 83630 |  
| Com\_set\_option | 14246 |  
| Com\_signal | 0 |  
| Com\_show\_authors | 0 |  
| Com\_show\_binlog\_events | 0 |  
| Com\_show\_binlogs | 0 |  
| Com\_show\_charsets | 0 |  
| Com\_show\_client\_statistics | 0 |  
| Com\_show\_collations | 0 |  
| Com\_show\_contributors | 0 |  
| Com\_show\_create\_db | 0 |  
| Com\_show\_create\_event | 0 |  
| Com\_show\_create\_func | 0 |  
| Com\_show\_create\_proc | 0 |  
| Com\_show\_create\_table | 0 |  
| Com\_show\_create\_trigger | 0 |  
| Com\_show\_databases | 1 |  
| Com\_show\_engine\_logs | 0 |  
| Com\_show\_engine\_mutex | 0 |  
| Com\_show\_engine\_status | 0 |  
| Com\_show\_events | 0 |  
| Com\_show\_errors | 0 |  
| Com\_show\_fields | 3196 |  
| Com\_show\_function\_status | 0 |  
| Com\_show\_grants | 0 |  
| Com\_show\_index\_statistics | 0 |  
| Com\_show\_keys | 114 |  
| Com\_show\_master\_status | 0 |  
| Com\_show\_open\_tables | 0 |  
| Com\_show\_plugins | 0 |  
| Com\_show\_privileges | 0 |  
| Com\_show\_procedure\_status | 0 |  
| Com\_show\_processlist | 0 |  
| Com\_show\_profile | 0 |  
| Com\_show\_profiles | 0 |  
| Com\_show\_relaylog\_events | 0 |  
| Com\_show\_slave\_hosts | 0 |  
| Com\_show\_slave\_status | 0 |  
| Com\_show\_slave\_status\_nolock | 0 |  
| Com\_show\_status | 40097 |  
| Com\_show\_storage\_engines | 0 |  
| Com\_show\_table\_statistics | 0 |  
| Com\_show\_table\_status | 1 |  
| Com\_show\_tables | 888 |  
| Com\_show\_temporary\_tables | 0 |  
| Com\_show\_thread\_statistics | 0 |  
| Com\_show\_triggers | 0 |  
| Com\_show\_user\_statistics | 0 |  
| Com\_show\_variables | 6 |  
| Com\_show\_warnings | 0 |  
| Com\_slave\_start | 0 |  
| Com\_slave\_stop | 0 |  
| Com\_stmt\_close | 24 |  
| Com\_stmt\_execute | 24 |  
| Com\_stmt\_fetch | 0 |  
| Com\_stmt\_prepare | 24 |  
| Com\_stmt\_reprepare | 0 |  
| Com\_stmt\_reset | 0 |  
| Com\_stmt\_send\_long\_data | 0 |  
| Com\_truncate | 6 |  
| Com\_uninstall\_plugin | 0 |  
| Com\_unlock\_tables | 0 |  
| Com\_update | 227 |  
| Com\_update\_multi | 45 |  
| Com\_xa\_commit | 0 |  
| Com\_xa\_end | 0 |  
| Com\_xa\_prepare | 0 |  
| Com\_xa\_recover | 0 |  
| Com\_xa\_rollback | 0 |  
| Com\_xa\_start | 0 |  
| Compression | OFF |  
| Connections | 54296 |  
| Created\_tmp\_disk\_tables | 3418 |  
| Created\_tmp\_files | 31 |  
| Created\_tmp\_tables | 46206 |  
| Delayed\_errors | 0 |  
| Delayed\_insert\_threads | 0 |  
| Delayed\_writes | 0 |  
| Flashcache\_enabled | OFF |  
| Flush\_commands | 1 |  
| Handler\_commit | 86387 |  
| Handler\_delete | 32 |  
| Handler\_discover | 0 |  
| Handler\_prepare | 2057 |  
| Handler\_read\_first | 5743 |  
| Handler\_read\_key | 1248365 |  
| Handler\_read\_last | 246 |  
| Handler\_read\_next | 3579643 |  
| Handler\_read\_prev | 12283 |  
| Handler\_read\_rnd | 69947 |  
| Handler\_read\_rnd\_next | 59906106 |  
| Handler\_rollback | 26 |  
| Handler\_savepoint | 0 |  
| Handler\_savepoint\_rollback | 0 |  
| Handler\_update | 449840 |  
| Handler\_write | 624521 |  
| Innodb\_adaptive\_hash\_cells | 276671 |  
| Innodb\_adaptive\_hash\_heap\_buffers | 204 |  
| Innodb\_adaptive\_hash\_hash\_searches | 1457179 |  
| Innodb\_adaptive\_hash\_non\_hash\_searches | 257712 |  
| Innodb\_background\_log\_sync | 17765 |  
| Innodb\_buffer\_pool\_pages\_data | 7276 |  
| Innodb\_buffer\_pool\_bytes\_data | 238419968 |  
| Innodb\_buffer\_pool\_pages\_dirty | 0 |  
| Innodb\_buffer\_pool\_bytes\_dirty | 0 |  
| Innodb\_buffer\_pool\_pages\_flushed | 3403 |  
| Innodb\_buffer\_pool\_pages\_LRU\_flushed | 0 |  
| Innodb\_buffer\_pool\_pages\_free | 710 |  
| Innodb\_buffer\_pool\_pages\_made\_not\_young | 0 |  
| Innodb\_buffer\_pool\_pages\_made\_young | 6 |  
| Innodb\_buffer\_pool\_pages\_misc | 205 |  
| Innodb\_buffer\_pool\_pages\_old | 2705 |  
| Innodb\_buffer\_pool\_pages\_total | 8191 |  
| Innodb\_buffer\_pool\_read\_ahead\_rnd | 0 |  
| Innodb\_buffer\_pool\_read\_ahead | 3599 |  
| Innodb\_buffer\_pool\_read\_ahead\_evicted | 0 |  
| Innodb\_buffer\_pool\_read\_requests | 15151289 |  
| Innodb\_buffer\_pool\_reads | 3597 |  
| Innodb\_buffer\_pool\_wait\_free | 0 |  
| Innodb\_buffer\_pool\_write\_requests | 11135 |  
| Innodb\_checkpoint\_age | 0 |  
| Innodb\_checkpoint\_max\_age | 7782360 |  
| Innodb\_checkpoint\_target\_age | 7539162 |  
| Innodb\_data\_fsyncs | 2703 |  
| Innodb\_data\_pending\_fsyncs | 0 |  
| Innodb\_data\_pending\_reads | 0 |  
| Innodb\_data\_pending\_writes | 0 |  
| Innodb\_data\_read | 122834944 |  
| Innodb\_data\_reads | 7403 |  
| Innodb\_data\_writes | 5741 |  
| Innodb\_data\_written | 113518080 |  
| Innodb\_dblwr\_pages\_written | 3403 |  
| Innodb\_dblwr\_writes | 367 |  
| Innodb\_deadlocks | 0 |  
| Innodb\_dict\_tables | 91 |  
| Innodb\_have\_atomic\_builtins | ON |  
| Innodb\_history\_list\_length | 906 |  
| Innodb\_ibuf\_discarded\_delete\_marks | 0 |  
| Innodb\_ibuf\_discarded\_deletes | 0 |  
| Innodb\_ibuf\_discarded\_inserts | 0 |  
| Innodb\_ibuf\_free\_list | 3 |  
| Innodb\_ibuf\_merged\_delete\_marks | 1 |  
| Innodb\_ibuf\_merged\_deletes | 0 |  
| Innodb\_ibuf\_merged\_inserts | 40 |  
| Innodb\_ibuf\_merges | 41 |  
| Innodb\_ibuf\_segment\_size | 5 |  
| Innodb\_ibuf\_size | 1 |  
| Innodb\_log\_waits | 0 |  
| Innodb\_log\_write\_requests | 2177 |  
| Innodb\_log\_writes | 1602 |  
| Innodb\_lsn\_current | 25002719406 |  
| Innodb\_lsn\_flushed | 25002719406 |  
| Innodb\_lsn\_last\_checkpoint | 25002719406 |  
| Innodb\_master\_thread\_1\_second\_loops | 15231 |  
| Innodb\_master\_thread\_10\_second\_loops | 1407 |  
| Innodb\_master\_thread\_background\_loops | 1159 |  
| Innodb\_master\_thread\_main\_flush\_loops | 1159 |  
| Innodb\_master\_thread\_sleeps | 15224 |  
| Innodb\_max\_trx\_id | 23454578 |  
| Innodb\_mem\_adaptive\_hash | 5576304 |  
| Innodb\_mem\_dictionary | 1187505 |  
| Innodb\_mem\_total | 137822208 |  
| Innodb\_mutex\_os\_waits | 50 |  
| Innodb\_mutex\_spin\_rounds | 20268 |  
| Innodb\_mutex\_spin\_waits | 27322 |  
| Innodb\_oldest\_view\_low\_limit\_trx\_id | 23454578 |  
| Innodb\_os\_log\_fsyncs | 1970 |  
| Innodb\_os\_log\_pending\_fsyncs | 0 |  
| Innodb\_os\_log\_pending\_writes | 0 |  
| Innodb\_os\_log\_written | 1820672 |  
| Innodb\_page\_size | 16384 |  
| Innodb\_pages\_created | 41 |  
| Innodb\_pages\_read | 7235 |  
| Innodb\_pages\_written | 3403 |  
| Innodb\_purge\_trx\_id | 23454397 |  
| Innodb\_purge\_undo\_no | 0 |  
| Innodb\_row\_lock\_current\_waits | 0 |  
| Innodb\_current\_row\_locks | 0 |  
| Innodb\_row\_lock\_time | 1 |  
| Innodb\_row\_lock\_time\_avg | 1 |  
| Innodb\_row\_lock\_time\_max | 1 |  
| Innodb\_row\_lock\_waits | 1 |  
| Innodb\_rows\_deleted | 32 |  
| Innodb\_rows\_inserted | 598 |  
| Innodb\_rows\_read | 63568506 |  
| Innodb\_rows\_updated | 434 |  
| Innodb\_read\_views\_memory | 112 |  
| Innodb\_descriptors\_memory | 8000 |  
| Innodb\_s\_lock\_os\_waits | 377 |  
| Innodb\_s\_lock\_spin\_rounds | 12629 |  
| Innodb\_s\_lock\_spin\_waits | 956 |  
| Innodb\_truncated\_status\_writes | 0 |  
| Innodb\_x\_lock\_os\_waits | 14 |  
| Innodb\_x\_lock\_spin\_rounds | 1427 |  
| Innodb\_x\_lock\_spin\_waits | 82 |  
| Key\_blocks\_not\_flushed | 0 |  
| Key\_blocks\_unused | 13396 |  
| Key\_blocks\_used | 1 |  
| Key\_read\_requests | 204 |  
| Key\_reads | 0 |  
| Key\_write\_requests | 342 |  
| Key\_writes | 0 |  
| Last\_query\_cost | 0.000000 |  
| Max\_used\_connections | 13 |  
| Not\_flushed\_delayed\_rows | 0 |  
| Open\_files | 20 |  
| Open\_streams | 0 |  
| Open\_table\_definitions | 111 |  
| Open\_tables | 123 |  
| Opened\_files | 14312 |  
| Opened\_table\_definitions | 147 |  
| Opened\_tables | 166 |  
| Performance\_schema\_cond\_classes\_lost | 0 |  
| Performance\_schema\_cond\_instances\_lost | 0 |  
| Performance\_schema\_file\_classes\_lost | 0 |  
| Performance\_schema\_file\_handles\_lost | 0 |  
| Performance\_schema\_file\_instances\_lost | 0 |  
| Performance\_schema\_locker\_lost | 0 |  
| Performance\_schema\_mutex\_classes\_lost | 0 |  
| Performance\_schema\_mutex\_instances\_lost | 0 |  
| Performance\_schema\_rwlock\_classes\_lost | 0 |  
| Performance\_schema\_rwlock\_instances\_lost | 0 |  
| Performance\_schema\_table\_handles\_lost | 0 |  
| Performance\_schema\_table\_instances\_lost | 0 |  
| Performance\_schema\_thread\_classes\_lost | 0 |  
| Performance\_schema\_thread\_instances\_lost | 0 |  
| Prepared\_stmt\_count | 0 |  
| Qcache\_free\_blocks | 1532 |  
| Qcache\_free\_memory | 3449472 |  
| Qcache\_hits | 207252 |  
| Qcache\_inserts | 38014 |  
| Qcache\_lowmem\_prunes | 723 |  
| Qcache\_not\_cached | 45459 |  
| Qcache\_queries\_in\_cache | 3102 |  
| Qcache\_total\_blocks | 7825 |  
| Queries | 404763 |  
| Questions | 404760 |  
| Rpl\_status | AUTH\_MASTER |  
| Select\_full\_join | 220 |  
| Select\_full\_range\_join | 0 |  
| Select\_range | 4587 |  
| Select\_range\_check | 0 |  
| Select\_scan | 50886 |  
| Slave\_heartbeat\_period | 0.000 |  
| Slave\_open\_temp\_tables | 0 |  
| Slave\_received\_heartbeats | 0 |  
| Slave\_retried\_transactions | 0 |  
| Slave\_running | OFF |  
| Slow\_launch\_threads | 0 |  
| Slow\_queries | 177 |  
| Sort\_merge\_passes | 25 |  
| Sort\_range | 3040 |  
| Sort\_rows | 114929 |  
| Sort\_scan | 3730 |  
| Ssl\_accept\_renegotiates | 0 |  
| Ssl\_accepts | 0 |  
| Ssl\_callback\_cache\_hits | 0 |  
| Ssl\_cipher | |  
| Ssl\_cipher\_list | |  
| Ssl\_client\_connects | 0 |  
| Ssl\_connect\_renegotiates | 0 |  
| Ssl\_ctx\_verify\_depth | 0 |  
| Ssl\_ctx\_verify\_mode | 0 |  
| Ssl\_default\_timeout | 0 |  
| Ssl\_finished\_accepts | 0 |  
| Ssl\_finished\_connects | 0 |  
| Ssl\_session\_cache\_hits | 0 |  
| Ssl\_session\_cache\_misses | 0 |  
| Ssl\_session\_cache\_mode | NONE |  
| Ssl\_session\_cache\_overflows | 0 |  
| Ssl\_session\_cache\_size | 0 |  
| Ssl\_session\_cache\_timeouts | 0 |  
| Ssl\_sessions\_reused | 0 |  
| Ssl\_used\_session\_cache\_entries | 0 |  
| Ssl\_verify\_depth | 0 |  
| Ssl\_verify\_mode | 0 |  
| Ssl\_version | |  
| Table\_locks\_immediate | 52485 |  
| Table\_locks\_waited | 0 |  
| Tc\_log\_max\_pages\_used | 0 |  
| Tc\_log\_page\_size | 0 |  
| Tc\_log\_page\_waits | 0 |  
| Threadpool\_idle\_threads | 0 |  
| Threadpool\_threads | 0 |  
| Threads\_cached | 8 |  
| Threads\_connected | 3 |  
| Threads\_created | 1280 |  
| Threads\_running | 1 |  
| Uptime | 22490 |  
| Uptime\_since\_flush\_status | 22490 |  
| binlog\_commits | 0 |  
| binlog\_group\_commits | 0 |  
| wsrep\_local\_state\_uuid | b0228e2d-2bc2-11e3-859e-0xfcxfghdfh |  
| wsrep\_protocol\_version | 4 |  
| wsrep\_last\_committed | 616 |  
| wsrep\_replicated | 616 |  
| wsrep\_replicated\_bytes | 659786 |  
| wsrep\_received | 3 |  
| wsrep\_received\_bytes | 138 |  
| wsrep\_local\_commits | 598 |  
| wsrep\_local\_cert\_failures | 0 |  
| wsrep\_local\_bf\_aborts | 0 |  
| wsrep\_local\_replays | 0 |  
| wsrep\_local\_send\_queue | 0 |  
| wsrep\_local\_send\_queue\_avg | 0.000000 |  
| wsrep\_local\_recv\_queue | 0 |  
| wsrep\_local\_recv\_queue\_avg | 0.000000 |  
| wsrep\_flow\_control\_paused | 0.000000 |  
| wsrep\_flow\_control\_sent | 0 |  
| wsrep\_flow\_control\_recv | 0 |  
| wsrep\_cert\_deps\_distance | 45.366667 |  
| wsrep\_apply\_oooe | 0.000000 |  
| wsrep\_apply\_oool | 0.000000 |  
| wsrep\_apply\_window | 0.000000 |  
| wsrep\_commit\_oooe | 0.000000 |  
| wsrep\_commit\_oool | 0.000000 |  
| wsrep\_commit\_window | 0.000000 |  
| wsrep\_local\_state | 4 |  
| wsrep\_local\_state\_comment | Synced |  
| wsrep\_cert\_index\_size | 233 |  
| wsrep\_causal\_reads | 0 |  
| wsrep\_incoming\_addresses | 10.0.0.8:3306 |  
| wsrep\_cluster\_conf\_id | 1 |  
| wsrep\_cluster\_size | 1 |  
| wsrep\_cluster\_state\_uuid | b0228e2d-2bc2-11e3-859e-0dzfgsdfg |  
| wsrep\_cluster\_status | Primary |  
| wsrep\_connected | ON |  
| wsrep\_local\_index | 0 |  
| wsrep\_provider\_name | Galera |  
| wsrep\_provider\_vendor | Codership Oy \<info@codership.com\> |  
| wsrep\_provider\_version | 2.6(r152) |  
| wsrep\_ready | ON |  
±-----------------------------------------±-------------------------------------+

My.cnf is stock standard except for setting up node names, addresses and SST auth.

---

<div class="post-metadata">

**Author:** ![francoisstark](https://avatars.discourse-cdn.com/v4/letter/f/a698b9/32.png) [@francoisstark](https://forums.percona.com/u/francoisstark)\
**Post date:** [October 3, 2013, 12:42am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/4 "2013-10-03T00:42:31Z")

</div>

Just had a look at the mysql error log.  
I have a lot of these before the cluster crashed and I went over to bootstrap mode:

130926 20:43:18 [Warning] Too many connections  
----I have since substantially improved front-end caching and should send less than half the traffic to the databases now.

Saturday morning the cluster became unstable and I had a lot of these:

130928 7:07:40 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
…  
130928 7:07:40 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) turning message relay requesting on, nonlive peers: tcp://10.0.0.5:4567  
130928 7:07:41 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) reconnecting to 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567), attempt 0  
130928 7:07:42 [Note] WSREP: evs::proto(4864b4ca-1969-11e3-91f6-efdb7950b797, GATHER, view\_id(REG,240fee80-1969-11e3-b3f3-0b9e4ca22bc1,260)) suspecting node: 36f066e7-1969-11e3-b3e4-bfffdefe859f  
130928 7:07:43 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:43 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:43 [Note] WSREP: declaring 240fee80-1969-11e3-b3f3-0b9e4ca22bc1 stable  
130928 7:07:43 [Note] WSREP: Node 240fee80-1969-11e3-b3f3-0b9e4ca22bc1 state prim  
130928 7:07:43 [Note] WSREP: view(view\_id(PRIM,240fee80-1969-11e3-b3f3-0b9e4ca22bc1,261) memb {  
240fee80-1969-11e3-b3f3-0b9e4ca22bc1,  
4864b4ca-1969-11e3-91f6-efdb7950b797,  
} joined {  
} left {  
} partitioned {  
36f066e7-1969-11e3-b3e4-bfffdefe859f,  
})  
130928 7:07:43 [Note] WSREP: forgetting 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567)  
130928 7:07:43 [Note] WSREP: deleting entry tcp://10.0.0.5:4567  
130928 7:07:43 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my\_idx = 1, memb\_num = 2  
130928 7:07:43 [Note] WSREP: forgetting 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://197.242.148.230:4567)  
130928 7:07:43 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.  
130928 7:07:43 [Note] WSREP: deleting entry tcp://197.242.148.230:4567  
130928 7:07:43 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:43 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) turning message relay requesting off  
130928 7:07:43 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:43 [Note] WSREP: STATE EXCHANGE: sent state msg: e838de4f-27fb-11e3-8c27-7ea8d538500b  
130928 7:07:43 [Note] WSREP: STATE EXCHANGE: got state msg: e838de4f-27fb-11e3-8c27-7ea8d538500b from 0 (###5)  
130928 7:07:43 [Note] WSREP: STATE EXCHANGE: got state msg: e838de4f-27fb-11e3-8c27-7ea8d538500b from 1 (###7)  
130928 7:07:43 [Note] WSREP: Quorum results:  
version = 2,  
component = PRIMARY,  
conf\_id = 219,  
members = 2/2 (joined/total),  
act\_id = 5954217,  
last\_appl. = 5953977,  
protocols = 0/4/2 (gcs/repl/appl),  
group UUID = 73cc2dce-0189-11e3-be43-e2d7eeaef85e  
130928 7:07:43 [Note] WSREP: Flow-control interval: [23, 23]  
130928 7:07:43 [Note] WSREP: New cluster view: global state: 73cc2dce-0189-11e3-be43-e2d7eeaef85e:5954217, view# 220: Primary, number of nodes: 2, my index: 1, protocol version 2  
130928 7:07:43 [Note] WSREP: wsrep\_notify\_cmd is not defined, skipping notification.  
130928 7:07:43 [Note] WSREP: Assign initial position for certification: 5954217, protocol version: 2  
130928 7:07:45 [Warning] WSREP: discarding established (time wait) 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567)  
130928 7:07:45 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:46 [Warning] WSREP: discarding established (time wait) 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567)  
130928 7:07:46 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:48 [Warning] WSREP: discarding established (time wait) 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567)  
130928 7:07:48 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:49 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping  
130928 7:07:49 [Note] WSREP: cleaning up 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://10.0.0.5:4567)  
130928 7:07:49 [Note] WSREP: cleaning up 36f066e7-1969-11e3-b3e4-bfffdefe859f (tcp://197.242.148.230:4567)  
130928 7:07:49 [Warning] WSREP: evs::proto(4864b4ca-1969-11e3-91f6-efdb7950b797, GATHER, view\_id(REG,240fee80-1969-11e3-b3f3-0b9e4ca22bc1,261)) source 36f066e7-1969-11e3-b3e4-bfffdefe859f is not supposed to be representative  
130928 7:07:50 [Note] WSREP: (4864b4ca-1969-11e3-91f6-efdb7950b797, ‘tcp://0.0.0.0:4567’) address ‘tcp://10.0.0.8:4567’ pointing to uuid 4864b4ca-1969-11e3-91f6-efdb7950b797 is blacklisted, skipping

…etc…

---- and a bit later this:  
130928 7:21:17 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.  
130928 7:21:17 [Note] WSREP: STATE EXCHANGE: sent state msg: cd389623-27fd-11e3-8df6-6327f157c0f2  
130928 7:21:17 [Note] WSREP: STATE EXCHANGE: got state msg: cd389623-27fd-11e3-8df6-6327f157c0f2 from 0 (###5)  
130928 7:21:17 [Note] WSREP: STATE EXCHANGE: got state msg: cd389623-27fd-11e3-8df6-6327f157c0f2 from 1 (###4)  
130928 7:21:17 [Note] WSREP: STATE EXCHANGE: got state msg: cd389623-27fd-11e3-8df6-6327f157c0f2 from 2 (###7)  
130928 7:21:17 [Warning] WSREP: Quorum: No node with complete state:

Version : 2  
Flags : 3  
Protocols : 0 / 4 / 2  
State : NON-PRIMARY  
Prim state : SYNCED  
Prim UUID : b9d06527-27fd-11e3-a1dd-36ebc5d2f591  
Prim seqno : 223  
Last seqno : 5954716  
Prim JOINED : 3  
State UUID : cd389623-27fd-11e3-8df6-6327f157c0f2  
Group UUID : 73cc2dce-0189-11e3-be43-e2d7eeaef85e  
Name : ‘###5’  
Incoming addr: ‘10.0.0.6:3306’

Version : 2  
Flags : 2  
Protocols : 0 / 4 / 2  
State : NON-PRIMARY  
Prim state : SYNCED  
Prim UUID : b9d06527-27fd-11e3-a1dd-36ebc5d2f591  
Prim seqno : 223  
Last seqno : 5954716  
Prim JOINED : 3  
State UUID : cd389623-27fd-11e3-8df6-6327f157c0f2  
Group UUID : 73cc2dce-0189-11e3-be43-e2d7eeaef85e  
Name : ‘###4’  
Incoming addr: ‘10.0.0.5:3306’

Version : 2  
Flags : 2  
Protocols : 0 / 4 / 2  
State : NON-PRIMARY  
Prim state : SYNCED  
Prim UUID : b9d06527-27fd-11e3-a1dd-36ebc5d2f591  
Prim seqno : 223  
Last seqno : 5954716  
Prim JOINED : 3  
State UUID : cd389623-27fd-11e3-8df6-6327f157c0f2  
Group UUID : 73cc2dce-0189-11e3-be43-e2d7eeaef85e  
Name : ‘###7’  
Incoming addr: ‘10.0.0.8:3306’

130928 7:21:17 [Note] WSREP: Full re-merge of primary b9d06527-27fd-11e3-a1dd-36ebc5d2f591 found: 3 of 3.  
130928 7:21:17 [Note] WSREP: Quorum results:  
version = 2,  
component = PRIMARY,  
conf\_id = 223,  
members = 3/3 (joined/total),  
act\_id = 5954716,

—and eventually the cluster froze. I had to restart one system in bootstrap mode and that is how it is still running.

---

<div class="post-metadata">

**Author:** ![francoisstark](https://avatars.discourse-cdn.com/v4/letter/f/a698b9/32.png) [@francoisstark](https://forums.percona.com/u/francoisstark)\
**Post date:** [October 3, 2013, 11:05am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/5 "2013-10-03T11:05:50Z")

</div>

I have installed pt-stalk, hopefully it will send me some emails during the night.

---

<div class="post-metadata">

**Author:** ![przemek](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/przemek/32/3_2.png) [@przemek](https://forums.percona.com/u/przemek)\
**Post date:** [October 4, 2013, 8:06am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/6 "2013-10-04T08:06:00Z")

</div>

In the slow log entries it’s the other way around, first is the header with information about query, then there is the query itself.  
Anyways:

# Query\_time: 10.851373 Lock\_time: 0.000059 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1 Rows\_read: 1

means some serious slow down, I suppose that was for the insert shown in previous example.

pt-stalk snapshot would tell also OS related statistics, like how the IO layer was loaded.

You did not confirm the involved table is InnoDB? Also by “My.cnf is stock standard” you mean also the InnoDB redo logs are default 5MB each and InnoDB buffer pool size default? If yes, then it’s surely not right settings for production purpose.

---

<div class="post-metadata">

**Author:** ![francoisstark](https://avatars.discourse-cdn.com/v4/letter/f/a698b9/32.png) [@francoisstark](https://forums.percona.com/u/francoisstark)\
**Post date:** [October 4, 2013, 9:37am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/7 "2013-10-04T09:37:28Z")

</div>

pt-stalk did not log anything yet, even with threshold set to 10. However, I saw my innodb buffer pool size was set to the default 128M, on a system with 32GB RAM! My active database is 2GB in size. This could be the root cause of all my problems. I added the following lines to my.cnf:

innodb\_buffer\_pool\_size = 10G  
innodb\_thread\_concurrency = 8  
innodb\_flush\_method = O\_DIRECT  
innodb\_file\_per\_table = 1  
innodb\_flush\_log\_at\_trx\_commit = 2  
innodb\_log\_buffer\_size = 4M

After restarting mysql I did a new slow\_log, and the analysis show that none of my queries take more than 10ms now. That’s better.

Next step: analyse the two dead cluster systems’ error logs and set up their innodb\_buffer\_pool\_size. Then try to join the cluster again.

---

<div class="post-metadata">

**Author:** ![przemek](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/przemek/32/3_2.png) [@przemek](https://forums.percona.com/u/przemek)\
**Post date:** [October 16, 2013, 2:07am UTC](https://forums.percona.com/t/insert-takes-13-seconds/2981/8 "2013-10-16T02:07:08Z")

</div>

The innodb\_buffer\_pool\_size is the most important setting from InnoDB performance point of view, but note also the innodb\_log\_file\_size is crucial for write performance! Usually setting it to 1GB+ makes sense. (btw: [url][http://www.mysqlperformanceblog.com/2011/07/09/how-to-change-innodb\_log\_file\_size-safely/[/url]](http://www.mysqlperformanceblog.com/2011/07/09/how-to-change-innodb_log_file_size-safely/%5B/url%5D))