| Bug #102278 | use mysqlbinlog|mysql recovery mysql add data is very slow | ||
|---|---|---|---|
| Submitted: | 18 Jan 2021 13:27 | Modified: | 21 Jan 2021 13:30 |
| Reporter: | peng gao | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: Command-line Clients | Severity: | S3 (Non-critical) |
| Version: | 5.7.21 | OS: | Red Hat (7.4) |
| Assigned to: | CPU Architecture: | Any | |
[19 Jan 2021 14:02]
MySQL Verification Team
Hi Mr. gao, Thank you for your bug report. However, we do not verify bugs for the old releases of the GA version. Hence, do let us know whether you can repeat that behaviour with the server and client of the latest release, 5.7.33. Release that you are using is ancient. Meanwhile, tens of thousands of bugs have been fixed.
[19 Jan 2021 15:01]
peng gao
Hi:
sorry! I use i can download newest version 5.7.32,this problem is also exist!
in my test env cpu like :
[root@mgr3 ~]# pstack 9738
#0 0x00007f1866fefafb in __memmove_ssse3_back () from /lib64/libc.so.6
#1 0x00000000004279bf in my_realloc (key=<optimized out>, ptr=0x7f185d994030, size=15210440, flags=<optimized out>) at /var/lib/pb2/sb_1-409304-1600863701.97/mysql-5.7.32/mysys/my_malloc.c:112
#2 0x000000000041f18a in String::mem_realloc (this=0xc020a0 <glob_buffer>, alloc_length=15210434, force_on_heap=<optimized out>) at /var/lib/pb2/sb_1-409304-1600863701.97/mysql-5.7.32/sql-common/sql_string.cc:128
#3 0x000000000041c7c2 in add_line (truncated=false, ml_comment=<optimized out>, in_string=<optimized out>, line_length=76, line=0x23a0811 "AAAAAAAAAP4KAAAAAAAAAP4AAAAAAAAAAP4AAAAAAAAAAP4AAAAAAAAAAP4AAAAAAAAAAP4AAAAA\n", buffer=...) at /var/lib/pb2/sb_1-409304-1600863701.97/mysql-5.7.32/client/mysql.cc:2802
#4 read_and_execute (interactive=false) at /var/lib/pb2/sb_1-409304-1600863701.97/mysql-5.7.32/client/mysql.cc:2371
#5 0x000000000041db28 in main (argc=3, argv=0x2370170) at /var/lib/pb2/sb_1-409304-1600863701.97/mysql-5.7.32/client/mysql.cc:1454
top - 09:54:17 up 8:00, 5 users, load average: 0.34, 0.39, 0.24
Tasks: 174 total, 5 running, 169 sleeping, 0 stopped, 0 zombie
%Cpu(s): 15.2 us, 37.4 sy, 0.0 ni, 47.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1863252 total, 103284 free, 494784 used, 1265184 buff/cache
KiB Swap: 524284 total, 524284 free, 0 used. 1168316 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
9755 root 20 0 145716 11240 2320 R 97.7 0.6 0:04.09 /root/bug/mysql-5.7.32-linux-glibc2.12-x86_64/bin/mysql -S/tmp/mysql3325.sock
6093 root 20 0 0 0 0 S 3.4 0.0 0:06.13 [kworker/u256:0]
when i change code like
--- mysql.cc 2020-09-23 08:00:04.000000000 -0400
+++ mysqlnew.cc 2021-01-19 09:44:25.378357335 -0500
@@ -1322,7 +1322,7 @@
my_end(0);
exit(1);
}
- glob_buffer.mem_realloc(512);
+ glob_buffer.mem_realloc(MAX_BATCH_BUFFER_SIZE);
completion_hash_init(&ht, 128);
init_alloc_root(PSI_NOT_INSTRUMENTED, &hash_mem_root, 16384, 0);
memset(&mysql, 0, sizeof(mysql));
MAX_BATCH_BUFFER_SIZE is 1G
this problem is reslove! i check mysql 8.0.21 code here is
glob_buffer.mem_realloc((status.batch) ? batch_io_size : 512);
in batch mode batch_io_size is 16M not 512 bytes,pelase verify! and apply this code back to 5.7
thanks!!
[19 Jan 2021 15:04]
peng gao
Hi: use one transaction and one command (like delete command delete 1000W data), then mysqlbinlog|mysql apply this trasaction binlog. can repeat this problem in mysql 5.7.32 thanks!
[19 Jan 2021 15:19]
peng gao
Hi: I downloand 5.7.33 also have this problem Tasks: 175 total, 2 running, 173 sleeping, 0 stopped, 0 zombie %Cpu(s): 16.2 us, 34.2 sy, 0.0 ni, 49.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 1863252 total, 69452 free, 503792 used, 1290008 buff/cache KiB Swap: 524284 total, 524020 free, 264 used. 1162616 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 9811 root 20 0 155992 14256 2308 R 99.7 0.8 0:15.73 /root/mysql-5.7.33-linux-glibc2.12-x86_64/bin/mysql -S/tmp/mysql3325.sock 9810 root 20 0 27728 4308 1528 S 2.0 0.2 0:00.73 /root/mysql-5.7.33-linux-glibc2.12-x86_64/bin/mysqlbinlog /opt/bin/log_bin.000002 thanks!!
[19 Jan 2021 15:53]
MySQL Verification Team
HI, Sorry, but this is not a bug. The bottleneck here is the pipe itself. You should reconfigure your Linux. Also, you should reconsider changing format of the binary log. Not a bug.
[19 Jan 2021 16:24]
peng gao
But I use pipe , why 8.0.18 load data time consume very very lower than 5.7.32(5.7.33).? thanks 8.0.18 [root@mgr3 bin]# time /opt/mysql/mgr3315/bin/mysqlbinlog /opt/bin/log_bin.000002 |/opt/mysql/mgr3315/bin/mysql -S'/tmp/mysql3325.sock' ERROR 2006 (HY000) at line 2928: MySQL server has gone away real 0m0.605s user 0m0.496s sys 0m0.190s 5.7.32 [root@mgr3 bin]# time /root/bug/mysql-5.7.32-linux-glibc2.12-x86_64/bin/mysqlbinlog /opt/bin/log_bin.000002 |/root/bug/mysql-5.7.32-linux-glibc2.12-x86_64/bin/mysql -S'/tmp/mysql3325.sock' ERROR 2006 (HY000) at line 2923: MySQL server has gone away real 0m33.444s user 0m10.931s sys 0m23.031s
[19 Jan 2021 16:25]
peng gao
error is mysqld (Got a packet bigger than 'max_allowed_packet' bytes)
[19 Jan 2021 16:56]
peng gao
Hi： I frist dump binlog to file,then redirect stdin like: /opt/my_mysql/bin/mysqlbinlog /opt/bin/log_bin.000002 > log.log 8.0.18 [root@mgr3 ~]# time /opt/mysql/mgr3315/bin/mysql -S'/tmp/mysql3325.sock' < log.log ERROR 2006 (HY000) at line 2923: MySQL server has gone away real 0m0.627s user 0m0.556s sys 0m0.055s 5.7.33 [root@mgr3 ~]# time /root/mysql-5.7.33-linux-glibc2.12-x86_64/bin/mysql -S'/tmp/mysql3325.sock' < log.log ERROR 2006 (HY000) at line 2923: MySQL server has gone away real 0m39.760s user 0m14.297s sys 0m25.445s please verify it again! not like pipe bottleneck.
[20 Jan 2021 13:00]
MySQL Verification Team
You have simply hit a timeout. Beside that, you can optimise server, clients and you can tune pipe itself on any Unix.
[20 Jan 2021 13:31]
peng gao
Hi I test again use redirect stdin and sucessful use mysql client load data to mysqld server 1、dump binlog /opt/my_mysql/bin/mysqlbinlog /opt/bin/log_bin.000002 > log.log 2、server mysql> set global innodb_flush_log_at_trx_commit=0; Query OK, 0 rows affected (0.00 sec) mysql> set global max_allowed_packet=128*1024*1024; Query OK, 0 rows affected (0.00 sec) mysql> set global sync_binlog=0; Query OK, 0 rows affected (0.00 sec) 3、load data 8.0.18 [root@mgr3 ~]# time /opt/mysql/mgr3315/bin/mysql -S'/tmp/mysql3325.sock' < log.log real 2m41.064s user 0m0.135s sys 0m0.018s [root@mgr3 ~]# 5.7.33 [root@mgr3 ~]# time /root/mysql-5.7.33-linux-glibc2.12-x86_64/bin/mysql -S'/tmp/mysql3325.sock' < log.log real 2m55.562s user 0m5.780s sys 0m11.612s pelase look at user and sys time,tanks
[21 Jan 2021 13:04]
MySQL Verification Team
Hi Mr. gao, Your report is a duplicate of the bug: https://bugs.mysql.com/bug.php?id=85155 This bug is fixed in 8.0 branch and it will not be ported back to 5.7, since this is about performance improvement. Beside that, 8.0 single-thread performance is worse then the same on 5.7. This is a known issue, being reported many times, but it will not be fixed so soon.
[21 Jan 2021 13:30]
peng gao
OK thanks！
[21 Jan 2021 14:00]
MySQL Verification Team
You are welcome !!
Description: Hi: we use mysqlbinlog|mysql to parse binlog and recover binlog,when have large trasaction,mysql client tool is very slow at add_line function. 20M trasaction event mysql add line use 1 hour!! cpu is 100% use in sy% and pstack mysql client stack like: __memmove_sse3 my_realloc String::mem_realloc add_line read_and_execute main when batch mode,mysql every time add 76 bytes event line to buffer,buffer init 520 bytes,when 20M event load in buffer then call com_do funcation to execute command。 Breakpoint 9, add_line (buffer=..., line=0xa603e0 "/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;", line_length=45, in_string=0x7fffffffe287 "", ml_comment=0x7fffffffe286, truncated=false) at /opt/percona-server-locks-detail-5.7.22/client/mysql.cc:2533 2533 bool need_space= 0; (gdb) p buffer.m_length $20 = 0 (gdb) p buffer.m_alloced_length $21 = 520 when buffer is smaller, every time allocate 4K mem: if (buffer.length() + length >= buffer.alloced_length()) buffer.mem_realloc(buffer.length()+length+IO_SIZE); this step rise frequently mem allocate.and cpu sy% is very high!! when mysql use batch mode can we use large init buffer or give our a parameter to control this. when i search bug i find Bug #85155 is like this,is this fix at mysql 8.0.13,what 5.7 version fix this? thanks!! How to repeat: use mysql5.7.21 clients to read large trasaction binlog(like 100M). Suggested fix: when mysql use batch mode can we use large init buffer or give our a parameter to control this.