1

I have one webserver running Magento : Community Edition 1.7.0.2 and a separate machine with MySQL 5.5.42 on it.

Both machines are EC2 instances.

I am seeing huge unexpected data traffic from the MySQL server to the web server - approximately 400 Mbps for (mostly) an hour which completely occupies the CPU of the web server. There also seems to be a mismatch between the data reported by CloudWatch and IPTraf.

We're trying to diagnose the issue - what can I run which will help identify why this is happening?

Observations:

  1. As per CloudWatch, the Magento webserver seems to receive 400MBps of data (at certain times) - screenshot 1
  2. As per IPTraf, the Magento webserver seems to receive only 50MBps - screenshot 2
  3. As per CloudWatch, the MySQL webserver seems to send 400MBps of data (at certain times) - screenshot 3

Screenshot 1 20151217-MagentoWebsite-server-CloudWatch-traffic-in

Screenshot 2 20151217-MagentoWebsite-server-iptraf-traffic

Screenshot 3 20151217-MySQL-server-CloudWatch-traffic-out

Others:

20151217-MySQL-server-CloudWatch-traffic-in

20151217-MySQL-server-iptraf-traffic

EDIT1

During the high data traffic to the webserver, the htop output is as follows (on the MySQL server):

(I think very temporarily it shows up as high CPU usage)

20151217-MySQL-server-htop-during-high-web-server-load-1

Mostly it's like this: 20151217-MySQL-server-htop-during-high-web-server-load-2

EDIT2:

top command output on MySQL server while high CPU load on web server

top - 00:08:54 up 28 days, 23:46,  2 users,  load average: 0.07, 0.06, 0.07
Tasks:  97 total,   1 running,  96 sleeping,   0 stopped,   0 zombie
Cpu(s): 11.2%us,  1.2%sy,  0.0%ni, 86.8%id,  0.6%wa,  0.0%hi,  0.2%si,  0.1%st
Mem:  31420088k total, 30966400k used,   453688k free,   166384k buffers
Swap:  4194300k total,    61328k used,  4132972k free,  8084828k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                     
13387 mysql     20   0 25.6g  21g 6884 S 17.9 70.5 263:34.95 mysqld                      
    1 root      20   0 19596 1068  828 S  0.0  0.0   0:02.09 init                        
    2 root      20   0     0    0    0 S  0.0  0.0   0:00.01 kthreadd                    
    3 root      20   0     0    0    0 S  0.0  0.0   0:13.48 ksoftirqd/0                 
    5 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 kworker/0:0H                
    7 root      20   0     0    0    0 S  0.0  0.0  20:42.18 rcu_sched                   
    8 root      20   0     0    0    0 S  0.0  0.0   0:00.00 rcu_bh                      
    9 root      RT   0     0    0    0 S  0.0  0.0   0:00.54 migration/0                 
   10 root      RT   0     0    0    0 S  0.0  0.0   0:00.46 migration/1                 
   11 root      20   0     0    0    0 S  0.0  0.0   0:44.45 ksoftirqd/1                 
   13 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 kworker/1:0H                
   14 root      RT   0     0    0    0 S  0.0  0.0   0:01.48 migration/2                 
   15 root      20   0     0    0    0 S  0.0  0.0   0:44.13 ksoftirqd/2                 
   17 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 kworker/2:0H                
   18 root      RT   0     0    0    0 S  0.0  0.0   0:01.44 migration/3                 
   19 root      20   0     0    0    0 S  0.0  0.0   0:12.68 ksoftirqd/3                 
   21 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 kworker/3:0H                
   22 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 khelper                     
   23 root      20   0     0    0    0 S  0.0  0.0   0:00.00 kdevtmpfs                   
   24 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 netns                       
   31 root      20   0     0    0    0 S  0.0  0.0   0:00.04 xenwatch                    
   32 root      20   0     0    0    0 S  0.0  0.0   0:00.00 xenbus                      
  130 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 writeback                   
  133 root      25   5     0    0    0 S  0.0  0.0   0:00.00 ksmd                        
  134 root      39  19     0    0    0 S  0.0  0.0   0:00.00 khugepaged                  
  135 root       0 -20     0    0    0 S  0.0  0.0   0:00.00 kintegrityd                 

