Ptrace on threads and linux signal handling issues

June 25th, 2008

At Proven Scaling it’s not always all about scaling databases. Sometimes we get to solve other problems not related to scaling at all. We have a client that has been using jmap (unsupported) to grab memory statistics from java. They found that after they ran jmap they were unable to shutdown the jvm without it hanging.

After working on the problem for a bit I found that after jmap ran ps showed the java process as stopped. This is strange since java was still able to process requests. In linux threads are treated as processes, they get a pid just like any other process. To be POSIX compliant linux has the notion of thread groups and a thread group leader so signals can be delivered to an entire thread group.

jmap gets memory statistics by using ptrace on the pid of the thread group leader. When ptracing a thread group leader only that thread is stopped and analyzed. Other threads are free to continue processing. Jmap is a bit buggy in that it attaches to a thread but never detaches. Linux has a safe guard that if the parent of a traced process quits then linux changes the traced processes’ state from traced to stopped because traced processes can’t be killed.

When jmap quits the ps shows the process in state T which means stopped. What it doesn’t say is that only the thread group leader is stopped. To get around the limitations of ps and process states I went directly to proc to get the process state. The example below was done using mysqld instead of java. It shows the process state of all the threads, including the leader during a simulated jmap run.

In this example 20924 is the pid of mysqld. I substituted mysql for java in this example because I had it handy on my dev server. It reacts the same way java does. The bad_trace app simulates jmap by doing a ptrace attach and exiting before a detach. It sleeps for a big in the middle so I can get the process state of a normal traced process. Here is the source for bad_trace if you want to follow along at home.


#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/ptrace.h>

int main(int argc, char **argv)
{
pid_t pid = 0;

if (argc < 2)
{
printf("First arg should be a pid\n");
return 1;
}

printf("argc %d\n", argc);
pid = atoi(argv[1]);
printf("Attaching to pid (%d)\n", pid);
ptrace(PTRACE_ATTACH, pid, NULL, NULL);
printf("Sleeping for ten seconds\n");
sleep (10);

return 0;
}

The bad_trace app does a ptrace attach and exits without detaching.

This is the normal state on an idle server all threads are sleeping.

ebergen@kamet:(/proc/20924/task) grep State */status
20924/status:State: S (sleeping)
20926/status:State: S (sleeping)
20927/status:State: S (sleeping)
20928/status:State: S (sleeping)
20929/status:State: S (sleeping)
20931/status:State: S (sleeping)
20932/status:State: S (sleeping)
20933/status:State: S (sleeping)
20934/status:State: S (sleeping)

I execute bad_trace which puts the thread group leader into traced mode waiting for bad_trace to examine it.


ebergen@kamet:(/proc/20924/task) ~/bad_trace 20924
Attaching to pid (20924)
Sleeping for ten seconds
[1]+ Stopped ~/bad_trace 20924

I suspend bad_trace to grab the stats. You can see that the thread group leader has stopped in tracing mode waiting for bad_trace to examine it and tell it to continue.


ebergen@kamet:(/proc/20924/task) grep State */status
20924/status:State: T (tracing stop)
20926/status:State: S (sleeping)
20927/status:State: S (sleeping)
20928/status:State: S (sleeping)
20929/status:State: S (sleeping)
20931/status:State: S (sleeping)
20932/status:State: S (sleeping)
20933/status:State: S (sleeping)
20934/status:State: S (sleeping)
ebergen@kamet:(/proc/20924/task) fg
~/bad_trace 20924

bad_trace resumes and exits without detaching from the traced process. To enable an admin to kill the traced process linux does some cleanup work by changing it’s state from traced to stopped. Now we can send signals to the thread group and they will be able to respond.


ebergen@kamet:(/proc/20924/task) grep State */status
20924/status:State: T (stopped)
20926/status:State: S (sleeping)
20927/status:State: S (sleeping)
20928/status:State: S (sleeping)
20929/status:State: S (sleeping)
20931/status:State: S (sleeping)
20932/status:State: S (sleeping)
20933/status:State: S (sleeping)
20934/status:State: S (sleeping)

Naturally we don’t want the thread group leader stopped if everything is OK so I send it a continue signal to resume operation. This is where things get weird.


ebergen@kamet:(/proc/20924/task) kill -CONT 20924

Instead of the thread group leader resuming operation linux decides that it’s a good idea to stop all threads instead.


ebergen@kamet:(/proc/20924/task) grep State */status
20924/status:State: T (stopped)
20926/status:State: T (stopped)
20927/status:State: T (stopped)
20928/status:State: T (stopped)
20929/status:State: T (stopped)
20931/status:State: T (stopped)
20932/status:State: T (stopped)
20933/status:State: T (stopped)
20934/status:State: T (stopped)

