[MDEV-13413] After the merge rocksdb.drop_table fails with warnings - Jira

Details

Type: Task
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Fix Version/s: 10.2.10
Component/s: Storage Engine - RocksDB
Labels:
None

Description

After I have merged fb/mysql-5.6 -> MariaDB, rocksdb.drop_table fails with warnings like pasted below. Upstream does not have the warnings.

~/dev-git/10.2-mariarocks/mysql-test$ ./mysql-test-run --mem rocksdb.drop_table

rocksdb.drop_table                       [ fail ]  Found warnings/errors in server log file!

        Test ended at 2017-07-31 10:57:11

line

2017-07-31 10:55:48 140556445300480 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:48 140556445300480 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:48 140556445300480 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:48 140556445300480 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:51 140556444694272 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:426] ------- DUMPING STATS -------

2017-07-31 10:55:51 140556444694272 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:427]

2017-07-31 10:55:51 140556444694272 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:377] STATISTICS:

2017-07-31 10:55:51 140556151777024 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [__system__] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:55:52 139796177463040 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:426] ------- DUMPING STATS -------

2017-07-31 10:55:52 139796177463040 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:427]

2017-07-31 10:55:52 139796177463040 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:377] STATISTICS:

2017-07-31 10:55:52 139796729816960 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [__system__] Stalling writes because we have 3 level-0 files rate 16777216

2017-07-31 10:55:54 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [rev:cf2] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:55:54 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:15 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [rev:cf2] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:15 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:37 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [rev:cf2] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:37 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:57 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [rev:cf2] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:56:57 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:57:07 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [rev:cf2] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:57:07 139796570359552 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:232] This condition must be satisfied: level0_stop_writes_trigger(1000) >= level0_slowdown_writes_trigger(-1) >= level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:249] Adjust the value to level0_stop_writes_trigger(1000)level0_slowdown_writes_trigger(2)level0_file_num_compaction_trigger(2)

2017-07-31 10:57:08 139853689759488 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:426] ------- DUMPING STATS -------

2017-07-31 10:57:08 139853689759488 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:427]

2017-07-31 10:57:08 139853689759488 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/db_impl.cc:377] STATISTICS:

2017-07-31 10:57:08 139854245111680 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:57:09 139854085629696 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/column_family.cc:698] [cf1] Stalling writes because we have 2 level-0 files rate 16777216

2017-07-31 10:57:10 139853706544896 [Warning] LibRocksDB:[/home/psergey/dev-git/10.2-mariarocks/storage/rocksdb/rocksdb/db/compaction_picker.cc:243] [rev:cf2] ExpandWhileOverlapping() failure because some of the necessary compaction input files are currently being compacted.

^ Found warnings in /home/psergey/dev-git/10.2-mariarocks/mysql-test/var/log/mysqld.1.err

The exact set of warnings produced varies across executions (edge case: under gdb, I often see none!).

Looking at the upstream, their server does produce those warnings as well (I can see them in var/log/mysqld.1.err file), but MTR does not consider them to be worth printing.

I've looked through the global and test' supressions and was unable to see messages like the above to be suppressed.

Attachments

Activity

Ascending order - Click to sort in descending order

Sergei Petrunia added a comment - 2017-07-31 12:51

Asked elenst to help with the investigation. The results are as follows:

Server's error log has "Test Start Markers" that look like this

CURRENT_TEST: rocksdb.drop_table

mysql-test-run.pl uses these to locate parts of mysqld.1.err that belong to a particular test.

However, rocksdb.drop_table does this:

--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err

This destroys the CURRENT_TEST: rocksdb.drop_table marker, which causes mysql-test-run to assume that none of the contents of the mysqld.1.err are caused by this test. (See sub extract_warning_lines, extract_server_log).

Because of that, warning lines in the .err file are ignored.

In MariaDB, mysql-test-run.pl and in particular extract_warning_lines work in a different way and are not fooled by this. This is why one can observe the difference between MySQL and MariaDB.

Sergei Petrunia added a comment - 2017-07-31 12:51 Asked elenst to help with the investigation. The results are as follows: Server's error log has "Test Start Markers" that look like this CURRENT_TEST: rocksdb.drop_table mysql-test-run.pl uses these to locate parts of mysqld.1.err that belong to a particular test. However, rocksdb.drop_table does this: --exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err This destroys the CURRENT_TEST: rocksdb.drop_table marker, which causes mysql-test-run to assume that none of the contents of the mysqld.1.err are caused by this test. (See sub extract_warning_lines , extract_server_log ). Because of that, warning lines in the .err file are ignored. In MariaDB, mysql-test-run.pl and in particular extract_warning_lines work in a different way and are not fooled by this. This is why one can observe the difference between MySQL and MariaDB.

