Sunday, December 31, 2006

Managing MySQL on Solaris 10: Part 7: Solaris Performance Tuning and Performance Monitoring Tools 2

Another great tool is lsof which provides a list of open files. Unfortunately, once again, it does not come pre-installed on Solaris. What that means is you must install it. The good thing is, it is worth the five minutes that go into its installation.

Before we go into how to install lsof, let's discuss a bit about how lsof works. Lsof works by reading kernel's proc structure information to obtain information about open UNIX dialect files. Lsof relates this information to the user structure. It then reads the open file structures that are normally stored in the user structure. From the 00PORTING file distributed with lsof:

Lsof stores information from the proc and user structures in an
internal, local proc structure table. It then processes the open
file structures by reading the file system nodes that lie behind
them, extracting and storing relevant data in internal local file
structures that are linked to the internal local process structure.

Once all data has been gathered, lsof reports it from its internal,
local tables.


Installing lsof
lsof installs itself in /usr/local

-bash-3.00$ cd /home/fmashraqi/install/
-sparc-local.gzt ftp://ftp.sunfreeware.com/pub/freeware/sparc/10/lsof-4.77-sol10
--23:04:59-- ftp://ftp.sunfreeware.com/pub/freeware/sparc/10/lsof-4.77-sol10-sparc-local.gz
=> `lsof-4.77-sol10-sparc-local.gz'
Resolving ftp.sunfreeware.com... 66.193.208.66
Connecting to ftp.sunfreeware.com[66.193.208.66]:21... connected.
Logging in as anonymous ... Logged in!
==> SYST ... done. ==> PWD ... done.
==> TYPE I ... done. ==> CWD /pub/freeware/sparc/10 ... done.
==> PORT ... done. ==> RETR lsof-4.77-sol10-sparc-local.gz ... done.
Length: 475,821 (unauthoritative)

100%[=================================================================================================================>] 475,821 1.02M/s

23:05:00 (1.01 MB/s) - `lsof-4.77-sol10-sparc-local.gz' saved [475821]

[root@db:/home/fmashraqi/install] ls
SUNWhea lsof-4.77-sol10-sparc-local.gz
bench sysbench
gcc test.c
innotop
[root@db:/home/fmashraqi/install] gunzip lsof-4.77-sol10-sparc-local.gz
[root@db31:/home/fmashraqi/install] pkgadd -d lsof-4.77-sol10-sparc-local

The following packages are available:
1 SMClsof lsof
(sparc) 4.77

Select package(s) you wish to process (or 'all' to process
all packages). (default: all) [?,??,q]: y

ERROR: Entry does not match available menu selection. Enter the number
of the menu item you wish to select, or the token which is associated
with the menu item, or a partial string which uniquely identifies the
token for the menu item. Enter ?? to reprint the menu.

Select package(s) you wish to process (or 'all' to process
all packages). (default: all) [?,??,q]: 1

Processing package instance from

lsof(sparc) 4.77
Vic Abell
Using as the package base directory.
## Processing package information.
## Processing system information.
5 package pathnames are already properly installed.
## Verifying disk space requirements.
## Checking for conflicts with packages already installed.
## Checking for setuid/setgid programs.

The following files are being installed with setuid and/or setgid
permissions:
/usr/local/bin/lsof
/usr/local/bin/sparcv7/lsof
/usr/local/bin/sparcv9/lsof

Do you want to install these as setuid/setgid files [y,n,?,q] y

Installing lsof as

## Installing part 1 of 1.
/usr/local/bin/lsof
/usr/local/bin/sparcv7/lsof
/usr/local/bin/sparcv9/lsof
/usr/local/doc/lsof/00.README.FIRST
/usr/local/doc/lsof/00CREDITS
/usr/local/doc/lsof/00DCACHE
/usr/local/doc/lsof/00DIALECTS
/usr/local/doc/lsof/00DIST
/usr/local/doc/lsof/00FAQ
/usr/local/doc/lsof/00LSOF-L
/usr/local/doc/lsof/00MANIFEST
/usr/local/doc/lsof/00PORTING
/usr/local/doc/lsof/00QUICKSTART
/usr/local/doc/lsof/00README
/usr/local/doc/lsof/00TEST
/usr/local/doc/lsof/00XCONFIG
/usr/local/doc/lsof/lsof.man
/usr/local/man/man8/lsof.8
[ verifying class ]

Installation of was successful.


See, Solaris isn't so bad :)

Now let's test whether it runs nicely.

[root@db:/home/fmashraqi/install] lsof | more
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
sched 0 root cwd VDIR 32,96 1024 2 /
init 1 root cwd VDIR 32,96 1024 2 /
init 1 root txt VREG 32,96 49016 5650 /sbin/init
init 1 root txt VREG 32,96 51084 3624 /lib/libuutil.so.1
init 1 root txt VREG 32,96 20572 3587 /lib/libdoor.so.1
init 1 root txt VREG 32,96 142996 3614 /lib/libscf.so.1
init 1 root txt VREG 32,96 5436 6795 /platform/SUNW,Sun-Fire-V440/lib/../../sun4u-us3/lib/libc_psr.so.1
init 1 root txt VREG 32,96 845916 3602 /lib/libnsl.so.1
...


We can get lsof to only display the files that are opened by mysqld process.

[root@db:/home/fmashraqi/install] ps -ef | grep mysqld
mysql 26297 26275 0 Dec 29 ? 8263:23 /usr/local/mysql/bin/mysqld --defaults-file=/opt/db/mysql/product/production/et
root 11143 10642 0 23:44:13 pts/18 0:00 grep mysqld
root 26275 1 0 Dec 29 ? 0:00 /bin/sh /opt/bin/mysqld_safe --defaults-file=/opt/d


Once we have the PID, we can use the -p option to filter by PID.
[root@db:/] lsof -p 26297 | more
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
mysqld 26297 mysql cwd VDIR 118,102 6656 7852 /opt/db/mysql/data
mysqld 26297 mysql txt VREG 118,102 6342120 7831 /opt/db/mysql/mysqld
mysqld 26297 mysql 0r VCHR 13,2 6815752 /devices/pseudo/mm@0:null
mysqld 26297 mysql 1w VREG 118,102 24343140 7853 /opt/db/mysql/data/db.err
mysqld 26297 mysql 2w VREG 118,102 24343140 7853 /opt/db/mysql/data/db.err
mysqld 26297 mysql 3u IPv4 0x3000dc9ccc0 0t0 TCP *:3306 (LISTEN)
mysqld 26297 mysql 4r DOOR 0t0 48 /var/run/name_service_door (door to nscd[13895]) (FA:->0x60007e42ac0)
mysqld 26297 mysql 5u unix 105,815 0t0 55050244 /devices/pseudo/tl@0:ticots->/tmp/mysql.sock (0x6000d970e60) (Vnode=0x3001b8ddc40)
mysqld 26297 mysql 6w VREG 118,102 132755952 7561 /opt/db/mysql/data/db-slow.log
mysqld 26297 mysql 7w VREG 118,102 1070493244 8904 /opt/db/mysql/data/db2-bin.003663
mysqld 26297 mysql 8u VREG 118,102 1938 7617 /opt/db/mysql/data/db-bin.index
mysqld 26297 mysql 9uW VREG 118,102 6627000320 7703 /opt/db/mysql/data/db-InnoDB
mysqld 26297 mysql 10u VREG 118,102 128886 7658 /opt/db/mysql/product (/dev/dsk/c0t0d0s6)
mysqld 26297 mysql 11u VREG 118,102 1668 7677 /opt/db/mysql/product (/dev/dsk/c0t0d0s6)
mysqld 26297 mysql 12uW VREG 118,102 277872640 7704 /opt/db/mysql/data/ib_logfile0
mysqld 26297 mysql 13uW VREG 118,102 277872640 7705 /opt/db/mysql/data/ib_logfile1
mysqld 26297 mysql 14u VREG 118,102 28 7683 /opt/db/mysql/data/master.info
mysqld 26297 mysql 15u VREG 118,102 0 7679 /opt/db/mysql/product (/dev/dsk/c0t0d0s6)
mysqld 26297 mysql 16u VREG 118,102 4 7738 /opt/db/mysql/data/db-relay-bin.000002
mysqld 26297 mysql 17u VREG 118,102 46 7718 /opt/db/mysql/data/db-relay-bin.index
mysqld 26297 mysql 18u VREG 118,102 28 7721 /opt/db/mysql/data/relay-log.info
mysqld 26297 mysql 19r VREG 118,102 4 7716 /opt/db/mysql/data/db-relay-bin.000001
mysqld 26297 mysql 20u IPv4 0x60003395380 0x6ff2c0a TCP db.domain.net:3306->st4.domain.net:50189 (ESTABLISHED)
mysqld 26297 mysql 21u VREG 118,102 35197 8810 /opt/db/mysql/product (/dev/dsk/c0t0d0s6)
--More--


If we don't want to have to search for the PID, we can simply specify the process name with the -c option:

[root@db:/] lsof -c mysqld

To get a count of how many LWPs have a given file open, try something like the following:

[root@db:/] lsof -p 26297 > /home/fmashraqi/logs/db2.lsof.1536; cat /home/fmashraqi/logs/db2.lsof.1536 | awk '{print $9}' | awk 'BEGIN {FS=":"} {print $1}' | sort |  uniq | while read i; do num=` grep "$i" /home/fmashraqi/logs/db2.lsof.1536 | wc -l`; echo "$num    $i"; done | more


After lsof has been installed, it is very worthwhile to read the 00.README.FIRST file in the /usr/local/doc/lsof.

Although I haven't, remember that it is highly recommended that you build your own lsof instead of using a pre-built binary.

Who is using a given file?
lsof can tell us about who is using a specified file

[root@db:/] lsof /opt/db/mysql/data/db1/subscribers.MYD | more
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
mysqld 26297 mysql 45u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 48u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 82u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 94u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 255u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 321u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD
mysqld 26297 mysql 420u VREG 118,102 1176704 7646 /opt/db/mysql/data/db1/subscribers.MYD


To get the total count
[root@db:/] lsof /opt/db/mysql/data/db1/subscribers.MYD | wc -l
784


To view all the network socket files open on a machine, supply the -i option.

[root@db:/] lsof -i | more
...
mysqld 26297 mysql 2991u IPv4 0x60007853400 0t12414219 TCP db.domain.net:3306->client.domain.net:40252 (ESTABLISHED)
...


For sshd connections a connection of IPv6 type, similar to the one below, may be noticed in lsof -i output:

sshd      23895   root    4u  IPv6 0x300153f4200     0t19040  TCP db.domain.net:ssh->client.domain.net:61885 (ESTABLISHED)


If you would like to filter the open network connections output by specifying a host, you can do that:
[root@db:/] lsof -i@client.domain.net
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
mysqld 26297 mysql 30u IPv4 0x6000b106200 0t5170868 TCP db.domain.net:3306->client.domain.net:44608 (ESTABLISHED)


Similarly, we can further filter by specifying the protocol in use

[root@db:/] lsof -iTCP@client.domain.com
# or
[root@db:/] lsof -iTCP@client.domain.com:40259


To view network connections of type IPv4 or IPv6
[root@db:/] lsof -i4
[root@db:/] lsof -i6


Another cool thing you can do is to match netstat output with lsof. First find the remote address in netstat output that you are interested in matching. For instance:
[root@db:/]netstat
db.3306 my.46726 66608 0 49232 0 CLOSE_WAIT


Now specify the remote address as a parameter to lsof option -i:
[root@db:/] lsof -i TCP@my:46726
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
mysqld 26297 mysql 627u IPv4 0x60003840040 0t304 TCP db.domain.net:3306->my.domain.net:46726 (CLOSE_WAIT)


If we want to see the connections opened by the mysql user we can use the -u option:
[root@db:/] lsof -umysql

To see connections opened by both the mysql user and the root user:
[root@db:/] lsof -umysql,root


We can also see connections opened by all users except mysql
[root@db:/] lsof -u ^root


To tell lsof not to lookup hostnames
lsof -n


Check out the lsof FAQ page.

Managing MySQL on Solaris 10: Part 6: Solaris Performance Tuning Tools 1

Part 5 of "Managing MySQL on Solaris 10" series will be published later

In Solaris, a process can be in any of the following states during the course of its execution.

O Running
S Sleeping
R Runnable (in dispatch queue)
Z Zombie
T Terminated
C* CPU

Using uptime to get quick summary statistics
-bash-3.00$ uptime
2:18pm up 119 day(s), 12:38, 56 users, load average: 1.00, 0.84, 0.81


[root@db:/] uptime
2:19pm up 194 day(s), 1:59, 16 users, load average: 16.64, 11.16, 13.32


When the competition for processor and other resources gets intense, the processes start getting increasingly delayed. We can see that on the db server, at the time of run queue being sampled, there were between 13 to 16 processes waiting to run (ready for CPU).

What processes are running?
One way to see what processes are running is to use the ps -el command. The e option displays information about every process that is currently running, while the l option specifies that the long listing format be used to display the information.

[root@db:/] ps -el | more
F S UID PID PPID C PRI NI ADDR SZ WCHAN TTY TIME CMD
1 T 0 0 0 0 0 SY ? 0 ? 0:43 sched
0 S 0 1 0 0 40 20 ? 298 ? ? 3:09 init
1 S 0 2 0 0 0 SY ? 0 ? ? 1:45 pageout
1 S 0 3 0 1 0 SY ? 0 ? ? 5522:07 fsflush
0 S 0 23152 23147 0 40 20 ? 376 ? pts/8 0:00 bash
0 S 0 8998 8975 0 39 20 ? 178 ? pts/7 0:00 more
0 S 0 23581 23579 0 40 20 ? 164 ? pts/6 0:00 sh
0 O 100 26297 26275 0 40 20 ? 961014 ? 7135:55 mysqld


In the above output:

F: historical flags
S: Process state
UID: ID of the process owner
PID: Process ID
PPID: Parent process ID
C: This is now obsolete. Historically it showed the utilization of the processor for scheduling
PRI: Process priority. In the above output the priority of the mysqld process is 40.
NI: Settings for nice
ADDR: Process address in memory
SZ: Process size. For the mysqld process, the size is 961014. SZ reports the total size of the process in virtual memory (includes all mapped file and devices).
WCHAN: The process is waiting for the resource which has this address.
TTY: What terminal is associated with this process.
TIME: How much time this process has accumulated on the CPU. We can see mysqld process has accumuated almost 7136 minutes.
CMD: The command (name of the process)


In the above output, we can also see that the fsflush process has accumulated a significant amount of time (5522:07 minutes) on the CPU.

The fsflush process flushes write buffers to disk at a predefined interval of time. Some Solaris performance tuning gurus suggest that the fsflush process shouldn't use 5 to 6 percent of the CPU. For dedicated database servers (running mysqld) like this, the fsflush can use more of the CPU, as in this case.

We can see that the fsflush process has used about 78% of the CPU time accumulated by the mysqld process, a figure that is indeed quite high.

Both the scheduler process (sched) and the fsflush process have the priority set to 0, which is the highest possible priority.

By specifying the y option in addition to e and l we can omit the F and ADDR columns and instead include an RSS column. The RSS column stands for "resident set size" of the process. One thing that is important to note is that when the y option is specified, the display units are changed to kilobytes instead of the default unit size of pages.

[root@db:/] ps -ely | more
S UID PID PPID C PRI NI RSS SZ WCHAN TTY TIME CMD
T 0 0 0 0 0 SY 0 0 ? 0:43 sched
S 0 1 0 0 40 20 440 2384 ? ? 3:09 init
S 0 2 0 0 0 SY 0 0 ? ? 1:47 pageout
S 0 3 0 1 0 SY 0 0 ? ? 5522:52 fsflush
S 0 19873 19872 0 40 20 104 2856 ? pts/12 2:41 top
S 0 7 1 0 40 20 520 9024 ? ? 29:20 svc.star
S 0 9 1 0 40 20 368 9664 ? ? 5:49 svc.conf
S 0 142 1 0 40 20 416 2320 ? ? 10:02 in.mpath
S 1 101 1 0 40 20 1688 4704 ? ? 14:15 kcfd
S 0 23202 23197 0 40 20 440 3008 ? pts/9 0:00 bash
S 0 378 1 0 40 20 288 2384 ? ? 0:07 snmpdx
S 0 100 1 0 40 20 208 2832 ? ? 0:00 devfsadm
S 0 8970 8968 0 40 20 800 1312 ? pts/7 0:00 sh
S 0 92 1 0 40 20 128 2544 ? ? 0:00 sysevent
S 0 23572 308 0 40 20 720 8584 ? ? 0:00 sshd
S 0 13895 1 0 40 20 1968 4400 ? ? 18:58 nscd
S 0 23147 23145 0 40 20 232 1312 ? pts/8 0:00 sh
S 0 91 1 0 40 20 528 4256 ? ? 34:32 picld
S 0 23152 23147 0 40 20 440 3008 ? pts/8 0:00 bash
S 0 8739 8737 0 40 20 232 1312 ? pts/4 0:00 sh
S 0 17517 17510 0 40 20 328 8272 ? ? 0:00 sshd
S 0 225 7 0 40 20 240 2016 ? ? 0:07 sac
S 0 23742 23735 0 40 20 328 8272 ? ? 0:00 sshd
S 0 309 1 0 40 20 416 8320 ? ? 5:40 fmd
S 0 236 1 0 40 20 440 1288 ? ? 1:24 utmpd
S 0 27866 7 0 40 20 208 2104 ? console 0:00 ttymon
S 0 23197 23195 0 40 20 232 1312 ? pts/9 0:00 sh
S 0 293 1 0 40 20 792 3896 ? ? 0:45 syslogd
S 0 23888 308 0 40 20 720 8584 ? ? 0:00 sshd
S 0 308 1 0 40 20 800 3936 ? ? 1:32 sshd
S 0 23581 23579 0 40 20 232 1312 ? pts/6 0:00 sh
S 100 26297 26275 3 40 20 7216696 7688112 ? ? 7241:22 mysqld
S 60001 403 1 0 40 20 344 2048 ? ? 4:07 nrpe


By dividing the SZ column for the mysqld process by 1024, we can get virtual memory usage by the mysqld process in megabytes. In the example above, the mysqld process is using 7688112 /1024 = 7151.6 MB or 89.4% of the virtual memory.

How many threads are associated with each process?
To find out how many threads are associated with the mysqld process, we can run the ps command with customized output. The output of ps can be customized by supplying the -o option. For instance, to show the number of LWPs associated, we specify nlwp after -o.

[root@db:/] ps -ef -onlwp -oargs | more
NLWP COMMAND
1 sched
1 /sbin/init -r
1 pageout
1 fsflush
1 top
11 /lib/svc/bin/svc.startd -r
13 /lib/svc/bin/svc.configd
1 /usr/lib/inet/in.mpathd -a
3 /usr/lib/crypto/kcfd
1 /usr/bin/bash
1 /usr/lib/snmp/snmpdx -y -c /etc/snmp/conf
6 devfsadmd
1 -sh
14 /usr/lib/sysevent/syseventd
1 /usr/lib/ssh/sshd
25 /usr/sbin/nscd
1 -sh
6 /usr/lib/picl/picld
1 /usr/bin/bash
1 -sh
1 /usr/lib/ssh/sshd
1 /usr/lib/saf/sac -t 300
1 /usr/lib/ssh/sshd
15 /usr/lib/fm/fmd/fmd
1 /usr/lib/utmpd
1 /usr/lib/saf/ttymon -g -d /dev/console -l console -T sun -m ldterm,ttcompat -h
1 -sh
13 /usr/sbin/syslogd
1 /usr/lib/ssh/sshd
1 /usr/lib/ssh/sshd
1 -sh
1210 /usr/local/mysql/bin/mysqld --defaults-file=/opt/db/mysql/product/production/et


We can see that mysqld process currently has 1210 threads associated to it.

Another tool to monitor performance is by using top. Unfortunately, top is not included by default on Solaris systems. The good news is that you can get it from www.sunfreeware.com.

When using top, beaware of broken top. Consider the following top output:
last pid:  9350;  load avg:  20.6,  17.8,  15.4;       up 194+03:23:12                                                                              15:43:04
90 processes: 89 sleeping, 1 on cpu
CPU states: 13.8% idle, 58.2% user, 28.1% kernel, 0.0% iowait, 0.0% swap
Memory: 8192M phys mem, 119M free mem, 16G swap, 11G free swap

PID USERNAME LWP PRI NICE SIZE RES STATE TIME CPU COMMAND
26297 mysql 999 59 0 7508M 7118M sleep 121.9H 316% mysqld
23646 root 1 59 0 3792K 784K sleep 15:56 0.46% top2
9350 root 1 59 0 2920K 1760K cpu 0:00 0.43% top
23664 root 1 59 0 2432K 816K sleep 7:12 0.16% iostat
23579 root 1 59 0 8272K 808K sleep 1:29 0.03% sshd
13895 root 25 59 0 4400K 1640K sleep 18:57 0.03% nscd
7 root 11 59 0 9024K 520K sleep 29:20 0.02% svc.startd
8968 root 1 59 0 8272K 1264K sleep 0:00 0.01% sshd
91 root 6 59 0 4256K 528K sleep 34:32 0.01% picld
236 root 1 59 0 1288K 440K sleep 1:23 0.01% utmpd
23638 root 1 59 0 8272K 800K sleep 0:19 0.01% sshd
410 root 1 59 0 9416K 2328K sleep 31:28 0.01% snmpd
9 root 13 59 0 9664K 368K sleep 5:48 0.00% svc.configd
309 root 15 59 0 8320K 416K sleep 5:40 0.00% fmd
101 daemon 3 59 0 4704K 1112K sleep 14:15 0.00% kcfd


Notice how top is reporting that mysqld is using 316% of CPU, something that is just not possible. On this machine when I installed a fresh copy of top, I got a totally different (and much more believable picture)

load averages: 14.62, 16.79, 15.29                                                                                                                  15:44:27
90 processes: 88 sleeping, 2 on cpu
CPU states: 38.2% idle, 44.8% user, 17.0% kernel, 0.0% iowait, 0.0% swap
Memory: 8192M real, 124M free, 7619M swap in use, 15G swap free

PID USERNAME LWP PRI NICE SIZE RES STATE TIME CPU COMMAND
26297 mysql 999 54 0 0K 0K cpu/3 122.0H 61.40% mysqld
9356 root 1 59 0 3792K 1456K cpu/1 0:00 0.16% top2
23646 root 1 59 0 3792K 784K sleep 15:56 0.09% top2
23664 root 1 59 0 2432K 816K sleep 7:12 0.04% iostat
20766 root 1 59 0 2432K 856K sleep 4:33 0.01% iostat
23579 root 1 59 0 8272K 808K sleep 1:29 0.01% sshd
91 root 6 59 0 4256K 528K sleep 34:32 0.00% picld
7 root 11 59 0 9024K 520K sleep 29:20 0.00% svc.startd
8975 root 1 59 0 3000K 1568K sleep 0:00 0.00% bash
8968 root 1 59 0 8272K 1264K sleep 0:00 0.00% sshd
410 root 1 59 0 0K 0K sleep 31:28 0.00% snmpd
13895 root 25 59 0 4400K 1640K sleep 18:57 0.00% nscd
101 daemon 3 59 0 4704K 1112K sleep 14:15 0.00% kcfd
142 root 1 59 0 2320K 416K sleep 10:01 0.00% in.mpathd
9 root 13 59 0 9664K 368K sleep 5:48 0.00% svc.configd


Now we can see that top is reporting only 61.40% of CPU is being used by the mysqld process. In addition, top is reporting that CPU is 38.2% idle.

Another, very useful tool to monitor process status is by using prstat, which has been a part of Solaris OS since Solaris 8. prstat provides us with a report on active process statistics. Once invoked, like top, prstat continues to run until it is interrupted by the user.

   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
26297 mysql 7508M 7140M cpu3 59 0 122:17:36 63% mysqld/1210
23646 root 3792K 784K sleep 59 0 0:15:58 0.1% top2/1
9376 root 4896K 4608K cpu0 59 0 0:00:00 0.1% prstat/1
23664 root 2432K 816K sleep 59 0 0:07:13 0.0% iostat/1
23579 root 8272K 808K sleep 59 0 0:01:29 0.0% sshd/1
20766 root 2432K 856K sleep 59 0 0:04:33 0.0% iostat/1
8968 root 8272K 1272K sleep 59 0 0:00:00 0.0% sshd/1
91 root 4256K 528K sleep 59 0 0:34:32 0.0% picld/6
13895 root 4400K 1184K sleep 59 0 0:18:57 0.0% nscd/25
7 root 9024K 520K sleep 59 0 0:29:20 0.0% svc.startd/11
23188 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
1457 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
23638 root 8272K 800K sleep 59 0 0:00:19 0.0% sshd/1
23602 root 8272K 328K sleep 59 0 0:00:00 0.0% sshd/1
17524 root 3016K 432K sleep 59 0 0:00:00 0.0% bash/1
14739 root 8584K 728K sleep 59 0 0:00:00 0.0% sshd/1
22814 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
22828 root 3008K 440K sleep 59 0 0:00:00 0.0% bash/1
8730 root 8584K 704K sleep 59 0 0:00:00 0.0% sshd/1
1455 root 8272K 328K sleep 59 0 0:00:00 0.0% sshd/1
23138 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
19867 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
17519 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
410 root 9416K 1136K sleep 59 0 0:31:28 0.0% snmpd/1
403 nobody 2048K 344K sleep 59 0 0:04:07 0.0% nrpe/1
23581 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
308 root 3936K 744K sleep 59 0 0:01:32 0.0% sshd/1
23888 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
293 root 3896K 584K sleep 59 0 0:00:44 0.0% syslogd/13
23197 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
27866 root 2104K 208K sleep 59 0 0:00:00 0.0% ttymon/1
236 root 1288K 440K sleep 59 0 0:01:23 0.0% utmpd/1
309 root 8320K 416K sleep 59 0 0:05:40 0.0% fmd/15
23742 root 8272K 328K sleep 59 0 0:00:00 0.0% sshd/1
225 root 2016K 248K sleep 59 0 0:00:07 0.0% sac/1
17517 root 8272K 328K sleep 59 0 0:00:00 0.0% sshd/1
8739 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
23152 root 3008K 440K sleep 59 0 0:00:00 0.0% bash/1
23147 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
23572 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
92 root 2544K 128K sleep 59 0 0:00:00 0.0% syseventd/14
8970 root 1312K 760K sleep 59 0 0:00:00 0.0% sh/1
100 root 2832K 208K sleep 59 0 0:00:00 0.0% devfsadm/6
Total: 90 processes, 1396 lwps, load averages: 16.72, 17.71, 16.19



We can filter the output of prstat by specifying PIDs, UIDs, zone IDs, CPU IDs, and even processor set IDs. A list of these IDs can be separated by commas (enclosed in quotes).

By invoking prstat with the a option, we can see information about both users and processes.

prstat -a
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
26297 mysql 7508M 6985M cpu0 49 0 135:08:13 36% mysqld/1210
10702 root 4832K 4568K cpu2 59 0 0:00:00 0.1% prstat/1
23646 root 3792K 784K sleep 59 0 0:17:21 0.1% top2/1
23664 root 2432K 816K sleep 59 0 0:07:50 0.0% iostat/1
23579 root 8272K 816K sleep 59 0 0:01:37 0.0% sshd/1
20766 root 2432K 856K sleep 59 0 0:04:38 0.0% iostat/1
91 root 4256K 528K sleep 59 0 0:34:35 0.0% picld/6
13895 root 4400K 1408K sleep 59 0 0:19:00 0.0% nscd/25
7 root 9024K 520K sleep 59 0 0:29:23 0.0% svc.startd/11
23147 root 1312K 232K sleep 59 0 0:00:00 0.0% sh/1
23572 root 8584K 720K sleep 59 0 0:00:00 0.0% sshd/1
92 root 2544K 128K sleep 59 0 0:00:00 0.0% syseventd/14
8970 root 1312K 592K sleep 59 0 0:00:00 0.0% sh/1
100 root 2832K 208K sleep 59 0 0:00:00 0.0% devfsadm/6
378 root 2384K 288K sleep 59 0 0:00:07 0.0% snmpdx/1
NPROC USERNAME SIZE RSS MEMORY TIME CPU
1 mysql 7508M 6985M 87% 135:08:13 36%
91 root 441M 52M 0.5% 2:59:09 0.2%
1 nobody 2048K 352K 0.0% 0:04:07 0.0%
1 daemon 4704K 1680K 0.0% 0:14:17 0.0%

Total: 94 processes, 1400 lwps, load averages: 2.21, 2.62, 2.89


If you would like to see new reports below the old report, specify the c option.

To filter the prstat output to display only processes or lwps that are bound to specified processor sets, specify the "-C" option.

Similarly to get CPU specific prstat report, use the -P option.

To sort the output in descending order specify the -s option followed by one of the five following values:
  • cpu (default)
  • pri (priority)
  • rss (resident set size)
  • size (size of process image)
  • time (process execution time)
To sort by ascending order, use the -S option.

Summary of total statistics can be viewed by using the -t option.

 NPROC USERNAME  SIZE   RSS MEMORY      TIME  CPU
1 mysql 7508M 7036M 88% 135:58:53 38%
91 root 441M 53M 0.5% 2:59:21 0.3%
1 nobody 2048K 352K 0.0% 0:04:07 0.0%
1 daemon 4704K 1552K 0.0% 0:14:17 0.0%

Total: 94 processes, 1400 lwps, load averages: 2.22, 2.47, 2.60


See man prstat for more on the prstat command.

Todo:
Usng psrset how can we make MySQL we bind mysqld process to groups of processors, instead of having it run on a single processor?

Saturday, December 30, 2006

Fotolog is Chile's #3 site

Fotolog: top 3 sites in Chile uses MySQL
Fotolog is the top 28th site in the world, according to Alexa rankings today, and, ofcourse, it uses MySQL :)

MyISAM DELETE statements taking forever

On one of my servers today I noticed some DELETE statements that had been running for more than 14000 seconds due to system locks.

 Queries: 180.2M  qps: 1294 Slow:  173.3k         Se/In/Up/De(%):    09/02/33/00
qps now: 2065 Slow qps: 8.1 Threads: 463 ( 225/ 738) 06/01/49/00
Cache Hits: 610.9k Hits/s: 4.3 Hits now: 4.1 Ratio: 3.9% Ratio now: 3.3%
Key Efficiency: 99.2% Bps in/out: 134.7k/ 1.5M Now in/out: 203.9k/ 1.3M

Id User Host/IP DB Time Cmd Query or State
-- ---- ------- -- ---- --- ----------
18951229 www 192.168.1.170 fl_db1 14516 Query DELETE FROM user_
19003358 www 192.168.1.107 fl_db1 14273 Query DELETE FROM user_
19014485 www 192.168.1.105 fl_db1 14221 Query DELETE FROM user_
19117224 www 192.168.1.109 fl_db1 13733 Query DELETE FROM user_
21707448 www 192.168.1.131 fl_db1 1474 Query DELETE FROM user_


One common misunderstanding is that when system locks are disabled (using --skip-external-locking), threads shouldn't be in "System lock" state. This confusion exists because we see state of "System lock" even when MyISAM locks are in place for a thread.

Key cache is flushed during the unlocking phase and can take some time. During the flush process, it my understanding that all key blocks that have been changed are written to the index file. So size of the key cache plays an important role here.

What I am investigating is why some of the DELETE records ocassionally take as much as 14000 seconds and how can that be decreased.

UPDATE:
So my boss found out the reason for the application issuing excessive DELETE statements. It turned out that within one class our old programmers were using DELETE followed by an INSERT to perform UPDATEs on the table. That is, ofcourse, terrible usage of resources and not to mention its horrible defragmentation effects.

If you ever, for some reason, find yourself in such situation, remember to defragment the tables.

Archival Deletes
Going forward, it would be very nice for MySQL to provide an option (for MyISAM tables) for a DBA to set "archival/status deletes" for a table. What I mean is that whenever a DELETE statement is issued, MyISAM shouldn't actually delete the record but instead mark it as deleted. Then later, those records can be physically deleted periodically, or on demand. I would really love to see something like this to help improve performance of DELETE operations.

One way to "relatively increase" the performance of DELETE statements is to lower its priority by specifying the LOW_PRIORITY attribute.

Read more about table locking issues on MySQL website.

Tuesday, December 26, 2006

Managing MySQL on Solaris 10: Part 4: Solaris Doors and Signals

The Solaris Doors API, originally developed as a core part of the Spring Operating System, is basically nothing more than an RPC mechanism. The Solaris Doors, which are made visible as door descriptors (standard UNIX file descriptors) , relies heavily on threads and allows us to call procedures between processes on the same system. A door client makes a call to a door server which has a thread that is awaken, which passed the scheduling control directly to the thread in the door server. The control and the response is passed back to the calling thread when the door server has completed executing the request.

A door is made visible to other applications by attaching an already existing door descriptor to an existing regular file in the UNIX file system.

Solaris supports the following doors functions

When events like segmentation violation (illegal address references) and floating point exceptions occur, a process or a thread within a process needs to be interrupted. The UNIX signal facility provides for handling such exceptions by notifying a process or a thread of such events.

The signals can be either synchronous or asynchronous depending on the reason and source of the signal.

The segmentation violation and folating point exceptions are examples of synchronous signals, which typically arise as "hardware trap" conditions. The executing instruction stream can cause synchronous signals. These signals are also sometimes refered to as traps because it can cause "a trap into a kernel trap handler."

On the other hand, asynchronous signals such as job control signals and signals to kill a process, arise from external events that may or may not be related to the current instruction stream. These signals are sometimes known as interrupts.

All signals have unique names beginning with SIG. Each signal also has a signal number.

A default disposition (out of four possible ones) is also defined for all possible signals, namely exit, core, stop and ignore.

A process can describe how it is going to handle such signals except when it receives SIGKILL and SIGSTOP since the disposition for these signals cannot be changed. For instance, a process can ignore such signals, catch them, or invoke the default action of a signal. Since Solaris is multithreaded, a signal can be directed to a specific thread within a process. We can also specify which threads will block (mask) which signals.

For more information on signals, read the article "A Primer on Signals in the Solaris OS." If you want more detailed information, get the book, "Advanced Programming in the UNIX Environment" by W. Richard Stevens.

References:

Sunday, December 17, 2006

Managing MySQL on Solaris 10: Part 3: Inter-process communication

Ever wondered how threads exchange data between themselves?

This sharing and exchange of data is made possible by inter-process communication, or IPC for short. There are several different types of inter-process communication for instance (IPC,System V IPC and POSIX IPC). In addition Solaris provides an additional advanced Solaris IPC.

According to Wikipedia:

Inter-Process Communication (IPC) is a set of techniques for the exchange of data between two or more threads in one or more processes. Processes may be running on one or more computers connected by a network. IPC techniques are divided into methods for message passing, synchronization, shared memory, and remote procedure calls (RPC). The method of IPC used may vary based on the bandwidth and latency of communication between the threads, and the type of data being communicated.

Wikipedia's article on Inter-process communication also goes on to say that "It is widely accepted that IPC can be implemented significantly faster in a microkernel environment than in classical monolithic kernel systems1." This means that IPC implementation is not as fast in Solaris (and other Unix systems) as it could be.

The socket that MySQL uses is typically present at /tmp/mysql.sock. This socket is an example of usage of traditional UNIX IPC. Sockets allow processes to communicate directly by providing a communication endpoint.

Another example of traditional UNIX IPC usage is when pipes are created which provides for a communication mechanism. On Solaris, when a pipe is created, "two file descriptors, fildes[0] and fildes[1]. The files associated with fildes[0] and fildes[1] are streams and are both opened for reading and writing. The O_NDELAY, O_NONBLOCK, and FD_CLOEXEC flags are cleared on both file descriptors. The fcntl(2) function can be used to set these flags".

"A read from fildes[0] accesses the data written to fildes[1] on a first-in-first-out (FIFO) basis and a read from fildes[1] accesses the data written to fildes[0] also on a FIFO basis3."

The System V IPC consists of System V shared memory, message queues, and semaphores. Kernel tunable parameters for System V IPC are specified in /etc/system file. In Solaris 10, the defaults of most of these parameters were increased to ease the tuning efforts.

Resources and References:
  1. Hermann Härtig, Michael Hohmuth, Jochen Liedtke, Sebastian Schönberg, Jean Wolter (October 1997). "The performance of μ-kernel-based systems". Proceedings of the 16th ACM symposium on Operating systems principles (SOSP), Saint-Malo, France: 74. ISBN 0-89791-916-5.
  2. Inter-process communication (Wikipedia)
  3. man -a pipe

Friday, December 15, 2006

Managing MySQL on Solaris 10: Part 2: Solaris Kernel Threads Model

The central component of most operating systems is the kernel. The kernel manages the resources of a system. In addition, the kernel facilitates and manages the communication between a system's hardware and software components.

Two levels of execution are provided by hardware: kernel mode execution and user mode execution. When in kernel mode, the software program can access all the instructions and every accessible piece of hardware. A program is in kernel space if running in kernel mode and in user space if running in user mode.

The Solaris kernel is a monolithic kernel, much like most Unix systems, as compared to a microkernel.

The software said to be running in kernel mode is. On the other hand, in user mode, the software cannot access certain some areas of functionality of the hardware. This prevents malicious programs from doing any damage to hardware.

In Monolithic kernels, the parts of the kernel that need to be accessible by most programs are placed in the kernel space. In other words, "the entire kernel is run in kernel space in supervisor mode" [3]. The examples of programs that are in the kernel space include device drivers, memory managers, scheduler, file systems etc.

For a program to be in kernel space, does not necessarily means that a program in user space cannot access its services. A number of system calls are made available to applications so they can access the services of programs that are running in kernel space.

Certain common libraries are not available to programmers programming in kernel space, which makes coding in that environment a bit harder. The problems and limitations associated with monolithic kernels does not end here. Debugging in kernel space is also hard due to the lack of quality debugging tools. For many changes to take effect, rebooting the system is required. Uncatched bugs in one kernel module can bring down the system.


Microkernel systems, on the other hand, place only those parts in kernel space for which being privileged is a requirement. These programs include IPC, basic schedulers, memory handling (basic) and I/O (basic). Other parts, such as memory handling and file systems, that could operate without being in privilege mode were moved to user space.


Solaris kernel, just like the Linux and FreeBSD kernels, are modular in the sense that they can dynamically (at runtime) load and unload modules. Using this dynamic nature of loading modules, the functionality and capability of kernels can be extended.

The Solaris kernel threads model is based on kernel threads, user threads, process and lightweight process objects.

Out of the four objects, it is the kernel threads object that is scheduled for execution, and then executed, on a processor.

Each user process also maintains a non-kernel thread state in the form of user threads.

Each user program has an execution environment known as process. The term process is also used to refer to the executable form of a program. Each process has, at the minimum, one thread of execution.

User threads created inside the process are visible to the kernel. The execution context of a user thread is known as lightweight process, commonly abbreviated as LWP.

The kernel threads are executed by the kernel for tasks related to and needed by the kernel.

The execution state of a kernel thread is saved for later restoration when it is moved off the process for later scheduling.

Thanks to the virtual file system implementation in Solaris OS, we can configure multiple types of file systems at the same time.

As you can expect, complete support for IPv4 and IPv6 is implemented in the networking subsystem of the Solaris kernel.

The following types of loadable kernel modules are supported by the Solaris module framework:
  • file systems (UFS, NFS)
  • scheduler classes (Fixed Priority (FX), Real Time (RT) etc)
  • execute file format loaders
  • loadable system calls (semsys Semaphores)
  • streams modules
  • bus/device drivers (PCI)
  • other/miscellaneous modules (IPC)
Until Solaris 8, a library-level thread scheduler to maintain LWP threads had to be maintained in addition to the kernel thread scheduler. User threads were multiplexed into a pool of LWPs and that created issues with concurrency management and scheduling latency. " The scheduling latency was the effect of waiting for the threads library scheduler to link a user thread to an available LWP4. The concurrency issue has to do with maintaining a sufficient number of LWPs such that the process does not have runnable user threads waiting for an execution resource (an LWP)."

Solaris 8 introduced a single-level model for threads model. With the new single-level model, an LWP and kernel thread are created for each new user thread. The benefit of that is that the user thread always has a LWP and a kernel thread.

Thread applications link to libthread.so, typically placed in /usr/lib directory. On my Sun V210 with Solaris 10, the /usr/lib/libthread.so links to /lib/libthread.so.1

-bash-3.00$ ls -ltr /usr/lib/libthread.so
lrwxrwxrwx 1 root root 24 Mar 30 2005 /usr/lib/libthread.so -> ../../lib/libthread.so.1


If you are still using Solaris 8, the new binary based on single-level model is fully compatible with older model. Applications do not need to be recompiled to use the single-level model binary. On Solaris 8, all we need to do is point the runtime linker's path environmental variable to the new binary. On Solaris 10, the default library is the single-model one. The benefits of the new threads model include improved performance, scalability, and reliability, reliable signal behavior, improved adaptive mutex lock implementation and user-level sleep queues for synchronization objects4.

The scheduling classes in Solaris are TS (Timeshare), IA (interactive [enchanced TS]), FSS (fair-share scheduling), FX (fixed-priority), SYS (system), RT (real-time) and interrupts. The interrupts have the highest priority (160-169).

When you are using Windows, the IA schedule class is being used as it increases the thread priority for the window that has the focus.

Resources:
1. Linux Kernel Archives Provides the Linux kernel source and more
2. Monolithic kernels and micro-kernels
3. Monolithic kernel
4. Solaris Internals

MySQL: Replication stopped: Lock wait timeout exceeded

One of my slave servers stopped twice in the last couple of days. The error in the error log file was:

061214 21:17:41 [ERROR] Slave: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'fl_db1'. Query: 'UPDATE user SET total_photos = total_photos + 1 WHERE user_name = '666damy666'', Error_code: 1205
061214 21:17:41 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'db2-bin.003509' position 342646547


I tried to learn more about the error code using perror and got
-bash-3.00$ perror 1205
Illegal error code: 1205


Information about the error is available on MySQL server error messages page of the manual.


Error: 1205 SQLSTATE: HY000 (ER_LOCK_WAIT_TIMEOUT)

Message: Lock wait timeout exceeded; try restarting transaction


The InnoDB error codes page lists the following information:

1205 (ER_LOCK_WAIT_TIMEOUT)

Lock wait timeout expired. Transaction was rolled back.


So how can we prevent that from happening?

This happens because the value of innodb_lock_wait_timeout was not enough for InnoDB to acquire the lock. On my servers it was set to default: 50.

The manual has following information:

The timeout in seconds an InnoDB transaction may wait for a lock before being rolled back. InnoDB automatically detects transaction deadlocks in its own lock table and rolls back the transaction. Beginning with MySQL 4.0.20 and 4.1.2, InnoDB notices locks set using the LOCK TABLES statement. Before that, if you use the LOCK TABLES statement, or other transaction-safe storage engines than InnoDB in the same transaction, a deadlock may arise that InnoDB cannot notice. In cases like this, the timeout is useful to resolve the situation. The default is 50 seconds.


I am going to investigate reasons behind the lock wait timeout exceeding. For now, let's see if increasing innodb_lock_wait_timeout to 120 will be enough on this slave server.

Unfortunately, we need to restart the server for the new values to take effect.

Thursday, December 14, 2006

Managing MySQL on Solaris 10: Part 1: Introduction

From time to time I receive requests from friends who are interested in learning more about managing MySQL on Solaris 10. To help them (and myself), I am planning to write about the internals of both MySQL and Solaris.

So if you have any questions that relate to adminstering and managing MySQL on Solaris, post them as comment, and though I don't promise, I will do my best to answer them.

What I usually recommend my friends is that they should start learning by finding a good authoritative book. In my opinion, reading one good authoritative book on the subject is better than reading three normal books.

