[h2] With LOCK_MODE=0, log file still has hundreds of locks

Discussion:

Patrick H

2018-01-03 19:33:54 UTC

Hello,

I am using:

java -Xmx4096m -Xverify:none -cp %CLASSPATH%\h2-1.4.196.jar
org.h2.tools.RunScript -url
"jdbc:h2:nioMapped:~/%DB_NAME%;LOCK_MODE=0;TRACE_LEVEL_FILE=3;UNDO_LOG=0"
-user "admin" -password "admin" -script "D:/dev/sql/sqlscript.sql"

and "sqlscript.sql' has a hundred or more: RUNSCRIPT FROM '<filename.sql>';

Basically, I have a master run script running hundreds of sub-RUNSCRIPT.
The objective of my master/sub-scripts it to bulk load data.

And when I review the log file, database.trace.db, it contains hundreds of
LOCKS.

For example:

2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
...
...
...

Can anyone please explain why locks are still happening with LOCK_MODE=0?

Thanks,

Patrick

--
You received this message because you are subscribed to the Google Groups "H2 Database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to h2-database+***@googlegroups.com.
To post to this group, send email to h2-***@googlegroups.com.
Visit this group at https://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/d/optout.

Patrick H

2018-01-03 23:17:31 UTC

Permalink

I believe this to be the problem.

