[MDEV-11420] encryption.innodb_encryption-page-compression failed in buildbot Created: 2016-11-29  Updated: 2017-06-01  Resolved: 2017-05-02

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB, Tests
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.1.23

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
PartOf
is part of MDEV-12253 Buffer pool blocks are accessed after... Closed
Relates
relates to MDEV-11738 Mariadb uses 100% of several of my 8 ... Closed
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-quantal-x86/builds/5298/steps/test/logs/stdio

encryption.innodb_encryption-page-compression 'xtradb' w2 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2016-11-29 16:32:56
 
line
 
2016-11-29 16:32:56 2495609664 [Warning] InnoDB: Trying to access missing tablespace 6
 
^ Found warnings in /usr/local/mariadb-10.2.3-linux-i686/mysql-test/var/2/log/mysqld.1.err
 
ok
 
 
 
 - saving '/usr/local/mariadb-10.2.3-linux-i686/mysql-test/var/2/log/encryption.innodb_encryption-page-compression-xtradb/' to '/usr/local/mariadb-10.2.3-linux-i686/mysql-test/var/log/encryption.innodb_encryption-page-compression-xtradb/'
 
 
 
Retrying test encryption.innodb_encryption-page-compression, attempt(2/3)...



 Comments   
Comment by Marko Mäkelä [ 2016-11-30 ]

This seems to be related to the discovery of encrypted tablespaces. In the server error log file the nearby tests are restarting the server often, and the warning appears to be issued for something that was created in the preceding test. Here are some relevant lines from the server error log:

CURRENT_TEST: encryption.innodb_encryption-page-compression
 
2016-11-29 16:32:47 3057669888 [Note] /usr/local/mariadb-10.2.3-linux-i686/bin/mysqld (mysqld 10.2.3-MariaDB-log) starting as process 19384 ...
 
…
 
2016-11-29 16:32:48 3057669888 [Note] Server socket created on IP: '127.0.0.1'.
 
2016-11-29 16:32:48 3057669888 [Note] /usr/local/mariadb-10.2.3-linux-i686/bin/mysqld: ready for connections.
 
Version: '10.2.3-MariaDB-log'  socket: '/usr/local/mariadb-10.2.3-linux-i686/mysql-test/var/tmp/2/mysqld.1.sock'  port: 16060  MariaDB Server
 
2016-11-29 16:32:48 2964670272 [Note] InnoDB: Tablespace ID 6 name test/innodb_normal:Default tablespace encryption mode scheme encrypted
 
2016-11-29 16:32:48 2964670272 [Note] InnoDB: Tablespace ID 7 name test/innodb_page_compressed1:Default tablespace encryption mode scheme encrypted
 
…
 
2016-11-29 16:32:52 2964367168 [Note] /usr/local/mariadb-10.2.3-linux-i686/bin/mysqld: Shutdown complete
 
 
 
2016-11-29 16:32:54 3056998144 [Note] /usr/local/mariadb-10.2.3-linux-i686/bin/mysqld (mysqld 10.2.3-MariaDB-log) starting as process 19546 ...
 
…
 
2016-11-29 16:32:54 3056998144 [Note] InnoDB: Tablespace ID 6 name test/innodb_normal:Default tablespace encryption mode scheme encrypted
 
…
 
Version: '10.2.3-MariaDB-log'  socket: '/usr/local/mariadb-10.2.3-linux-i686/mysql-test/var/tmp/2/mysqld.1.sock'  port: 16060  MariaDB Server
 
2016-11-29 16:32:56 2495609664 [Warning] InnoDB: Trying to access missing tablespace 6
 
CURRENT_TEST: encryption.innodb_encryption-page-compression

It appears to me that the server is being restarted between the two instances of the test, and that the preceding test (encryption.innodb_encryption-page-compression) is where the offending warning message is being issued. The table innodb-normal is being both created and dropped in the test.
Could there be some dangling reference to this table (tablespace 6) in some persistent data structure? Doublewrite buffer? It cannot be the change buffer, because there is no secondary index defined on innodb_normal (or for any other table created in the test, for that matter).
A possible fix could be to replace fil_space_acquire() with fil_space_acquire_silent() after careful review.
I had a quick check of the fil_space_acquire() calls and did not find anything suspicious.

Comment by Marko Mäkelä [ 2016-12-01 ]

One more thought: If the DROP TABLE statements somehow (I do not see how) end up in the InnoDB background DROP TABLE queue, it is possible that the DROP TABLE statements get executed on the next server startup while some code (which code? buf0rea.cc?) is trying to access the tablespaces.

I should study the encryption code to see if there are any background operations that could explain this.

Comment by Elena Stepanova [ 2016-12-12 ]

The test still crashes on Power, I don't know if it's the same or a different problem:
http://buildbot.askmonty.org/buildbot/builders/p8-rhel7-bintar-debug/builds/1927/steps/test/logs/stdio

