Showing posts with label logs. Show all posts
Showing posts with label logs. Show all posts

Thursday, August 11, 2011

Usability improvements in Tungsten Replicator 2.0.4

If you love a software product, you should try to improve it, and not be afraid of criticizing it. This principle has guided me with MySQL (where I have submitted many usability bugs, and discussed interface with developers for years), and it proves true for Tungsten Replicator as well. When I started working at Continuent, while I was impressed by the technology, I found the installation procedure and the product logs quite discouraging. I would almost say disturbing. Fortunately, my colleagues have agreed on my usability focus, and we can enjoy some tangible improvements. I have already mentioned the new installation procedure, which requires just one command to install a full master/slave cluster. I would like to show how you can use the new installer to deploy a multiple source replication topology like the following: The first step is to install one master in each node. I can run the commands from node #4, which is the one that will eventually receive the updates from the remote masters, and where I need to install the slave services:
TUNGSTEN_BASE=$HOME/newinst
SERVICES=(alpha bravo charlie delta)
REPLICATOR=$TUNGSTEN_BASE/tungsten/tungsten-replicator/bin/replicator

for N in 1 2 3 4
do
    INDEX=$(($N-1))

  ./tools/tungsten-installer \
    --master-slave \
    --master-host=qa.r$N.continuent.com \
    --datasource-user=tungsten \
    --datasource-password=secret \
    --service-name=${SERVICES[$INDEX]} \
    --home-directory=$TUNGSTEN_BASE \
    --cluster-hosts=qa.r$N.continuent.com \
    --start-and-report
done
The above loop will install a master (remotely or locally) in the four servers. Then I need to create the slave services. To do it, I use the updated configure-service in the tools directory.
TUNGSTEN_TOOLS=$TUNGSTEN_BASE/tungsten/tools
COMMON_OPTIONS='-C -q 
    --local-service-name=delta 
    --role=slave 
    --service-type=remote 
    --allow-bidi-unsafe=true 
    --datasource=qa_r4_continuent_com' 

$TUNGSTEN_TOOLS/configure-service $COMMON_OPTIONS --master-host=qa.r1.continuent.com  alpha 
$TUNGSTEN_TOOLS/configure-service $COMMON_OPTIONS --master-host=qa.r2.continuent.com  bravo
$TUNGSTEN_TOOLS/configure-service $COMMON_OPTIONS --master-host=qa.r3.continuent.com  charlie 

