Database process hangs sporadically when running inside an other Java application about mariadb4j HOT 11 CLOSED

hello @akkie - thank you for your interest in MariaDB4j, and for reporting this!

It's difficult to know what could be going on just based on your description. Could you elaborate what exactly you mean by "the MariaDB process hangs sporadically" - the JVM proc running the tests (maybe when/while it's trying to stop() DB?), or the MariaDB proc? I suspect you mean it's the former, because your second statement "I can connect to the database process and view the database structure" seems to confirm that MariaDB is NOT hung - do you see what I mean?

What I would then do to further analyse this yourself, if I were you, is to debug exactly where/how the JVM proc is stuck. You should be able to do this relatively easily using jstack if you have local access to your build server. Alternatively, you could start your JVM build job proc with something like "-Xrunjdwp:server=y,transport=dt_socket,address=4000,suspend=n" and then attach remote debug.

I suspect that you may find that, for some reason, you're stuck in class DB in method stop(), in ManagedProcess destroy() ? That "should" work, but in your case apparently doesn't always.. hm.

If that's it, I do have an idea for an alternative (or "first attempt" strategy) to shutdown the DB process - may be you could try this out and send me a pull request suggesting this? ;-) The idea is that to shutdown the DB, instead of just trying a OS proc kill, you could (first?) either run (as in exec) "mysqladmin shutdown -u... -p..." (see https://mariadb.com/kb/en/mysqladmin/) OR (better?) send (as in via JDBC) SHUTDOWN (see https://mariadb.com/kb/en/shutdown/). Maybe that strategy works better to stop it, in your case?

Will you please let me know what you find out, so that others can benefit from your investigation? Thank you!

from mariadb4j.

Hi,

Thanks for your answer.

I'm not sure whats going on and which process hung. For me it seems that none of the both processes hung, because I can connect to the database and if I shut down the database the build process resumes also. I think also that the problem comes from starting and not from stopping the database. Because the log suggest this and the tests can't be run against the database.

Maybe the problem occurs because the database process detaches from the JVM process during startup?

I will check your suggestions and let you know what I find out.

from mariadb4j.

Hi,

the output from jstack confirms my assumption. It seems that the database process gets detached from console and then MariaDB4j waits for log messages.

jstack -J-d64 -m 25882
Attaching to process ID 25882, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.55-b03
Deadlock Detection:

No deadlocks found.

----------------- 25886 -----------------
0x00007fca7e659a3e  __pthread_cond_timedwait + 0x13e
0x00007fca7d83c174  _ZN2os5sleepEP6Threadlb + 0x254
0x00007fca7d6a4662  JVM_Sleep + 0x342
0x00007fca7528ad91  <Unknown compiled code>
0x00007fca75006058  * ch.vorburger.exec.ManagedProcess.waitForConsoleMessage(java.lang.String) bci:161 line:373 (Interpreted frame)
0x00007fca75006058  * ch.vorburger.mariadb4j.DB.start() bci:221 line:129 (Interpreted frame)
0x00007fca75006058  * test.MySQLSpecification$class.start(test.MySQLSpecification) bci:6 line:85 (Interpreted frame)

What do you think?

from mariadb4j.

Hi @akkie - I'm terribly sorry for my long silence here, I've had other priorities since - are you still interested? ;-)

I had a closer look into it this week-end. So basically what happened in your case is that, as you absolutely correctly figured, during DB.start() MariaDB4j waited "forever" for the (hard-coded) log message "mysqld: ready for connections." to appear from the externally launched process. The idea of why I did this is that tests should not be able to start hitting the DB until it's up.. which seemed like a good idea (and clearly "mostly" works), but in your case it waits forever, sometimes - despite that message clearly appearing in your log, even though I can see you're using Percona, another mysql compatible DB, not MariaDB; but the message is the same, so that shouldn't be an issue. It must be some timing/concurrency issue that I'm missing; and despite having looked over the code again now, I can't seem to spot the case which could cause it.

But I've now changed the implementation slightly - it will now (latest; please pull & rebuild) never wait forever for "mysqld: ready for connections." anymore, but give up waiting after 10s - that's probably a safer strategy. I suspect that will resolve your case despite mystery above (at the detriment of possible useless 10s wait time at your tests start-up time).

