sysbench的lua小改动导致的性能差异

最新推荐文章于 2022-02-23 12:43:35 发布
最新推荐文章于 2022-02-23 12:43:35 发布
阅读量161 收藏
点赞数
文章标签： lua 数据库 运维


|  导语

最近在配合某同事做一项性能压测，发现相同数据量、相同数据库参数、相同sysbench压力、相同数据库版本和sysbench版本、相同服务器硬件环境下，我和同事的压测结果天差地别：一个小时压测结束后，我的压测结果中出现了高频率周期性阻塞(tps,qps为0)，而同事的压测结果中未出现阻塞(tps,qps从头到尾都比较稳定)。正常情况下，在环境完全相同时，不可能会出现如此巨大的性能差异。但这次，不可能发生的事情它的确发生了。经过复测与排查，终于发现了其中的奥妙。

服务器硬件信息

  • 数据库主机 
    * CPU：72 process 
    * memory：128G 
    * 磁盘：某存储 100G 
    * 网卡：intel 万兆网卡

  • 数据库版本：MySQL 5.7.21

  • sysbench版本：1.0.9

  • sysbench主机 
    * CPU：20 process 
    * memory：128G 
    * 磁盘：本地SAS 50G 
    * 网卡：intel 万兆网卡


|  复测结果数据

先来看看压测结果数据，如下图所示（注：此处只截取了前几十秒的数据进行对比）：

  • 我的压测结果（下图可见，明显的周期性tps，qps为0的情况） 

  • 同事的压测结果（下图可见，tps,qps较为稳定且并未出现阻塞情况） 


|  抓取等待事件

看到上文第1节中的结果，如果根据以往的经验、常识来快速判断...估计会懵圈！！当得知同事的测试结果很稳定时，我本能地想：要把等待事件信息拉出来瞧瞧！！下面是我与同事各自在复测时截取的等待事件信息（复测时间为3分钟）（不想仔细看等待事件内容的亲可直接跳至第3节）

operation操作时间统计（每秒查询一次，查询数十次截取时间最长的5次）

点击(此处)折叠或打开

  1. # 我的
  2. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  3. +----------------------------------+-----------+
  4. | sys.format_time(sum(timer_wait)) | operation |
  5. +----------------------------------+-----------+
  6. | 1.20 s | idle |
  7. | 219.20 ms | write |
  8. +----------------------------------+-----------+
  9. 2 rows in set (0.01 sec)
  10. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  11. +----------------------------------+-----------+
  12. | sys.format_time(sum(timer_wait)) | operation |
  13. +----------------------------------+-----------+
  14. | 1.16 s | idle |
  15. | 182.44 ms | write |
  16. +----------------------------------+-----------+
  17. 2 rows in set (0.01 sec)
  18. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  19. +----------------------------------+-----------+
  20. | sys.format_time(sum(timer_wait)) | operation |
  21. +----------------------------------+-----------+
  22. | 1.17 s | idle |
  23. | 164.27 ms | write |
  24. +----------------------------------+-----------+
  25. 2 rows in set (0.01 sec)
  26. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  27. +----------------------------------+-----------+
  28. | sys.format_time(sum(timer_wait)) | operation |
  29. +----------------------------------+-----------+
  30. | 1.21 s | idle |
  31. | 268.65 ms | write |
  32. +----------------------------------+-----------+
  33. 2 rows in set (0.01 sec)
  34. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  35. +----------------------------------+-----------+
  36. | sys.format_time(sum(timer_wait)) | operation |
  37. +----------------------------------+-----------+
  38. | 11.78 s | fetch |
  39. | 1.61 s | idle |
  40. +----------------------------------+-----------+
  41. 2 rows in set (0.02 sec)
  42. # 同事的
  43. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  44. +----------------------------------+-----------+
  45. | sys.format_time(sum(timer_wait)) | operation |
  46. +----------------------------------+-----------+
  47. | 21.17 ms | idle |
  48. | 1.58 ms | fetch |
  49. +----------------------------------+-----------+
  50. 2 rows in set (0.02 sec)
  51. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  52. +----------------------------------+-----------+
  53. | sys.format_time(sum(timer_wait)) | operation |
  54. +----------------------------------+-----------+
  55. | 185.44 ms | idle |
  56. +----------------------------------+-----------+
  57. 1 row in set (0.02 sec)
  58. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  59. +----------------------------------+-----------+
  60. | sys.format_time(sum(timer_wait)) | operation |
  61. +----------------------------------+-----------+
  62. | 141.82 ms | lock |
  63. | 110.90 ms | fetch |
  64. | 3.30 ms | idle |
  65. +----------------------------------+-----------+
  66. 3 rows in set (0.01 sec)
  67. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  68. +----------------------------------+-----------+
  69. | sys.format_time(sum(timer_wait)) | operation |
  70. +----------------------------------+-----------+
  71. | 2.91 s | idle |
  72. +----------------------------------+-----------+
  73. 1 row in set (0.00 sec)
  74. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  75. +----------------------------------+-----------+
  76. | sys.format_time(sum(timer_wait)) | operation |
  77. +----------------------------------+-----------+
  78. | 1.20 s | idle |
  79. +----------------------------------+-----------+
  80. 1 row in set (0.01 sec)
  81. mysql> select sys.format_time(sum(timer_wait)),operation from performance_schema.events_waits_history_long where timer_wait > 1000000000 group by operation order by sum(timer_wait) desc;
  82. +----------------------------------+-----------+
  83. | sys.format_time(sum(timer_wait)) | operation |
  84. +----------------------------------+-----------+
  85. | 215.34 ms | idle |
  86. +----------------------------------+-----------+
  87. 1 row in set (0.01 sec)