encryption.innodb_encryption-page-compression 'xtradb' w4 [ fail ]
 
        Test ended at 2016-12-10 19:07:35
 
 
 
CURRENT_TEST: encryption.innodb_encryption-page-compression
 
 
 
 
 
Server [mysqld.1 - pid: 11628, winpid: 11628, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2016-12-10 19:06:39 70367258122384 [Note] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld (mysqld 10.2.3-MariaDB-debug-log) starting as process 11240 ...
 
2016-12-10 19:06:39 70367258122384 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2016-12-10 19:06:39 70367258122384 [Note] Plugin 'SEQUENCE' is disabled.
 
2016-12-10 19:06:39 70367258122384 [Note] Plugin 'partition' is disabled.
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: PUNCH HOLE support available
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Uses event mutexes
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Using Linux native AIO
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Number of pools: 1
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Using generic crc32 instructions
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Completed initialization of buffer pool
 
2016-12-10 19:06:39 70366823182656 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Tablespace ID 0 name innodb_system:Default tablespace encryption mode scheme unencrypted
 
2016-12-10 19:06:39 70367258122384 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Tablespace ID 5 name innodb_temporary:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Waiting for purge to start
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: 5.7.14 started; log sequence number 1238508
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Creating 1 encryption thread id 70366709936448 total threads 4.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Creating 2 encryption thread id 70366701547840 total threads 4.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Creating 3 encryption thread id 70366693159232 total threads 4.
 
2016-12-10 19:06:40 70367258122384 [Note] InnoDB: Creating 4 encryption thread id 70366684770624 total threads 4.
 
2016-12-10 19:06:41 70366667993408 [Note] InnoDB: Loading buffer pool(s) from /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysql-test/var/4/mysqld.1/data/ib_buffer_pool
 
2016-12-10 19:06:41 70366667993408 [Note] InnoDB: Buffer pool(s) load completed at 161210 19:06:41
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_CMP' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_TEMP_TABLE_INFO' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2016-12-10 19:06:41 70367258122384 [Warning] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld: unknown option '--loose-pam-debug'
 
2016-12-10 19:06:41 70367258122384 [Note] Server socket created on IP: '127.0.0.1'.
 
2016-12-10 19:06:41 70367258122384 [Note] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld: ready for connections.
 
Version: '10.2.3-MariaDB-debug-log'  socket: '/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysql-test/var/tmp/4/mysqld.1.sock'  port: 16000  Source distribution
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 6 name test/innodb_normal:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 7 name test/innodb_page_compressed1:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 8 name test/innodb_page_compressed2:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 9 name test/innodb_page_compressed3:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 10 name test/innodb_page_compressed4:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 11 name test/innodb_page_compressed5:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 12 name test/innodb_page_compressed6:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 13 name test/innodb_page_compressed7:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:42 70366976965952 [Note] InnoDB: Tablespace ID 14 name test/innodb_page_compressed8:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:06:43 70366976965952 [Note] InnoDB: Tablespace ID 15 name test/innodb_page_compressed9:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:29 70366976572736 [Note] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld (root[root] @ localhost []): Normal shutdown
 
 
 
2016-12-10 19:07:29 70366976572736 [Note] Event Scheduler: Purging the queue. 0 events
 
2016-12-10 19:07:29 70366651216192 [Note] InnoDB: FTS optimize thread exiting.
 
2016-12-10 19:07:29 70366976572736 [Note] InnoDB: Starting shutdown...
 
2016-12-10 19:07:29 70366667993408 [Note] InnoDB: Dumping buffer pool(s) to /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysql-test/var/4/mysqld.1/data/ib_buffer_pool
 
2016-12-10 19:07:29 70366667993408 [Note] InnoDB: Buffer pool(s) dump completed at 161210 19:07:29
 
2016-12-10 19:07:30 70366976572736 [Note] InnoDB: Shutdown completed; log sequence number 5368640
 
2016-12-10 19:07:30 70366976572736 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2016-12-10 19:07:30 70366976572736 [Note] Debug sync points hit:                   757836
 
2016-12-10 19:07:30 70366976572736 [Note] Debug sync points executed:              0
 
2016-12-10 19:07:30 70366976572736 [Note] Debug sync points max active per thread: 0
 
2016-12-10 19:07:30 70366976572736 [Note] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld: Shutdown complete
 
 
 
2016-12-10 19:07:32 70366508587152 [Note] /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld (mysqld 10.2.3-MariaDB-debug-log) starting as process 11630 ...
 
2016-12-10 19:07:32 70366508587152 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2016-12-10 19:07:32 70366508587152 [Note] Plugin 'SEQUENCE' is disabled.
 
2016-12-10 19:07:32 70366508587152 [Note] Plugin 'partition' is disabled.
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: PUNCH HOLE support available
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Uses event mutexes
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Using Linux native AIO
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Number of pools: 1
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Using generic crc32 instructions
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Completed initialization of buffer pool
 
2016-12-10 19:07:32 70366076596544 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Tablespace ID 0 name innodb_system:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:32 70366508587152 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 3 name mysql/innodb_index_stats:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 2 name mysql/innodb_table_stats:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 6 name test/innodb_normal:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 7 name test/innodb_page_compressed1:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 8 name test/innodb_page_compressed2:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 9 name test/innodb_page_compressed3:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 10 name test/innodb_page_compressed4:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 11 name test/innodb_page_compressed5:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 12 name test/innodb_page_compressed6:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 13 name test/innodb_page_compressed7:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 14 name test/innodb_page_compressed8:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 15 name test/innodb_page_compressed9:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Tablespace ID 16 name innodb_temporary:Default tablespace encryption mode scheme encrypted
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Waiting for purge to start
 
161210 19:07:33 [ERROR] mysqld got signal 11 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.2.3-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=153
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63061 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x48c00
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: 5.7.14 started; log sequence number 5368640
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Creating 1 encryption thread id 70365963350336 total threads 4.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Creating 2 encryption thread id 70365954961728 total threads 4.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Creating 3 encryption thread id 70365946573120 total threads 4.
 
2016-12-10 19:07:33 70366508587152 [Note] InnoDB: Creating 4 encryption thread id 70365938184512 total threads 4.
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(my_print_stacktrace-0xab1b04)[0x35568f1c]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(handle_fatal_signal-0x14b3d98)[0x34aa9100]
 
linux-vdso64.so.1(__kernel_sigtramp_rt64+0x0)[0x3fff7ab80478]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0xee158c)[0x34e4158c]
 