Sergei Petrunia added a comment - 2017-07-31 12:55

Another takeaway from the disucssion with [elenst: It is a really bad practice to truncate the mysqld.1.err file. The file contains errors not from this test, but also from whatever tests that were run before.

When one uses --parallel=N, tests are scheduled nearly at random, so truncating mysqld.1.err in some tests will cause warnings to be missed, and this may happen in an unpredictable way.

There are 3 tests that truncate mysqld.1.err, all in MyRocks:

suite/rocksdb/t/drop_table3.inc:12:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err

suite/rocksdb/t/drop_table.test:16:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err

suite/rocksdb/t/drop_table2.test:16:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err

Sergei Petrunia added a comment - 2017-07-31 12:55 Another takeaway from the disucssion with [ elenst : It is a really bad practice to truncate the mysqld.1.err file. The file contains errors not from this test, but also from whatever tests that were run before. When one uses --parallel=N, tests are scheduled nearly at random, so truncating mysqld.1.err in some tests will cause warnings to be missed, and this may happen in an unpredictable way. There are 3 tests that truncate mysqld.1.err, all in MyRocks: suite/rocksdb/t/drop_table3.inc:12:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err suite/rocksdb/t/drop_table.test:16:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err suite/rocksdb/t/drop_table2.test:16:--exec truncate --size=0 $MYSQLTEST_VARDIR/log/mysqld.1.err

Elena Stepanova added a comment - 2017-07-31 13:02

truncating mysqld.1.err in some tests will cause warnings to be missed, and this may happen in an unpredictable way.

Technically, warnings from other tests shouldn't be missed if everything else works correctly, because the check for warnings is performed after each test; but generally the server error log is valuable for analyzing problems, comparing outcomes, establishing timing, etc.; truncating it is a bad practice.

Elena Stepanova added a comment - 2017-07-31 13:02 truncating mysqld.1.err in some tests will cause warnings to be missed, and this may happen in an unpredictable way. Technically, warnings from other tests shouldn't be missed if everything else works correctly, because the check for warnings is performed after each test; but generally the server error log is valuable for analyzing problems, comparing outcomes, establishing timing, etc.; truncating it is a bad practice.

Sergei Petrunia added a comment - 2017-07-31 13:30

Taking another look at why are we having this issue with the warnings to begin with

suite/rocksdb/t/drop_table-master.opt

has this:

--rocksdb_info_log_level=info_level

I assume it made sense at some point in the past when rocksdb.drop_table used to analyze mysqld.1.err
but after this patch
https://github.com/facebook/mysql-5.6/commit/3e34eea5459bfe8f9c55fbf5a22abf1bc9e8e902 it no longer does.

It seems that printing any extra messages to the error log is totally unnecessary.

Sergei Petrunia added a comment - 2017-07-31 13:30 Taking another look at why are we having this issue with the warnings to begin with suite/rocksdb/t/drop_table-master.opt has this: --rocksdb_info_log_level=info_level I assume it made sense at some point in the past when rocksdb.drop_table used to analyze mysqld.1.err but after this patch https://github.com/facebook/mysql-5.6/commit/3e34eea5459bfe8f9c55fbf5a22abf1bc9e8e902 it no longer does. It seems that printing any extra messages to the error log is totally unnecessary.

Sergei Petrunia added a comment - 2017-10-29 10:24

This was fixed by

commit 1388afcd840024d8e5d2b8f6e176a12f36933016

Author: Sergei Petrunia <psergey@askmonty.org>

Date:   Mon Jul 31 13:44:15 2017 +0000

    MDEV-13413: After the merge rocksdb.drop_table fails with warnings

    - Fix the bad merge in drop_table.test

    - Remove the obsolete rocksdb_info_log_level=info_level option

      which caused warnings to be found in the error log.

Sergei Petrunia added a comment - 2017-10-29 10:24 This was fixed by commit 1388afcd840024d8e5d2b8f6e176a12f36933016 Author: Sergei Petrunia <psergey@askmonty.org> Date: Mon Jul 31 13:44:15 2017 +0000 MDEV-13413: After the merge rocksdb.drop_table fails with warnings - Fix the bad merge in drop_table.test - Remove the obsolete rocksdb_info_log_level=info_level option which caused warnings to be found in the error log.

People

Assignee:: Sergei Petrunia

Reporter:: Sergei Petrunia

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2017-07-31 12:21

Updated:: 2017-10-29 10:24

Resolved:: 2017-10-29 10:24

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server