Hey,
So I ran into a really interesting issue the other day.
I was developing an app in PHP and was preparing it for https. In this project I use sessions and cookies with the secure flag set and when I enabled https I noticed that all requests to the server took a very long time. One request took about 8-10 seconds and I could not figure out why.
I was using these versions on CentOS 7 running on the main machine.
|
1 2 3 4 5 6 7 8 |
yum list installed|grep -E '(httpd|php)' httpd.x86_64 2.4.6-40.el7.centos.4 @updates httpd-tools.x86_64 2.4.6-40.el7.centos.4 @updates php.x86_64 5.4.16-36.3.el7_2 @updates php-cli.x86_64 5.4.16-36.3.el7_2 @updates php-common.x86_64 5.4.16-36.3.el7_2 @updates php-mysql.x86_64 5.4.16-36.3.el7_2 @updates php-pdo.x86_64 5.4.16-36.3.el7_2 @updates |
This project is a little special because I am running the mysql-server on Remnux in a virtual machine in KVM on the main machine. Remnux is running this version of mysql-server:
|
1 2 3 4 |
remnux@remnux:~$ dpkg -l|grep mysql-server ii mysql-server 5.5.46-0ubuntu0.14.04.2 all MySQL database server (metapackage depending on the latest version) ii mysql-server-5.5 5.5.46-0ubuntu0.14.04.2 amd64 MySQL database server binaries and system database setup ii mysql-server-core-5.5 5.5.46-0ubuntu0.14.04.2 amd64 MySQL database server binaries |
I doubt you would have the issue if the mysql server ran on the same machine, I.e localhost. On this scenario the machine used 10.1.1.2 and the Remnux instance where the database is running is using 192.168.10.250.
So, as you may understand I am using 192.168.10.250 as the database in my php code.
I started to debug with strace by attaching to the httpd process:
|
1 |
ps auxw | grep -E 'sbin/httpd' | awk '{print"-p " $2}' | xargs strace -F |
This will print a lot of nice stuff when you suspect something is really strange. For instance, below you see the web server reading a file called dbfunctions.php.
|
1 2 3 4 5 6 7 |
[pid 11222] open("/var/www/html/functions/dbfunctions.php", O_RDONLY) = 16 [pid 11222] fstat(16, {st_mode=S_IFREG|0644, st_size=13579, ...}) = 0 [pid 11222] fstat(16, {st_mode=S_IFREG|0644, st_size=13579, ...}) = 0 [pid 11222] fstat(16, {st_mode=S_IFREG|0644, st_size=13579, ...}) = 0 [pid 11222] mmap(NULL, 13579, PROT_READ, MAP_SHARED, 16, 0) = 0x7f5a31b10000 [pid 11222] munmap(0x7f5a31b10000, 13579) = 0 [pid 11222] close(16) |
This is how a connection to the mysql server looks like. You can see the connect() and setsocketopt() functions being called to establish a connection. It was also here I noticed a delay.
|
1 2 3 4 5 6 7 |
[pid 11222] connect(16, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("192.168.10.250")}, 16) = 0 [pid 11222] setsockopt(16, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0 [pid 11222] setsockopt(16, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0 [pid 11222] setsockopt(16, SOL_IP, IP_TOS, [8], 4) = 0 [pid 11222] setsockopt(16, SOL_TCP, TCP_NODELAY, [1], 4) = 0 [pid 11222] setsockopt(16, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 [pid 11222] read(16, "_\0\0\0\n5.5.46-0ubuntu0.14.04.2-log"..., 16384) = 99 |
It can be useful to troubleshoot delays.
I also found a thread on stack overflow which suggested that the cause was DNS recursive requests. So I fired up tcpdump with this command
|
1 |
tcpdump -pi eno1 port 53 |
And I saw that the machine was trying to do reverse lookups of 192.168.x.x which took forever (Going out to google)
I had a discussion with a friend and after trying nginx I realised that the problem was not apache or nginx. He suggested I try this setting in the mysql-server on Remnux.
http://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_skip-name-resolve
I edited the file /etc/mysql/my.cnf and added the setting “skip-name-resolve”. Here is a snippet from my configuration file on Remnux:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
[mysqld] # # * Basic Settings # user = mysql pid-file = /var/run/mysqld/mysqld.pid socket = /var/run/mysqld/mysqld.sock port = 3306 basedir = /usr datadir = /var/lib/mysql tmpdir = /tmp lc-messages-dir = /usr/share/mysql skip-external-locking skip-name-resolv |
After a restart of everything the issue was gone.
I hope I can help someone else by making this documented and the steps to troubleshoot public. This was really a very strange issue and took some time to troubleshoot.
Good luck!