[#MDEV-17845] Extreme high open file limit used

Comment by Minh [ 2018-11-27 ]

10.3.11 also similar issue.

Comment by Elena Stepanova [ 2018-11-28 ]

When you connect to the server and run show global status like 'Open_files', what do you see?

Comment by Jarkko Uitti [ 2019-01-11 ]

I am running 10.3.11 and have this issue too.

show global status like 'open_files';

Variable_name	Value
Open_files	18446744073709551172

Rebooted db today and open_files was 40 minutes normal. Then again open_files jumped to extremely high.

OS: Ubuntu 16.04.5 LTS
DB: mysql Ver 15.1 Distrib 10.3.11-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

Comment by Elena Stepanova [ 2019-01-11 ]

jarkkou,

After it jumps up, does it ever change back to normal (without server restart), or does it stay this way?
Does FLUSH STATUS happen to have any effect?

Comment by Jarkko Uitti [ 2019-01-12 ]

I am monitoring db status by nagios. Here is some statistics:
db restart
48 minutes normal
23 hours high
6 minutes normal
6 minutes high
5 hours normal
2 minutes high
12 minute normal
6 minutes high
4 minutes normal
2 minutes high
3 hours normal
6 hours high

Now it's
show global status like 'open_files';

Variable_name	Value
Open_files	18446744073709551356

flush status doesn't have any effect.

Comment by Elena Stepanova [ 2019-01-12 ]

Thank you.
We've had some problems with status values temporarily going crazy before, although I don't think it has ever been about Open_files in particular. Some got fixed, some we couldn't reproduce. We'll see if we can figure out this one.

Comment by Elena Stepanova [ 2019-01-14 ]

ATTENTION: in the test case below, a wrong numeric comparison is used, due to a known bug in MTR: MDEV-18228.
If the bug has been fixed, modify the condition to something like $val > 1000 or whatever, otherwise it won't fail, even though it will print bad values.

MTR test case
--let $iterations=1000000

--exec $MYSQL_SLAP --create-schema=test --silent --concurrency=1 --number-of-queries=$iterations --query="ALTER TABLE mysql.plugin FORCE ; FLUSH TABLES" > /dev/null 2>&1 &
--exec $MYSQL_SLAP --create-schema=test --silent --concurrency=1 --number-of-queries=$iterations --query="SELECT db FROM mysql.db ORDER BY db LIMIT 0" > /dev/null 2>&1 &

--let $run= $iterations
while ($run)
{
--dec $run
--let $val= query_get_value(SHOW STATUS LIKE 'Open_files',Value,1)
--echo Run $run: Open_files: $val

# ATTENTION! It is an intentionally wrong comparison, due to MDEV-18228
if ($val < 0)
{
--let $run= 0
--die
}
}

--echo # All done, except that slap might still be running

Modify --run value at the beginning of the test as needed. It represents the number of queries which each thread will run.

The problem appears as this:

Run 997650: Open_files: 5

Run 997649: Open_files: 3

Run 997648: Open_files: 3

Run 997647: Open_files: 1

Run 997646: Open_files: 18446744073709551615

bug.t2                                   [ fail ]

        Test ended at 2019-01-14 16:56:13

CURRENT_TEST: bug.t2

mysqltest: At line 19:

Reproducible on 10.3 and 10.4. Couldn't reproduce on 10.2.
While the problem is not limited to non-debug builds, it is reproducible much easier and faster on RelWithDebInfo builds.

Here is an alternative RQG test (modify the path to basedir as needed):

git clone https://github.com/MariaDB/randgen --branch elenst-mdev17845 rqg-mdev17845

cd rqg-mdev17845

perl ./runall-new.pl --skip-gendata --grammar=mdev17845.yy --threads=3 --duration=300 --basedir=/data/bld/10.3-rel --vardir=/dev/shm/vardir --validators=CheckFieldValue

or, for an already running server,

perl ./gentest.pl --dsn="dbi:mysql:user=root:host=127.0.0.1:port=3306:database=test" --grammar=mdev17845.yy --threads=3 --duration=300   --validators=CheckFieldValue --queries=100M

(modify port if needed and make sure the server is running in shm, it's much easier reproducible there).

With the RQG test, the problem represents like this:

# 2019-01-14T17:12:42 [9995] ERROR: For query 'SHOW STATUS LIKE 'Open_files' /* Validate 2 < 1000000000000 for row 1 */ /* QNO 35308 CON_ID 13 */ ' on row 1 result 18446744073709551615 does not meet the condition < 1000000000000

# 2019-01-14T17:12:42 [9995] Full row: [1] : Open_files; [2] : 18446744073709551615;

# 2019-01-14T17:12:42 [9995] GenTest: Server crash or critical failure (STATUS_REQUIREMENT_UNMET) reported, the child will be stopped

Comment by Sergei Golubchik [ 2019-05-04 ]

please, review https://github.com/MariaDB/server/commit/a7548c58a57

Comment by Sergey Vojtovich [ 2019-05-04 ]

Ok to push.

[MDEV-17845] Extreme high open file limit used Created: 2018-11-27 Updated: 2020-08-25 Resolved: 2019-05-07
Status:	Closed
Project:	MariaDB Server
Component/s:	Server
Affects Version/s:	10.3.10, 10.3, 10.4
Fix Version/s:	10.3.15, 10.4.5

[MDEV-17845] Extreme high open file limit used Created: 2018-11-27 Updated: 2020-08-25 Resolved: 2019-05-07