等待事件按照时间开销倒序排序，取出超过ms的部分（每秒查询一次，查询数十次截取时间最长的5次）

点击(此处)折叠或打开

  1. # 我的
  2. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  3. +----------------------------------------+-----------------+-----------------------------+-----------+
  4. | event_name | source | sys.format_time(timer_wait) | operation |
  5. +----------------------------------------+-----------------+-----------------------------+-----------+
  6. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 37.31 ms | write |
  7. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 37.08 ms | write |
  8. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 23.95 ms | write |
  9. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 23.06 ms | write |
  10. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 20.99 ms | write |
  11. ......
  12. +----------------------------------------+-----------------+-----------------------------+-----------+
  13. 50 rows in set (0.02 sec)
  14. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  15. +--------------------------------------+-----------------+-----------------------------+-----------+
  16. | event_name | source | sys.format_time(timer_wait) | operation |
  17. +--------------------------------------+-----------------+-----------------------------+-----------+
  18. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 15.71 ms | write |
  19. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 14.94 ms | write |
  20. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 14.22 ms | write |
  21. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 13.93 ms | write |
  22. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 13.53 ms | write |
  23. ......
  24. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  25. +--------------------------------------+-----------------+-----------------------------+-----------+
  26. | event_name | source | sys.format_time(timer_wait) | operation |
  27. +--------------------------------------+-----------------+-----------------------------+-----------+
  28. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 41.05 ms | write |
  29. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 34.67 ms | write |
  30. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 31.63 ms | write |
  31. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 31.30 ms | write |
  32. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 28.09 ms | write |
  33. ......
  34. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  35. +-------------------------------------+-----------------+-----------------------------+-----------+
  36. | event_name | source | sys.format_time(timer_wait) | operation |
  37. +-------------------------------------+-----------------+-----------------------------+-----------+
  38. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 33.20 ms | sync |
  39. | wait/io/table/sql/handler | handler.cc:3084 | 26.20 ms | fetch |
  40. | wait/io/table/sql/handler | handler.cc:3032 | 23.26 ms | fetch |
  41. | wait/io/table/sql/handler | handler.cc:3032 | 21.26 ms | fetch |
  42. | wait/io/table/sql/handler | handler.cc:3032 | 19.07 ms | fetch |
  43. | wait/io/table/sql/handler | handler.cc:3084 | 18.55 ms | fetch |
  44. ......
  45. | wait/io/table/sql/handler | handler.cc:7992 | 12.07 ms | insert |
  46. | wait/io/table/sql/handler | handler.cc:3084 | 11.96 ms | fetch |
  47. | wait/io/table/sql/handler | handler.cc:3032 | 11.31 ms | fetch |
  48. | wait/io/table/sql/handler | handler.cc:3084 | 11.04 ms | fetch |
  49. | wait/io/table/sql/handler | handler.cc:3084 | 10.69 ms | fetch |
  50. | wait/io/table/sql/handler | handler.cc:7992 | 9.58 ms | insert |
  51. | wait/io/table/sql/handler | handler.cc:3032 | 9.55 ms | fetch |
  52. | wait/io/table/sql/handler | handler.cc:3032 | 9.27 ms | fetch |
  53. | wait/io/table/sql/handler | handler.cc:7992 | 9.10 ms | insert |
  54. | wait/io/table/sql/handler | handler.cc:3084 | 9.01 ms | fetch |
  55. | wait/io/table/sql/handler | handler.cc:3032 | 7.69 ms | fetch |
  56. ......
  57. | wait/io/table/sql/handler | handler.cc:3084 | 5.70 ms | fetch |
  58. | wait/io/table/sql/handler | handler.cc:3032 | 5.69 ms | fetch |
  59. | wait/io/table/sql/handler | handler.cc:3032 | 5.63 ms | fetch |
  60. | wait/io/table/sql/handler | handler.cc:3084 | 5.63 ms | fetch |
  61. | wait/io/table/sql/handler | handler.cc:3084 | 5.57 ms | fetch |
  62. | wait/io/table/sql/handler | handler.cc:3084 | 5.53 ms | fetch |
  63. | wait/io/table/sql/handler | handler.cc:7992 | 5.52 ms | insert |
  64. | wait/io/table/sql/handler | handler.cc:3084 | 5.51 ms | fetch |
  65. | wait/io/table/sql/handler | handler.cc:3032 | 5.48 ms | fetch |
  66. | wait/io/table/sql/handler | handler.cc:3032 | 5.43 ms | fetch |
  67. +-------------------------------------+-----------------+-----------------------------+-----------+
  68. 50 rows in set (0.02 sec)
  69. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  70. +--------------------------------------+-----------------+-----------------------------+-----------+
  71. | event_name | source | sys.format_time(timer_wait) | operation |
  72. +--------------------------------------+-----------------+-----------------------------+-----------+
  73. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 33.20 ms | sync |
  74. | wait/io/table/sql/handler | handler.cc:3032 | 19.07 ms | fetch |
  75. | wait/io/file/innodb/innodb_data_file | fil0fil.cc:5778 | 18.71 ms | write |
  76. | wait/io/table/sql/handler | handler.cc:3032 | 14.12 ms | fetch |
  77. | wait/io/table/sql/handler | handler.cc:3032 | 13.16 ms | fetch |
  78. | wait/io/table/sql/handler | handler.cc:3032 | 13.08 ms | fetch |
  79. | wait/io/table/sql/handler | handler.cc:3032 | 12.56 ms | fetch |
  80. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 12.23 ms | sync |
  81. | wait/io/table/sql/handler | handler.cc:3032 | 12.22 ms | fetch |
  82. | wait/io/table/sql/handler | handler.cc:3032 | 11.31 ms | fetch |
  83. | wait/io/table/sql/handler | handler.cc:3084 | 11.04 ms | fetch |
  84. ......
  85. | wait/io/table/sql/handler | handler.cc:3032 | 5.86 ms | fetch |
  86. | wait/io/table/sql/handler | handler.cc:3032 | 5.79 ms | fetch |
  87. | wait/io/table/sql/handler | handler.cc:3032 | 5.78 ms | fetch |
  88. | wait/io/table/sql/handler | handler.cc:3084 | 5.74 ms | fetch |
  89. | wait/io/table/sql/handler | handler.cc:3032 | 5.71 ms | fetch |
  90. | wait/io/table/sql/handler | handler.cc:3032 | 5.71 ms | fetch |
  91. ......
  92. | wait/io/table/sql/handler | handler.cc:3032 | 3.88 ms | fetch |
  93. | wait/io/table/sql/handler | handler.cc:3084 | 3.88 ms | fetch |
  94. | wait/io/table/sql/handler | handler.cc:3084 | 3.86 ms | fetch |
  95. | wait/io/table/sql/handler | handler.cc:3032 | 3.85 ms | fetch |
  96. | wait/io/table/sql/handler | handler.cc:3084 | 3.81 ms | fetch |
  97. | wait/io/table/sql/handler | handler.cc:3084 | 3.81 ms | fetch |
  98. | wait/io/table/sql/handler | handler.cc:3032 | 3.80 ms | fetch |
  99. +--------------------------------------+-----------------+-----------------------------+-----------+
  100. 50 rows in set (0.02 sec)
  101. # 同事的
  102. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  103. +---------------------------------------------+-------------------+-----------------------------+-----------+
  104. | event_name | source | sys.format_time(timer_wait) | operation |
  105. +---------------------------------------------+-------------------+-----------------------------+-----------+
  106. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 16.18 ms | sync |
  107. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 5.34 ms | sync |
  108. ......
  109. +---------------------------------------------+-------------------+-----------------------------+-----------+
  110. 50 rows in set (0.01 sec)
  111. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  112. +---------------------------------------+--------------------+-----------------------------+-----------+
  113. | event_name | source | sys.format_time(timer_wait) | operation |
  114. +---------------------------------------+--------------------+-----------------------------+-----------+
  115. | wait/synch/mutex/innodb/trx_sys_mutex | ha_innodb.cc:15727 | 1.87 ms | lock |
  116. | wait/synch/mutex/innodb/trx_sys_mutex | ha_innodb.cc:15727 | 1.64 ms | lock |
  117. | wait/io/table/sql/handler | handler.cc:3084 | 1.63 ms | fetch |
  118. | wait/io/table/sql/handler | handler.cc:3084 | 1.63 ms | fetch |
  119. | wait/synch/mutex/innodb/trx_sys_mutex | read0read.cc:584 | 1.61 ms | lock |
  120. | wait/synch/mutex/innodb/trx_sys_mutex | read0read.cc:584 | 1.57 ms | lock |
  121. ......
  122. +---------------------------------------+--------------------+-----------------------------+-----------+
  123. 50 rows in set (0.02 sec)
  124. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  125. +------------------------------------------+--------------------+-----------------------------+-----------+
  126. | event_name | source | sys.format_time(timer_wait) | operation |
  127. +------------------------------------------+--------------------+-----------------------------+-----------+
  128. | wait/synch/mutex/innodb/lock_mutex | lock0lock.cc:6844 | 1.27 ms | lock |
  129. | wait/synch/mutex/innodb/lock_mutex | lock0lock.cc:6047 | 1.19 ms | lock |
  130. | wait/io/table/sql/handler | handler.cc:3032 | 1.19 ms | fetch |
  131. | wait/io/table/sql/handler | handler.cc:8033 | 1.13 ms | update |
  132. | wait/io/table/sql/handler | handler.cc:3084 | 1.07 ms | fetch |
  133. | wait/synch/mutex/innodb/trx_sys_mutex | read0read.cc:584 | 1.05 ms | lock |
  134. | wait/io/table/sql/handler | handler.cc:8066 | 1.03 ms | delete |
  135. ......
  136. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  137. +---------------------------------------+-------------------+-----------------------------+-----------+
  138. | event_name | source | sys.format_time(timer_wait) | operation |
  139. +---------------------------------------+-------------------+-----------------------------+-----------+
  140. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 14.18 ms | sync |
  141. | wait/io/table/sql/handler | handler.cc:3084 | 4.72 ms | fetch |
  142. | wait/io/file/innodb/innodb_log_file | fil0fil.cc:5992 | 4.20 ms | sync |
  143. | wait/synch/mutex/sql/LOCK_table_cache | table_cache.h:115 | 1.68 ms | lock |
  144. | wait/synch/mutex/sql/LOCK_table_cache | table_cache.h:115 | 1.66 ms | lock |
  145. | wait/synch/mutex/sql/LOCK_table_cache | table_cache.h:115 | 1.56 ms | lock |
  146. | wait/synch/mutex/sql/LOCK_table_cache | table_cache.h:115 | 1.49 ms | lock |
  147. ......
  148. mysql> select event_name,source,sys.format_time(timer_wait),operation from performance_schema.events_waits_history_long where event_name!='idle' order by TIMER_WAIT desc limit 50;
  149. +-------------------------------------------+------------------+-----------------------------+----------------+
  150. | event_name | source | sys.format_time(timer_wait) | operation |
  151. +-------------------------------------------+------------------+-----------------------------+----------------+
  152. | wait/synch/sxlock/innodb/fil_space_latch | fsp0fsp.cc:3365 | 7.84 ms | exclusive_lock |
  153. | wait/io/table/sql/handler | handler.cc:3032 | 1.00 ms | fetch |
  154. ......
  155. +-------------------------------------------+------------------+-----------------------------+----------------+
  156. 50 rows in set (0.01 sec)