May I ask what made you conclude that the "process gets detached from console" (you wrote above) ? Maybe I'm missing something there. If it still happens for you, or if after upgrading to my latest it won't block anymore but you see the new ""Timed out waiting for ... after X ms (returning false)" WARN log + "Database does not seem to have started up correctly? Magic string not seen" ManagedProcessException, could you provide a more complete full log? I wonder e.g. at what point the "Asked to wait for.." or "Thread is now going to wait for " messages appeared in your scenario (when it blocks or new gives up).

from mariadb4j.

Hi @akkie just wanted to let you know that I've just fixed an indirectly related issue in https://github.com/vorburger/MariaDB4j/issues/12 .. (and I'm still trying to chase the root cause of this one - unless with the upgrade from commons-exec commons-exec 1.1 to commons-exec 1.2 this one magically gets solved).

from mariadb4j.

Hi,

I'm currently involved into another project. I let you know if the issue remains as soon if I can test it. Thanks for your work on this.

Best regards,
Christian

from mariadb4j.

In a test where I'm stupidly start/stop 10'000 I'm able to reproduce this - and still see it even after #12 and commons-exec 1.2 upgrade..

Found https://issues.apache.org/jira/plugins/servlet/mobile#issue/EXEC-63 - not sure if it could be related to to this.

I'll need to investigate this more after holidays. (Unless anyone can dig deeper before - help more than appreciated - don't be shy!).

from mariadb4j.

I've now tested it again with the latest snapshot and the issue still remains. Would it be possible to create a new branch which contains the patched version of commons-exec from this repository that is referenced in the issue you mentioned?

from mariadb4j.

@akkie I just had a look at this again tonight.. with current latest master as of now (7b18ea8), as already before, I really don't not getting any "hang" anymore.. can you clarify what you mean when you say "the issue still remains" - does "Database process hangs sporadically when running inside an other Java application" for you? If so, a new jstack would be useful.

I'm NOT saying its all fine - if I run https://github.com/vorburger/MariaDB4j/blob/master/src/test/java/ch/vorburger/mariadb4j/tests/StartManyTimes.java then it does fail with "Timed out waiting for ... after X ms (returning false)" WARN log + "Database does not seem to have started up correctly? Magic string not seen" sooner or later - but never with a hang. The "new" issue, probably due to the same root cause, just manifesting itself differently now that I have introduced timeouts.

I was hesitant to use msandiford/commons-exec fork repo, as it's behind, but have created a patch of https://issues.apache.org/jira/browse/EXEC-63 that I applied myself locally.. unfortunately when running the x100000 StartManyTimes it still eventually failed as explained above, so this doesn't help.. details:

00:37:51.890 [main] INFO ch.vorburger.exec.ManagedProcess - Starting Program [/tmp/MariaDB4j/base/bin/mysqld, --no-defaults, --console, --skip-grant-tables, --max_allowed_packet=64M, --basedir=/tmp/MariaDB4j/base, --datadir=/tmp/MariaDB4j/data/38749, --port=38749, --socket=/tmp/MariaDB4j.38749.sock](in working directory /tmp/MariaDB4j/base)
00:37:51.890 [main] DEBUG ch.vorburger.exec.ManagedProcess - /tmp/MariaDB4j/base/bin/mysqld is not a java.io.File, so it won't be made executable (which MAY be a problem on *NIX, but not for sure)
00:37:51.897 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: The InnoDB memory heap is disabled
00:37:51.897 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins
00:37:51.897 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Compressed tables use zlib 1.2.3
00:37:51.897 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Using Linux native AIO
00:37:51.901 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Initializing buffer pool, size = 128.0M
00:37:51.905 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Completed initialization of buffer pool
00:37:51.907 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: InnoDB: The first specified data file ./ibdata1 did not exist:
00:37:51.907 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: InnoDB: a new database to be created!
00:37:51.907 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Setting file ./ibdata1 size to 10 MB
00:37:51.907 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: InnoDB: Database physically writes the file full: wait...
00:37:51.991 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: 141120 0:37:51 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
00:37:51.991 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: InnoDB: Setting log file ./ib_logfile0 size to 5 MB
00:37:51.991 [Exec Stream Pumper] ERROR ch.vorburger.exec.ManagedProcess - mysqld: InnoDB: Database physically writes the file full: wait...
00:37:51.991 [main] INFO ch.vorburger.exec.ManagedProcess - Thread is now going to wait for "mysqld: ready for connections." to appear in Console output of process Program [/tmp/MariaDB4j/base/bin/mysqld, --no-defaults, --console, --skip-grant-tables, --max_allowed_packet=64M, --basedir=/tmp/MariaDB4j/base, --datadir=/tmp/MariaDB4j/data/38749, --port=38749, --socket=/tmp/MariaDB4j.38749.sock](in working directory /tmp/MariaDB4j/base) for max. 30000ms