BTW, I used to spend a lot of time finding the right book before buying it. Earlier this year I signed up for Safari Books Online (by O'reilly). My membership gave me a ten slot bookshelf. I really liked the service so I decided to get unlimited access to the books.

One of the books I highly recommend on Solaris is Solaris Internals: Solaris 10 and OpenSolaris Kernel Architecture, Second Edition. It is written by Jim Mauro and Richard McDougall. Community authors for the book include Frank Batschulat (UFS), Russell Blaine, Jeff Bonwick (ZFS) and Bryan Cantrill (DTrace) among many others.

On the MySQL side, the book on the top of my "to-recommend-list" is Pro MySQL by none other than Jay Pipes and Michael Kruckenberg (they both are my friends but that's NOT the reason I am recommending it). Seriously, if you are planning to buy one good authoritative book, buy this one.

Solaris 2.0 was released in 1992. Today, it is one of the leading operating systems offering reliability, performance, scalability, observability and more.

To get the latest information on Solaris, you can look at What's New on http://docs.sun.com/app/docs. On the docs site you can also access a variety of guides. For instance, you can get the Solaris 10 System Administrator Collection.

Solaris ZFS Administration Guide provides information for both SPARC and x86 (64-bit and 32-bit x86 compatible) based systems. This guide will help you in setting up and managing Solaris ZFS file systems.

In case you are wondering what is ZFS, I will let the guide provide the introduction:
"The Solaris ZFS file system is a revolutionary new file system that fundamentally changes the way file systems are administered, with features and benefits not found in any other file system available today. ZFS has been designed to be robust, scalable, and simple to administer."
ZFS, a transactional file system, manages the physical storage using a concept known as storage pools. Using the volume manager you can get the image of a single device and still take advantage of multiple devices.

One cool thing about Solaris is that each new release contains features found in old releases, however new releases may no longer support older hardware.

Solaris 10, a volume production operating system, does not support 32-bit SPARC processors. It doesn't support UltraSPARC I processor either. Solaris 10 only has a 64-bit release which can run on SPARC systems that use UltraSPARC II, UltraSPARC III, or UltraSPARC IV processors. You don't need to worry about 32-bit SPARC programs and applications as they can run without any issue on Solaris 10 64-bit kernel.

A lot of cool and innovative work has been done on Solaris 10. As a result it offers predictive self-healing, Service Management Framework (SMF), Fault Manager, Zones, Dynamic resource pools (DRP), physical memory control, dynamic tracing (DTrace), process rights management and much, much more. More documentation on what's new in Solaris 10 is available online. At the time of writing this post, there have been four Solaris 10 releases: 3/05, 1/06, 6/06 and 11/06.

Like every other DBA, I need a wide variety of tools for monitoring and analyzing system and application performance. On Solaris I get a variety of tools. Some of the tools that come very handy at times include vmstat (virtual memory statistics), mpstat (per-processor statistics), iostat (I/O statistics), netstat (network status), sar (system activity reporter), ptools (process tools), cpustat (CPU performance statistics), busstat (bus-related performance statistics), mdb (modular debugger), prstat (process statistics), truss (trace system calls and signals), apptrace (traces application function calls to Solaris shared libraries) and DTrace.

Solaris 10 has a 64-bit kernel and features process address space. That allows it to deliver a LP64 environment for execution. Long and pointer data types on it are 64 bits wide.

On Solaris 10, thanks to the modular binary kernel, kernel compilations aren't required when kernel parameters are changed or new functionality is added.

Threads can interupt threads that are of lower-priority if they need to run.

Wednesday, December 06, 2006

Changing character set from latin1 to utf8: Alter table vs. dump and import

Chat log with kimseong on #mysql regarding character sets.
 when you dump data in a latin1 table with MySQL, is it converted by default to utf8?
FrankMash: mysqldump? yes it is, but there are options to set it to latin1
kimseong: thanks. I have a table in latin1 that I am planning to dump and then change one field in its structure to be utf8
kimseong: should I dump data in utf8 (default) or specify (latin1) to preserve special chars
FrankMash: alter table can change directly, no need to dump, but backup first anyway
alter table does takes longer than dump/importing in our test
FrankMash: if you data is really stored as latin1, then it does not matter
FrankMash: it gets tricky if data is stored as utf8 in latin1 column
kimseong: thanks. so upon re-importing the data (assuming dump is utf8) will the characters be converted back to the charset specified in the table definition
yes
kimseong: yes that would be tricky. thank you :)

MySQL: Alter table vs. dump / load

Quick question: If one dumps a table (latin1) and then changes the charset of one of the fields to utf8 and then load the dump back, will the result be different than if one had used alter table to convert a field's charset?

Friday, December 01, 2006

relay_log_space_limit stopped working after replication reset?

I recently reset replication on one of my servers and since then my relay_log_space_limit=8G setting has stopped working since the relay log files continue to grow beyond the 8G limit (currently 15G).

Has anyone else experienced this before? Why would it suddenly stop honoring the relay log space limit?

Sunday, November 19, 2006

What's wrong with this graph?

So I am currently working on a MySQL server that is showing behavior as depicted in the following graph.


There can be several possible reasons for these sudden drops. I am working on the issue and will be posting the results. Have you experienced something similar?

Is the Query Cache hurting you?

If you are using memcached, you may want to check your query cache hits : cache inserts ratio. On one of my servers I inherited this ratio was 0.35 indicating that having the query cache turned on was actually harmful. I believe at the very least you need to have a ratio of 1. I was chatting with Sheeri and we both were of the opinion that a ratio of 90 was a very healthy ratio. By turning query cache off by default, we can then selectively cache the queries we need.

Later when I was talking to Ronald, he said he really wanted to be able to query the query cache to see what queries are cached. If will indeed be really cool to see that implemented.

So since turning the query cache off, I have been witnessing more throughput as less resources are being spent to maintain the inserts to query cache (which wasn't being effectively used at all).

I wanted to make all of these a little bit more detailed posts but have so little time. However I did want to post something to may be, expand upon, later. Your comments, questions are welcome and appreciated.

MySQL Camp: Good Time Flies Fast

It's really hard for me to believe how time has just been flying. Ever since I got back from the very awesome MySQL Camp at Google headquarters, I have been planning to write about it but for one reason or another, I couldn't.

Short version is that I had a great time at the MySQL Camp. I got to meet a lot of new and old friends. It was like a dream come true to hang out with everyone. Very special thanks to everyone I met at the conference as I had some very good discussions. Also thanks to:

Kevin Burton of TailRank for his idea
Jay Pipes for his intense hard work to make this event a big success
Leslie "Hacker Herder" Hawthorn, Mickey, Kynan, Chris and others for their excellent hospitality
Jeremy Cole and Eric Bergen of Proven Scaling for the plentiful, unending supply of beer
Brian Aker, MÃ¥rten Mickos, Michael "Monty" Widenius, David Axmark, Zack Urlocker, Ken Jacobs for just being there :)
Google for being an excellent host of this first camp and providing gourmet food and T-Shirts
MySQL for making the event possible
everyone for hanging out at the Tied House

I also got to hangout with Sheeri Kritzer, Baron Schwartz, Kaj Arnö, Kevin Burton, Dathan Pattishall and many other cool people.


There were so many cool sessions at the camp. Ronald Bradford has many good blog posts about the happenings of MySQL Camp at Google. I will write more about this as I get some time.

Overall, something that I would definitely love to attend next time.

Friday, November 10, 2006

Tools from Google

Chip Turner is giving a presentation on some of the tools used by Google.
[root@srv31 ~]# mkdir /google
[root@srv31 ~]# cd /google/
[root@srv31 google]# svn checkout http://google-mysql-tools.googlecode.com/svn/t runk/ google-mysql-tools
A google-mysql-tools/compat_logging.py
A google-mysql-tools/compact_innodb.py
A google-mysql-tools/compat_flags.py
A google-mysql-tools/thread_pool.py
A google-mysql-tools/COPYING
A google-mysql-tools/mypgrep.py
A google-mysql-tools/config_helper.py
A google-mysql-tools/dbspec_lib.py
A google-mysql-tools/command_pool.py
Checked out revision 2.


Tools that people keep re-writing.

All the code is in Python and released under Apache license.

mypgrep (mytop + grep)

If you have more than 5 dbs then it gets kinda difficult to monitor.
Find queries coming from certain IPs etc.

compactinoodb: deals with fragmentation. 20% to 30% increase in speeds becuase the data gets sequential. Must be done offline. Do it on replica and fail-over to replica. If using one large tablespace file instead of per table tablespace then also you can gain performance.

How often do you fragment? Not too often. It depends on how often you use drop table or deletes.

Another way: Change table to MyISAM and then to InnoDB. But this cannot be done on separate servers. You can kill the dump and import. Killing the alter can be bad.

OPTIMIZE/ANALYZE doesn't free up space. It does defragment but doesn't

Google running 4.0 in a lot of places and "cannot use tablespace per table" in all cases.

ERIC: Check how busy disk is compared to QPS and then decide whether to OPTIMIZE.

mod_ndb: REST Web Services API for MySQL

I am sitting in JD Duncan's session "Introducing mod_ndb, a REST Web Services API for MySQL Cluster" as it is really interesting. I kind of wanted to attend the SolidDB storage engine session and the community session happening concurrently, but the mod_ndb stuff is pretty cool.

I am going to try to get the presentation files hopefully from JD.

In case you are wondering, NDB = Network Database.

The HTTP Database uses HTTP instead of SQL. He is planning to create a good HTTP database in the future.

How to get mod_ndb:

(If you are at Google) http://192.168.22.214/code
otherwise: jdd at mysql dot com

Random Notes:

If you are a "PHP shop" its beneficial to use multithreading.

"sort merge join is better than nested loop join"

YouTube uses "Suse" and mostly InnoDB.

Investigate IO issues with SAN.

"recompile memcache to store BLOBs"

Memcache storage engine?

"Falcon is all about row cache"

At Google's Headquarters

Like everyone else, I am very excited to be at Google headquarters attending MySQL Camp. There are more than 200 attendees at the camp, which is really exciting. During the last couple of days, the number participants literally doubled. Folks from YouTube, Google, Yahoo and of course MySQL are all here.

So far I have met Jay Pipes, Jeremy Cole, Eric Bergen, Paul Tuckfield (YouTube and PayPal:paul at tuckfield), Kaj Arno and Sheeri Kritzer. Can't wait to meet others. Will be posting details soon.

Oh, and yes, we got Google T-shirts. Yay!

Also, not to forget, Ronald was introduced as Roland. Funny!

Wednesday, November 01, 2006

Going to MySQL Camp

So November has started and I am really excited to be going to the MySQL Camp. It will be great to finally see everyone again. In other exciting news, Ronald Bradford is coming to New York, Yay!

I will get to Mountain View on Thursday night and will also be renting a car. Jay Pipes and Ronald have already made a "call for free ride" however if you are still looking for a ride, feel free to message me. Since Jay Pipes is hanging out at the airport for sometime on Thursday, I will try to give him some company.

I will be staying at Best Western, Mountain View.

As has been pointed earlier, you do need to register for the camp (FREE) for security reasons. I sent my registration last week.

The Participants page has been updated by someone (Jay probably) to show who is registered. You can now add your name there along with the extra information needed.

PS: On the MySQL Camp home page, the link to the Participants page is broken. I tried to edit it to correct the link but got the message:

This page is locked. Only administrators and moderators may edit it.
If someone with appropriate permissions to the Wiki reads this, can we please correct the link. It currently points to http://mysqlcamp.org/%3Cb%3EParticipants%3C/b%3E instead of http://mysqlcamp.org/Participants

Wednesday, October 11, 2006

MySQL Benchmarking 4: Compiling Super-Smack on Solaris 10

I hate to start the blog post with the same "I've been really busy excuse" but honestly that's the truth. Ever since I wrote the last post, one important thing happened to me. My dentist prescribed me a mouth wash and it turned out that I was severely allergic to it. My upper lip became extremely swollen and remained like that for couple of days until I got a shot of steroid. Ughh, it was really painful. Anyways, time has just been flying by and I have a lot of catching up to do.

This is the part 4 of MySQL Benchmarking series. In the last post I showed you how you can compile Sysbench on Solaris 10. In this post, I will be showing you how you can compile Super-Smack on Solaris 10.

MySQL Super Smack was originally developed by Sasha Pachev (sasha at surveypro dot com), a former MySQL employee. After Sasha, Jeremy Zawodny of Yahoo! took over the maintenance of Super Smack. When Jeremey got really busy with Yahoo! stuff, Tony Bourke took over the Super Smack project.

Getting Super Smack to compile on Solaris 10 was really a headache even though a Sun blog post claimed it wasn't. Nonetheless, I finally succeeded with the help of Andy.

Download Super Smack source (the current version is 1.3).
wget http://vegan.net/tony/supersmack/super-smack-1.3.tar.gz


Navigate to the directory and then uncompress and extract the software
gunzip super-smack-1.3.tar.gz

tar -xf super-smack-1.3.tar


Now set your environment as follows.
LDFLAGS=-lsocket -lnsl -lm
LD_LIBRARY_PATH=/usr/local/mysql/lib:/usr/ccs/lib:/usr/lib:/usr/local/lib:/lib:/usr/ucblib
PATH=/usr/bin:/usr/sbin:/usr/sfw/bin:/usr/ccs/bin:/opt/SUNWspro/bin:/usr/sbin:/usr/bin:/usr/local/bin:.:/usr/ccs/bin:/usr/local/mysql/bin
CXX=/usr/local/bin/g++
CFLAGS=-xarch=v9
CC=/opt/SUNWspro/bin/cc
CXXFLAGS=-m64

Depending on your compiler you may need the following instead
CFLAGS=-m64


Before continuing, ensure you have SUNWflexlex installed and /usr/sfw/bin in your path.

Next step is to run configure

[root@db:/home/fmashraqi/install/bench/super-smack-1.3] ./configure --with-mysql
checking for a BSD-compatible install... ./install-sh -c
checking whether build environment is sane... yes
checking whether make sets $(MAKE)... yes
checking for working aclocal... missing
checking for working autoconf... missing
checking for working automake... missing
checking for working autoheader... missing
checking for working makeinfo... missing
checking for sh... /bin/bash
checking for gcc... /opt/SUNWspro/bin/cc
checking for C compiler default output file name... a.out
checking whether the C compiler works... yes
checking whether we are cross compiling... no
checking for suffix of executables...
checking for suffix of object files... o
checking whether we are using the GNU C compiler... no
checking whether /opt/SUNWspro/bin/cc accepts -g... yes
checking for /opt/SUNWspro/bin/cc option to accept ANSI C... none needed
checking whether we are using the GNU C++ compiler... yes
checking whether /usr/local/bin/g++ accepts -g... yes
checking how to run the C preprocessor... /opt/SUNWspro/bin/cc -E
checking for a BSD-compatible install... ./install-sh -c
checking whether ln -s works... yes
checking for flex... flex
checking for flex... (cached) flex
checking for yywrap in -lfl... no
checking for yywrap in -ll... yes
checking lex output file root... lex.yy
checking whether yytext is a pointer... yes
checking for bison... no
checking for byacc... no
checking for compress in -lz... yes
checking for crypt in -lcrypt... yes
checking for crypt... yes
checking for libmysqlclient...
checking for mysql_real_connect in -lmysqlclient... yes
checking for mysql.h...
checking for egrep... egrep
checking for ANSI C header files... yes
checking for sys/types.h... yes
checking for sys/stat.h... yes
checking for stdlib.h... yes
checking for string.h... yes
checking for memory.h... yes
checking for strings.h... yes
checking for inttypes.h... yes
checking for stdint.h... yes
checking for unistd.h... yes
checking sys/time.h usability... yes
checking sys/time.h presence... yes
checking for sys/time.h... yes
checking for unistd.h... (cached) yes
checking whether time.h and sys/time.h may both be included... yes
checking return type of signal handlers... void
checking for gettimeofday... yes
checking for strerror... yes
configure: creating ./config.status
config.status: creating Makefile
config.status: creating src/Makefile
config.status: creating config.h
config.status: executing default-1 commands

Building with the following options:

MySQL Support..................... yes
PostgreSQL Support................ no
Oracle Support.................... no

If this is not what you intended, please re-run configure.

Thanks for using super-smack!


Now edit the src/Makefile and add
-lsocket -lnsl

to
LIBS = -L/usr/local/mysql/lib -lcrypt -lz  -lsocket -lnsl


Now run make. It will fail.

make  all-recursive
Making all in src
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c super-smack.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c client.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c engines.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c die.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c dictionary.cc
yacc -d super-smack-yacc.yy && mv y.tab.c super-smack-yacc.cc
if test -f y.tab.h; then if cmp -s y.tab.h super-smack-yacc.h; then rm -f y.tab.h; else mv
y.tab.h super-smack-yacc.h; fi; else :; fi
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c super-smack-yacc.cc
flex super-smack-lex.ll && mv lex.yy.c super-smack-lex.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c super-smack-lex.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c query.cc
query.cc: In member function `void Query_report::fd_send(int)':
query.cc:200: warning: cast from pointer to integer of different size
query.cc:200: warning: cast from pointer to integer of different size
query.cc:219: warning: cast from pointer to integer of different size
query.cc:219: warning: cast from pointer to integer of different size
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c parse.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c libsmack.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c mysql-client.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c pg-client.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c ora-client.cc
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c tcp_client.cc
In file included from tcp_client.cc:2:
tcp_client.h: In member function `TcpClient::operator void*()':
tcp_client.h:58: warning: cast to pointer from integer of different
size
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o super-smack
super-smack.o client.o engines.o die.o dictionary.o
super-smack-yacc.o super-smack-lex.o query.o parse.o libsmack.o
mysql-client.o pg-client.o ora-client.o tcp_client.o
-L/usr/local/mysql/lib -lmysqlclient -L/usr/local/mysql/lib -lcrypt
-lz -lsocket -lnsl
Undefined first referenced
symbol in file
yyerror(char const*) super-smack-yacc.o
ld: fatal: Symbol referencing errors. No output written to
super-smack
collect2: ld returned 1 exit status
*** Error code 1
make: Fatal error: Command failed for target `super-smack'
Current working directory
/home/fmashraqi/install/bench/super-smack-1.3/src
*** Error code 1
The following command caused the error:
set fnord ; amf=$2; dot_seen=no; target=`echo all-recursive | sed s/-recursive//`; list='src'; for subdir in $list; do echo "Making $target in $subdir"; if test "$subdir" = "."; then dot_seen=yes; local_target="$target-am"; else local_target="$target"; fi; (cd $subdir && make $local_target) || case "$amf" in *=*) exit 1;; *k*) fail=yes;; *) exit 1;; esac;
done; if test "$dot_seen" = "no"; then make "$target-am" || exit 1; fi; test -z "$fail"
make: Fatal error: Command failed for target `all-recursive'
Current working directory
/home/fmashraqi/install/bench/super-smack-1.3
*** Error code 1
make: Fatal error: Command failed for target `all-recursive-am'


When it does fail, edit the following line (around 107) of super-smack-yacc.cc and search for
YYCONST
and remove it.

Before:
void yyerror(YYCONST char *);


End:
void yyerror(char *);


Then run make again and then make install.

Running make:

make  all-recursive
Making all in src
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c super-smack-yacc.cc
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o super-smack
super-smack.o client.o engines.o die.o dictionary.o
super-smack-yacc.o super-smack-lex.o query.o parse.o libsmack.o
mysql-client.o pg-client.o ora-client.o tcp_client.o
-L/usr/local/mysql/lib -lmysqlclient -L/usr/local/mysql/lib -lcrypt
-lz -lsocket -lnsl
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c gen-data.cc
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o gen-data gen-data.o
die.o -L/usr/local/mysql/lib -lcrypt -lz -lsocket -lnsl
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c test-dictionary.cc
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o test-dictionary
test-dictionary.o dictionary.o die.o libsmack.o
-L/usr/local/mysql/lib -lcrypt -lz -lsocket -lnsl
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c test-client.cc
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o test-client
test-client.o client.o engines.o die.o dictionary.o query.o
libsmack.o mysql-client.o pg-client.o ora-client.o
-L/usr/local/mysql/lib -lmysqlclient -L/usr/local/mysql/lib -lcrypt
-lz -lsocket -lnsl
/usr/local/bin/g++ -DHAVE_CONFIG_H -I. -I. -I..
-I/usr/local/mysql/include -m64 -c test_tcp_client.cc
In file included from test_tcp_client.cc:1:
tcp_client.h: In member function `TcpClient::operator void*()':
tcp_client.h:58: warning: cast to pointer from integer of different
size
/usr/local/bin/g++ -m64 -lsocket -lnsl -lm -o test_tcp_client
test_tcp_client.o tcp_client.o -L/usr/local/mysql/lib -lcrypt -lz
-lsocket -lnsl


Now run make install
Making install in src
/bin/bash ../mkinstalldirs /usr/local/bin
.././install-sh -c super-smack /usr/local/bin/super-smack
.././install-sh -c gen-data /usr/local/bin/gen-data
/bin/bash ./mkinstalldirs /usr/share/smacks /var/smack-data
cp -rp ./smacks/* /usr/share/smacks


Super Smack should build compile fine now. However when you will try to run it, you will get "wrong ELFClass errors"

$ super-smack
ld.so.1: super-smack: fatal: /usr/local/lib/libstdc++.so.5: wrong ELF
class: ELFCLASS32
Killed


This is because of a 32 bit libstdc++.so being used

[root@db:/home/fmashraqi/install/bench/super-smack-1.3] file /usr/local/bin/super-smack
/usr/local/bin/super-smack: ELF 64-bit MSB executable SPARCV9 Version 1, dynamically linked, not stripped
[root@db:/home/fmashraqi/install/bench/super-smack-1.3] file /usr/local/lib/libstdc++.so
/usr/local/lib/libstdc++.so: ELF 32-bit MSB dynamic lib SPARC Version 1, dynamically linked, not stripped


To correct the error, we need to use an alternative 64-bit libstdc++.so
crle -64 -u -l /usr/local/lib/sparcv9


on your system this may be (but the above worked for me)
crle -64 -u -l /usr/sfw/lib/sparcv9


You can also try modifying LIBS environment variable to avoid the above crle stuff.

LIBS=-R/usr/sfw/lib/sparcv9 -R/usr/local/mysql/lib -lnsl -lsocket


At this point Super Smack should be working.

Stay tuned as in future we will be putting all these tools to some good use.

Friday, September 22, 2006

[ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry,

So lately this error message has been appearing more and more in the log files of my slaves

060524 17:45:45 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060801 9:42:13 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060801 13:33:41 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060801 20:41:30 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060802 2:28:21 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060802 3:46:29 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060802 3:48:47 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060802 5:02:53 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060802 6:25:57 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060901 21:58:11 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060902 2:20:46 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060902 2:53:30 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060903 11:37:36 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060903 18:58:28 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060903 21:35:54 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060904 23:23:12 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060905 1:55:37 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060906 1:52:49 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060906 3:35:50 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060906 3:55:13 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060906 9:15:55 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060907 0:16:43 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060907 6:25:03 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060907 7:00:45 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060907 7:10:20 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060907 7:25:40 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 8:31:23 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 14:07:42 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 15:26:54 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 15:44:04 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 17:02:23 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060914 19:34:36 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060915 1:16:43 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060915 6:23:26 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060915 15:10:09 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060915 23:31:01 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 0:34:22 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 0:53:07 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 1:18:46 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 2:14:17 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 3:09:49 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 5:31:41 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 8:16:14 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060916 19:14:32 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 4:31:30 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 5:09:30 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 5:42:54 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 5:59:50 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 6:19:29 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 6:51:12 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 7:28:21 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 9:11:02 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060917 17:12:12 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 1:32:13 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 6:22:10 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 7:57:29 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 8:15:41 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 8:29:47 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 8:57:13 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 9:22:59 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 10:17:37 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060918 16:56:22 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 3:28:49 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 6:44:39 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 9:13:49 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 10:45:18 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 11:19:04 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 11:43:34 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 12:44:05 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 13:51:59 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060919 17:42:23 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 2:21:19 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 6:07:38 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 10:36:03 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 16:39:58 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 18:56:05 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 19:57:34 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 21:06:00 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 22:43:42 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060920 23:40:12 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060921 1:57:11 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060921 7:08:38 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060921 12:53:20 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 4:03:47 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 5:04:55 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 5:43:06 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 6:14:05 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 6:42:56 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 7:37:25 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
060922 10:50:05 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)


I have been investigating the reason for this. Matthew Lord suggested in this bug report that in at least some cases, this reconnection was expected due to the slave_net_timeout value, which on my server is set to default.

mysql> SHOW VARIABLES LIKE 'slave_net_timeout';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| slave_net_timeout | 3600 |
+-------------------+-------+
1 row in set (0.00 sec)


Other timeout variables
mysql> SHOW VARIABLES LIKE '%timeout%';
+--------------------------+-------+
| Variable_name | Value |
+--------------------------+-------+
| connect_timeout | 15 |
| delayed_insert_timeout | 300 |
| innodb_lock_wait_timeout | 50 |
| interactive_timeout | 28800 |
| net_read_timeout | 30 |
| net_write_timeout | 60 |
| slave_net_timeout | 3600 |
| sync_replication_timeout | 0 |
| wait_timeout | 28800 |
+--------------------------+-------+
9 rows in set (0.00 sec)

Seeing the time when the above errors appeared, it is clear that in some cases the reconnection is occuring multiple times within an hour. This leads me to indicate that something else is going on here. One thing I noticed is that the reconnection is happening everytime slave switches to a new log file.
060524 17:45:45 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.001628' position 587419455
060801 9:42:13 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002268' position 754471449
060801 13:33:41 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002269' position 318959997
060801 20:41:30 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002270' position 318856904
060802 2:28:21 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002271' position 318933307
060802 3:46:29 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002272' position 318843694
060802 3:48:47 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002272' position 716398470
060802 5:02:53 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002273' position 318901405
060802 6:25:57 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002274' position 318930542
060830 9:57:59 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002554' position 926355659
060901 21:58:11 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002580' position 1015598952
060902 2:20:46 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002581' position 1015599182
060902 2:53:30 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002582' position 1015592759
060903 11:37:36 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002595' position 544695514
060903 18:58:29 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002596' position 544696110
060903 21:35:54 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002597' position 544609673
060904 23:23:13 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002605' position 149900829
060905 1:55:37 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002606' position 149901053
060906 1:52:50 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002612' position 450457914
060906 3:35:50 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002613' position 450443729
060906 3:55:14 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002614' position 450459188
060906 9:15:55 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002615' position 238998569
060907 0:16:43 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002616' position 238969084
060907 6:25:03 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002617' position 238982702
060907 7:00:45 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002618' position 238992216
060907 7:10:20 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002619' position 238927275
060907 7:25:40 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002619' position 924791139
060914 8:31:23 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002677' position 908960062
060914 14:07:42 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002678' position 908904132
060914 15:26:55 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002679' position 908886495
060914 15:44:04 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002680' position 908915040
060914 17:02:23 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002681' position 192263658
060914 19:34:36 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002682' position 192288645
060915 1:16:44 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002683' position 192314960
060915 6:23:27 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002684' position 192313581
060915 15:10:09 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002685' position 192302436
060915 23:31:01 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002686' position 192257517
060916 0:34:22 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002687' position 192209960
060916 0:53:07 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002688' position 192330206
060916 1:18:47 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002688' position 968380500
060916 2:14:17 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002689' position 968393724
060916 3:09:49 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002690' position 968428073
060916 5:31:41 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002691' position 968448699
060916 8:16:14 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002692' position 968365497
060916 19:14:32 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002693' position 968446897
060917 4:31:30 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002694' position 968446979
060917 5:09:30 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002695' position 968399196
060917 5:42:54 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002696' position 192228405
060917 5:59:50 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002697' position 192266326
060917 6:19:29 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002698' position 192287578
060917 6:51:12 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002699' position 192233081
060917 7:28:21 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002700' position 192219086
060917 9:11:02 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002701' position 192225663
060917 17:12:12 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002702' position 192222395
060918 1:32:13 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002703' position 192232114
060918 6:22:10 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002703' position 968461872
060918 7:57:29 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002704' position 968442279
060918 8:15:41 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002705' position 968373031
060918 8:29:47 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002706' position 968440179
060918 8:57:13 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002707' position 968447052
060918 9:22:59 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002708' position 968443197
060918 10:17:37 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002709' position 968439668
060918 16:56:22 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002710' position 968438755
060919 3:28:49 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002711' position 968427682
060919 6:44:39 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002712' position 968444779
060919 9:13:49 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002713' position 968450077
060919 10:45:18 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002714' position 968435044
060919 11:19:04 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002715' position 968338956
060919 11:43:34 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002716' position 968432120
060919 12:44:05 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002717' position 968443215
060919 13:51:59 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002718' position 968443892
060919 17:42:23 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002719' position 968409684
060920 2:21:19 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002720' position 968436935
060920 6:07:38 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002721' position 968443697
060920 10:36:03 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002722' position 968397302
060920 16:39:58 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002723' position 968383643
060920 18:56:05 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002724' position 968437352
060920 19:57:34 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002725' position 968502168
060920 21:06:00 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002726' position 968409788
060920 22:43:42 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002727' position 968402634
060920 23:40:12 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002728' position 968390187
060921 1:57:11 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002729' position 968358219
060921 7:08:38 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002730' position 968442367
060921 12:53:20 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002731' position 968382723
060922 4:03:48 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002732' position 968402053
060922 5:04:55 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002734' position 968379386
060922 5:43:06 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002735' position 968396895
060922 6:14:05 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002737' position 968438049
060922 6:42:56 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002738' position 968348169
060922 7:37:25 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002739' position 968438301
060922 10:50:05 [ERROR] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'db2-bin.002740' position 968444121


I have the relay_log_space_limit specified and am now wondering if these reconnections are made everytime the slave thread pauses for more space to be freed up.

mysql> SHOW VARIABLES LIKE 'relay_log_space_limit';
+-----------------------+-------------+
| Variable_name | Value |
+-----------------------+-------------+
| relay_log_space_limit | 12884901888 |
+-----------------------+-------------+
1 row in set (0.00 sec)


Actually that makes quite sense. However the reason I would like to investigate it even further is because yesterday MySQL restarted itself immediately after one of these reconnections causing once again, a MyISAM corruption. Your comments, as always are welcome and appreciated.