Sending a second continue signal does the right thing and the process resumes.


ebergen@kamet:(/proc/20924/task) kill -CONT 20924
ebergen@kamet:(/proc/20924/task) grep State */status
20924/status:State: S (sleeping)
20926/status:State: S (sleeping)
20927/status:State: S (sleeping)
20928/status:State: S (sleeping)
20929/status:State: S (sleeping)
20931/status:State: S (sleeping)
20932/status:State: S (sleeping)
20933/status:State: S (sleeping)
20934/status:State: S (sleeping)

I did some digging in the kernel and didn’t see any specific reason for this behavior. I suspect it’s a kernel bug that has never been uncovered because tracing a single thread of a threaded process isn’t a very common operation.

Splitting flush logs command

May 19th, 2008

Last week I was working with a client that rediscovered a bug where setting expire_logs_days and issuing a flush logs causes the server to crash. It’s MySQL Bug #17733 if you want to have a look. Seeing MySQL crash was enough inspiration to fix something that I and others have wanted to fix in MySQL for years.

Currently a flush logs command tries to flush all of the following logs in order:

  • General Log
  • Slow Query Log
  • Binary Log
  • Relay Log
  • Store Engine Logs (If available)
  • Error Log

The reason I wanted to fix this is because my client was issuing a flush logs to rotate the error log on a server with no replication. The crash was caused by replication. With individual flush logs it’s less likely for this to happen again in the future. People can simply issue a query for the log they want to flush. The new commands flush logs named in the command. They are:

  • flush general log;
  • flush slow log;
  • flush binary log;
  • flush relay log;
  • flush engine logs;
  • flush error log;

The words log and logs are interchangeable. The query “flush general log” is just as valid as “flush general logs” even though there is only one log. I submitted the patch as a fix for MySQL Bug #14104.

The patch, flush_logs.patch was diffed against 6.0.4 but also applies on 5.1.24.

Rotation for different log files isn’t uniform. Rotating the slow log simply closes and opens it. I’m planning to write a second patch that rotates log files using the same numbered scheme as binary logs. This fixes the rotation for slow and general log as well as eliminating the annoying issue of error logs being destroyed after they are rotated to foo.log-old.

This patch hasn’t been accepted or committed yet so if you have any suggestions on how to make it better please let me know.

Auto vertical output lands in MySQL 6.0.4

April 21st, 2008

Have you ever executed a query from the MySQL command line client only to find that the output wrapped and the result is unreadable? In the past you have to run the query again with \G instead of ; or \g to get it to display the output in a vertical mode. My feature in MySQL 6.0.4 fixes that. The auto-vertical-output option tells the command line client to display the results in vertical format if the results are going to be too wide to display horizontally. It does this without re-executing the query because MySQL passes the length of each column in the result set. If the client isn’t able to determine the width of the screen it will default to 80 chars.

Replication tutorial notes - part 2

April 14th, 2008

This is a continuation of the MySQL User Conference replication notes part one.

The session is opening up talking about failover. The shared disk in this case is drbd. DRBD is a fine product for replicating block devices of single disk systems. It’s made redundant by raid and doesn’t provide as much protection as binary log failover. You can find my notes on why I don’t recomment DRBD for MySQL in drbd in the real world.

Lars went a bit quick through the other two configurations. I’ll try to review the slides and post comments.

The next configuration is using federated. The federated storage engine has many problems that make it almost useless for any production deployment. Mats says, “Federated isn’t the fastest engine in the world”. That’s an understatement. Join on two tables as they describe it is almost impossible. Aside from the performance issues this is my favorite limitation of the federated engine, “There is no way for the FEDERATED engine to know if the remote table has changed. The reason for this is that this table must work like a data file that would never be written to by anything other than the database system. The integrity of the data in the local table could be breached if there was any change to the remote database.”

Lars mentions Jeremy’s failover design that is recommended by Proven Scaling. Thanks Lars!

There is a lot of confusion about the difference between row based and statement based replication. Hopefully my row based replication post can clear up some of the confusion.

For keeping things simple and easy to debug I recommend sticking with either row or statement based replication. Teaching the implications of each to application developers is going to be more difficult than sticking with one model. The exception is things that can’t use row based replication like DML statements.

When using a SAN make sure you have redundant SANs, your backups aren’t on the same SAN as mysql and that if you have to use a shared san you have good control over the resources. MySQL is very sensitive to i/o latency increases. If someone else does a large operation on the SAN it can increase the i/o latency in mysql causing operations to take longer which can bring down your application.