按照等待事件类型统计总数、平均、最大、最小等待时长（只取出前50）

点击(此处)折叠或打开

  1. # 我的
  2. mysql> select * from sys.waits_global_by_latency limit 50;
  3. +-----------------------------------------------------------+-----------+---------------+-------------+-------------+
  4. | events | total | total_latency | avg_latency | max_latency |
  5. +-----------------------------------------------------------+-----------+---------------+-------------+-------------+
  6. | wait/io/table/sql/handler | 50405591 | 9.64 h | 688.46 us | 11.26 s |
  7. | wait/synch/mutex/innodb/trx_sys_mutex | 6815615 | 6.61 m | 58.20 us | 25.66 ms |
  8. | wait/io/socket/sql/client_connection | 8527800 | 1.64 m | 11.53 us | 11.44 ms |
  9. | wait/synch/sxlock/innodb/fil_space_latch | 22637 | 1.44 m | 3.83 ms | 10.36 s |
  10. | wait/synch/sxlock/innodb/dict_operation_lock | 90 | 1.40 m | 934.44 ms | 9.70 s |
  11. | wait/io/file/innodb/innodb_data_file | 204837 | 1.22 m | 358.33 us | 112.80 ms |
  12. | wait/synch/mutex/innodb/sync_array_mutex | 1863469 | 1.03 m | 33.24 us | 10.80 ms |
  13. | wait/synch/mutex/innodb/log_sys_write_mutex | 602223 | 59.64 s | 99.03 us | 11.26 ms |
  14. | wait/io/file/innodb/innodb_log_file | 8158 | 46.84 s | 5.74 ms | 82.44 ms |
  15. | wait/synch/mutex/sql/LOCK_table_cache | 7534927 | 46.66 s | 6.19 us | 11.16 ms |
  16. | wait/synch/sxlock/innodb/index_tree_rw_lock | 5966049 | 44.10 s | 7.39 us | 10.43 s |
  17. | wait/synch/mutex/sql/THD::LOCK_thd_data | 142798237 | 22.75 s | 159.20 ns | 2.52 ms |
  18. ......
  19. 50 rows in set (0.04 sec)
  20. # 同事的
  21. mysql> select * from sys.waits_global_by_latency limit 50;
  22. +-----------------------------------------------------+-----------+---------------+-------------+-------------+
  23. | events | total | total_latency | avg_latency | max_latency |
  24. +-----------------------------------------------------+-----------+---------------+-------------+-------------+
  25. | wait/io/table/sql/handler | 280178382 | 32.65 m | 6.99 us | 324.56 ms |
  26. | wait/synch/mutex/innodb/trx_sys_mutex | 24005580 | 15.87 m | 39.66 us | 36.95 ms |
  27. | wait/io/socket/sql/client_connection | 28521546 | 5.47 m | 11.52 us | 21.09 ms |
  28. | wait/synch/mutex/innodb/log_sys_write_mutex | 1383193 | 3.18 m | 137.81 us | 15.70 ms |
  29. | wait/io/file/innodb/innodb_log_file | 22238 | 2.82 m | 7.60 ms | 456.05 ms |
  30. | wait/synch/mutex/innodb/sync_array_mutex | 5195017 | 2.64 m | 30.52 us | 10.90 ms |
  31. | wait/synch/mutex/sql/LOCK_table_cache | 24012569 | 2.26 m | 5.65 us | 23.75 ms |
  32. | wait/synch/mutex/sql/THD::LOCK_thd_data | 621837619 | 1.69 m | 162.80 ns | 3.15 ms |
  33. | wait/synch/mutex/sql/THD::LOCK_query_plan | 844318371 | 1.61 m | 114.00 ns | 6.14 ms |
  34. | wait/synch/mutex/innodb/log_sys_mutex | 9348544 | 1.33 m | 8.55 us | 13.32 ms |
  35. | wait/synch/mutex/sql/THD::LOCK_thd_query | 444158105 | 46.16 s | 103.60 ns | 3.11 ms |
  36. | wait/lock/table/sql/handler | 12006244 | 31.98 s | 2.66 us | 5.55 ms |
  37. | wait/synch/mutex/innodb/lock_mutex | 8701428 | 29.39 s | 3.38 us | 8.93 ms |
  38. | wait/synch/mutex/innodb/redo_rseg_mutex | 2670852 | 27.70 s | 10.37 us | 242.76 ms |
  39. | wait/io/file/innodb/innodb_data_file | 73925 | 25.97 s | 351.35 us | 97.23 ms |
  40. ......
  41. 50 rows in set (0.05 sec)

