Bug #83151 high number of SHOW WARNINGS can stall server if compressed protocol in use
Submitted: 26 Sep 2016 14:27 Modified: 23 Jan 2019 14:13
Reporter: Riccardo Pizzi Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Connection Handling Severity:S2 (Serious)
Version:5.6.33 OS:CentOS
Assigned to: CPU Architecture:Any
Tags: performance

[26 Sep 2016 14:27] Riccardo Pizzi
Description:
When using client/server compression, issuing SHOW WARNINGS eats an incredible amount of system CPU time. This behaviour is already visible with 16 threads, at 64 threads it will saturate a 32 CPU machine completely.

We have encountered this bug in production, where an ORM was configured to issue a SHOW WARNINGS statement after each and every query. We had complete MySQL stalls that lasted from several seconds to few minutes because of this, as the machine was CPU bound during this time with 99% of system time used by MySQL server. MySQL was unable to perform any operation during the stall.

This only happens if you have MySQL compression enabled!

This has been verified on 5.6.33 (latest at this time).

How to repeat:
- install sysbench with MySQL driver from usual source
- create the LUA script  below and place it on your test system
- run sysbench as follows: ./sysbench --mysql-host=.... --mysql-user=sysbench --mysql-password=sbtest --mysql-db=sbtest --test=show_warnings.lua --max_requests=0 --max_time=20 --num-threads=64 --mysql-engine-trx=yes --mysql-compression=on run
- watch system CPU reach 100%

LUA script:

--- snip ---
pathtest = string.match(test, "(.*/)") or ""

dofile(pathtest .. "./sysbench/tests/db/common.lua")

function thread_init(thread_id)
   set_vars()
end

function event(thread_id)
   db_query("SHOW WARNINGS")
end
--- snip ---
[27 Sep 2016 6:31] MySQL Verification Team
Hello Riccardo,

Thank you for the report.

Thanks,
Umesh
[23 Jan 2019 14:10] Nikolai Ikhalainen
Hello,
Are you still able to reproduce this issue?
I'm getting significantly better results for show warnings (or select 1) query execution in recent 5.6, 5.7 and 8.0:
docker cp show_warnings.lua mysql83151_sysbench_1:/usr/share/sysbench/
for h in mysql5633 mysql5643 mysql5725 mysql8014; do echo $h; docker-compose exec sysbench bash -c "echo -n no compression;sysbench --threads=16 --mysql-compression=off --mysql-host=$h --mysql-user=root --mysql-password=secret --mysql-db=information_schema /usr/share/sysbench/show_warnings.lua run 2>&1 |grep -F queries:;echo -n '   compression';sysbench --threads=16 --mysql-compression=on --mysql-host=$h --mysql-user=root --mysql-password=secret --mysql-db=information_schema /usr/share/sysbench/show_warnings.lua run 2>&1 |grep -F queries:" ; done
mysql5633
no compression    queries:                             1420836 (142018.55 per sec.)
   compression    queries:                             430418 (43025.41 per sec.)
mysql5643
no compression    queries:                             1323344 (132289.08 per sec.)
   compression    queries:                             1025112 (102478.62 per sec.)
mysql5725
no compression    queries:                             1211112 (121062.25 per sec.)
   compression    queries:                             893404 (89311.30 per sec.)
mysql8014
no compression    queries:                             994196 (99382.34 per sec.)
   compression    queries:                             821052 (82070.60 per sec.)

the test environment created with docker-compose up:
docker-compose.yml:
version: '2'
services:
  mysql5633:
    image: mysql:5.6.33
    environment:
      - MYSQL_ROOT_PASSWORD=secret
  mysql5643:
    image: mysql:5.6.43
    environment:
      - MYSQL_ROOT_PASSWORD=secret
  mysql5725:
    image: mysql:5.7.25
    environment:
      - MYSQL_ROOT_PASSWORD=secret
  mysql8014:
    image: mysql:8.0.14
    environment:
      - MYSQL_ROOT_PASSWORD=secret
    command: ["--loose-default-authentication-plugin=mysql_native_password"]
  sysbench:
    image: severalnines/sysbench:latest
    command: ["/bin/sleep", "86400"]

show_warnings.lua:
#!/usr/bin/env sysbench
require("oltp_common")

function prepare_statements()
end

function event()
   con:query("SELECT 1/0")
   con:query("SHOW WARNINGS")
end
[23 Jan 2019 14:13] Riccardo Pizzi
You did not mention CPU consumption in your tests.
Not sure docker is a good way to test this bug...
[26 Jan 2019 4:54] Nikolai Ikhalainen
Hi Riccardo,

I have all 4 CPU cores fully utilized during test.
I'm seeing a huge improvements for for small queries and compression inside and outside docker compare to 5.6.33 (with sysbench, but not with mysqlslap).

So, are you still able to reproduce this bug with fresh mysql 5.6, 5.7 or 8.0?
[14 Sep 2021 10:02] MySQL Verification Team
I also don't see any real problem on current 8.0.28-trunk.

16 threads running with --compress=0 yields 132k qps vs 88k qps with --compress=1 and the CPU cores are fully used and no severe degradation happens with more threads,  even 32 threads doesn't get slower.

--
processor	: 7
vendor_id	: GenuineIntel
cpu family	: 6
model		: 58
model name	: Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz
stepping	: 9
microcode	: 0x21
--