MySql inserts high CPU load

Question

I have nginx receiving POST requests and a tiny PHP script that puts request body to MySql. The problem is very high MySql CPU usage when I have 300 POSTs per second. I expected MySql to be a fast thing that can handle much more that 300 inserts per second. I use Amazon EC2 small instance, Amazon Linux.

top - 18:27:06 up 3 days,  1:43,  2 users,  load average: 4.40, 5.39, 5.76
Tasks: 178 total,   4 running, 174 sleeping,   0 stopped,   0 zombie
Cpu(s): 24.6%us, 13.4%sy,  0.0%ni,  0.0%id,  1.1%wa,  0.0%hi,  4.9%si, 56.0%st
Mem:   1717480k total,  1640912k used,    76568k free,   193364k buffers
Swap:   917500k total,     5928k used,   911572k free,   824136k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 7677 mysql     20   0  313m 153m 6124 S 39.0  9.2 393:49.11 mysqld
16529 nginx     20   0  157m 151m  820 R 15.2  9.0  28:36.50 nginx
29793 php       20   0 36780 3240 1896 S  2.5  0.2   0:00.34 php-fpm
29441 php       20   0 36780 3204 1892 S  2.2  0.2   0:00.78 php-fpm
29540 php       20   0 36780 3204 1900 S  2.2  0.2   0:00.82 php-fpm
29603 php       20   0 36780 3220 1892 S  2.2  0.2   0:00.61 php-fpm
29578 php       20   0 36780 3200 1900 S  1.9  0.2   0:00.42 php-fpm
29950 php       20   0 36780 3192 1900 S  1.9  0.2   0:00.48 php-fpm
30030 php       20   0 36780 3180 1888 S  1.9  0.2   0:00.08 php-fpm
30025 php       20   0 36780 3200 1888 S  1.6  0.2   0:00.11 php-fpm
29623 php       20   0 36780 3184 1892 S  1.3  0.2   0:00.49 php-fpm
29625 php       20   0 36780 3236 1900 S  1.3  0.2   0:00.46 php-fpm
29686 php       20   0 36780 3364 1900 R  1.3  0.2   0:00.51 php-fpm
29863 php       20   0 36780 3184 1892 S  1.3  0.2   0:00.23 php-fpm
30018 php       20   0 36780 3192 1892 S  1.3  0.2   0:00.19 php-fpm
29607 php       20   0 36780 3224 1900 S  1.0  0.2   0:00.42 php-fpm
29729 php       20   0 36780 3180 1888 R  1.0  0.2   0:00.41 php-fpm

Here is my PHP code:

<?php
    $mysqli=new mysqli("localhost", "root", "", "errorreportsraw");
    $project_id=$_REQUEST["project_id"];
    $data=$_REQUEST["data"];
    $date=date("Y-m-d H-i-s");
    $mysqli->query("insert into rawreports(date, data, project_id) values ('$date', '$data', '$project_id')")
?>

I tried mysql_connect, mysql_pconnect, mysqli("localhost",...), mysqli("p:localhost", ...) - still the same. No queries are running against the database except these inserts.

Here's my table:

CREATE TABLE `rawreports` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `date` datetime NOT NULL,
  `data` mediumtext NOT NULL,
  `project_id` varchar(100) NOT NULL,
  PRIMARY KEY (`id`)
);

It's pretty simple, no indexes, just to store the POST data for later processing. 'data' field is something about 3 kilobytes in most cases. Tried innodb and myisam - still the same.

Here's my SHOW PROCESSLIST, nothing except multiple inserts:

mysql> show processlist;
+---------+----------------------+-----------+-----------------+---------+------+------------------+------------------------------------------------------------------------------------------------------+
| Id      | User                 | Host      | db              | Command | Time | State            | Info                                                                                                 |
+---------+----------------------+-----------+-----------------+---------+------+------------------+------------------------------------------------------------------------------------------------------+
| 3872248 | root                 | localhost | NULL            | Query   |    0 | NULL             | show processlist                                                                                     |
| 3901991 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902003 | root                 | localhost | errorreportsraw | Sleep   |    0 |                  | NULL                                                                                                 |
| 3902052 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902053 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902054 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902055 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902056 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902057 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902058 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902059 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902060 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"protocol_version":" |
| 3902061 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902062 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902063 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902064 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902065 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902066 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902067 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902068 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902069 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902070 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902071 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902072 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902073 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902074 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902075 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902076 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902077 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902078 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902079 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902080 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902081 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902082 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902083 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902084 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902085 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902086 | root                 | localhost | errorreportsraw | Query   |    0 | update           | insert into rawreports(date, data, project_id) values ('2012-05-05 17-01-37', '{"exceptions":[{"stac |
| 3902087 | unauthenticated user | localhost | NULL            | Connect | NULL | Reading from net | NULL                                                                                                 |
+---------+----------------------+-----------+-----------------+---------+------+------------------+------------------------------------------------------------------------------------------------------+
39 rows in set (0.00 sec)

Here's the PROFILE when I do the same insert manually while server is still under pressure:

set profiling=1;
insert into rawreports(date, data, project_id) values('2012-05-04 00:58:08','[3000-chars-data-here]','5');
show profile ALL for query 1;

Status                          Duration    CPU_user    CPU_system  Context_voluntary    Context_involuntary    Block_ops_in    Block_ops_out   Messages_sent   Messages_received   Page_faults_major   Page_faults_minor   Swaps   Sourc
starting                        0.000231    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       NULL    NULL    NULL
checking permissions            0.000030    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       check_access    sql_parse.cc    4745
Opening tables                  0.000057    0.001000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       open_tables     sql_base.cc     4836
System lock                     0.000030    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       mysql_lock_tables       lock.cc 299
init                            0.000037    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       mysql_insert    sql_insert.cc   721
update                          0.075716    0.001999    0.011998    166                  2                      0               0               0               0                   0                   0                   0       mysql_insert    sql_insert.cc   806
Waiting for query cache lock    0.000087    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       lock    sql_cache.cc    552
update                          0.000037    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       NULL    NULL    NULL
end                             0.000024    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       mysql_insert    sql_insert.cc   1049
query end                       0.000042    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       mysql_execute_command   sql_parse.cc    4434
closing tables                  0.000031    0.000000    0.001000    0                    0                      0               0               0               0                   0                   0                   0       mysql_execute_command   sql_parse.cc    4486
freeing items                   0.000126    0.000000    0.000000    0                    1                      0               0               0               0                   0                   0                   0       mysql_parse     sql_parse.cc    5634
logging slow query              0.000030    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       log_slow_statement      sql_parse.cc    1460
cleaning up                     0.000024    0.000000    0.000000    0                    0                      0               0               0               0                   0                   0                   0       dispatch_command        sql_parse.cc    1416

I use MySql 5.5.20. Tried both InnoDB and MyISAM - both the same.
Here's my iostat output:

# iostat -x
Linux 3.2.12-3.2.4.amzn1.i686 05/15/2012      _i686_  (1 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          23.67    0.03   18.39    4.09   52.87    0.95

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     1.74    0.03    0.78     1.50    25.12    32.85     0.01   14.03   5.92   0.48
xvdap3            0.00     0.00    0.01    0.01     0.05     0.08    10.47     0.00    5.72   1.09   0.00
xvdf              0.40    18.59   23.14  117.55   753.12  3465.25    29.98     0.53    3.74   2.38  33.46

The most obvious thing is to batch insert and commit them all together not one by one. But I can't do that because every insert is a separate POST request, separate PHP script execution. They're all executed simultaneously and don't interfer with each other.

Seems to be a pretty simple task, what my CPU is actually doing so hard? Don't have much experience with mysql, php, linux. Probably I just miss something. Thanks for any ideas!

Answer 1

By "later" processing, do you possibly mean 1 hour or 1 day later? If that is the case then I would write the information to a CSV file which you rotate out once an hour or so and then when you need to do your "later"processing you can load the files into MySQL using LOAD DATA INFILE

http://dev.mysql.com/doc/refman/5.1/en/load-data.html

I have had LOAD DATA INFILE load 100s of MB of information in less than a minute, this method would be a great way to speed up your web response.

Answer 2

Are you running that PHP code in a loop? You can insert more than one row at a time in a single query, and this may help lower the CPU load. All you need to do is provide a comma separated list of values, something like this:

insert into rawreports(date, data, project_id) values (('$date1', '$data1', '$project_id1'),('$date2', '$data2', '$project_id2'), .....)")

also if you are running in a loop, you don't need to repeat the new mysqli() for every iteration.