Comment 8 for bug 1380895

Revision history for this message
Paul Namuag (paul-namuag) wrote :

# mysqld --version
mysqld Ver 5.5.40-36.1-log for Linux on x86_64 (Percona Server (GPL), Release 36.1, Revision 707)

UPON START:
====================
top - 06:12:54 up 1 min, 1 user, load average: 0.00, 0.00, 0.00
Tasks: 92 total, 1 running, 91 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.0%us, 0.3%sy, 0.0%ni, 99.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 15137652k total, 528752k used, 14608900k free, 27688k buffers
Swap: 2064376k total, 0k used, 2064376k free, 61304k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 1612m 249m 5796 S 0.3 1.7 0:00.81 mysqld

free -m:

             total used free shared buffers cached
Mem: 14782 555 14227 0 27 63
-/+ buffers/cache: 464 14318
Swap: 2015 0 2015

vmstat -Sm 2:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 0 0 0 14914 28 66 0 0 467 10 101 177 1 2 97 0 0
 0 0 0 14914 28 66 0 0 0 0 50 64 0 0 100 0 0
 0 0 0 14914 28 66 0 0 0 18 44 51 0 0 100 0 0

AFTER A WHILE:
==================

top - 06:23:04 up 11 min, 7 users, load average: 1.02, 0.67, 0.28
Tasks: 126 total, 1 running, 125 sleeping, 0 stopped, 0 zombie
Cpu(s): 61.7%us, 38.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.3%hi, 0.0%si, 0.0%st
Mem: 15137652k total, 5942004k used, 9195648k free, 28636k buffers
Swap: 2064376k total, 0k used, 2064376k free, 2509120k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 3468m 2.9g 7284 S 99.4 20.1 4:24.12 mysqld

show processlist:

+----+------+-----------+------+---------+------+----------------------+---------+
| id | user | host | db | command | time | state | time_ms |
+----+------+-----------+------+---------+------+----------------------+---------+
| 1 | root | localhost | NULL | Query | 289 | checking permissions | 288799 |
+----+------+-----------+------+---------+------+----------------------+---------+

free -m:

             total used free shared buffers cached
Mem: 14782 5372 9410 0 27 2450
-/+ buffers/cache: 2894 11888
Swap: 2015 0 2015

vmstat -Sm 2:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 1 0 0 9455 29 2569 0 0 0 0 1000 79 61 39 0 0 0
 1 0 0 9414 29 2569 0 0 0 30 1012 87 62 39 0 0 0
 1 0 0 9373 29 2569 0 0 0 0 1005 70 60 40 0 0 0
 1 0 0 9332 29 2569 0 0 0 0 1008 73 61 39 0 0 0
 1 0 0 9291 29 2569 0 0 0 24 1010 95 63 37 0 0 0
 1 0 0 9250 29 2569 0 0 0 0 1009 71 61 40 0 0 0

top:

top - 06:34:09 up 22 min, 7 users, load average: 1.17, 1.03, 0.66
Tasks: 126 total, 1 running, 125 sleeping, 0 stopped, 0 zombie
Cpu(s): 58.2%us, 40.1%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.7%hi, 1.0%si, 0.0%st
Mem: 15137652k total, 14978772k used, 158880k free, 2744k buffers
Swap: 2064376k total, 1566652k used, 497724k free, 11140k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 16.5g 14g 2408 S 95.5 97.1 15:20.07 mysqld

show processlist:

+----+------+-----------+------+---------+------+----------------------+---------+
| id | user | host | db | command | time | state | time_ms |
+----+------+-----------+------+---------+------+----------------------+---------+
| 1 | root | localhost | NULL | Query | 983 | checking permissions | 982983 |
+----+------+-----------+------+---------+------+----------------------+---------+

free -m:

             total used free shared buffers cached
Mem: 14782 14645 137 0 2 12
-/+ buffers/cache: 14629 152
Swap: 2015 1654 361

vmstat:
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 2 0 1011 149 2 13 0 20 376 19504 1085 173 54 46 0 0 0
 1 0 1051 152 2 14 0 20 232 19574 1083 161 55 45 0 1 0
...
 2 0 1859 155 2 15 0 0 552 30 1031 124 57 43 0 0 0
 1 2 1913 143 2 14 0 27 476 26462 927 170 48 37 0 14 0
 2 2 1914 145 3 12 0 1 7444 668 704 1176 3 8 0 89 0

This is the last part where OOM is triggered:
======================================

top (before OOM is triggered):
top - 06:34:55 up 23 min, 7 users, load average: 1.89, 1.23, 0.74
Tasks: 116 total, 1 running, 115 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.3%us, 69.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.7%hi, 29.3%si, 0.0%st
Mem: 15137652k total, 15008428k used, 129224k free, 120k buffers
Swap: 2064376k total, 2064376k used, 0k free, 2372k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 17.1g 14g 60 S 84.9 97.5 15:58.04 mysqld

processlist (before OOM is triggered):

+----+------+-----------+------+---------+------+----------------------+---------+
| id | user | host | db | command | time | state | time_ms |
+----+------+-----------+------+---------+------+----------------------+---------+
| 1 | root | localhost | NULL | Query | 1025 | checking permissions | 1024345 |
+----+------+-----------+------+---------+------+----------------------+---------+

free -m (before OOM is triggered):

             total used free shared buffers cached
Mem: 14782 14653 129 0 2 10
-/+ buffers/cache: 14641 141
Swap: 2015 2015 0

vmstat (before OOM is triggered):

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 2 0 1011 149 2 13 0 20 376 19504 1085 173 54 46 0 0 0
 1 0 1051 152 2 14 0 20 232 19574 1083 161 55 45 0 1 0
 1 1 1085 150 2 13 0 17 372 16742 1072 183 59 42 0 0 0
 1 1 1124 151 2 10 0 20 1104 19236 1108 244 54 46 0 0 0
...
 2 0 1479 160 2 11 0 26 742 25366 1115 203 57 43 0 0 0
 1 1 1505 150 2 11 0 13 1120 12830 1091 228 60 40 0 0 0
 1 0 1546 150 2 12 0 20 356 19798 1083 176 57 43 0 0 0
 1 1 1582 149 2 11 0 18 582 17718 1086 197 58 42 0 0 0
...
 1 0 2098 173 2 9 0 26 532 25674 1107 226 53 47 0 0 0
 2 1 2110 150 2 8 0 6 914 6262 1067 187 57 43 0 0 0
 1 1 2113 137 2 8 0 2 1688 1470 1062 236 59 41 0 0 0
...
 3 2 2113 132 0 2 0 0 49628 524 3480 3773 0 100 0 0 0
 2 1 2113 132 0 1 0 0 171710 290 5093 6770 1 99 0 1 0
 3 4 2113 132 0 1 0 0 204980 102 4558 5691 0 100 0 0 0
 1 10 2113 139 0 3 1 2 171168 2180 5193 7528 1 95 0 4 0

iostat (before OOM is triggered):

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 713.04 797.83 4342.39 158.70 289386.96 7691.30 66.00 17.65 3.96 0.21 95.71
dm-0 0.00 0.00 4071.20 30.98 253908.70 247.83 61.96 10.74 2.63 0.20 81.52
dm-1 0.00 0.00 369.57 886.41 2956.52 7091.30 8.00 28.59 22.90 0.46 57.99

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 870.76 2369.59 3588.89 247.95 159054.97 21113.45 46.96 16.69 4.30 0.23 87.08
dm-0 0.00 0.00 3826.90 38.60 153974.27 308.77 39.91 5.00 1.29 0.21 81.35
dm-1 0.00 0.00 635.09 2600.58 5080.70 20804.68 8.00 214.77 66.38 0.22 72.28

dm-0 is the device where mysql data resides
dm-1 is the swap space

When state is "checking permissions" disk i/o is very low except when swap space is used as seen above. If sending data/opening tables, it’s high.