[0x0]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0xf66130)[0x34ec6130]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0xf65dc8)[0x34ec5dc8]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12bed98)[0x3521ed98]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12c024c)[0x3522024c]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12c08b8)[0x352208b8]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x11f07cc)[0x351507cc]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12057e0)[0x351657e0]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12061f0)[0x351661f0]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x1206e90)[0x35166e90]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x1207328)[0x35167328]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12080e4)[0x351680e4]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12086fc)[0x351686fc]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x12090bc)[0x351690bc]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x1209484)[0x35169484]
 
/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld(+0x120deac)[0x3516deac]
 
/opt/at8.0/lib64/power8/libpthread.so.0(+0xb9e0)[0x3fff7ab4b9e0]
 
/opt/at8.0/lib64/power8/libc.so.6(clone-0xaa8e8)[0x3fff7a2e18d0]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file
 
----------SERVER LOG END-------------
 
mysqltest failed but provided no output
 
The result from queries just before the failure was:
 
< snip >
 
count(*)
 
5000
 
select count(*) from innodb_page_compressed8 where c1 < 500000;
 
count(*)
 
5000
 
select count(*) from innodb_page_compressed9 where c1 < 500000;
 
count(*)
 
5000
 
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_encrypted';
 
variable_value >= 0
 
1
 
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_decrypted';
 
variable_value >= 0
 
1
 
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_compressed';
 
variable_value >= 0
 
1
 
SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_decompressed';
 
variable_value >= 0
 
1
 
 
 
 
 
 
 
 - saving '/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysql-test/var/4/log/encryption.innodb_encryption-page-compression-xtradb/' to '/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysql-test/var/log/encryption.innodb_encryption-page-compression-xtradb/'
 
 - found 'core.11630' (0/5)
 
 
 
Trying 'dbx' to get a backtrace
 
 
 
Trying 'gdb' to get a backtrace
 
Core generated by '/home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/mysqld'
 
Output from gdb follows. The first stack trace is from the failing thread.
 
The following stack traces are from all threads (so the failing one is
 
duplicated).
 
--------------------------
 
[New LWP 11648]
 
[New LWP 11667]
 
[New LWP 11670]
 
[New LWP 11674]
 
[New LWP 11630]
 
[New LWP 11640]
 
[New LWP 11645]
 
[New LWP 11668]
 
[New LWP 11671]
 
[New LWP 11672]
 
[New LWP 11680]
 
[New LWP 11643]
 
[New LWP 11647]
 
[New LWP 11669]
 
[New LWP 11673]
 
[New LWP 11678]
 
[New LWP 11646]
 
[New LWP 11642]
 
[New LWP 11644]
 
[New LWP 11679]
 
[New LWP 11681]
 
 
 
warning: Could not load shared library symbols for linux-vdso64.so.1.
 
Do you need "set solib-search-path" or "set sysroot"?
 
 
 