I don’t recommend using a hardware load balancer to manage write load between masters. There is a risk of sending writes to both masters at the same time. In a properly configured dual master setup half the writes will be rejected on a read only error. The worst case is that writes go to both masters causing replication error and inconsistent data.

The tutorial is wrapping up now. I look forward to using row based replication 5.1. Thanks Lars and Mats.

Replication tutorial notes - part 1

April 14th, 2008

I’m attempting to live blog corrections and notes while sitting in the replication tutorial. Lars is covering available options in MySQL replication. I’m going to attempt to cover some recommended best practices and things that are possible to do in MySQL but should be avoided. Please keep in mind that I’m writing this during the presentation. If anything is confusing post a comment and I will clean it up.

When designing a MySQL architecture that are several possible configurations. Two that should be avoided are dual master where you write to both masters. Configuring replication in a dual master dual writer setup means there is no single authority on the data. There is also no need to write to both masters as this doesn’t give you any performance improvement. Each master has to process the same sql statements. One step further is circular replication that wasn’t mentioned in the talk but has been in other publications. When using three or more masters if one dies there is no way to restore it without brining down the other masters.

There are several configuration options for filtering data on the slaves. You can filter but the current database or by tables. My recommendation is to keep the data on the slave the same as the master as much as possible. When the slave is different you’re much more likely to have queries succeed on the master but fail on the slave. The worst of these options is replicate-do-db. This option filters queries based on “USE db”. If the use db is set differently on the master the query will succeed but can be passed through the slave without executing. This is a silent failure and won’t cause replication to stop.

A quick note about show binlog events. This is similar to mysqlbinlog in that it dumps events in the binary log. The difference is that show binlog events doesn’t include set variables.

When using relay slaves it’s very important to always configure them in pairs. If a relay slave dies there is no good way to to connect it’s slaves to the relay slave’s master. Using blackhole can cause silent failures to be passed through as well as issues with auto increment and storage engine differences. Blackhole should always be avoided.

Reset slave should function the way it does on the slide in that it should delete everything and leave the slave in a blank state. It actually deletes the logs and resets the host, user, and password. The functionality has been changed a few times in different version so be sure to check the manual. The differences are in that mysql may keep the old host information in memory or it may forget.

Purge master logs was covered briefly. It should be noted that purge master logs won’t purge logs that a connected slave hasn’t downloaded. If a slave is disconnected the master will happily delete logs that a slave hasn’t downloaded yet. I recommend keeping at least 7 days of logs on the master for situations where slave gets disconnected.

Now we’re into the section of specialized slaves. These slaves have a subset of data on the master. Avoid this as much as possible see my row based replication post about half way down for the reasons.

The slide for HA + Scale out has dual master with all of the slaves hanging off of one master. It’s better to have slaves hanging off each master because if the active master dies hard enough that you can’t get binlog offsets from it then there isn’t a good way to change slaves over to the existing master. Balancing your slaves will make it easier to failover. Ah excellent someone up front just pointed this out.

Innodb handler_delete and handler_update status

March 26th, 2008

I woke up this morning to a nice surprise. Peter Zaitsev from MySQL Performance Blog mentioned my fix for a crash in MySQL. Thanks Peter! That reminded me that I need to write this post about another fix.

A storage engine is called a “handler” in MySQL internals. Handler events are per row at the storage engine layer. For example an insert query that inserts 3 rows will cause one Com_insert increment and 3 handler_write increments. The way these statistics are implemented the storage engine is responsible for incrementing statistics itself. Innodb is missing function calls to increment the handler_delete and handler_update status variables. I’ve filed bug #35537 with MySQL that contains a patch adding in the missing statistic_increment calls.

It seems strange that storage engines are responsible for incrementing global statistics. Brian Aker tells me that this is because the handler interface is a direct pass through to the storage engine. I’m guessing that it was easier to do the statistics increment in the storage engine rather than chase down all the handler calls in the server and change them to functions that call the handler and increment statistics.

ref or null join type crash and patch

March 23rd, 2008

While working with a client we found a query that can crash MySQL. It has to do with ref_or_null outer joins where the table contains a null value. MySQL fails to tell the storage engine to initialize the index before reading from it. It crashes when used with MyISAM tables but it could result in an incorrect key file for table error with other storage engines. You can find the test case and patch in bug #34945. I’ve waited to blog about it until MySQL approved my patch. As of this writing my patch has been approved and committed for release in 5.0.60.

MySQL Enterprise Registration Emails

March 5th, 2008