|  利用等待事件分析差异

通过对上文第2节抓取的等待事件进行仔细地对比，可以看到在我的压测结果的等待事件中，对表的write(对表的写入)、fetch（可以理解为对表的读取）、sync(表数据落盘)等操作普遍在10ms以上(甚至高达37ms)，而同事的压测结果的等待事件中，对表的write、fetch、sync等操作ms级别以上很少，有ms级别以上的也在2ms以内，从等待事件类型统计数据中也可以看到，wait/io/table/sql/handler 等待事件在我的测试结果中平均等待时间为688.46 us ，而同事的是6.99 us，而我的最大等待时间为11.26 s ，同事的为324.56 ms。

那么，问题来了：为什么会有这个差异？

百思不得其解，只能继续压测，然而无意间却发现，同事的环境在压测的时候数据量居然不增长...

点击(此处)折叠或打开

  1. # 同事的（从下面5次查询sbtest1表的id最大值我们可以看到，都为5159769 ）
  2. mysql> select max(id),now() from sbtest1;
  3. +---------+---------------------+
  4. | max(id) | now() |
  5. +---------+---------------------+
  6. | 5159769 | 2001-01-25 01:47:28 |
  7. +---------+---------------------+
  8. 1 row in set (0.00 sec)
  9. mysql> select max(id),now() from sbtest1;
  10. +---------+---------------------+
  11. | max(id) | now() |
  12. +---------+---------------------+
  13. | 5159769 | 2001-01-25 01:47:31 |
  14. +---------+---------------------+
  15. 1 row in set (0.00 sec)
  16. mysql> select max(id),now() from sbtest1;
  17. +---------+---------------------+
  18. | max(id) | now() |
  19. +---------+---------------------+
  20. | 5159769 | 2001-01-25 01:47:33 |
  21. +---------+---------------------+
  22. 1 row in set (0.00 sec)
  23. mysql> select max(id),now() from sbtest1;
  24. +---------+---------------------+
  25. | max(id) | now() |
  26. +---------+---------------------+
  27. | 5159769 | 2001-01-25 01:47:35 |
  28. +---------+---------------------+
  29. 1 row in set (0.00 sec)
  30. mysql> select max(id),now() from sbtest1;
  31. +---------+---------------------+
  32. | max(id) | now() |
  33. +---------+---------------------+
  34. | 5159769 | 2001-01-25 01:47:39 |
  35. +---------+---------------------+
  36. 1 row in set (0.00 sec)
  37. # 而我的（从下面5次查询sbtest1表的id最大值可以看到，5次分别为5167559 、5169955、5172245 、5174269 、5175955 ）
  38. mysql> select max(id),now() from sbtest1;
  39. +---------+---------------------+
  40. | max(id) | now() |
  41. +---------+---------------------+
  42. | 5167559 | 2001-01-25 01:48:29 |
  43. +---------+---------------------+
  44. 1 row in set (0.00 sec)
  45. mysql> select max(id),now() from sbtest1;
  46. +---------+---------------------+
  47. | max(id) | now() |
  48. +---------+---------------------+
  49. | 5169955 | 2001-01-25 01:48:31 |
  50. +---------+---------------------+
  51. 1 row in set (0.00 sec)
  52. mysql> select max(id),now() from sbtest1;
  53. +---------+---------------------+
  54. | max(id) | now() |
  55. +---------+---------------------+
  56. | 5172245 | 2001-01-25 01:48:33 |
  57. +---------+---------------------+
  58. 1 row in set (0.00 sec)
  59. mysql> select max(id),now() from sbtest1;
  60. +---------+---------------------+
  61. | max(id) | now() |
  62. +---------+---------------------+
  63. | 5174269 | 2001-01-25 01:48:36 |
  64. +---------+---------------------+
  65. 1 row in set (0.00 sec)
  66. mysql> select max(id),now() from sbtest1;
  67. +---------+---------------------+
  68. | max(id) | now() |
  69. +---------+---------------------+
  70. | 5175955 | 2001-01-25 01:48:38 |
  71. +---------+---------------------+
  72. 1 row in set (0.00 sec)