EDIT3

I ran the following (during the heavy traffic phase) to track the MySQL processes, but there was nothing amiss in the results. The queries mentioned were all "fine" - nothing which could explain this really odd behavior.

mysqladmin -u DATABASEUSER -p -hIPADDRESS -i 1 --verbose processlist > /tmp/mysql-processlist3.txt

Have a look at the initial output (which WAS during the heavy traffic phase). Edited to remove redundancy.

+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+
| Id     | User         | Host              | db            | Command | Time | State | Info                  |
+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+
| 113267 | DATABASEUSER | IPADDRESS_1:55847 | DATABASE_NAME | Sleep   | 12   |       |                       |
| 113297 | DATABASEUSER | IPADDRESS_1:55942 | DATABASE_NAME | Sleep   | 0    |       |                       |
...
| 113310 | DATABASEUSER | IPADDRESS_1:55978 | DATABASE_NAME | Sleep   | 0    |       |                       |
| 113311 | DATABASEUSER | IPADDRESS_1:55982 |               | Query   | 0    |       | show full processlist |
+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+

+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+
| Id     | User         | Host              | db            | Command | Time | State | Info                  |
+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+
| 113267 | DATABASEUSER | IPADDRESS_1:55847 | DATABASE_NAME | Sleep   | 13   |       |                       |
| 113301 | DATABASEUSER | IPADDRESS_1:55952 | DATABASE_NAME | Sleep   | 0    |       |                       |
...
| 113310 | DATABASEUSER | IPADDRESS_1:55978 | DATABASE_NAME | Sleep   | 0    |       |                       |
| 113311 | DATABASEUSER | IPADDRESS_1:55982 |               | Query   | 0    |       | show full processlist |
| 113312 | DATABASEUSER | IPADDRESS_1:55985 | DATABASE_NAME | Sleep   | 0    |       |                       |
...
+--------+--------------+-------------------+---------------+---------+------+-------+-----------------------+
...
9 such instances (as above)
...

+--------+--------------+-------------------+---------------+---------+------+----------+----------------------------------------------------------------------+
| Id     | User         | Host              | db            | Command | Time | State    | Info                                                                 |
+--------+--------------+-------------------+---------------+---------+------+----------+----------------------------------------------------------------------+
| 113267 | DATABASEUSER | IPADDRESS_1:55847 | DATABASE_NAME | Sleep   | 23   |          |                                                                      |
| 113311 | DATABASEUSER | IPADDRESS_1:55982 |               | Query   | 0    |          | show full processlist                                                |
| 113333 | DATABASEUSER | IPADDRESS_1:56047 | DATABASE_NAME | Sleep   | 0    |          |                                                                      |
| 113334 | DATABASEUSER | IPADDRESS_1:56050 | DATABASE_NAME | Query   | 0    | updating | DELETE FROM `tablecore_session` WHERE (session_expires < 1450397372) |
| 113335 | DATABASEUSER | IPADDRESS_1:56054 | DATABASE_NAME | Sleep   | 0    |          |                                                                      |
...
| 113346 | DATABASEUSER | IPADDRESS_1:56088 | DATABASE_NAME | Sleep   | 0    |          |                                                                      |
+--------+--------------+-------------------+---------------+---------+------+----------+----------------------------------------------------------------------+

... ... ...

EDIT4

During the high data traffic to the webserver, the htop output is as follows (on the Magento / web server):

