Test Case to generate something useful in the output:
|
Connection #1 |
create table t (id int) engine=innodb; |
insert into t (id) values (1),(2),(3),(4),(5); |
start transaction; |
select * from t for update; |
|
Connection #2 |
show engine innodb status\G
|
create table innodb_lock_monitor (id int) engine=innodb; |
show engine innodb status\G
|
drop table innodb_lock_monitor; |
Works for me on Linux, current bzr tree.
I'll check Windows / 5.5.30 release build
I tried mariadb-5.5.30-winx64.zip on Windows 7, works for me (the output is below). The only oddity I noticed was that if I watch the error log file through notepad++, which usually prompts to reload a file if the file is modified, it does not do so in this case – I needed to force reload from disk to see innodb status output. Possibly it's normal behavior with the error log on Windows; anyway, I don't suppose that's what you meant.
If it isn't working for you, maybe it's more subtle than just Windows + 5.5.30? Which flavor of Windows and which MariaDB package are you using?
A fragment from the error log:
130320 23:43:57 [Note] Plugin 'FEEDBACK' is disabled.
|
130320 23:43:57 InnoDB: The InnoDB memory heap is disabled
|
130320 23:43:57 InnoDB: Mutexes and rw_locks use Windows interlocked functions
|
130320 23:43:57 InnoDB: Compressed tables use zlib 1.2.3
|
130320 23:43:57 InnoDB: Initializing buffer pool, size = 128.0M
|
130320 23:43:57 InnoDB: Completed initialization of buffer pool
|
InnoDB: The first specified data file .\ibdata1 did not exist:
|
InnoDB: a new database to be created!
|
130320 23:43:57 InnoDB: Setting file .\ibdata1 size to 10 MB
|
InnoDB: Database physically writes the file full: wait...
|
130320 23:43:58 InnoDB: Log file .\ib_logfile0 did not exist: new to be created
|
InnoDB: Setting log file .\ib_logfile0 size to 5 MB
|
InnoDB: Database physically writes the file full: wait...
|
130320 23:43:58 InnoDB: Log file .\ib_logfile1 did not exist: new to be created
|
InnoDB: Setting log file .\ib_logfile1 size to 5 MB
|
InnoDB: Database physically writes the file full: wait...
|
InnoDB: Doublewrite buffer not found: creating new
|
InnoDB: Doublewrite buffer created
|
InnoDB: 127 rollback segment(s) active.
|
InnoDB: Creating foreign key constraint system tables
|
InnoDB: Foreign key constraint system tables created
|
130320 23:43:58 InnoDB: Waiting for the background threads to start
|
130320 23:43:59 InnoDB: 5.5.30-MariaDB started; log sequence number 0
|
130320 23:43:59 [Note] Event Scheduler: Loaded 0 events
|
130320 23:43:59 [Note] bin\mysqld: ready for connections.
|
Version: '5.5.30-MariaDB' socket: '' port: 3306 mariadb.org binary distribution
|
|
|
=====================================
|
130320 23:45:18 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 19 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 5 1_second, 5 sleeps, 0 10_second, 9 background, 9 flush
|
srv_master_thread log flush and writes: 5
|
----------
|
SEMAPHORES
|
----------
|
OS WAIT ARRAY INFO: reservation count 10, signal count 10
|
Mutex spin waits 6, rounds 24, OS waits 0
|
RW-shared spins 10, rounds 300, OS waits 10
|
RW-excl spins 0, rounds 0, OS waits 0
|
Spin rounds per wait: 4.00 mutex, 30.00 RW-shared, 0.00 RW-excl
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 305
|
Purge done for trx's n:o < 0 undo n:o < 0
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 0, not started
|
MySQL thread id 2, OS thread handle 0x246c, query id 7 localhost ::1 root
|
---TRANSACTION 303, ACTIVE 26 sec
|
2 lock struct(s), heap size 376, 6 row lock(s)
|
MySQL thread id 1, OS thread handle 0x246c, query id 6 localhost ::1 root
|
TABLE LOCK table `test`.`t` trx id 303 lock mode IX
|
RECORD LOCKS space id 0 page no 307 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 303 lock_mode X
|
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
|
0: len 8; hex 73757072656d756d; asc supremum;;
|
|
|
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 6; hex 000000000200; asc ;;
|
1: len 6; hex 000000000302; asc ;;
|
2: len 7; hex 83000001340110; asc 4 ;;
|
3: len 4; hex 80000001; asc ;;
|
|
|
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 6; hex 000000000201; asc ;;
|
1: len 6; hex 000000000302; asc ;;
|
2: len 7; hex 8300000134011e; asc 4 ;;
|
3: len 4; hex 80000002; asc ;;
|
|
|
Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 6; hex 000000000202; asc ;;
|
1: len 6; hex 000000000302; asc ;;
|
2: len 7; hex 8300000134012c; asc 4 ,;;
|
3: len 4; hex 80000003; asc ;;
|
|
|
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 6; hex 000000000203; asc ;;
|
1: len 6; hex 000000000302; asc ;;
|
2: len 7; hex 8300000134013a; asc 4 :;;
|
3: len 4; hex 80000004; asc ;;
|
|
|
Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
|
0: len 6; hex 000000000204; asc ;;
|
1: len 6; hex 000000000302; asc ;;
|
2: len 7; hex 83000001340148; asc 4 H;;
|
3: len 4; hex 80000005; asc ;;
|
|
|
--------
|
FILE I/O
|
--------
|
I/O thread 0 state: wait Windows aio (insert buffer thread)
|
I/O thread 1 state: wait Windows aio (log thread)
|
I/O thread 2 state: wait Windows aio (read thread)
|
...
|
Hello,
Many thanks for the info.
I am actually using the exact same: mariadb-5.5.30-winx64.zip on Windows 7
I'll re-test everything again tomorrow and let you know my results.
Best wishes,
Chris
I've re-tested this on my end, and still see the strange behavior.
I'm not sure what else to check though, or how best to troubleshoot it.
I am using mariadb-5.5.30-winx64.zip on Windows 7
I actually previously installed an earlier MariaDB 5.5 via the Windows installer, and then later upgraded to 5.5.30 (just using the zip version to upgrade).
Here is my session:
C:\Windows\system32>mysql -uroot -pmysql -P3310
|
Welcome to the MySQL monitor. Commands end with ; or \g. |
Your MySQL connection id is 2 |
Server version: 5.5.30-MariaDB mariadb.org binary distribution |
|
|
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved. |
|
|
Oracle is a registered trademark of Oracle Corporation and/or its |
affiliates. Other names may be trademarks of their respective |
owners.
|
|
|
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. |
|
|
mysql> select @@version; |
+----------------+ |
| @@version |
|
+----------------+ |
| 5.5.30-MariaDB |
|
+----------------+ |
1 row in set (0.00 sec) |
|
|
mysql> select @@innodb_version; |
+------------------+ |
| @@innodb_version |
|
+------------------+ |
| 5.5.30-MariaDB |
|
+------------------+ |
1 row in set (0.00 sec) |
|
|
mysql> show global status like 'uptime'; |
+---------------+--------+ |
| Variable_name | Value |
|
+---------------+--------+ |
| Uptime | 282607 |
|
+---------------+--------+ |
1 row in set (0.08 sec) |
|
|
mysql> use test |
Database changed |
mysql> show tables;
|
+---------------------+ |
| Tables_in_test |
|
+---------------------+ |
| innodb_lock_monitor |
|
| sessions |
|
| t |
|
| t1 |
|
+---------------------+ |
4 rows in set (0.00 sec) |
|
|
mysql> show create table innodb_lock_monitor\G |
*************************** 1. row ***************************
|
Table: innodb_lock_monitor |
Create Table: CREATE TABLE `innodb_lock_monitor` ( |
`id` int(11) DEFAULT NULL |
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
1 row in set (0.07 sec) |
|
|
mysql>
|
You can see the versions, the table exists, uptime, etc.
Here is the corresponding error log:
130322 13:21:38 [Note] Plugin 'FEEDBACK' is disabled.
|
130322 13:21:40 [Note] Event Scheduler: Loaded 0 events
|
130322 13:21:40 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: ready for connections.
|
Version: '5.5.30-MariaDB' socket: '' port: 3310 mariadb.org binary distribution
|
Here is my my.ini file:
[mysqld]
|
datadir=C:/Program Files/MariaDB 5.5/data
|
port=3310
|
sql_mode="STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION"
|
default_storage_engine=innodb
|
innodb_buffer_pool_size=96M
|
innodb_log_file_size=50M
|
character-set-server=utf8
|
log_warnings = 2
|
# Enable the 2 below to disable XtraDB+ and Enable MySQL's (Oracle's) InnoDB Plugin
|
ignore_builtin_innodb
|
plugin-load=innodb=ha_innodb.dll;innodb_trx=ha_innodb.dll;innodb_locks=ha_innodb.dll;innodb_lock_waits=ha_innodb.dll;innodb_cmp=ha_innodb.dll;innodb_cmp_reset=ha_innodb.dll;innodb_cmpmem=ha_innodb.dll;innodb_cmpmem_reset=ha_innodb.dll
|
[client]
|
port=3310
|
my.ini is located in the datadir
datadir = C:\Program Files\MariaDB 5.5\data
And just so you see other things can be written to the error log, I ran "mysqladmin debug" on this instance. Then shut it down, restarted, re-created the table, and it has been running ever since, and has not output InnoDB Status yet:
130322 10:29:37 [Note] Plugin 'FEEDBACK' is disabled.
|
130322 10:29:39 [Note] Event Scheduler: Loaded 0 events
|
130322 10:29:39 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: ready for connections.
|
Version: '5.5.30-MariaDB' socket: '' port: 3310 mariadb.org binary distribution
|
|
|
Status information:
|
|
|
Current dir: C:\Program Files\MariaDB 5.5\data\
|
Running threads: 1 Stack size: 294912
|
Current locks:
|
lock: 0x11c592c8:
|
|
|
lock: 0x11b71228:
|
|
|
lock: 0x11b7a318:
|
|
|
lock: 0x11b77e48:
|
|
|
lock: 0x11b63a18:
|
|
|
lock: 0x11b5d778:
|
|
|
lock: 0x11b50c28:
|
|
|
lock: 0x11b459e8:
|
|
|
lock: 0x11b3b6f8:
|
|
|
lock: 0x40a21ce0:
|
|
|
lock: 0x40a21dc0:
|
|
|
lock: 0x40a21ea0:
|
|
|
lock: 0x40a21f80:
|
|
|
lock: 0x40a22140:
|
|
|
lock: 0x40a22060:
|
|
|
lock: 0x40a22220:
|
|
|
lock: 0x40a22300:
|
|
|
lock: 0x40a223e0:
|
|
|
lock: 0x40a224c0:
|
|
|
lock: 0x40a225a0:
|
|
|
lock: 0x40a22680:
|
|
|
lock: 0x40a22760:
|
|
|
lock: 0x40a22840:
|
|
|
lock: 0x40a22ae0:
|
|
|
lock: 0x40a22920:
|
|
|
lock: 0x40a22a00:
|
|
|
|
|
Key caches:
|
default
|
Buffer_size: 134217728
|
Block_size: 1024
|
Division_limit: 100
|
Age_threshold: 300
|
Partitions: 0
|
blocks used: 0
|
not flushed: 0
|
w_requests: 0
|
writes: 0
|
r_requests: 0
|
reads: 0
|
|
|
|
|
handler status:
|
read_key: 0
|
read_next: 0
|
read_rnd 0
|
read_first: 0
|
write: 0
|
delete 0
|
update: 0
|
|
|
Table status:
|
Opened tables: 1
|
Open tables: 26
|
Open files: 20
|
Open streams: 0
|
130322 13:21:32 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: Normal shutdown
|
|
|
130322 13:21:32 [Note] Event Scheduler: Purging the queue. 0 events
|
130322 13:21:32 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: Shutdown complete
|
|
|
|
|
|
|
|
|
Events status:
|
LLA = Last Locked At LUA = Last Unlocked At
|
WOC = Waiting On Condition DL = Data Locked
|
|
|
Event scheduler status:
|
State : INITIALIZED
|
Thread id : 0
|
LLA : n/a:0
|
LUA : n/a:0
|
WOC : NO
|
Workers : 0
|
Executed : 0
|
Data locked: NO
|
|
|
Event queue status:
|
Element count : 0
|
Data locked : NO
|
Attempting lock : NO
|
LLA : <unknown>:139
|
LUA : <unknown>:149
|
WOC : NO
|
Next activation : never
|
130322 13:21:38 [Note] Plugin 'FEEDBACK' is disabled.
|
130322 13:21:40 [Note] Event Scheduler: Loaded 0 events
|
130322 13:21:40 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: ready for connections.
|
Version: '5.5.30-MariaDB' socket: '' port: 3310 mariadb.org binary distribution
|
Please advise. I'm happy to provide any other info, and/or test out anything, etc. (if you think it's worth investigating).
Hi Chris,
How exactly did you upgrade from zip? (Not that it could have been done wrong, I just want to imitate the exact same setup on my system).
So, your server is running as a service? Maybe it has something to do with that, I vaguely remember MySQL having problems with the error log before that turned out to be specific to running as a service.
Does the same happen with the "regular" InnoDB monitor (as opposed to the lock monitor) – i.e. if you create innodb _monitor table?
And just to make triple-sure,
- you (re-)start server,
- then you (re-)create the table,
- then you wait a few seconds,
- then you (re-)open the log file and don't see output there
- in this very order, right?
Yes, that's exactly it.
To take it a step further, this morning, I completely removed/uninstalled my MariaDB 5.5 instance, and installed it fresh from the mariadb-5.5.30-winx64.msi.
This exhibits the problem for me.
If I disable XtraDB+, and create the innodb_lock_monitor (and I also tried just innodb_monitor), nothing is logged. But it is as soon as I re-enable XtraDB+.
So it does indeed seem to be related to the 'service'.
Hope this helps, and please just let me know if there's anything further I can provide or test.
Many thanks 
I see the same behavior with 5.3 and 5.2 as well - both initially installed via the .msi installer files and both run as services.
Yes, it's definitely related to the service. The very same installation with the same config file, when run manually, works all right.
The problem is actually visible in the startup log already, the part that you quoted above:
130322 13:21:38 [Note] Plugin 'FEEDBACK' is disabled.
|
130322 13:21:40 [Note] Event Scheduler: Loaded 0 events
|
130322 13:21:40 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: ready for connections.
|
Version: '5.5.30-MariaDB' socket: '' port: 3310 mariadb.org binary distribution
|
All InnoDB messages are missing there – it looks like InnoDB just cannot write into the error log file at all.
I don't see any obvious errors in procmon, it looks like nobody even attempts to write into the error log despite the enabled monitor (while with XtraDB mysqld.exe does it all the time).
Stack trace of the file write when the same server / plugin are started manually:
12:35:02.8219504 AM mysqld.exe 16824 WriteFile C:\Program Files\MariaDB 5.5\data\HOME.err SUCCESS Offset: 87,384, Length: 3,448, Priority: Normal
|
|
|
|
|
0 fltmgr.sys FltAcquirePushLockShared + 0x907 0xfffff88001394067 C:\Windows\system32\drivers\fltmgr.sys
|
1 fltmgr.sys FltIsCallbackDataDirty + 0xa39 0xfffff88001395329 C:\Windows\system32\drivers\fltmgr.sys
|
2 fltmgr.sys fltmgr.sys + 0x16c7 0xfffff880013936c7 C:\Windows\system32\drivers\fltmgr.sys
|
3 ntoskrnl.exe NtCreateFile + 0x31f 0xfffff80003382e0b C:\Windows\system32\ntoskrnl.exe
|
4 ntoskrnl.exe NtWriteFile + 0x7e3 0xfffff8000338d803 C:\Windows\system32\ntoskrnl.exe
|
5 ntoskrnl.exe KeSynchronizeExecution + 0x3a23 0xfffff80003075ed3 C:\Windows\system32\ntoskrnl.exe
|
6 ntdll.dll ZwWriteFile + 0xa 0x76fb139a C:\Windows\System32\ntdll.dll
|
7 KernelBase.dll WriteFile + 0x7b 0x7fefc441b3b C:\Windows\System32\KernelBase.dll
|
8 kernel32.dll WriteFile + 0x36 0x76e63566 C:\Windows\System32\kernel32.dll
|
9 ha_innodb.dll _write_nolock + 0x45d, f:\dd\vctools\crt_bld\self_64_amd64\crt\src\write.c(324) 0x7fee9a081a1 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
10 ha_innodb.dll _write + 0x8d, f:\dd\vctools\crt_bld\self_64_amd64\crt\src\write.c(73) 0x7fee9a08531 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
11 ha_innodb.dll _flush + 0x42, f:\dd\vctools\crt_bld\self_64_amd64\crt\src\fflush.c(152) 0x7fee9a01456 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
12 ha_innodb.dll _fflush_nolock + 0x1d, f:\dd\vctools\crt_bld\self_64_amd64\crt\src\fflush.c(101) 0x7fee9a014ad C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
13 ha_innodb.dll fflush + 0x2c, f:\dd\vctools\crt_bld\self_64_amd64\crt\src\fflush.c(64) 0x7fee9a015f4 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
14 ha_innodb.dll srv_printf_innodb_monitor + 0x461, c:\buildbot\winx64-packages\build\mariadb-5.5.30\storage\innobase\srv\srv0srv.c(2007) 0x7fee99e28b1 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
15 ha_innodb.dll srv_monitor_thread + 0x124, c:\buildbot\winx64-packages\build\mariadb-5.5.30\storage\innobase\srv\srv0srv.c(2188) 0x7fee99e2d54 C:\Program Files\MariaDB 5.5\lib\plugin\ha_innodb.dll
|
16 kernel32.dll BaseThreadInitThunk + 0xd 0x76e5652d C:\Windows\System32\kernel32.dll
|
17 ntdll.dll RtlUserThreadStart + 0x21 0x76f8c521 C:\Windows\System32\ntdll.dll
|
On a side note, I don't seem to see anything logged when I create just "innodb_monitor" (as opposed to "innodb_lock_monitor"). Please check this one as well (and any of those other innodb monitors - tables and tablespace), as it is working with XtraDB+ enabled.
Hi Chris,
You mean that you aren't getting anything either with innodb_lock_monitor or with innodb_monitor, right?
I didn't either, I tried it as well (but only when it's run as a service; in standalone mode it worked).
Yes, that's correct.
Still reproducible with InnoDB plugin on 5.5 and 10.0 running as a service (on 10.0 – both with the deprecated table creation, and with innodb_status_output).
As said above, not reproducible with XtraDB.
But also not reproducible on MySQL 5.6.21, which probably means that the problem is not in InnoDB plugin as such, but in it being a plugin?..
I have a local VM where I can experiment in any mean and wild way, as long as I know what can help to investigate the problem.
No separate InnoDB plugin anymore