why?

经过与同事重新仔细确认，唯一的差别就是sysbench的测试命令不同（sysbench是同事编译安装的，我没注意到这个细节，阴差阳错造成了使用了不同的lua脚本）

点击(此处)折叠或打开

  1. # 我的是使用的安装目录/usr/local/share/sysbench目录下的oltp.lua脚本
  2. sysbench --test=/usr/local/share/sysbench/tests/include/oltp_legacy/oltp.lua --mysql-table-engine=innodb --mysql-db=sysbench_test --oltp-table-size=5000000 --oltp-tables-count=8 --mysql-host=172.16.130.2 --mysql-port=3307 --mysql-user=root --mysql-password='password' --report-interval=1 --threads=256 --time=3600 run
  3. # 同事的直接使用了编译目录/root/sysbench/sysbench-1.0.9下的oltp.lua脚本
  4. sysbench

经过对比两个lua脚本文件的差异，发现有一行不相同

点击(此处)折叠或打开

  1. # 我的
  2. for i=1, oltp_delete_inserts do
  3. i = sb_rand(1, oltp_table_size)
  4. rs = db_query("DELETE FROM " .. table_name .. " WHERE id=" .. i)
  5. c_val = sb_rand_str([[
  6. ###########-###########-###########-###########-###########-###########-###########-###########-###########-###########]])
  7. pad_val = sb_rand_str([[
  8. ###########-###########-###########-###########-###########]])
  9. ## 不同的地方在这里，由于为了避免主键冲突，把lua生成的随机主键值i变量删了，让数据库利用表自身的自增属性来填充主键值
  10. rs = db_query("INSERT INTO " .. table_name .. " ( k, c, pad) VALUES " .. string.format("(%d, '%s', '%s')",sb_rand(1, oltp_table_size) , c_val, pad_val))
  11. end
  12. # 同事的
  13. for i=1, oltp_delete_inserts do
  14. i = sb_rand(1, oltp_table_size)
  15. rs = db_query("DELETE FROM " .. table_name .. " WHERE id=" .. i)
  16. c_val = sb_rand_str([[
  17. ###########-###########-###########-###########-###########-###########-###########-###########-###########-###########]])
  18. pad_val = sb_rand_str([[
  19. ###########-###########-###########-###########-###########]])
  20. ## 同事的并未改动这一行，默认情况下，自增主键值是使用lua脚本生成的i变量(即1, oltp_table_size之间的随机数 )
  21. rs = db_query("INSERT INTO " .. table_name .. " (id, k, c, pad) VALUES " .. string.format("(%d, %d, '%s', '%s')",i, sb_rand(1, oltp_table_size) , c_val, pad_val))
  22. end

|  结论推导

仔细看第3节中的lua脚本代码，delete和insert两个操作被放进了同一个for循环中（其他的update_index和update_non_index是各自单独的一个for循环，互不影响），也就是说：

  • 使用lua脚本随机生成主键值时：假设当delete操作删除id=1的数据行时，紧接着insert也会使用相同的id=1的主键值。所以高概率会出现innodb重复使用delete数据行所在的页来存放insert数据，在sysbench高并发压力下，大部分的insert数据存储可能只需要在内存中已存在的页内操作即可，无需太多IO操作

  • 不使用lua脚本随机生成的主键值，而是使用表的自增属性生成主键值时：假设当delete操作删除id=1的数据行时，紧接着insert由于是表自增属性自己生成，也就是说几乎不太可能id=1，所以高概率会出现innodb重新申请一个数据页来写入insert数据，在sysbench高并发压力下，大部分的insert数据存储可能需要从磁盘文件中重新申请空间，IO操作较为频繁

至此，我和同事的压测结果有巨大差异的原因大致确定，后续经过反复的验证，也确认了是由于oltp.lua脚本的微小差异导致的。由于我们大多数时候都是使用的本地盘，而本地盘IO延迟低，通常情况下sysbench压测时这点微小的差异容易被忽略。而在此案例中，由于我们测试的环境中使用了某存储设备，相对于本地盘，IO延迟大大增加，进而造成了因为oltp.lua脚本的微小差异而导致最后压测结果的巨大差异。

提示：如果不想改动lua脚本，又想避免主键冲突有办法解决吗？有的，从sysbench 0.5版本开始，新增了一个隐藏选项--mysql-ignore-errors，用于忽略指定的错误，如果要避免主键冲突，指定选项--mysql-ignore-errors=1062 即可。


|  作者简介

罗小波·沃趣科技高级数据库技术专家

IT从业多年，历任运维工程师、高级运维工程师、运维经理、数据库工程师，曾参与版本发布系统、轻量级监控系统、运维管理平台、数据库管理平台的设计与编写，熟悉MySQL体系结构，Innodb存储引擎，喜好专研开源技术，追求完美。


来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/28218939/viewspace-2155345/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/28218939/viewspace-2155345/

congcheng1062
关注
  • 0
    点赞
  • 踩
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
sysbench-lua文件包
06-09
01. common.lua 02. delete.lua 03. insert.lua 04. oltp.lua 05. parallel_prepare.lua 06. select.lua 07. select_random_points.lua 08. select_random_ranges.lua 09. update_index.lua 10. update_non_index.lua 此外还有 11. oltp_simple.lua 12. newrelic.lua
从sysbench中学习Lua
congbao6525的博客
12-06 267
我做事喜欢结果导向，喜欢快速迭代，能10分钟搞定，绝对不愿意花15分钟。但是技术行当，还是得耐得住寂寞，因为很多事情10分钟搞不定，可能100分钟，1000分钟也搞不定，但是不代表我们真搞不定，需要花一些时间...
sysbench安装与使用 部分脚本修改
mm1277663638的专栏
10-30 1002
1. 编译安装 Shell>pwd /home/nocode Shell> bzr branch lp:~sysbench-developers/sysbench/0.5  sysbench Shell> cd sysbench Shell> ./autogen.sh Shell> ./configure Shell> make Shell> sud
SYSBench测试icelack和cascade CPU性能差异太大
py199122的博客
08-31 1193
一：问题现象 同事在使用sysbench工具测试cpu性能时发现，icelack和cascade lack两种CPU的性能差别太大，如下图所示，左侧代表icelack，右侧代表cascade（注：本文大部分图片都是对比性的，默认左侧为icelack，右侧为cascade）。 通过计算发现相差2.33倍，这数据一看就不科学。 直接对比两种CPU，icelack的频率2299是低于cascade2399，所以cascade的CPU cycle是更快，指令执行的速度也更快才合理，带着这些疑问进一步分析s
sysbench 自带的Lua脚本
十五十六
08-06 7775
文章目录sysbench 自带的Lua脚本Lua脚本读写性能测试语句oltp_common.luabulk_insert.luaoltp_delete.luaoltp_insert.luaoltp_point_select.luaoltp_read_only.luaoltp_read_write.luaoltp_update_index.luaoltp_update_non_index.luaol...
性能测试sysbench.rar
05-22
在大多数Linux发行版中，sysbench依赖于一些库，如libmysqlclient（如果要进行MySQL性能测试）、Lua等。确保这些依赖已经安装，然后执行： ``` ./configure make sudo make install ``` sysbench的主要功能包括CPU...
性能测试工具sysbench简介
03-23
性能测试工具sysbench简介.您现在的位置：首页-->Oracle-->性能测试工具sysbench简介性能测试工具sysbench简介出处信息sysbench是一款开源的多线程性能测试工具，可以执行CPU/内存/线程/IO/数据库等方面的性能...
数据库工具sysbench安装教程和性能测试例子
09-10
sysbench 提供了全面的基准测试方案，包括 CPU 性能、磁盘 I/O 性能、调度器性能、内存分配与传输速度、POSIX 线程性能以及数据库的在线事务处理（OLTP）性能测试。 ### 安装 sysbench 1. **下载源码**：从 ...
Sysbench多线程性能测试工具
09-10
总的来说，`Sysbench`是评估MySQL数据库性能的强大工具，其丰富的测试选项和灵活的`Lua`脚本支持，使得性能优化工作更为高效和精确。通过对测试结果的深入分析，可以有效地识别和解决性能问题，提升系统整体性能。
sysbench使用及自定义oltp测试lua脚本
热门推荐
hubo890224的专栏
07-31 1万+
sysbench的安装使用，几使用自定义lua脚本进程oltp测试
sysbench和lua的简单研究
yanhuang_cn的博客
05-21 1715
精力有限，所以先专注Mysql（等Mysql精通后研究TiDB），先从sysbench-0.4.12.14开始 - https://dev.mysql.com/downloads/benchmarks.html create database sbtest; grant all privileges on sbtest.* to test@‘localhost’ identified by ‘W...
mysql能抗住多少tps_使用Sysbench对MySQL进行压力测试
weixin_39639174的博客
12-05 937
微信公众号：Whcat关注我可了解更多的Java技术干货。问题或建议，请公众号留言;如果你觉得本篇文章对你有帮助，请帮忙点一下在看，谢谢！｜前言sysbench是一个模块化、跨平台、多线程基准测试工具，主要用于评估测试各种不同系统参数下的数据库负载情况。sysbench目前支持对MySQL/Oracle/PostgreSQL数据库进行基准测试。除了sysbench外，可以对数据库...
和lua的效率对比测试_2021001期：Sysbench多线程性能测试工具
weixin_29196613的博客
01-09 187
Sysbench一款开源的多线程性能测试工具，可提供以下几个方面的测试：cpu ：提供一个简单的cpu测试fileIo：文件磁盘io的测试memory：内存分配及传输速度thread：线程调度测试mutex：POSIX的锁测试OLTP：数据库性能，主要支持MYSQL, PgSQL, Oracle 这3种数据库安装详看git， 当前操作的Sysbench版本是1.0.17命令1sysben...
sysbench压测使用问题记录
敖尔其楞的专栏
05-10 3105
在使用sysbench0.4进行压测的过程中发现，如果在单用户并发下，如果指定了不同的，oltp-table-size及oltp-tables-count，得到的结果偏差很大，在测试不同的用户并发的时候，需要根据情况指定不同的oltp-tables-count 值。...
MySQL 存储过程性能测试(Sysbench自定义lua脚本)
nayanminxing的专栏
12-06 4878
安装sysbench sysbench的OLTP测试 几个重要参数解读 lua脚本解析 commonlua oltp_simplelua oltplua 自定义lua脚本的结构 自定义lua脚本的测试过程 测试存储过程 入职新公司，领导给的第一个任务就是说：我们打算在业务里面上存储过程，但是据说存储过程性能不好，所以你来出一个测试方案测试一下，额，刚拿到需求的时候懵懵哒，第一，我还真不知道存储过
sysbench基准测试（2）——oltp.lua测试
weixin_33782386的博客
10-09 310
前面知道sysbench基准测试的主要步骤为：prepare（准备数据集）→ run（运行测试）→ cleanup（清除数据集） 这一节介绍oltp.lua测试。 oltp基准测试模拟了一个简单的事物处理系统的工作负载。 ①、准备数据集（使用test数据库，用户名root，密码123456，表数目8，每张表记录10万，测试oltp.lua）： [root@loc...
测试软件：sysbench-oltp（1）
crj2951的博客
08-01 113
1、数据库基准测试OLTP，在sysbench 0.5版本中，可使用了lua脚本进行测试，也可以根据业务需求自定义lua脚本进行测试。 2、在测试之前先查看oltp.lua脚本 dofile(pa...
sysbench花式采坑之二：自增值导致的主键冲突
woqutechteam的博客
11-23 1499
上期《sysbench花式采坑之一：自增值导致的TPS不可靠》介绍到，在sysbench压测过程中，如果自增值不为1会导致性能测试值偏高的现象，其实在发现这个现象之前，在单实例性能测试时我还遇到了一个主键冲突的问题。 | MySQL单实例sysbench压测时出现主键冲突 《sysbench花式采坑之一：自增值导致的TPS不可靠》这篇文章里解释了sysbench关于插入的操作是先随机生一个id...
Linux性能优化（二）——sysbench压力测试工具
天山老妖
02-23 4772
一、sysbench简介 1、sysbench简介 sysBench是一个模块化的、跨平台、多线程基准测试工具，主要用于评估测试各种不同系统参数下的数据库负载情况。sysbench提供如下测试： （1）CPU性能 （2）磁盘IO性能 （3）调度程序性能 （4）内存分配及传输速度 （5）POSIX线程性能 （6）数据库性能(OLTP基准测试) sysbench支持MySQL、PostgreSQL、Oracle数据库。 2、sysbench安装 Build构建依赖安装： yum...
RHEL6 Sysbench性能测试.docx
10-30
本文主要介绍了在RHEL6.1系统上使用sysbench进行性能测试的过程。sysbench是一款开源的多线程性能测试工具，可以用于执行CPU、内存、线程、IO、数据库等方面的性能测试。目前支持的数据库有MySQL、Oracle和...

“相关推荐”对你有帮助么？

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值