[MXS-1212] Excessive execution time when maxrows limit has been reached Created: 2017-03-29  Updated: 2017-04-19  Resolved: 2017-04-19

Status: Closed
Project: MariaDB MaxScale
Component/s: maxrows
Affects Version/s: None
Fix Version/s: 2.1.3

Type: Bug Priority: Major
Reporter: Johan Wikman Assignee: Massimiliano Pinto (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Attachments: File maxscale.cnf     File maxscale.cnf     Text File maxscale.log    

 Description   

"I also tested the max_resultset_size option. This worked, but I noticed a significant increase in query execution time when the size was exceeded. With the filter off, the query executed in less and 1 second. With the filter in place, I got a resultset of 0 records after 23 seconds."



 Comments   
Comment by Darin [ 2017-03-30 ]

Note in the description, I had this issue ONLY when exceeding the max_resultset_size parameter. Not when exceeding the maxrows parameter.

Comment by Massimiliano Pinto (Inactive) [ 2017-03-31 ]

MaxScale configuration:

[MaxRows]
type=filter
module=maxrows
max_resultset_rows=10
max_resultset_size=900000
debug=3

[Read-Only-Service]
type=service
router=readconnroute
router_options=running
servers=server1,server2,server3
user=massi
passwd=massi
filters=MaxRows

MySQL client to maxscale:

mysql -h 127.0.0.1 -P 8806 -umassi -pmassi

MySQL [(none)]> select repeat('a', 1000000);
Empty set (0.01 sec)

Messages in the log file:
2017-03-31 08:58:54 info : [readconnroute] Routed [COM_QUERY] to 'server1': select repeat('a', 1000000)
2017-03-31 08:58:54 notice : [maxrows] RESULTSET
2017-03-31 08:58:54 notice : [maxrows] Current size 1000068B of resultset, at least as much as maximum allowed size 878KiB. Not returning data.
2017-03-31 08:58:54 notice : [maxrows] OK or EOF packet seen: the resultset has 1 rows. [Discarded]

I see the empty result set comes immediately.

Would you mind adding MaxScale configuration and a SQL example that takes that long time, 23 seconds?

Comment by Darin [ 2017-03-31 ]

I have a table with 12 columns and 66k rows. When I execute select * from table with the filters=MaxRows line commented out under the [Splitter Service] the entire query is returned in about 5s.
When I uncomment the filters=MaxRows line under [Splitter Service], an empty result set is returned in about 23s.
Maxscale is running on an m4.xlarge server, 4 cpu cores. I have noted that during the 23s I am waiting for the empty result set to return, 1 of the 4 cores is pegged at 100%. Something is cpu bound in the max_resultset_size parameter.
The max_resultset_rows parameter was commented out in both tests.
I am able to consistently reproduce the 5s and 23s execution times.
maxscale.cnf

Comment by Massimiliano Pinto (Inactive) [ 2017-04-02 ]

Hi Darin, thanks for the update.

As long as you are able to reproduce the 23s execution time I would like ask you to add in maxscale.cfnf

[maxscale]
threads=4
syslog=1
maxlog=1
log_to_shm=1
log_warning=1
log_notice=1

[MaxRows]
type=filter
module=maxrows
debug=3

then you could connect to MaxScale using a mysql/mariadb client:

MySQL [(none)]> select repeat('a', 50000) from test.t4 limit 10;
Empty set (0.01 sec)

Please report the content of maxscale.log: this is as an example from my setup, using that configuration:

_2017-04-02 18:08:26 info : [readconnroute] Routed [COM_QUERY] to 'server1': select repeat('a', 50000) from test.t4 limit 10
2017-04-02 18:08:26 notice : [maxrows] RESULTSET
2017-04-02 18:08:26 notice : [maxrows] Current size 100072B of resultset, at least as much as maximum allowed size 64KiB. Not returning data.
2017-04-02 18:08:26 notice : [maxrows] OK or EOF packet seen: the resultset has 10 rows. [Discarded]
_

This way the MaxScale log could tell us something more.

Thanks.

Massimiliano

Comment by Darin [ 2017-04-06 ]

maxscale.cnf maxscale.log

Log and cnf attached.

2017-04-06 18:36:22 notice : [maxrows] Maxrows filter is sending data.
2017-04-06 18:36:40 notice : [maxrows] OK or EOF packet seen: the resultset has 66548 rows. [Discarded]
You can see from the timestamps, 18 seconds elapsed before the EOF notice. I commented out the filter and got the full resultset in ~6s.

I'm also surprised the log says the result set exceeded rows when I have the rows limited commented out.

Comment by Massimiliano Pinto (Inactive) [ 2017-04-07 ]

Fixed usage of gwbuf_length: partial buffer only, not the whole buffer.

This lowers CU usage when receiving 30.000 and more rows

+ csdata->res.length += gwbuf_length(data);
....

  • size_t buflen = gwbuf_length(csdata->res.data);
    + size_t buflen = csdata->res.length;
Comment by Massimiliano Pinto (Inactive) [ 2017-04-07 ]

Code pushed to 2.1 branch:

MXS-1212: use res.length for buffer length instead of computing the size of the whole buffer chain

This reduces CPU usage and decreases the response time for result sets
with many rows.

https://github.com/mariadb-corporation/MaxScale/commit/f4a5134a83a79dd45a07cb75edfb1777773c049f

Generated at Thu Feb 08 04:05:03 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.