warning: File "/opt/at8.0/lib64/power8/libthread_db-1.0.so" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load:/usr/bin/mono-gdb.py".
 
To enable execution of this file add
 
	add-auto-load-safe-path /opt/at8.0/lib64/power8/libthread_db-1.0.so
 
line to your configuration file "/home/buildbot/.gdbinit".
 
To completely disable this security protection add
 
	set auto-load safe-path /
 
line to your configuration file "/home/buildbot/.gdbinit".
 
For more information about this security protection see the
 
"Auto-loading safe path" section in the GDB manual.  E.g., run from the shell:
 
	info "(gdb)Auto-loading safe path"
 
 
 
warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
 
 
 
warning: File "/opt/at8.0/lib64/power8/libthread_db-1.0.so" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load:/usr/bin/mono-gdb.py".


Program terminated with signal 11, Segmentation fault.
 
#0  0x00003fff7ab54f00 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:60
 
60	../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
 
#0  0x00003fff7ab54f00 in __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../sysdeps/unix/sysv/linux/pthread_kill.c:60
 
#1  0x00000000355690b4 in my_write_core (sig=11) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/mysys/stacktrace.c:477
 
#2  0x0000000034aa9670 in handle_fatal_signal (sig=11) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/sql/signal_handler.cc:294
 
#3  <signal handler called>
 
#4  0x0000000034e4158c in OSMutex::enter (this=0x10) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/include/sync0types.h:475
 
#5  0x0000000034ec6130 in os_event::set (this=0x0) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/os/os0event.cc:73
 
#6  0x0000000034ec5dc8 in os_event_set (event=0x0) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/os/os0event.cc:484
 
#7  0x000000003521ed98 in fil_crypt_get_latest_key_version (crypt_data=0x3fff79a71d80) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/fil/fil0crypt.cc:156
 
#8  0x000000003522024c in fil_encrypt_buf (crypt_data=0x3fff79a71d80, space=0, offset=7, lsn=5368659, src_frame=0x3fff647f4000 "\001A\224\314", page_size=..., dst_frame=0x3fff72920000 "z\206\344\365") at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/fil/fil0crypt.cc:543
 
#9  0x00000000352208b8 in fil_space_encrypt (space=0, offset=7, lsn=5368659, src_frame=0x3fff647f4000 "\001A\224\314", page_size=..., dst_frame=0x3fff72920000 "z\206\344\365") at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/fil/fil0crypt.cc:649
 
#10 0x00000000351507cc in buf_page_encrypt_before_write (bpage=0x3fff64780000, src_frame=0x3fff647f4000 "\001A\224\314", space_id=0) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0buf.cc:7473
 
#11 0x00000000351657e0 in buf_flush_write_block_low (bpage=0x3fff64780000, flush_type=BUF_FLUSH_LIST, sync=false) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1082
 
#12 0x00000000351661f0 in buf_flush_page (buf_pool=0x3fff74791200, bpage=0x3fff64780000, flush_type=BUF_FLUSH_LIST, sync=false) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1241
 
#13 0x0000000035166e90 in buf_flush_try_neighbors (page_id=..., flush_type=BUF_FLUSH_LIST, n_flushed=1, n_to_flush=200) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1465
 
#14 0x0000000035167328 in buf_flush_page_and_try_neighbors (bpage=0x3fff64780000, flush_type=BUF_FLUSH_LIST, n_to_flush=200, count=0x3fff60ffe248) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1537
 
#15 0x00000000351680e4 in buf_do_flush_list_batch (buf_pool=0x3fff74791200, min_n=200, lsn_limit=18446744073709551615) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1797
 
#16 0x00000000351686fc in buf_flush_batch (buf_pool=0x3fff74791200, flush_type=BUF_FLUSH_LIST, min_n=200, lsn_limit=18446744073709551615, n=0x3fff60ffe458) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:1875
 
#17 0x00000000351690bc in buf_flush_do_batch (buf_pool=0x3fff74791200, type=BUF_FLUSH_LIST, min_n=200, lsn_limit=18446744073709551615, n=0x3fff60ffe458) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:2046
 
#18 0x0000000035169484 in buf_flush_lists (min_n=200, lsn_limit=18446744073709551615, n_processed=0x3fff60ffe510) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:2156
 
#19 0x000000003516deac in buf_flush_page_cleaner_coordinator (arg=0x0) at /home/buildbot/maria-slave/power8-vlp03-bintar-debug/build/storage/innobase/buf/buf0flu.cc:3377
 
#20 0x00003fff7ab4b9e0 in start_thread (arg=0x3fff60fff140) at pthread_create.c:312
 
#21 0x00003fff7a2e18d0 in .__clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96

Comment by Elena Stepanova [ 2017-02-12 ]

The test crashes a lot now, not only on Power, but on usual x86 platforms, also on 10.1. Sometimes with various symptoms from MDEV-9359, but not limited to it.

