Using tcpdump and pt-query-digest for Low Level Traffic Analysis

Recently we had an "interesting" situation arise that required a bit of work and a bit of thought. The issue was that we had some slave servers that began "hanging". We noticed that a table change didn't get propogated down one of the slaves and investigation showed that the master binary log execution position (Exec_Master_Log_Pos in the output of SHOW SLAVE STATUS\G) was not changing. There were no errors in the error log. Stopping slave on the server and restarting it brought replication back online but it only lasted for a few minutes. Then the exact same behaviour was exhibited -- no errors but replication hung.

It was an odd situation and one in which I thought the core problem was a network issue. However, I had to prove the problem to other people. I thought it was a good time to pull out one of the many tools in the Percona Toolkit. In this case I combined the standard Unix tcpdump tool with pt-query-digest to easily verify that, in fact, the slave server was periodically just "losing contact" with the master -- it would send out a request, but the master would never receive it. 

The following was run on the master server. I using the host option narrowed down the data being logged the specific slave (host.ip.address) as this server had multiple slaves. This data was then piped into query digest where it gave me the results in real time.

tcpdump -s 65535 -x -nn -q -tttt -i any host host.ip.address | pt-query-digest --type tcpdump --print --noreport

The following was run on the slave: 

tcpdump -s 65535 -x -nn -q -tttt -i any  port 3306 | pt-query-digest --type tcpdump --print --noreport

 In this case I capatured all data on port 3306 on any interface. A few minutes of analysis of these commands running simultaneously and it became very clear that the core issue was a network problem (since resolved thankfully).

Maximum Open Files

Recently I was discussing with some colleagues the possibility of consolidating some MySQL servers. While the servers are not heavily loading (averaging less than 1,000 queries a second) they are pretty large in terms of storage requirements. Each server has roughly 200 databases on each with approximatley 50 tables. Thats 10,000 tables per server.  Each server contains up to 1 terabyte of data so if you consolidated servers at a 10:1 ratio you would have 10 terabytes of data, 2,000 databases and 100,000 tables with 10,000 queries per second average load.

Alright, that's a lot. And without testing I don't know if it would work. It probably wouldn't.  But it might. And if it did, it would save the company a significant amount of money.  But, while discussing this,  someone brought up that open files limit might be a problem. Open files limit is the maximum number of files the operating system or the MySQL server can have open at any time. I'm sure other apps have the same setting - in fact I'm quite certain Apache does. I'm just most familiar with MySQL.  After figuring out the rough numbers above I looked up the open file limits for RedHat 5 and it was just a bit over a million maximum. That's good. Then I look up MySQL's open_files_limit variable. I thought the maximum amount might be a problem but couldn't remember what it was. I (re)discovered the maximum number of open files for MySQL (any 5.X version) is 65,535. Hmmmmm......so it's less than 1/10th of the operating system maximum. Well under the number of tables we would have in this configuration. So we won't even bother testing it.

