Replication Triggers a Performance Schema Issue on Percona XtraDB Cluster

October 21, 2016

Author

David Ducos

MySQL

Percona Software

Share this Post:

In this blog post, we’ll look at how replication triggers a Performance Schema issue on Percona XtraDB Cluster.

During an upgrade to Percona XtraDB Cluster 5.6, I faced an issue that I wanted to share. In this environment, we set up three Percona XtraDB Cluster nodes (mostly configured as default), copied from a production server. We configured one of the members of the cluster as the slave of the production server.

During the testing process, we found that a full table scan query was taking four times less in the nodes where replication was not configured. After reviewing mostly everything related to the query, we decided to use perf.

We executed:

perf record -a -g -F99 -p $(pidof mysqld) -- sleep 60

1	perf record -a -g -F99 -p $(pidof mysqld) -- sleep 60

And the query in another terminal a couple of times. Then we executed:

perf report > perf.out

1	perf report > perf.out

And we found in the perf.out this useful information:

# To display the perf.data header info, please use --header/--header-only options.<br>#<br># Samples: 5K of event 'cpu-clock'<br># Event count (approx.): 57646464070<br>#<br># Children Self Command Shared Object Symbol<br># ........ ........ ....... .................. ............................................................................................................................................................<br>#<br>62.03% 62.01% mysqld mysqld [.] my_timer_cycles<br>|<br>---my_timer_cycles<br><br>4.66% 4.66% mysqld mysqld [.] 0x00000000005425d4<br>|<br>---0x5425d4<br><br>4.66% 0.00% mysqld mysqld [.] 0x00000000001425d4<br>|<br>---0x5425d4<br><br>3.31% 3.31% mysqld mysqld [.] 0x00000000005425a7<br>|<br>---0x5425a7

1

# To display the perf.data header info, please use --header/--header-only options. # # Samples: 5K of event 'cpu-clock' # Event count (approx.): 57646464070 # # Children Self Command Shared Object Symbol # ........ ........ ....... .................. ............................................................................................................................................................ # 62.03% 62.01% mysqld mysqld [.] my_timer_cycles | ---my_timer_cycles 4.66% 4.66% mysqld mysqld [.] 0x00000000005425d4 | ---0x5425d4 4.66% 0.00% mysqld mysqld [.] 0x00000000001425d4 | ---0x5425d4 3.31% 3.31% mysqld mysqld [.] 0x00000000005425a7 | ---0x5425a7

As you can see, the my_timer_cycles function took 62.03% of the time. Related to this, we found a blog (http://dtrace.org/blogs/brendan/2011/06/27/viewing-the-invisible/) that explained how after enabling the Performance Schema, the performance dropped 10%. So, we decided to disable Performance Schema in order to see if this issue was related to the one described in the blog. We found that after the restart required by disabling Performance Schema, the query was taking the expected amount of time.

We also found out that this was triggered by replication, and nodes rebuilt from this member might have this issue. It was the same if you rebuilt from a member that was OK: the new member might execute the query slower.

Finally, you should take into account that my_timer_cycles seems to be called on a per-row basis, so if your dataset is small you will never notice this issue. However, if you are doing a full table scan of a million row table, you could face this issue.

Conclusion

If you are having query performance issues, and you can’t find the root cause, try disabling or debugging instruments from the Performance Schema to see if that is causing the issue.