Comment by Daniel Black [ 2017-02-16 ]

Revision 74a5638a1d5de35f5f377aaae6a5d5266e4d05a6 (mariadb/10.1) - same test on innodb plugin
x86_64, Ubuntu-16.04

cmake /source -DCMAKE_BUILD_TYPE=Debug -DBUILD_CONFIG=mysql_release -DWITH_PROTOBUF=system -DWITH_NDB_JAVA=NO -DCMAKE_C_COMPILER=gcc -DCMAKE_CXX_COMPILER=g++ '-DCMAKE_C_FLAGS_RELWITHDEBINFO=-m64 -O3 -g -mtune=native' '-DCMAKE_CXX_FLAGS_RELWITHDEBINFO=-m64 -O3 -g -mtune=native' '-DCMAKE_C_FLAGS=-m64 -O3 -g -mtune=native' '-DCMAKE_CXX_FLAGS=-m64 -O3 -g -mtune=native' -DWITH_SSL=system -DCMAKE_INSTALL_PREFIX=/mysql/mariadb-upstream-Debug-10.2 -DCMAKE_C_COMPILER_LAUNCHER=ccache -DCMAKE_CXX_COMPILER_LAUNCHER=ccache -DWITHOUT_FEDERATED_STORAGE_ENGINE=1 -DWITHOUT_FEDERATEDX_STORAGE_ENGINE=1 -DWITHOUT_TOKUDB_STORAGE_ENGINE=1
 
...
 
12:09:30 encryption.innodb_encryption-page-compression 'innodb_plugin' w20 [ fail ]
 
12:09:30         Test ended at 2017-02-16 01:09:30
 
12:09:30 
12:09:30 CURRENT_TEST: encryption.innodb_encryption-page-compression
 
12:09:30 mysqltest: At line 155: query 'drop table innodb_page_compressed5' failed: 2013: Lost connection to MySQL server during query
 
12:09:30 
12:09:30 The result from queries just before the failure was:
 
12:09:30 < snip >
 
12:09:30 update innodb_page_compressed9 set c1 = c1 + 1;
 
12:09:30 SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_encrypted';
 
12:09:30 variable_value >= 0
 
12:09:30 1
 
12:09:30 SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_decrypted';
 
12:09:30 variable_value >= 0
 
12:09:30 1
 
12:09:30 SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_compressed';
 
12:09:30 variable_value >= 0
 
12:09:30 1
 
12:09:30 SELECT variable_value >= 0 FROM information_schema.global_status WHERE variable_name = 'innodb_num_pages_page_decompressed';
 
12:09:30 variable_value >= 0
 
12:09:30 1
 
12:09:30 drop procedure innodb_insert_proc;
 
12:09:30 drop table innodb_normal;
 
12:09:30 drop table innodb_page_compressed1;
 
12:09:30 drop table innodb_page_compressed2;
 
12:09:30 drop table innodb_page_compressed3;
 
12:09:30 drop table innodb_page_compressed4;
 
12:09:30 drop table innodb_page_compressed5;
 
12:09:30 
12:09:30 More results from queries before failure can be found in /build/build/mysql-test/var/20/log/innodb_encryption-page-compression.log
 
12:09:30 
12:09:30 
12:09:30 Server [mysqld.1 - pid: 332, winpid: 332, exit: 256] failed during test run
 
12:09:30 Server log from this test:
 
12:09:30 ----------SERVER LOG START-----------
 
12:09:30 2017-02-16  1:09:21 140597154433280 [Note] /build/build/sql/mysqld (mysqld 10.1.22-MariaDB) starting as process 85997 ...
 
12:09:30 2017-02-16  1:09:21 140597154433280 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
12:09:30 2017-02-16  1:09:21 140597154433280 [Note] Plugin 'partition' is disabled.
 
12:09:30 2017-02-16  1:09:21 140597154433280 [Note] Plugin 'SEQUENCE' is disabled.
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: The InnoDB memory heap is disabled
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: Using Linux native AIO
 
12:09:30 2017-02-16  1:09:22 140597154433280 [Note] InnoDB: Using SSE crc32 instructions
 
12:09:30 2017-02-16 01:09:22 7fdf53724900 InnoDB: Warning: io_setup() failed with EAGAIN. Will make 5 attempts before giving up.
 
12:09:30 InnoDB: Warning: io_setup() attempt 1 failed.
 
12:09:30 InnoDB: Warning: io_setup() attempt 2 failed.
 
12:09:30 InnoDB: Warning: io_setup() attempt 3 failed.
 
12:09:30 InnoDB: Warning: io_setup() attempt 4 failed.
 
12:09:30 InnoDB: Warning: io_setup() attempt 5 failed.
 