File: MVTable.java
public boolean lock(Session session, boolean exclusive,
boolean forceLockEvenInMvcc) {
int lockMode = database.getLockMode();
if (lockMode == Constants.LOCK_MODE_OFF) {
return false;
}

database.getLockMode() is returning '3' as opposed to '0'.

I'm trying to determine if LOCK_MODE=0 is passed to the database object.

Patrick

Post by Patrick H
Hello,
java -Xmx4096m -Xverify:none -cp %CLASSPATH%\h2-1.4.196.jar
org.h2.tools.RunScript -url
"jdbc:h2:nioMapped:~/%DB_NAME%;LOCK_MODE=0;TRACE_LEVEL_FILE=3;UNDO_LOG=0"
-user "admin" -password "admin" -script "D:/dev/sql/sqlscript.sql"
and "sqlscript.sql' has a hundred or more: RUNSCRIPT FROM '<filename.sql>';
Basically, I have a master run script running hundreds of sub-RUNSCRIPT.
The objective of my master/sub-scripts it to bulk load data.
And when I review the log file, database.trace.db, it contains hundreds of
LOCKS.
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
...
...
...
Can anyone please explain why locks are still happening with LOCK_MODE=0?
Thanks,
Patrick

Patrick H

2018-01-04 00:22:32 UTC

Permalink

Constructor, public Database(ConnectionInfo ci, String cipher) where all
the URL options are parsed never parses for the 'LOCK_MODE' option. Thus
never changes the default value for Database.lockMode which is
Constants.DEFAULT_LOCK_MODE (3).

Patrick

Post by Patrick H
I believe this to be the problem.
File: MVTable.java
public boolean lock(Session session, boolean exclusive,
boolean forceLockEvenInMvcc) {
int lockMode = database.getLockMode();
if (lockMode == Constants.LOCK_MODE_OFF) {
return false;
}
database.getLockMode() is returning '3' as opposed to '0'.
I'm trying to determine if LOCK_MODE=0 is passed to the database object.
Patrick

Post by Patrick H
Hello,
java -Xmx4096m -Xverify:none -cp %CLASSPATH%\h2-1.4.196.jar
org.h2.tools.RunScript -url
"jdbc:h2:nioMapped:~/%DB_NAME%;LOCK_MODE=0;TRACE_LEVEL_FILE=3;UNDO_LOG=0"
-user "admin" -password "admin" -script "D:/dev/sql/sqlscript.sql"
and "sqlscript.sql' has a hundred or more: RUNSCRIPT FROM
'<filename.sql>';
Basically, I have a master run script running hundreds of sub-RUNSCRIPT.
The objective of my master/sub-scripts it to bulk load data.
And when I review the log file, database.trace.db, it contains hundreds
of LOCKS.
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
...
...
...
Can anyone please explain why locks are still happening with LOCK_MODE=0?
Thanks,
Patrick

Patrick H

2018-01-04 00:48:10 UTC

Permalink

This also seems to be incorrect:

File: org.h2.schema.Sequence
private void flushInternal(Session session) {
final boolean metaWasLocked = database.lockMeta(session);
// just for this case, use the value with the margin
try {
writeWithMargin = true;
database.updateMeta(session, this);
} finally {
writeWithMargin = false;
}
if (!metaWasLocked) {
database.unlockMeta(session);
}
}

I would think you'd only want to call database.unlockMeta when
'metaWasLocked' == true

Why would you want to unlock something when it wasn't locked?

Patrick

Post by Patrick H
Constructor, public Database(ConnectionInfo ci, String cipher) where all
the URL options are parsed never parses for the 'LOCK_MODE' option. Thus
never changes the default value for Database.lockMode which is
Constants.DEFAULT_LOCK_MODE (3).
Patrick

Post by Patrick H
Hello,
java -Xmx4096m -Xverify:none -cp %CLASSPATH%\h2-1.4.196.jar
org.h2.tools.RunScript -url
"jdbc:h2:nioMapped:~/%DB_NAME%;LOCK_MODE=0;TRACE_LEVEL_FILE=3;UNDO_LOG=0"
-user "admin" -password "admin" -script "D:/dev/sql/sqlscript.sql"
and "sqlscript.sql' has a hundred or more: RUNSCRIPT FROM
'<filename.sql>';
Basically, I have a master run script running hundreds of sub-RUNSCRIPT.
The objective of my master/sub-scripts it to bulk load data.
And when I review the log file, database.trace.db, it contains hundreds
of LOCKS.
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
...
...
...
Can anyone please explain why locks are still happening with LOCK_MODE=0?
Thanks,
Patrick

Noel Grandin

2018-01-04 06:21:15 UTC

Permalink

Post by Patrick H
Why would you want to unlock something when it wasn't locked?

Because updateMeta will lock it, and we don't want to unlock it if it was
previously locked.

Noel Grandin

2018-01-04 06:24:54 UTC

Permalink

It's not obvious how this works - set a breakpoint in Database.setLockMode
and you'll see how it parses the options from the URL.

Patrick H

2018-01-04 17:30:49 UTC

Permalink

Yes, I have done that (breakpoint on setLockMode) and it is not called
before these log outputs:

2018-01-03 11:04:28 lock: 1 exclusive write lock requesting for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock added for SYS
2018-01-03 11:04:28 lock: 1 exclusive write lock unlock SYS
...
...

Answer this: Is LOCK_MODE=0 to disable ALL locking or just some locking?
The documentation suggests ALL locking is disabled.

And if the answer is ALL, then clearly from the log file this is not
happening.

For testing I added code:

this.lockMode = ci.getProperty("LOCK_MODE", Constants.DEFAULT_LOCK_MODE);

to constructor:

Database(ConnectionInfo ci, String cipher)

and the original log locking output was removed. However, I don't fully
understand the locking design to know if this correct.

This is why I shared my analysis to help focus developer's attention.

Patrick

Post by Noel Grandin

It's not obvious how this works - set a breakpoint in Database.setLockMode
and you'll see how it parses the options from the URL.

Noel Grandin

2018-01-04 19:12:37 UTC

Permalink

what you are seeing is just the locking we do during startup.â

Patrick H

2018-01-04 19:31:27 UTC

Permalink

No, locking is happening throughout. I see locking happen with every
sub-RUNSCRIPT.

Why is locking even happening? Again, is LOCK_MODE to disable ALL locking
or not?

Post by Noel Grandin
what you are seeing is just the locking we do during startup.â

Noel Grandin

2018-01-05 06:37:24 UTC

Permalink

Yup, it should disable all locking.â Why this is happening for you I don't
know.

Patrick H

2018-01-05 15:29:36 UTC

Permalink

Why this is happening for you I don't know.

Are you suggesting it doesn't happen to you?

Has there been any testing that focuses on RUNSCRIPT being used in a SQL
script file?

From my testing calling RUNSCRIPT seems to seriously alter the designed
behavior of H2.

Locking is unreliable and TRACE output doesn't work.

Yup, it should disable all locking.â Why this is happening for you I don't
know.

Noel Grandin

2018-01-05 19:08:53 UTC

Permalink

LOCK_MODE=0 is not something we have a lot of test coverage for, so I only
know that is works for normal cases.â

You're more than welcome to submit patches to fix your specific use-case.

Patrick H

2018-01-05 21:16:06 UTC

Permalink

I don't see how calling RUNSCRIPT is abnormal, but OK.

I'll see about adding fix:

this.lockMode = ci.getProperty("LOCK_MODE", Constants.DEFAULT_LOCK_MODE);

to constructor:

Database(ConnectionInfo ci, String cipher)

Post by Noel Grandin
LOCK_MODE=0 is not something we have a lot of test coverage for, so I only
know that is works for normal cases.â
You're more than welcome to submit patches to fix your specific use-case.

Continue reading on narkive:

Search results for '[h2] With LOCK_MODE=0, log file still has hundreds of locks' (Questions and Answers)

replies

So my Windows XP Home Edition will not let me log in.?

started 2009-11-13 18:43:52 UTC

software

replies

Help me remove spyware and don't give me the usual advice about lavasoft's ad-aware, thanks?

started 2008-10-24 19:18:08 UTC

security

replies

help my comp got locked?