So I can buy four terabyte enterprise-grade drives (http://news.cnet.com/8301-17938_105-57521020-1/wd-ships-4tb-enterprise-grade-hard-drive/), stick six of them in a server and have 12 terabytes of RAID 10 space but I am limited to 65k open files by MySQL? I can buy a server from Dell that has a ridiculous number of cpus/cores and supports 128 - 768 GB of RAM. And yet I can't consolidate ten servers that have one CPU and 8 gigs of RAM down to one server because of a very low limit on open_files_limit? Please don't arbitrarily limit what I can do with my server. While you can't have as many open files in the application as you can in OS  I see no reason for a dedicated MySQL server that the maximum for this shouldn't be 650,000 instead of 65k. 

Am I the only one who thinks this is strange? Maybe I'm out in left field on this..but I doubt I'm the only person who has ever experienced this problem.

Lessons Learned

Ah, the sometimes bitter pill of experience.

Recently I got "the call" about a server that was having problems. I began standard troubleshooting procedures but didn't see anything abnormal. After about 15 minutes of getting irritated I opened up the my.cnf and looked through it. Imagine my suprise when I saw the innodb_log_file_size parameter was set to 5M (five megabytes). Even though it was hard-coded in the my.cnf, this is actually the default size (at least through MySQL 5.1). A log file size of five megabytes is pitifully small and was proving to be a severe bottleneck for the system. The two log files were being , filled up and flushed more frequently than once a second.

Once the source of the trouble was discovered it was a simple matter of filing a RFC and resolving the issue. We increased the log file size to 2000 megabytes so flushing of the transaction logs occured when the server had the time/resources and not when the log ran out of space.

The problem really wasn't the five megabyte innodb log file. The problem was that I made an assumption that the my.cnf for this server (and the several hundred other servers under my care) had a reasonable configuration.  You know what they say about assumptions. I should have taken the time to "baseline" things and determine if servers were configured reasonably. If I had take the time to do so this issue would have never happened.

Using tools such as percona toolkit it would be fairly easy to gather this information. Lesson learned -- never trust that things were done properly before you where there.

Scripting continued

Since I have been discussing scripting lately I thought I would continue with another topic I touched on briefly - backups.

I have written and modified the following script over the last few years. I have used it (and continue to use it) with multiple clients. It uses Percona's Xtrabackup to take the backup (although it can be easily modified to use mysqldump instead).

First the script

-----------------------------------------------------------------------------------------------------------------

#!/bin/bash
SAVEIFS=$IFS
IFS=$""
day_of_week=`date +%a`
backup_dir=/mysql-backup/
logfile=/root/backup_log.txt
report=/tmp/report.txt
servername=slave1
email=bmurphy@paragon-cs.com
password=`cat /root/.ssh/.backup_password`

# run backup
echo ' ' > $report
echo 'The backup is now beginning:' >> $report
echo ' ' >> $report
echo `date` >> $report


# remove compressed files older than 7 days

find $backup_dir/compressed -type f -mtime +6 -exec rm {} \;
rm -rf $backup_dir/tmp/*
/usr/bin/innobackupex-1.5.1 --user=root --password=$password --slave-info $backup_dir/tmp > $logfile 2>&1
echo ' ' >> $report
echo 'The backup is now complete:' >> $report
echo ' ' >> $report
echo `date` >> $report

# When innobackup finishes successfully, it writes to the log:
#   innobackupex-1.5.1: completed OK!
# The following checks if that string exists in the log file

grep "innobackupex-1.5.1: completed OK!" "/root/backup_log.txt" 2>&1 > /dev/null
if [ $? -ne 0 ]         # string not found, ie. backup failed
then
  echo "Backup failure. Please check log at /root/backup_log.txt" >> $report
  /bin/mailer.pl "$email" "$servername-mysql-backup@pargon-cs.com" "Failed: $servername MySQL Backup Report" "The backup failed, see attached report." "/root/backup_log.txt"
      exit 1
else
      echo "Backup completed successfully. Results logged at /root/backup_log.txt" >> $report

      echo ' ' >> $report
      echo 'Beginning tarring/compression:' >> $report
      echo ' ' >> $report
      echo `date` >> $report


      # compress backup directory and store in $backup_dir/compressed

      tar cvzf $backup_dir/compressed/mysql-backup-$day_of_week.tar.gz $backup_dir/tmp/ >> $logfile 2>&1
      status=$?
      if [[ $status != 0 ]] ; then

        echo ' ' >> $report
        echo 'Tar compressions failed.' >> $report
        echo 'Please check backup!!!' >> $report
        echo 'The backup was left in $backup/tmp' >> $report
        echo ' ' >> $report
        success='no'
        /bin/mailer.pl "$email" "$servername-mysql-backup@paragon-cs.com" "Failure: $servername MySQL Backup Report" "The compression of the backup was a failure. See attached report." "/tmp/report.txt"

        exit 1

      else
        echo ' ' >> $report
        echo 'The compression of backup is now complete:' >> $report
        echo ' ' >> $report
        echo `date` >> $report
        rm -rf $backup_dir/tmp/*
        success='yes'
      fi

      echo 'Disk space used:' >> $report
      echo ' ' >> $report
      echo `df -kh` >> $report
      echo ' ' >> $report
      echo `date` >> $report


      /bin/mailer.pl "$email" "$servername-mysql-backup@paragon-cs.com" "Success: $servername MySQL Backup Report" "The backup was successful. See attached report." "/tmp/report.txt"



      IFS=$SAVEIFS
  exit 0

fi

 -----------------------------------------------------------------------

Notice I have logging of success (and failure). There is some error checking (although probably not enough). I abstract quite a bit of it so it makes it easy to modify things like where the password is located and the location of the backup. The mailer program is a custom perl script that is used to provide a little more reliability and logging. since that was written by a colleague I don't have the ability to include it. However, there are other similar scripts available online.

Do NOT rely on yourself to run backups. Cron is your friend. Logging is your friend for when there are problems. And since we are on the topics of backups...do not ever assume backups are running correctly. I prefer to have restores automated and checked weekly. At least quarterly a backup should be restored and checked by hand.

And a full dump is not the only backup you should be making. But this isn't a post on backups. So we'll save that for another post.

km

A simple script

As I discussed in the last post there is a virtual requirement for scripting ability in a large scale environment. The following is a simple script that could be used deploy scripts to pool of server.

--------------------------------------------------

#!/bin/bash

script=path/to/script/file.sql

for i in {1..100}
do
  (
  for dc in 'chi' 'la' 'sf'
  do
    for db in `mysql -u dba -h mysql${i}-${dc} -e "SHOW DATABASES"`
 do
      if [[ -z `mysql -u dba -s -rB -h  mysql${i}-${dc} $db  < $script` >> output/mysql.success ]]
      then echo p-cs${i}-${dc} $db >> output/mysql.broken;
      fi
    done;
  done;
  )&
done;

This isn't a tutorial on bash programming, but I want to point out a couple of things here that are relevant.

1) A reasonable naming scheme for your servers is important. Don't call them Gandolf, Bilbo and Frodo as cool as those names are. Once your pool of servers grows past six this just doesn't scale and much it more difficult to programmatically access in a loop. There are numerous naming strategies available but you should probably at least include what server type it is (dev, testing or production) and what data center it is located in. EVEN if you are only in one data center right now there is always the chance for growth down the road and redundancy (ie multiple data centers) is important.

2) "Parallelize" if possible. In this case I forked off the loop so that the script is executed against each server at the same time instead of serially. The & sign is used to do this in a bash script.

3) This may be obvious, but you should always write some type of output to a file. Log errors AND successes.

There is much more but I don't want to make this post to long. Start solving your small problems now programmatically so that you gain experience and build a bag of "tricks" to use down the road.