12:09:30 2017-02-16 01:09:24 7fdf53724900 InnoDB: Error: io_setup() failed with EAGAIN after 5 attempts.
 
12:09:30 InnoDB: You can disable Linux Native AIO by setting innodb_use_native_aio = 0 in my.cnf
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] InnoDB: Linux Native AIO disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Completed initialization of buffer pool
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Highest supported file format is Barracuda.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: 128 rollback segment(s) are active.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Waiting for purge to start
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: 5.6.35 started; log sequence number 1629796
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Creating #1 thread id 140596794607360 total threads 4.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Creating #2 thread id 140596786214656 total threads 4.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Creating #3 thread id 140596769453824 total threads 4.
 
12:09:30 2017-02-16  1:09:24 140596819785472 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] InnoDB: Creating #4 thread id 140596752676608 total threads 4.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_CMP' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'FEEDBACK' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown option '--loose-pam-debug'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Warning] /build/build/sql/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] Server socket created on IP: '127.0.0.1'.
 
12:09:30 2017-02-16  1:09:24 140597154433280 [Note] /build/build/sql/mysqld: ready for connections.
 
12:09:30 Version: '10.1.22-MariaDB'  socket: '/build/build/mysql-test/var/tmp/20/mysqld.1.sock'  port: 16360  MariaDB Server
 
12:09:30 2017-02-16  1:09:25 140597153512192 [Note] /build/build/sql/mysqld: Normal shutdown
 
12:09:30 
12:09:30 2017-02-16  1:09:25 140597153512192 [Note] Event Scheduler: Purging the queue. 0 events
 
12:09:30 2017-02-16  1:09:25 140596803000064 [Note] InnoDB: FTS optimize thread exiting.
 
12:09:30 2017-02-16  1:09:25 140597153512192 [Note] InnoDB: Starting shutdown...
 
12:09:30 2017-02-16  1:09:28 140597153512192 [Note] InnoDB: Shutdown completed; log sequence number 5760292
 
12:09:30 2017-02-16  1:09:28 140597153512192 [Note] /build/build/sql/mysqld: Shutdown complete
 
12:09:30 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] /build/build/sql/mysqld (mysqld 10.1.22-MariaDB) starting as process 333 ...
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'partition' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'SEQUENCE' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: The InnoDB memory heap is disabled
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Using Linux native AIO
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Using SSE crc32 instructions
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Completed initialization of buffer pool
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Highest supported file format is Barracuda.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: 128 rollback segment(s) are active.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Waiting for purge to start
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: 5.6.35 started; log sequence number 5760292
 
12:09:30 2017-02-16  1:09:28 139909427877632 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Creating #1 thread id 139909394331392 total threads 4.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Creating #2 thread id 139909377554176 total threads 4.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Creating #3 thread id 139909369161472 total threads 4.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] InnoDB: Creating #4 thread id 139909360768768 total threads 4.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_CMP' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'FEEDBACK' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown option '--loose-pam-debug'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Warning] /build/build/sql/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] Server socket created on IP: '127.0.0.1'.
 
12:09:30 2017-02-16  1:09:28 139909759301888 [Note] /build/build/sql/mysqld: ready for connections.
 
12:09:30 Version: '10.1.22-MariaDB'  socket: '/build/build/mysql-test/var/tmp/20/mysqld.1.sock'  port: 16360  MariaDB Server
 
12:09:30 170216  1:09:29 [ERROR] mysqld got signal 11 ;
 
12:09:30 This could be because you hit a bug. It is also possible that this binary
 
12:09:30 or one of the libraries it was linked against is corrupt, improperly built,
 
12:09:30 or misconfigured. This error can also be caused by malfunctioning hardware.
 
12:09:30 
12:09:30 To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
12:09:30 
12:09:30 We will try our best to scrape up some info that will hopefully help
 
12:09:30 diagnose the problem, but since we have already crashed, 
12:09:30 something is definitely wrong and this may fail.
 
12:09:30 
12:09:30 Server version: 10.1.22-MariaDB
 
12:09:30 key_buffer_size=1048576
 
12:09:30 read_buffer_size=131072
 
12:09:30 max_used_connections=1
 
12:09:30 max_threads=153
 
12:09:30 thread_count=1
 
12:09:30 It is possible that mysqld could use up to 
12:09:30 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62897 K  bytes of memory
 
12:09:30 Hope that's ok; if not, decrease some variables in the equation.
 
12:09:30 
12:09:30 Thread pointer: 0x7f3f3ae97008
 
12:09:30 Attempting backtrace. You can use the following information to find out
 
12:09:30 where mysqld died. If you see no messages after this, something went
 
12:09:30 terribly wrong...
 
12:09:30 stack_bottom = 0x7f3f477480b8 thread_stack 0x48400
 
12:09:30 /build/build/sql/mysqld(my_print_stacktrace+0x29)[0x55b9e9048ed9]
 
