[MDEV-13413] After the merge rocksdb.drop_table fails with warnings Created: 2017-07-31  Updated: 2017-10-29  Resolved: 2017-10-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - RocksDB
Fix Version/s: 10.2.10

Type: Task Priority: Major
Reporter: Sergei Petrunia Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
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.

 Comments   
Comment by Sergei Petrunia [ 2017-07-31 ]

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.

Comment by Sergei Petrunia [ 2017-07-31 ]

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

Comment by Elena Stepanova [ 2017-07-31 ]

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.

Comment by Sergei Petrunia [ 2017-07-31 ]

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.

Comment by Sergei Petrunia [ 2017-10-29 ]

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.

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