Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-5199

rocksdb.prefix_extractor_override fails: At line 80: Test assertion failed in assert.inc

    Details

    • Type: Bug
    • Status: On Hold
    • Priority: Medium
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: MyRocks
    • Labels:
    • Environment:

      Description

      $ ./mtr --force rocksdb.prefix_extractor_override
      Logging: /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/mysql/mysql-test/mysql-test-run.pl  --force 
      rocksdb.prefix_extractor_override
      MySQL Version 5.7.24
      Too long tmpdir path 
      '/var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/tmp'  
      creating a shorter one...
       - using tmpdir: '/tmp/VKUz2BWKRo'
      
      Checking supported features...
       - SSL connections supported
      Collecting tests...
       - adding combinations for rocksdb
      Removing old var directory...
      Creating var directory 
      '/var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var'...
      Installing system database...
      Using parallel: 1
      
      ==============================================================================
      
      TEST                                      RESULT   TIME (ms) or COMMENT
      --------------------------------------------------------------------------
      
      worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
      [ 50%] rocksdb.prefix_extractor_override 'write_prepared' [ fail ]
              Test ended at 2018-12-19 20:02:18
      
      CURRENT_TEST: rocksdb.prefix_extractor_override
      mysqltest: In included file ./include/assert.inc at line 81:
      included from 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/mysql/mysql-test/suite/rocksdb/t/prefix_extractor_override.test 
      at line 50:
      At line 80: Test assertion failed in assert.inc
      
      The result from queries just before the failure was:
      SET @orig_rocksdb_update_cf_options = @@global.rocksdb_update_cf_options;
      CREATE TABLE t1 (id1 BIGINT, id2 BIGINT, id3 BIGINT, id4 BIGINT, PRIMARY KEY (id1, id2, id3, id4) comment 'cf1') 
      ENGINE=rocksdb collate latin1_bin;
      set global rocksdb_force_flush_memtable_now = 1;
      
      Original Prefix Extractor:
      
      SELECT * FROM information_schema.rocksdb_cf_options WHERE option_type like '%prefix_extractor%';
      CF_NAME OPTION_TYPE     VALUE
      __system__      PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      cf1     PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      default PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      select variable_value into @u from performance_schema.global_status where 
      variable_name='rocksdb_bloom_filter_prefix_checked';
      SELECT COUNT(*) FROM t1 WHERE id1=1 AND id2=1 AND id3=1;
      COUNT(*)
      1
      include/assert.inc ["Expected exactly one bloom filter prefix check"]
      
      Prefix Extractor (after override_cf_options set, should not be changed):
      
      SELECT * FROM information_schema.rocksdb_cf_options WHERE option_type like '%prefix_extractor%';
      CF_NAME OPTION_TYPE     VALUE
      __system__      PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      cf1     PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      default PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      SET @@global.rocksdb_update_cf_options = 'cf1={prefix_extractor=capped:26};';
      
      Changed Prefix Extractor (after update_cf_options set, without restart):
      
      SELECT * FROM information_schema.rocksdb_cf_options WHERE option_type like '%prefix_extractor%';
      CF_NAME OPTION_TYPE     VALUE
      __system__      PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      cf1     PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      default PREFIX_EXTRACTOR        rocksdb.CappedPrefix.24
      select variable_value into @u from performance_schema.global_status where 
      variable_name='rocksdb_bloom_filter_prefix_checked';
      SELECT COUNT(*) FROM t1 WHERE id1=1 AND id2=1 AND id3=1;
      COUNT(*)
      1
      include/assert.inc ["Expected no bloom filter prefix check"]
      ######## Test assertion failed: "Expected no bloom filter prefix check" ########
      Dumping debug info:
      Assertion text: '"Expected no bloom filter prefix check"'
      Assertion condition: '"[select variable_value-@u from performance_schema.global_status where 
      variable_name=\'rocksdb_bloom_filter_prefix_checked\']" = 0'
      Assertion condition, interpolated: '"1" = 0'
      Assertion result: '0'
      safe_process[33273]: Child process: 33274, exit: 1
      
      
      
      Server [mysqld.1 - pid: 33239, winpid: 33239] log:
      Server log from this test:
      ----------SERVER LOG START-----------
      2018-12-19T19:02:18.196305Z 0 [Warning] Insecure configuration for --secure-file-priv: Data directory is 
      accessible through --secure-file-priv. Consider choosing a different directory.
      2018-12-19T19:02:18.196358Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to 
      all OS users. Consider choosing a different directory.
      2018-12-19T19:02:18.196378Z 0 [Note] 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/sql/mysqld (mysqld 
      5.7.24-27-log) starting as process 33240 ...
      2018-12-19T19:02:18.199194Z 0 [Note] InnoDB: PUNCH HOLE support available
      2018-12-19T19:02:18.199220Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2018-12-19T19:02:18.199226Z 0 [Note] InnoDB: Uses event mutexes
      2018-12-19T19:02:18.199231Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2018-12-19T19:02:18.199236Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      2018-12-19T19:02:18.199241Z 0 [Note] InnoDB: Using Linux native AIO
      2018-12-19T19:02:18.199499Z 0 [Note] InnoDB: Number of pools: 1
      2018-12-19T19:02:18.199617Z 0 [Note] InnoDB: Using CPU crc32 instructions
      2018-12-19T19:02:18.201248Z 0 [Note] InnoDB: Initializing buffer pool, total size = 24M, instances = 1, chunk 
      size = 24M
      2018-12-19T19:02:18.202392Z 0 [Note] InnoDB: Completed initialization of buffer pool
      2018-12-19T19:02:18.203591Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread 
      priority can be changed. See the man page of setpriority().
      2018-12-19T19:02:18.215125Z 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/mysqld.1/data/xb_doublewrite
      2018-12-19T19:02:18.215764Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
      2018-12-19T19:02:18.230164Z 0 [Note] InnoDB: Created parallel doublewrite buffer at 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/mysqld.1/data/xb_doublewrite, 
      size 3932160 bytes
      2018-12-19T19:02:18.233643Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2018-12-19T19:02:18.233696Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file 
      full; Please wait ...
      2018-12-19T19:02:18.265106Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2018-12-19T19:02:18.265909Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are 
      active.
      2018-12-19T19:02:18.265923Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
      2018-12-19T19:02:18.266653Z 0 [Note] InnoDB: Waiting for purge to start
      2018-12-19T19:02:18.317805Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.24-27 started; log 
      sequence number 1355541
      2018-12-19T19:02:18.318364Z 0 [Note] InnoDB: Loading buffer pool(s) from 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/mysqld.1/data/ib_buffer_pool
      2018-12-19T19:02:18.318911Z 0 [Note] Plugin 'FEDERATED' is disabled.
      2018-12-19T19:02:18.321382Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181219 22:02:18
      2018-12-19T19:02:18.338031Z 0 [Note] RocksDB: Got ENOENT when listing column families
      2018-12-19T19:02:18.338051Z 0 [Note] RocksDB:   assuming that we're creating a new database
      2018-12-19T19:02:18.338152Z 0 [Note] RocksDB: Column Families at start:
      2018-12-19T19:02:18.338181Z 0 [Note]   cf=default
      2018-12-19T19:02:18.338189Z 0 [Note]     write_buffer_size=65536
      2018-12-19T19:02:18.338194Z 0 [Note]     target_file_size_base=67108864
      2018-12-19T19:02:18.365237Z 0 [Note] RocksDB: creating a column family __system__
      2018-12-19T19:02:18.365270Z 0 [Note]     write_buffer_size=65536
      2018-12-19T19:02:18.365275Z 0 [Note]     target_file_size_base=67108864
      2018-12-19T19:02:18.382120Z 0 [Note] RocksDB: Table_store: loaded DDL data for 0 tables
      2018-12-19T19:02:18.382271Z 0 [Note] RocksDB instance opened
      2018-12-19T19:02:18.382326Z 0 [Warning] unknown variable 'loose-mysqlx-port=13009'
      2018-12-19T19:02:18.382339Z 0 [Warning] unknown variable 'loose-mysqlx-socket=/tmp/VKUz2BWKRo/mysqlx.1.sock'
      2018-12-19T19:02:18.382343Z 0 [Warning] unknown variable 'loose-debug-sync-timeout=600'
      2018-12-19T19:02:18.385405Z 0 [Note] Salting uuid generator variables, current_pid: 33240, server_start_time: 
      1545246138, bytes_sent: 0,
      2018-12-19T19:02:18.385452Z 0 [Note] Generated uuid: '9b31e9af-03c0-11e9-87d7-000c29545adf', server_start_time: 
      9356228227407484818, bytes_sent: 94084374039824
      2018-12-19T19:02:18.385469Z 0 [Warning] No existing UUID has been found, so we assume that this is the first 
      time that this server has been started. Generating a new UUID: 9b31e9af-03c0-11e9-87d7-000c29545adf.
      2018-12-19T19:02:18.388432Z 0 [Note] Skipping generation of SSL certificates as options related to SSL are 
      specified.
      2018-12-19T19:02:18.389073Z 0 [Warning] CA certificate 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/mysql/mysql-test/std_data/cacert.pem is self signed.
      2018-12-19T19:02:18.389139Z 0 [Note] Skipping generation of RSA key pair as 
      --sha256_password_auto_generate_rsa_keys is set to OFF.
      2018-12-19T19:02:18.389158Z 0 [Warning] RSA private key file not found: 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/mysqld.1/data//private_key.pem. 
      Some authentication plugins will not work.
      2018-12-19T19:02:18.389168Z 0 [Warning] RSA public key file not found: 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/mysql-test/var/mysqld.1/data//public_key.pem. 
      Some authentication plugins will not work.
      2018-12-19T19:02:18.389176Z 0 [Note] Server hostname (bind-address): '*'; port: 13001
      2018-12-19T19:02:18.389198Z 0 [Note] IPv6 is available.
      2018-12-19T19:02:18.389206Z 0 [Note]   - '::' resolves to '::';
      2018-12-19T19:02:18.389264Z 0 [Note] Server socket created on IP: '::'.
      2018-12-19T19:02:18.390101Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/tmp' in the path 
      is accessible to all OS users. Consider choosing a different directory.
      2018-12-19T19:02:18.393952Z 0 [Note] Failed to start slave threads for channel ''
      2018-12-19T19:02:18.400828Z 0 [Note] Event Scheduler: Loaded 0 events
      2018-12-19T19:02:18.401243Z 0 [Note] 
      /var/tmp/portage/dev-db/percona-server-5.7.24.27/work/percona-server-5.7.24.27_build/sql/mysqld: ready for 
      connections.
      Version: '5.7.24-27-log'  socket: '/tmp/VKUz2BWKRo/mysqld.1.sock'  port: 13001  Gentoo Linux 
      percona-server-5.7.24.27
      2018-12-19T19:02:18.557962Z 3 [Note] RocksDB: creating a column family cf1
      2018-12-19T19:02:18.557978Z 3 [Note]     write_buffer_size=65536
      2018-12-19T19:02:18.557982Z 3 [Note]     target_file_size_base=67108864
      2018-12-19T19:02:18.626094Z 3 [Note] RocksDB: Manual memtable flush.
      2018-12-19T19:02:18.641712Z 3 [Warning] MyRocks: failed to apply the options for column family 'cf1'. Invalid 
      argument: Option not changeable: prefix_extractor
      ----------SERVER LOG END-------------
      
      [...]
      
      Test rocksdb.prefix_extractor_override has failed 2 times, no more retries!
      
      --------------------------------------------------------------------------
      The servers were restarted 2 times
      Spent 0.000 of 7 seconds executing testcases
      
      Completed: Failed 2/2 tests, 0.00% were successful.
      
      Failing test(s): rocksdb.prefix_extractor_override
      

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                Whissi Thomas Deutschmann
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated: