| Bug #77774 | deadlock or something when piping mysqldump | mysql | ||
|---|---|---|---|
| Submitted: | 18 Jul 2015 17:13 | Modified: | 23 Jul 2015 8:38 |
| Reporter: | teo teo | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: mysqldump Command-line Client | Severity: | S3 (Non-critical) |
| Version: | 5.5.38-0+wheezy1 | OS: | Debian |
| Assigned to: | CPU Architecture: | Any | |
[18 Jul 2015 17:13]
teo teo
[21 Jul 2015 14:27]
MySQL Verification Team
Hi! This is a known problem that we have experienced with our users and customers for so many times. The reason why second command gets stuck is that size of pipe buffer in the shell is so much smaller then required. And MUCH larger buffering is required since mysqldump produces much faster output then what mysql CLI is able to execute on the server. You can try to increase as much as you can the size of pipe buffers, but this can help only in very small mysqldump outputs. The command on bash shell is: ulimit -p N where you can put large number instead of N. However, this will not help, since shell has hard limits. You can read in OS manual how to increase those. In essence, this is a very well known problem with shells and not a MySQL problem.
[21 Jul 2015 16:10]
teo teo
Ok, but either mysql or mysqldump (I guess it should be mysqldump, when unable to write to the pipe) should exit with an error message. How can it possibly wait forever and without that being a bug??
[21 Jul 2015 17:35]
MySQL Verification Team
Problem is again in the shell. Shell returns to mysqldump that output is written with success. That is how shell works. So, mysqldump does not have any indication that it is waiting ... It is actually shell that is waiting on mysql, because reading data from server is much faster then DML commands that mysql CLI executes on the other server. It is possible to consider whether mysql CLI could discover that data is coming from the pipe and then to make a very large buffer for additional buffering. But that would be a feature request that would require lots of work.
[21 Jul 2015 17:48]
teo teo
Then I'm missing something. You're telling me Shell tells mysqldump that data has been written succesfully, right? The only way I can conceive that happening is that the buffer gets overwritten, so mysqldump does the whole dump overwriting the buffer again and again while mysql is still struggling to execute the queries it read from the buffer. (how shell would allow that is beyond me, but anyway, if it is a bug it is in bash) But then, I can't picture who gets stuck waiting for what. Eventually mysql will end executing at least the first queries. Wouldn't it then find broken data in the buffer and complain? Or won't it get at least some kind of signal from the shell that the buffer cannot be read because it was overflowed? and shouldn't it complain then? Again, I'm pretty sure I'm missing something
[22 Jul 2015 16:07]
Tsubasa Tanaka
Your working case, mysqldump && mysql < tmp.sql, were 1. FLUSH TABLES WITH READ LOCK by mysqldump 2. Write a part of statements into tmp.sql by mysqldump * This is repeated until mysqldump writes all part of statements. 3. UNLOCK TABLES by mysqldump 4. mysqldump quits. 5. Read and execute statement in tmp.sql sequentially by mysql. 6. mysql quits. Not working case, mysqldump | mysql, were 1. FLUSH TABLES WITH READ LOCK by mysqldump 2. Write a part of statements into *PIPE* by mysqldump 3. Read a part of statements from pipe by mysql 4. But, mysqldump still keeps global lock(got at "1."), mysql can't execute statement from PIPE. 5. Because of pipe stacks, mysqldump can't write next part of statements and never release global lock(stacked) This is normal pipe's behavior. http://linux.die.net/man/7/pipe
[22 Jul 2015 18:52]
teo teo
Are you taking about LOCK TABLES? if so, you're missing that mysqldump and mysql are operating on different databases
[22 Jul 2015 21:12]
teo teo
I have verified that both processes get stuck, not just mysql. I still can't see how that can happen. Let's picture it: Mysqldump starts writing into the pipe's buffer, and mysql reads from it. At some point, mysql starts executing a query, which is way slower than mysqldump is producing output. Hence mysqldump fills the buffer. It definitely does not overwrite it (as I wrongly got from the explanation in the first comment), otherwise the mysqldump process would end, and that is not the case. Also, I'm pretty sure the system won't allow mysql to write into the pipe if the buffer is full. So, for some time while mysql is busy executing a query, mysqldump can't keep writing and waits. But then, when mysql is done executing the query and is ready to read from the buffer, what is the problem at all? Why can't mysql just read from the buffer, freeing a piece of it, or all of it (depending on whether it contains more or less than a full query), allowing mysqldump to go on writing a bit more of output? Then, if mysql got a full query, it would start running it, and mysqldump would have to start waiting again; if mysql got only a partial query, it would read one more "round" of data from the buffer (written by mysqldump as soon as the buffer had been freed), and so on, until it gets a full query, then it executes it, "blocking" mysqldump again. And so on. The whole process would be as slow as the slowest party involved (mysql), but it would eventually end. I can't picture how it gets stuck. Unless you tell me that Mysql doesn't have an internal buffer of its own, that is, if it has read the whole buffer and it doesn't have a full query to run, it cannot read the new contents of the buffer again, because it's unable to accumulate input until it gets a complete query. But if that was the case, then I wonder how mysql can read queried from a file. But even assuming there's something I'm missing, and that the pipe's buffering mechanism actually does cause some sort of I-can't-write-until-you-read-and-you-can't-read-until-i-write situation (I still want to understand how exactly), then ok, let's say pipe cannot intrinsically work. Then, what still seems a bug to me, most probably of mysqldump, is that it is not capable of detecting it and exiting with an error. If mysqldump gets stuck waiting, unable to write, for too long, shouldn't it have a timeout, after which it could exit with an error such as "unable to write output" or something?!?
[23 Jul 2015 1:17]
Tsubasa Tanaka
mysqldump --lock-all-tables raises "FLUSH TABLES WITH READ LOCK", which is all over databases in mysqld.
The command you provided seems restore into another database but same mysqld, thus you are affected "FLUSH TABLES WITH READ LOCK"'s locking.
Sample data is "world database" which provided by Oracle MySQL.
```
$ mysql -S /usr/mysql/5.5.44/data/mysql.sock --host=localhost --user=root d1 < world_innodb.sql
$ mysqldump -S /usr/mysql/5.5.44/data/mysql.sock --skip-dump-date --host=localhost --user=root --lo
ck-all-tables d1 | mysql -S /usr/mysql/5.5.44/data/mysql.sock --host=localhost --user=root d2
mysql55> show full processlist;
+----+------+-----------+------+---------+------+------------------------------+-----------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+------+---------+------+------------------------------+-----------------------------+
| 13 | root | localhost | d2 | Query | 29 | Waiting for global read lock | DROP TABLE IF EXISTS `City` |
| 14 | root | localhost | d1 | Sleep | 29 | | NULL |
| 15 | root | localhost | NULL | Query | 0 | NULL | show full processlist |
+----+------+-----------+------+---------+------+------------------------------+-----------------------------+
3 rows in set (0.00 sec)
```
Thread id 14 is mysqldump's thread and id 13 is mysql's one.
```
$ gdb -p $(pidof mysqldump)
(gdb) bt
#0 0x00000030624db520 in __write_nocancel () at ../sysdeps/unix/syscall-template.S:82
#1 0x0000003062471ad3 in _IO_new_file_write (f=0x306278e7a0, data=<value optimized out>, n=4096) at fileops.c:1268
#2 0x0000003062473085 in new_do_write (fp=0x306278e7a0,
data=0x7f01959ab000 ",103962),(1531,'Portmore','JAM','St. Andrew',99799),(1532,'Tokyo','JPN','Tokyo-to',7980230),(1533,'Jokohama [Yokohama]','JPN','Kanagawa',3339594),(1534,'Osaka','JPN','Osaka',2595674),(1535,'Nagoya','J"..., to_do=4096)
at fileops.c:522
#3 _IO_new_do_write (fp=0x306278e7a0,
data=0x7f01959ab000 ",103962),(1531,'Portmore','JAM','St. Andrew',99799),(1532,'Tokyo','JPN','Tokyo-to',7980230),(1533,'Jokohama [Yokohama]','JPN','Kanagawa',3339594),(1534,'Osaka','JPN','Osaka',2595674),(1535,'Nagoya','J"..., to_do=4096)
at fileops.c:495
#4 0x000000306247174d in _IO_new_file_xsputn (f=0x306278e7a0, data=0x1d3ffe0, n=38) at fileops.c:1350
#5 0x00000030624672bc in _IO_fputs (str=0x1d3ffe0 "(1633,'Kure','JPN','Hiroshima',206504)", fp=0x306278e7a0) at iofputs.c:42
#6 0x0000000000413c3e in dump_table (table=<value optimized out>, db=<value optimized out>)
at /export/home/pb2/build/sb_0-15205200-1430829639.81/rpm/BUILD/mysql-5.6.25/mysql-5.6.25/client/mysqldump.c:3793
#7 0x0000000000414a6f in dump_all_tables_in_db (database=0x7fffb4efb555 "d1")
at /export/home/pb2/build/sb_0-15205200-1430829639.81/rpm/BUILD/mysql-5.6.25/mysql-5.6.25/client/mysqldump.c:4435
#8 0x00000000004163d5 in dump_databases (argc=1, argv=0x1d261d8)
at /export/home/pb2/build/sb_0-15205200-1430829639.81/rpm/BUILD/mysql-5.6.25/mysql-5.6.25/client/mysqldump.c:4244
#9 main (argc=1, argv=0x1d261d8)
at /export/home/pb2/build/sb_0-15205200-1430829639.81/rpm/BUILD/mysql-5.6.25/mysql-5.6.25/client/mysqldump.c:5885
```
[23 Jul 2015 1:29]
Tsubasa Tanaka
Maybe, we misunderstood each other because of global lock's behavior in mysqldump. Still I think this is not a bug, the behavior is result of combination of mysqldump --lock-all-tables and pipe's buffer. If you'd like to modify this behavior, you should report a new report as "feature request", IMHO. > If mysqldump gets stuck waiting, unable to write, for too long, shouldn't it have a timeout, after which it could exit with an error such as "unable to write output" or something?!? How about using mysql --init-command="SET SESSION lock_wait_timeout= n" for a workaround? mysql will time out after n seconds and pipe will be broken, mysqldump will get SIGPIPE and exit with error. ``` $ mysqldump -S /usr/mysql/5.5.44/data/mysql.sock --skip-dump-date --host=localhost --user=root --lock-all-tables d1 | mysql -S /usr/mysql/5.5.44/data/mysql.sock --host=localhost --user=root --init-command="SET SESSION lock_w ait_timeout= 3" d2 ERROR 1205 (HY000) at line 22: Lock wait timeout exceeded; try restarting transaction mysqldump: Got errno 32 on write ```
[23 Jul 2015 8:38]
teo teo
Oh shit, not THAT makes sense. I am misusing --lock-all-tables instead of --lock-tables So, all the bullsh** about buffers and pipes was pure nonsense?
[25 Jul 2015 15:07]
Tsubasa Tanaka
If your dumped data is smaller than pipe's buffer, this doesn't hang because mysqldump exits immediately and release its lock. For example, mysqldump with --no-data works as expected in this pipe situation. ``` $ time mysqldump -S /usr/mysql/5.5.44/data/mysql.sock --skip-dump-date --no-data --host=localhost --user=root --lock-all-tables d1 | mysql -S /usr/mysql/5.5.44/data/mysql.sock --host=localhost --user=root d2 real 0m0.362s user 0m0.010s sys 0m0.009s ```