12:09:30 /build/build/sql/mysqld(handle_fatal_signal+0x2f5)[0x55b9e8bc0a05]
 
12:09:30 /lib/x86_64-linux-gnu/libpthread.so.0(+0x113e0)[0x7f3f45f3b3e0]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x1e359a)[0x7f3f3dd1259a]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x1fb69e)[0x7f3f3dd2a69e]
 
12:09:30 mysys/stacktrace.c:268(my_print_stacktrace)[0x7f3f3dd223d9]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x1f4651)[0x7f3f3dd23651]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x1f4c49)[0x7f3f3dd23c49]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x1aa776)[0x7f3f3dcd9776]
 
12:09:30 /build/build/mysql-test/var/20/plugins/ha_innodb.so(+0x102cfe)[0x7f3f3dc31cfe]
 
12:09:30 sql/handler.cc:2352(ha_delete_table(THD*, handlerton*, char const*, char const*, char const*, bool))[0x55b9e8bc7b92]
 
12:09:30 sql/sql_table.cc:2471(mysql_rm_table_no_locks(THD*, TABLE_LIST*, bool, bool, bool, bool, bool))[0x55b9e8ac44c8]
 
12:09:30 sql/sql_table.cc:2085(mysql_rm_table(THD*, TABLE_LIST*, char, char))[0x55b9e8ac4e44]
 
12:09:30 sql/sql_parse.cc:4229(mysql_execute_command(THD*))[0x55b9e8a43897]
 
12:09:30 sql/sql_parse.cc:7327(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x55b9e8a4a6ba]
 
12:09:30 sql/sql_parse.cc:1490(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x55b9e8a4d618]
 
12:09:30 sql/sql_parse.cc:1111(do_command(THD*))[0x55b9e8a4dd3e]
 
12:09:30 sql/sql_connect.cc:1349(do_handle_one_connection(THD*))[0x55b9e8b0f01c]
 
12:09:30 sql/sql_connect.cc:1263(handle_one_connection)[0x55b9e8b0f1c7]
 
12:09:30 perfschema/pfs.cc:1863(pfs_spawn_thread)[0x55b9e8e045b8]
 
12:09:30 /lib/x86_64-linux-gnu/libpthread.so.0(+0x770a)[0x7f3f45f3170a]
 
12:09:30 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f3f455d682d]
 
12:09:30 
12:09:30 Trying to get some variables.
 
12:09:30 Some pointers may be invalid and cause the dump to abort.
 
12:09:30 Query (0x7f3f2dc1f020): drop table innodb_page_compressed5
 
12:09:30 Connection ID (thread ID): 2
 
12:09:30 Status: NOT_KILLED
 
12:09:30 
12:09:30 Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=off
 
12:09:30 
12:09:30 The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
12:09:30 information that should help you find out what is causing the crash.
 
12:09:30 Writing a core file
 
12:09:30 ----------SERVER LOG END-------------

Comment by Marko Mäkelä [ 2017-02-16 ]

danblack, could you try to resolve the ha_innodb.so symbols?
I think I have seen similar failures when testing --suite=encryption in a WITH_ASAN build. The InnoDB tablespace encryption in 10.1 and 10.2 suffers from race conditions and design problems. jplindst is working on a fix in MDEV-11738.

Comment by Daniel Black [ 2017-02-16 ]

Sorry I couldn't get the debug symbols, I've changed my CI to have gdb so I'll have them next time. I noticed this output has an io_setup failure so it might be some transitory test environment failure, sorry - should of looked closer. I'll keep an eye on MDEV-11738 for changes.

Comment by Sergei Golubchik [ 2017-03-29 ]

Currently it either hands to takes too long:

encryption.innodb_encryption-page-compression 'innodb' w2 [ fail ]  timeout after 900 seconds

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest/builds/8229/steps/test_2/logs/stdio

Comment by Elena Stepanova [ 2017-04-23 ]