$TUNGSTEN_BASE/tungsten/tungsten-replicator/bin/replicator restart
$TUNGSTEN_BASE/tungsten/tungsten-replicator/bin/trepctl services
These commands create the slave services locally in Delta. After restarting the replicator, a simple test will be creating something different in each master, and check that the data has replicated to the single slave. The latest improvement in matter of usability is the simplification of the replicator logs. Until a few days ago, if you had an error in the replicator, you would get a long list of not exactly helpful stuff. For example, if I create a table in a slave, and then create the same table in the master, I will break replication. The extended log would produce something like this:
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,216 [tsandbox - q-to-dbms-0] ERROR pipeline.SingleThreadStageTask Event application failed: seqno=1 fragno=0 message=java.sql.SQLException: Statement failed on slave but succeeded on master
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,217 [tsandbox - Event dispatcher thread] ERROR management.OpenReplicatorManager Received error notification, shutting down services: Event application failed: seqno=1 fragno=0 message=java.sql.SQLException: Statement failed on slave but succeeded on master
INFO   | jvm 1    | 2011/08/11 18:10:52 | com.continuent.tungsten.replicator.applier.ApplierException: java.sql.SQLException: Statement failed on slave but succeeded on master
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.applier.MySQLDrizzleApplier.applyStatementData(MySQLDrizzleApplier.java:183)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.applier.JdbcApplier.apply(JdbcApplier.java:1233)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.applier.ApplierWrapper.apply(ApplierWrapper.java:101)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.runTask(SingleThreadStageTask.java:498)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.run(SingleThreadStageTask.java:155)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2011/08/11 18:10:52 | Caused by: java.sql.SQLException: Statement failed on slave but succeeded on master
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.applier.MySQLDrizzleApplier.applyStatementData(MySQLDrizzleApplier.java:139)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       ... 5 more
INFO   | jvm 1    | 2011/08/11 18:10:52 | Caused by: java.sql.SQLSyntaxErrorException: Table 't1' already exists
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at org.drizzle.jdbc.internal.SQLExceptionMapper.get(SQLExceptionMapper.java:78)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at org.drizzle.jdbc.DrizzleStatement.executeBatch(DrizzleStatement.java:930)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at com.continuent.tungsten.replicator.applier.MySQLDrizzleApplier.applyStatementData(MySQLDrizzleApplier.java:125)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       ... 5 more
INFO   | jvm 1    | 2011/08/11 18:10:52 | Caused by: org.drizzle.jdbc.internal.common.QueryException: Table 't1' already exists
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at org.drizzle.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:500)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at org.drizzle.jdbc.internal.mysql.MySQLProtocol.executeBatch(MySQLProtocol.java:546)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       at org.drizzle.jdbc.DrizzleStatement.executeBatch(DrizzleStatement.java:917)
INFO   | jvm 1    | 2011/08/11 18:10:52 |       ... 6 more
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,218 [tsandbox - Event dispatcher thread] WARN  management.OpenReplicatorManager Performing emergency service shutdown
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,219 [tsandbox - Event dispatcher thread] INFO  pipeline.Pipeline Shutting down pipeline: slave
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,219 [tsandbox - q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Terminating processing for stage task thread
INFO   | jvm 1    | 2011/08/11 18:10:52 | 2011-08-11 18:10:52,219 [tsandbox - q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Last successfully processed event prior to termination: seqno=0 eventid=mysql-bin.000002:0000000000000426;20
Did you see the reason for the error? No? Neither did I. I would need to open the THL, look for event #1, and determine what it was. Instead, the new user.log looks like this:
2011-08-11 18:10:52,216 ERROR Received error notification: Event application failed: seqno=1 fragno=0 message=java.sql.SQLException: Statement failed on slave but succeeded on master
Caused by : java.sql.SQLException: Statement failed on slave but succeeded on master
Caused by : Statement failed on slave but succeeded on master
Caused by : Table 't1' already exists
Caused by : Table 't1' already exists
2011-08-11 18:10:54,721 INFO  State changed ONLINE -> OFFLINE:ERROR
2011-08-11 18:10:54,721 WARN  Received irrelevant event for current state: state=OFFLINE:ERROR event=OfflineNotification
That's much better. It is not perfect yet, but it will be soon. Right now, it tells me what is wrong without forcing me to go hunting for it amid hundreds of stack trace lines. Give it a try, using the latest replicator build.

Wednesday, March 02, 2011

beware of the log

The MySQL general log is one of my favorite features for a quick debug. I especially like the ability of starting and stopping it on demand, which was introduced in MySQL 5.1.
However, using the general log has its drawbacks.
Today I was debugging a nasty bug that results from two statements that should be applied sequentially, but that were instead concurrent. These kind of problems are hard to cope with, as they are intermittent. Sometimes all goes well, and you get the expected result. And then, sometimes the statements fly on different directions and I stare at the screen, trying to understand where did they stray.
After some try-and-fail, I decided to enable the general log just before the offending statements, and to turn it down immediately after. Guess what? With the general log on, the test never failed. What was an intermittently failing test became an always succeeding test.
What happened is that the general log delayed the query execution just enough for the following statement to arrive when it was expected.
In the end, the bug had to be unveiled using white box techniques.
Moral of the story: using a general log alters the status of the server. If you use it, be prepared to deal with its side effects.

Monday, April 27, 2009

MySQL 5.4 performance with logging


MySQL 5.4
About a month ago, I published the results of MySQL 5.x performance with logging. The results covered several versions, from 5.0.45 to 5.1.33. Among the conclusions of the post was the consideration that MySQL 5.0.x is faster than MySQL 5.1 in read only operations. I hinted that better results may come for MySQL 5.1. When I wrote that post I had, in fact, an ace up my sleeve, because I had already benchmarked the performance of MySQL 5.4, using the same criteria shown in my previous post. The results, as you can see from the charts below, tell that you don't need to downgrade to 5.0 to achieve the performance you want, but MySQL 5.4 may be the right choice.

MySQL 5.1 + 5.4 read-only logging performance

MySQL 5.1 + 5.4 read-only logging performance

MySQL 5.0 read-only Logging performance

MySQL 5.0 read-only Logging performance

MySQL 5.1 + 5.4 binlog performance

MySQL 5.1 + 5.4 binlog performance

MySQL 5.0 binlog performance

MySQL 5.0 binlog performance

A piece of trivia. On April 9, users of MySQL Sandbox may have noticed that I left a clue of what was about to happen. Among the accepted versions, you could see "5.3, 5.4. 5.5" :-)

Wednesday, March 25, 2009

MySQL 5.x performance with logging

There has been much talking about MySQL performance related to logging. Since MySQL 5.1.21, when Bug #30414 was reported (Slowdown (related to logging) in 5.1.21 vs. 5.1.20) I have been monitoring the performance of the server, both on 5.0 and 5.1.
Recently, I got a very powerful server, which makes these measurements meaningful.
Thus, I measured the performance of the server, using all publicly available sources, because I want this benchmark to be repeatable by everyone.
I will first describe the method used for the benchmarks, and then I report the results.

The server

The server is a Linux Red Hat Enterprise 5.2, running on a 8core processor, with 32 GB RAM and 1.5 TB storage.

$ cat /etc/redhat-release
Red Hat Enterprise Linux Server release 5.2 (Tikanga)

$ cat /proc/cpuinfo |grep "processor\|model name" | sort |uniq
model name : Intel(R) Xeon(R) CPU E5450 @ 3.00GHz
processor : 0
processor : 1
processor : 2
processor : 3
processor : 4
processor : 5
processor : 6
processor : 7

cat /proc/meminfo
MemTotal: 32967056 kB
MemFree: 22790272 kB

Method

I downloaded the source code tarball, as released for every version of MySQL, from 5.0.45 to 5.0.77 and from 5.1.20 to 5.1.33. I also took the code for 5.0.79 from the Bazaar tree on Launchpad.
For each version, I did the following:
* expanded the tarball to a directory;
* compiled the code using ./BUILD/compile-pentium64-max;
* built a binary using ./source/make_binary_distribution;
* installed the binary using MySQL Sandbox, assigning 5GB of RAM to innodb_buffer_pool_size;
* Tun the sysbench OLTP transactional test, 8 threads, 1,000,000 records, 1 minute run;

After installing, all database instances where shut down, and only one database server was active at any given time during the tests, to have clean results.
The servers were cleaned up, with all databases and log files removed between tests.
Additionally, all operating system memory cache was erased between tests.

The sysbench commands used for the tests were the following:
sysbench --test=oltp --oltp-table-size=1000000 \
--mysql-db=test --mysql-user=msandbox \
--mysql-password=msandbox --mysql-host=127.0.0.1 \
--mysql-port=$PORT --num-threads=8 prepare

sysbench --test=oltp --oltp-table-size=1000000 \
--mysql-db=test --mysql-user=msandbox \
--mysql-password=msandbox --mysql-host=127.0.0.1 \
--mysql-port=$PORT --max-time=60 --oltp-read-only=on \
--max-requests=0 --num-threads=8 run

sysbench --test=oltp --oltp-table-size=1000000 \
--mysql-db=test --mysql-user=msandbox \
--mysql-password=msandbox --mysql-host=127.0.0.1 \
--mysql-port=$PORT --max-time=60 --oltp-read-only=off \
--max-requests=0 --num-threads=8 run

The not so exciting results first


Using Sysbench with --oltp-read-only=on, MySQL 5.0 outperforms MySQL 5.1 constantly. In a read-only situation, it looks like 5.0 is much better than 5.1.

read only 5.0

read-only 5.1
Additional bad news is that Bug #30414 is still unfixed. Table logging takes away 50% of performance and thus is not recommended. General logs on file, instead, with the ability of logging on demand, is an affordable diagnostic tool.
Partial good news can be deducted by the ability of MySQL 5.1 to perform better with file logging, compared to MySQL 5.0.

The good news


Normal operations in a MySQL server are not read only, and include a binary log. For my second batch of testing, then, I compared performance with --oltp-read-only=off with and without binary logs. In this situation, MySQL 5.1 outperforms MySQL 5.0 in all cases. It's also nice to observe that the performance is improving gradually from earlier versions to recent ones. Kudos to MySQL engineers for their constant dedication to the server improvement.

Read-write 5.0

read-write TPS 5.1
The even better news is that, in MySQL 5.1, performance gain on 5.0.x has been increasing steadily.

What does this tell you? That MySQL 5.1 is much, much better than 5.0 for online transaction processing, while MySQL 5.0 seems to be better at concurrent read-only operations. My immediate reaction is that I should use MySQL 5.1 for a master and 5.0 for slaves. However, there are two considerations that stop me. First, using a master of a higher version than the slaves is not recommended, although some tests that I made after this discovery show that you can actually do it, provided that you don't use any specific MySQL 5.1 features. And second, the improvement path is such, that I believe MySQL 5.1 is going to catch up on 5.0 for read-only operations. As soon as this happens, I will let you know immediately! Probably, we will know more at the Users Conference 2009.

Summing up

I think that MySQL 5.1 has much to offer in comparison to 5.0.
The tests that I have performed are not definite. Sysbench is just one of the possible tests, and it doesn't mean that your production server will follow the same pattern or have the same performance. It's just an independent way of measuring the server performance, and especially is a repeatable way, which everyone can reproduce.
I warmly invite you to repeat these tests on different machines and let me know your results.

Sunday, January 04, 2009

Q&A; on MySQL 5.1

Listening to Sheeri's presentation on MySQL 5.1, I saw that there are a few questions left unanswered. I am listing here some of the questions that I found interesting, plus a few from an early webinar on the same topic.

Q: does Partitioning physically split data?
A: No. Some engines (MyISAM, Archive) do a physical split, but this is not necessary, as you see if you apply partitioning to a InnoDB table. Partitioning is a logical split of data, for easy retrieval. It is completely transparent to the user.
Q: Can you set partitions to different servers?
A: No. Partitions are logical parts of one table within one server. Partitioning through the Federated engine is not supported.
Q: How efficient are Row-Based Replication operations compared to Statement based ones?
A: RBR is faster when the insert or update is the result of an expensive operation. Otherwise, the efficiency for insertion and deletion is roughly equivalent. Updates on multiple records are usually more expensive with Row-Based Replication.
Q: Is the event scheduler polluting the Error Log?
A: yes, unfortunately. But it has been fixed in 5.1.31 (See also Bug#38066. As you can see from the discussion in the bug report page, it was object of a long and intense discussion.
Q: Can you send email through the Event Scheduler?
A: No. But you can integrate it with a hack using MySQL Proxy through Federated tables.
Q: Is there an equivalent to SHOW FULL PROCESSLIST from the INFORMATION SCHEMA?
A: Yes. Actually, SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST is equivalent to SHOW FULL PROCESSLIST. See the manual
Q: Are partitions supported in replication?
A: Yes. Partitions are fully supported in replication. The only problem you may have is when using the "DATA DIRECTORY" and "INDEX DIRECTORY" clauses, if the slave does not have the same directory structure and OS privileges as the master.
Q: Is the event scheduler supported in replication?
A: Yes. The event definition is replicated but left inactive, and the effects of the event scheduler are replicated as any other statement. When promoting a slave to master, it is necessary to manually activate the events.
Q: What happened to RENAME DATABASE? Why is not available anymore?
A: RENAME DATABASE was a command implemented in the early stages of MySQL 5.1, for the specific purpose of helping the upgrade script to set the database name with the appropriate charset. It had a deadly side effect, though. It removed all the objects associated with the database. Thus, it was removed and renamed in such a way that nobody would use it for simply renaming a database.
Q: How does the slow query log work with microseconds?
A: To catch slow queries with duration measured in less than 1 second, you can set the long_query_time global variable to a fractional value. E.g. set global long_query_time=0.5; will enable queries taking more than 1/2 second to be logged to the slow queries log.

Wednesday, October 29, 2008

MySQL 5.1.29 - Last RC - small changes


MySQL

MySQL 5.1.29 is available.
This is the last RC. Yes. You heard me right. The long wait is almost over. The next release will be GA.
Sharpen your tools, and get ready to use partitions, row-based replication, and the event scheduler in production without that uneasy sense of guilt that you feel when using non-GA software.

There are a few small changes in MySQL 5.1.29.

SHOW PROFILES

It was already in a preview, but now SHOW PROFILES is available in 5.1 binaries. As you may recall, it is not active by default. It becomes active when the session variable profiling is set.
This feature is going to be very useful when measuring the impact of partitioning or RBR on your queries. I will do some testing soon.

Logging

Log on demand is one of the main features of MySQL 5.1. It means that you can enable and disable general logs and slow query logs without restarting the server. You can also change the log file names, again without a restart.
What was missing was the ability of setting a log file name in the options file, without actually starting the logging. The old option log, could set the general log file name, but it will also start the logging immediately. If you want to set the log file name without activating the logging, now you can use general_log_file=filename or slow_query_log_file=file_name in the options file. These features were already available as system variables, but not as startup options.

Row-base logging safety

From this version, setting the binlog format for a session will require the SUPER privilege.
This change was decided to make it consistent with similar events. If you want to stop or enable the binary log, you can use SET SQL_LOG_BIN=0, but only if you have the SUPER privilege. Both suspending the binary logging and changing its format are affecting replication, and as such, the SUPER privilege is required.

For the complete list of changes affecting MySQL 5.1.29, please look at the manual.

Monday, August 13, 2007

How MySQL 5.1 is going to change your life

Are you getting ready for MySQL 5.1? You should. I know that it's taken a long way from alpha to beta, but now it is really close to GA. Really. There is no way it's going to stay beta forever. Very soon someone in the high management will realize that all the outstanding bugs were fixed, and MySQL 5.1 is ready for prime time.
And then, you will have to get used to it. Meaning that there a lot of stuff that is so attractive, that you will want to explore the manual in search of guidance.
Let me give you a preview of what's there for you.
Partitioning

Better start reading some theory on this stuff. If you have performance problems with huge loads of data, this is really what you should be doing. Partitioning is a chunk of pure performance hooked to a database. It's not in any way related to relational theory, and you don't need to redesign your database, but surely you need to rethink it in terms of partitioning.
Rush to read the manual and Robin Schumacher introductory article. If you really want to get the most about partitioning, though, you should check The Art of SQL (Note: I am not affiliated with the author or the publisher. This advice is out of my goodness only)

Row based replication

This is heavy stuff. For demanding application. If you have been dreaming of a more robust replication mechanism for MySQL, here it is.
Row based replication will send to the slave the data, rather than the statement to reproduce it. All edge cases where normal replication leave you in doubt are now handled efficiently by row-based replication. And if you want to get the best of the two worlds, you can still choose the mixed format. Check it out.

Log tables on demand

Get ready for a new experience. Logs whenever you need them, without scheduling a server reboot.
The new logs can materialize in your server in several shapes. You can have them as files, the same as you have seen them in previous versions, or you can have them as CVS tables (which you can convert to MyISAM or to something else), or you can have both at once, tables and files.
And your logs are dynamic. You can tell the server to start and stop logging, to change the log file name, to log on tables and files or only on one of them, you'll have more options than some video games.
And your life will change when you realize that you will need to plan for backups that include the logs. Yes. This is the downside. Get used to it.

Event scheduler

Someone said that the event scheduler is the coolest new feature in MySQL 5.1. Perhaps it was my reaction as well when I saw it for the first time. I can't tell you if it's the best one, but surely it will change your way of working. Say goodbye to OS dependent schedulers. Your database will take care of its own jobs. Setting up events is ridiculously easy. Once you try, you will be hooked forever.

XML functions
To tell you the truth, this is my least favorite feature in 5.1, because for theoretical reasons I am not fond of XML, but I have to admit that it's going to be damn useful, and I will have to get acquainted to it. It will save time and allow for flexible integration schemes with applications that only talk XML.
What else? MySQL 5.1 will change your life, sure. To see the other reasons for my prediction, check the list of wonders for the upcoming version.