[Updated: 2008-03-05 Jeremy writes to tell that I left out the provenscaling.com contact form submission on the 21st and the blank email with a pdf on the 27th]
[Updated: 2008-03-26 Rob Young from MySQL AB sent me an email on the 17th saying, "We are currently working to implement PayPal to cut down on the email interactions we have in place around our manual fulfillment process. Testing is going well and we should have this implemented in the next few weeks."]

Recently Proven Scaling decided to purchase a MySQL Enterprise subscription. We will be evaluating Enterprise to see if it’s knowledge base is valuable to our customers as a supplement to Proven Scaling’s consulting services.

The subscription process seems remarkably manual on MySQL’s part. It involves them sending us five emails (not counting the mysql.com registration), all of which are from different senders. Some are from people others are automated. Here is a breakdown in chronological order:

Feb 20 12:25PM
shop@mysql.com - Online Order Confirmation

Feb 20 8:20PM
support-feedback@mysql.com - Welcome to MySQL Enterprise

Feb 20 8:49PM
enterprise-feedback@mysql.com - MySQL Enterprise: User account password changed

Feb 21 8:51AM
provenscaling.com contact form submission with creepy upsell - “Please provide my contact information to the person(s) responsible so I can assist with future orders. There are packaging options that are not available with on line purchases….”

Feb 22 10:39AM
ar@mysql.com - Your - MySQL - Invoice

Feb 22 8:41PM
rwolfejones@mysql.com - Credit Card receipt from MySql

Feb 27th 4:25pm
julie@mysql.com - MySQL receipt for Invoice

This seems a bit excessive. It also raises several questions about the registration process. Why does it take 8 hours for the order to be filled? Does someone have to manually approve the order? The second email is “Welcome to MySQL Enterprise” from support-feedback while the third email is from enterprise-feedback with notification of an account change. This email is because Enterprise generates and emails out a password on the first login.

What’s the difference between support-feedback and enterprise-feedback? A few days later after the account is setup accounts receivable sends us an invoice. Then ten hours later a credit card receipt. Why isn’t MySQL using automated credit card processing? The credit card receipt also looks like it was copied and pasted into the email.

I hope that we’re some kind of special case and that not all of the MySQL Enterprise customers have to go through the same process. I look forward to hearing comments from MySQL on this process.

The difference between %iowait from sar and %util from iostat

February 25th, 2008

Recently I needed to explain the difference between %iowait from sar and %util from iostat. They both measure outstanding i/o requests but their method for measurement is slightly different. From the sar man page iowait is defined as:

iowait:
Percentage of time that the CPU or CPUs were idle during which the system had an outstanding disk I/O request.

Iostat has a slightly different definition of it’s disk metric which is %util (percent utilization).

%util:
Percentage of CPU time during which I/O requests were issued to the device (bandwidth utilization for the device). Device saturation occurs when this value is close to 100%.

The definitions are very similar but there is a slight difference. %iowait uses the per cpu timings from /proc/stat. /proc/stat breaks down cpu time into four parts. The fields are defined as:

  • user: normal processes executing in user mode
  • nice: niced processes executing in user mode
  • system: processes executing in kernel mode
  • idle: twiddling thumbs
  • iowait: waiting for I/O to complete
  • irq: servicing interrupts
  • softirq: servicing softirqs
  • steal: involuntary wait

The only one important for this discussion is iowait. Inside the kernel iowait time is bascially time processes spend waiting for reqeusts that have been sent into the i/o scheduler.

iostat’s %util is measured using /proc/diskstats which keeps track of the number of miliseconds devices spent with outstanding i/o requests. iostat compares uptime of the server to the number of miliseconds spent doing i/o to determine how busy the disk is.

The main difference I can see between these two approaches is that sar will count the time a i/o request spent in the i/o scheduler where iostat won’t.

A few test runs show wildly different results from the two different tools. While running bonnie++, iostat, and sar in parallel some times iostat returns 100 %util and sar returns 25% iowait. During the read phase of bonnie++ iostat can return 100% where sar returns 1%. It’s very strange…

I’m still a bit unclear about all the differences. I’ll update this post when I learn more.

Pho Hoa’s Got Wood!

February 9th, 2008

For those of you that don’t live in the culturally diverse bay area, pho is a Vietnamese soup consisting of rice noodles in a clear broth and various meats. Around here it’s typically eaten with over sized plastic chopsticks. The problem is that wet noodles are very difficult to pick up with plastic chopsticks. The Pho Hoa in Mountain View recently switched from plastic to wooden chopsticks. Hooray! Chopstick challenged patrons like myself can now safely eat pho without risk of a large blob of slippery noodles sliding off the sticks into the bowl blasting them with scalding hot broth.

Next they need to get rid of their $10 minimum Visa charge.