It stopped failing in buildbot on March 30, and then started failing again on April 12, first on bb-10.1-marko ( http://askmonty.org/buildbot/builders/kvm-deb-xenial-x86/builds/1657 ) and further on various 10.1-based trees, the latest for now being April 22 on 10.1 main:
http://buildbot.askmonty.org/buildbot/builders/p8-rhel71-bintar/builds/1986

Thus, I'm adding 10.1 to the list of affected/fix versions and removing 10.2-ga label.

Comment by Jan Lindström (Inactive) [ 2017-04-28 ]

10.1:

commit 765a43605a42c069ede604826ede2d93d72c4fdd
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Apr 26 15:19:16 2017 +0300

MDEV-12253: Buffer pool blocks are accessed after they have been freed

Problem was that bpage was referenced after it was already freed
from LRU. Fixed by adding a new variable encrypted that is
passed down to buf_page_check_corrupt() and used in
buf_page_get_gen() to stop processing page read.

This patch should also address following test failures and
bugs:

MDEV-12419: IMPORT should not look up tablespace in
PageConverter::validate(). This is now removed.

MDEV-10099: encryption.innodb_onlinealter_encryption fails
sporadically in buildbot

MDEV-11420: encryption.innodb_encryption-page-compression
failed in buildbot

MDEV-11222: encryption.encrypt_and_grep failed in buildbot on P8

Removed dict_table_t::is_encrypted and dict_table_t::ibd_file_missing
and replaced these with dict_table_t::file_unreadable. Table
ibd file is missing if fil_get_space(space_id) returns NULL
and encrypted if not. Removed dict_table_t::is_corrupted field.

Ported FilSpace class from 10.2 and using that on buf_page_check_corrupt(),
buf_page_decrypt_after_read(), buf_page_encrypt_before_write(),
buf_dblwr_process(), buf_read_page(), dict_stats_save_defrag_stats().

Added test cases when enrypted page could be read while doing
redo log crash recovery. Also added test case for row compressed
blobs.

btr_cur_open_at_index_side_func(),
btr_cur_open_at_rnd_pos_func(): Avoid referencing block that is
NULL.

buf_page_get_zip(): Issue error if page read fails.

buf_page_get_gen(): Use dberr_t for error detection and
do not reference bpage after we hare freed it.

buf_mark_space_corrupt(): remove bpage from LRU also when
it is encrypted.

buf_page_check_corrupt(): @return DB_SUCCESS if page has
been read and is not corrupted,
DB_PAGE_CORRUPTED if page based on checksum check is corrupted,
DB_DECRYPTION_FAILED if page post encryption checksum matches but
after decryption normal page checksum does not match. In read
case only DB_SUCCESS is possible.

buf_page_io_complete(): use dberr_t for error handling.

buf_flush_write_block_low(),
buf_read_ahead_random(),
buf_read_page_async(),
buf_read_ahead_linear(),
buf_read_ibuf_merge_pages(),
buf_read_recv_pages(),
fil_aio_wait():
Issue error if page read fails.

btr_pcur_move_to_next_page(): Do not reference page if it is
NULL.

Introduced dict_table_t::is_readable() and dict_index_t::is_readable()
that will return true if tablespace exists and pages read from
tablespace are not corrupted or page decryption failed.
Removed buf_page_t::key_version. After page decryption the
key version is not removed from page frame. For unencrypted
pages, old key_version is removed at buf_page_encrypt_before_write()

dict_stats_update_transient_for_index(),
dict_stats_update_transient()
Do not continue if table decryption failed or table
is corrupted.

dict0stats.cc: Introduced a dict_stats_report_error function
to avoid code duplication.

fil_parse_write_crypt_data():
Check that key read from redo log entry is found from
encryption plugin and if it is not, refuse to start.

PageConverter::validate(): Removed access to fil_space_t as
tablespace is not available during import.

Fixed error code on innodb.innodb test.

Merged test cased innodb-bad-key-change5 and innodb-bad-key-shutdown
to innodb-bad-key-change2. Removed innodb-bad-key-change5 test.
Decreased unnecessary complexity on some long lasting tests.

Removed fil_inc_pending_ops(), fil_decr_pending_ops(),
fil_get_first_space(), fil_get_next_space(),
fil_get_first_space_safe(), fil_get_next_space_safe()
functions.

fil_space_verify_crypt_checksum(): Fixed bug found using ASAN
where FIL_PAGE_END_LSN_OLD_CHECKSUM field was incorrectly
accessed from row compressed tables. Fixed out of page frame
bug for row compressed tables in
fil_space_verify_crypt_checksum() found using ASAN. Incorrect
function was called for compressed table.

Added new tests for discard, rename table and drop (we should allow them
even when page decryption fails). Alter table rename is not allowed.
Added test for restart with innodb-force-recovery=1 when page read on
redo-recovery cant be decrypted. Added test for corrupted table where
both page data and FIL_PAGE_FILE_FLUSH_LSN_OR_KEY_VERSION is corrupted.

Adjusted the test case innodb_bug14147491 so that it does not anymore
expect crash. Instead table is just mostly not usable.

fil0fil.h: fil_space_acquire_low is not visible function
and fil_space_acquire and fil_space_acquire_silent are
inline functions. FilSpace class uses fil_space_acquire_low
directly.

recv_apply_hashed_log_recs() does not return anything.

Comment by Jan Lindström (Inactive) [ 2017-06-01 ]

10.2:
commit aad8cefd2d0e49acb9f8ae3ebaa0e3b90f27b89c
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Thu Jun 1 14:08:41 2017 +0300

Enable innodb_encryption-page-compression test.

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