top - 12:17:31 up 4 days, 19:59,  6 users,  load average: 12.92, 11.89, 8.21
Tasks: 193 total,  16 running, 176 sleeping,   0 stopped,   1 zombie
Cpu(s): 93.5%us,  3.7%sy,  0.0%ni,  2.2%id,  0.0%wa,  0.0%hi,  0.6%si,  0.0%st
Mem:  15406732k total, 15202500k used,   204232k free,  1413660k buffers
Swap:  2097148k total,    27516k used,  2069632k free, 10080992k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
16939 apache    20   0  594m 100m  64m R 54.2  0.7   4:14.04 php-fpm
16368 apache    20   0  613m 135m  83m R 53.5  0.9   7:23.11 php-fpm
16742 apache    20   0  592m 126m  80m R 53.2  0.8   5:13.40 php-fpm
16872 apache    20   0  503m 100m  70m R 53.2  0.7   5:07.95 php-fpm
16744 apache    20   0  599m 114m  74m R 52.5  0.8   5:45.73 php-fpm
17185 apache    20   0  508m  90m  55m R 51.8  0.6   1:31.18 php-fpm
17312 apache    20   0  502m  70m  40m R 51.8  0.5   0:06.46 php-fpm
16695 apache    20   0  514m 114m  74m R 51.2  0.8   6:15.36 php-fpm
16626 apache    20   0  610m 134m  83m R 50.8  0.9   5:41.57 php-fpm
17073 apache    20   0  599m 121m  68m R 50.8  0.8   2:57.10 php-fpm
17088 apache    20   0  506m  90m  57m R 50.8  0.6   2:47.49 php-fpm
17018 apache    20   0  581m  99m  64m R 50.5  0.7   3:21.40 php-fpm
16749 apache    20   0  596m  99m  62m R 49.2  0.7   5:30.00 php-fpm
16766 apache    20   0  789m 302m  72m R 47.8  2.0   5:42.89 php-fpm
16736 apache    20   0  592m 122m  78m R 44.2  0.8   5:52.52 php-fpm
17347 root      20   0     0    0    0 Z  3.7  0.0   0:00.11 /do_web/webmin- <defunct>
12198 root      20   0  117m 3356 2648 S  2.0  0.0   1:17.01 htop
17348 root      20   0  112m 7460 6368 S  1.7  0.0   0:00.05 sshd
32098 root      20   0     0    0    0 S  1.7  0.0   0:31.38 kworker/u16:0
 6527 do_ssh_a  20   0  117m 3372 2524 S  1.3  0.0  41:25.85 htop
11820 do_ssh_a  20   0  117m 3728 2752 S  1.3  0.0   1:04.59 htop
13854 do_ssh_a  20   0  119m 5256 2616 S  1.3  0.0   0:49.03 htop
14045 do_ssh_a  20   0  117m 3356 2756 S  1.3  0.0   0:42.00 htop
17346 do_ssh_a  20   0 15268 2248 1872 R  0.7  0.0   0:00.02 top
    7 root      20   0     0    0    0 S  0.3  0.0   8:01.96 rcu_sched

EDIT5

Full processlist output (which was referred to in EDIT3) is at: http://pastebin.com/7QBwnAW3

EDIT6

The difference in the data transfer speeds reported by iptraf and CloudWatch has been resolved. CloudWatch reports speeds per minute (as per email from AWS helpdesk inquiry), so:

As per CloudWatch,

we are consuming ~400 million (not mega) bytes per minute, 
so 400/60 = 6.66 million bytes per second, 
which is 6666 kilo bytes per second, 
which at 8 bits per byte is: 53328 kilo bits per second.
  • In EDIT1, is the high VIRT and RES column values fine? As per mugurel.sumanariu.ro/linux/… "RES stands for the resident size, which is an accurate representation of how much actual physical memory a process is consuming. " – siliconpi Dec 18 '15 at 0:39
0

While the thing is happening, go into mysql and do SHOW FULL PROCESSLIST;. That will say what is doing lots of I/O.

top, VIRT, etc, provide noting useful for tracking down what MySQL is doing.

Also, turn on the slowlog and have long_query_time=1. After a while, the slowlog will probably provide the answer.

  • Strange. DELETE FROM tablecore_session WHERE (session_expires < 1450397372) is the only thing that would be sending any data. And it sends virtually nothing. Were you connected with SUPER priv when you ran that? Otherwise, you only see your own connections. – Rick James Dec 18 '15 at 17:42
  • 1
    Is the Cloud service doing a backup? – Rick James Dec 18 '15 at 17:42

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.