Notice the gap in the timestamp here... its as if when it started waiting, it stopped piping..

00:38:22.093 [main] WARN ch.vorburger.exec.ManagedProcess - Timed out waiting for ""mysqld: ready for connections."" after 30000ms (returning false)
00:38:22.093 [main] DEBUG ch.vorburger.exec.ManagedProcess - Going to destroy Program [/tmp/MariaDB4j/base/bin/mysqld, --no-defaults, --console, --skip-grant-tables, --max_allowed_packet=64M, --basedir=/tmp/MariaDB4j/base, --datadir=/tmp/MariaDB4j/data/38749, --port=38749, --socket=/tmp/MariaDB4j.38749.sock](in working directory /tmp/MariaDB4j/base)
00:38:22.920 [Exec Default Executor] INFO ch.vorburger.exec.ManagedProcess - Program [/tmp/MariaDB4j/base/bin/mysqld, --no-defaults, --console, --skip-grant-tables, --max_allowed_packet=64M, --basedir=/tmp/MariaDB4j/base, --datadir=/tmp/MariaDB4j/data/38749, --port=38749, --socket=/tmp/MariaDB4j.38749.sock](in working directory /tmp/MariaDB4j/base) just exited, with value 0
00:38:22.944 [main] INFO ch.vorburger.exec.ManagedProcess - Successfully destroyed Program [/tmp/MariaDB4j/base/bin/mysqld, --no-defaults, --console, --skip-grant-tables, --max_allowed_packet=64M, --basedir=/tmp/MariaDB4j/base, --datadir=/tmp/MariaDB4j/data/38749, --port=38749, --socket=/tmp/MariaDB4j.38749.sock](in working directory /tmp/MariaDB4j/base)
Exception in thread "main" 00:38:22.945 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
00:38:22.945 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
00:38:22.945 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
00:38:22.946 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
00:38:22.946 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
00:38:22.946 [Shutdown Hook Deletion Thread for Temporary DB /tmp/MariaDB4j/data/38749] INFO ch.vorburger.mariadb4j.DB - cleanupOnExit() ShutdownHook deleting temporary DB data directory: /tmp/MariaDB4j/data/38749
ch.vorburger.exec.ManagedProcessException: Database does not seem to have started up correctly? Magic string not seen in 30000ms: mysqld: ready for connections., last 100 lines of console:
141120 0:37:51 InnoDB: The InnoDB memory heap is disabled
141120 0:37:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins
141120 0:37:51 InnoDB: Compressed tables use zlib 1.2.3
141120 0:37:51 InnoDB: Using Linux native AIO
141120 0:37:51 InnoDB: Initializing buffer pool, size = 128.0M
141120 0:37:51 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
141120 0:37:51 InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
at ch.vorburger.mariadb4j.DB.start(DB.java:154)
at ch.vorburger.mariadb4j.tests.StartManyTimes.main(StartManyTimes.java:45)

So unless the mysqld process really gets "stuck" somehow, which is very unlikely, I suspect that this is some (concurrency? overflow) bug in my https://github.com/vorburger/MariaDB4j/blob/master/src/main/java/ch/vorburger/exec/ManagedProcess.java, https://github.com/vorburger/MariaDB4j/blob/master/src/main/java/ch/vorburger/exec/RollingLogOutputStream.java, or perhaps in the org.apache.commons.collections.buffer.CircularFifoBuffer.CircularFifoBuffer(int) I'm using (wrongly?).. @mseaton, @osimola, @djazayeri, @cioan, @szermatt if any of you happen to be able to offer any insight into this, that would be incredibly cool and very helpful.

from mariadb4j.

Actually... I think I may have found a solution for this (local, not out yet) - a combined all-in-one startAndWaitForConsoleMessageMaxMs() instead of a separate start() + waitForConsoleMessageMaxMs() significantly simplifies this; should have thought about this before.

10'000x StartManyTimes running right now over night to confirm; will then push out if OK.

from mariadb4j.

Yea, it works. I've run the build 3-times without an error. Many, many thanks for your work on this.

from mariadb4j.