You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@manifoldcf.apache.org by Olivier Tavard <ol...@francelabs.com> on 2019/05/06 09:55:57 UTC
issue for indexing large blobs into databases
Hi MCF community,
We have some issues with the JDBC connector to index database with large LONGBLOB into it : I mean files more than 100 MB.
To reproduce the issue, I created a simple database on MySQL 5.7 with only one table into it with 2 columns : id (int) and data (longblob).
There are 8 records in the table : two records with very small files : less than 5 KB and 6 records with a large file of 192 MB.
If I include in my crawl only one big BLOB, the crawl is successful.
seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
But if I include more than 2 of these (with a WHERE IN condition or if select all the records of the table) the job stays in running condition but no document is processed :
seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
There is no message in the logs (even with debug mode activated).
The tests were done in a Docker cluster on dedicated servers (4 cores, 32 GB RAM each).
Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx and xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper based synchronization.
We have a dump of the database here : https://www.datafari.com/files/mcftest.tar.gz <https://www.datafari.com/files/mcftest.tar.gz>
In other cases, we also encounter this error :
Error: Unexpected jobqueue status - record id 1555190422690, expecting active status, saw 0
Any ideas of what the problem could be ? or at least why there is nothing in the debug log you think ?
Thank you,
Best regards,
Olivier
Re: issue for indexing large blobs into databases
Posted by Olivier Tavard <ol...@francelabs.com>.
Hi Karl,
Thanks for your answer and the quick fix.
Best regards,
Olivier
> Le 13 mai 2019 à 19:46, Karl Wright <da...@gmail.com> a écrit :
>
> I committed a fix for this hang to trunk.
> Karl
>
>
> On Mon, May 13, 2019 at 11:40 AM Karl Wright <da...@gmail.com> wrote:
>
>> Thanks -- this shows a classic deadlock occurring, where the System.exit()
>> call effectively blocks the thread that does it from exiting, and thus
>> blocks the system from shutting down. This is a change of behavior in the
>> JVM; not sure when it happened, but this didn't happen before. But it
>> easily addressed.
>>
>> Karl
>>
>>
>> On Mon, May 13, 2019 at 10:58 AM Olivier Tavard <
>> olivier.tavard@francelabs.com> wrote:
>>
>>> Hi Karl,
>>>
>>> Thank you for your mail.
>>> I installed an ootb MCF 2.13 to have a clean installation. I launched the
>>> File-based multiprocess example and I did the previous tests I mentioned.
>>> I managed to see the error that you told me about :
>>>
>>> agents process ran out of memory - shutting down
>>> java.lang.OutOfMemoryError: Java heap space
>>> at com.mysql.jdbc.Buffer.ensureCapacity(Buffer.java:155)
>>> at com.mysql.jdbc.Buffer.writeBytesNoNull(Buffer.java:513)
>>> at
>>> com.mysql.jdbc.MysqlIO.readRemainingMultiPackets(MysqlIO.java:3116)
>>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2971)
>>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
>>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
>>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:910)
>>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1405)
>>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>>> at
>>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>>> at
>>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>>> at
>>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>>> at
>>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>>>
>>> But the mcf-agent process is still active, it was not shut down.
>>> I did a new thread dump, I obtained this :
>>> Full thread dump OpenJDK 64-Bit Server VM (25.212-b01 mixed mode):
>>>
>>> "Shutdown thread" #8 prio=5 os_prio=0 tid=0x00007f8ccc014000 nid=0x436a
>>> in Object.wait() [0x00007f8c2a9e8000]
>>> java.lang.Thread.State: TIMED_WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at
>>> org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
>>> - locked <0x00000000e0930708> (a java.lang.Integer)
>>> at
>>> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopSystem(CrawlerAgent.java:617)
>>> at
>>> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopAgent(CrawlerAgent.java:249)
>>> at
>>> org.apache.manifoldcf.agents.system.AgentsDaemon.stopAgents(AgentsDaemon.java:168)
>>> - locked <0x00000000eab32808> (a java.util.HashMap)
>>> at
>>> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsShutdownHook.doCleanup(AgentsDaemon.java:395)
>>> at
>>> org.apache.manifoldcf.core.system.ManifoldCF.cleanUpEnvironment(ManifoldCF.java:1540)
>>> - locked <0x00000000eab24af8> (a java.util.ArrayList)
>>> - locked <0x00000000eab24ca0> (a java.lang.Integer)
>>> at
>>> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread.run(ManifoldCF.java:1718)
>>>
>>> "MySQL Statement Cancellation Timer" #2567 daemon prio=5 os_prio=0
>>> tid=0x00007f8c84061800 nid=0x4090 in Object.wait() [0x00007f8c2aeed000]
>>> java.lang.Thread.State: WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at java.lang.Object.wait(Object.java:502)
>>> at java.util.TimerThread.mainLoop(Timer.java:526)
>>> - locked <0x00000000ebe79d20> (a java.util.TaskQueue)
>>> at java.util.TimerThread.run(Timer.java:505)
>>>
>>> "Connection pool reaper" #2565 daemon prio=5 os_prio=0
>>> tid=0x00007f8cf809d000 nid=0x408e waiting on condition [0x00007f8c2aceb000]
>>> java.lang.Thread.State: TIMED_WAITING (sleeping)
>>> at java.lang.Thread.sleep(Native Method)
>>> at
>>> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>>>
>>> "Worker thread '0'" #66 daemon prio=5 os_prio=0 tid=0x00007f8cfc209800
>>> nid=0x35d8 in Object.wait() [0x00007f8d0c6f4000]
>>> java.lang.Thread.State: WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at java.lang.Thread.join(Thread.java:1252)
>>> - locked <0x00000000eab24b28> (a
>>> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread)
>>> at java.lang.Thread.join(Thread.java:1326)
>>> at
>>> java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:107)
>>> at
>>> java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
>>> at java.lang.Shutdown.runHooks(Shutdown.java:123)
>>> at java.lang.Shutdown.sequence(Shutdown.java:167)
>>> at java.lang.Shutdown.exit(Shutdown.java:212)
>>> - locked <0x00000000eaae4150> (a java.lang.Class for java.lang.Shutdown)
>>> at java.lang.Runtime.exit(Runtime.java:109)
>>> at java.lang.System.exit(System.java:971)
>>> at
>>> org.apache.manifoldcf.crawler.system.WorkerThread.run(WorkerThread.java:851)
>>>
>>> "Connection pool reaper" #13 daemon prio=5 os_prio=0
>>> tid=0x00007f8cfc04b000 nid=0x35a0 waiting on condition [0x00007f8d2c47b000]
>>> java.lang.Thread.State: TIMED_WAITING (sleeping)
>>> at java.lang.Thread.sleep(Native Method)
>>> at
>>> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>>>
>>> "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b6000
>>> nid=0x359c runnable [0x0000000000000000]
>>> java.lang.Thread.State: RUNNABLE
>>>
>>> "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b3000
>>> nid=0x359b waiting on condition [0x0000000000000000]
>>> java.lang.Thread.State: RUNNABLE
>>>
>>> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b0800
>>> nid=0x359a waiting on condition [0x0000000000000000]
>>> java.lang.Thread.State: RUNNABLE
>>>
>>> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f8d3c0af000
>>> nid=0x3599 waiting on condition [0x0000000000000000]
>>> java.lang.Thread.State: RUNNABLE
>>>
>>> "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f8d3c07b800 nid=0x3598
>>> in Object.wait() [0x00007f8d410d3000]
>>> java.lang.Thread.State: WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
>>> - locked <0x00000000eaaf2038> (a java.lang.ref.ReferenceQueue$Lock)
>>> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
>>> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
>>>
>>> "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f8d3c079000
>>> nid=0x3597 in Object.wait() [0x00007f8d411d4000]
>>> java.lang.Thread.State: WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at java.lang.Object.wait(Object.java:502)
>>> at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
>>> - locked <0x00000000eaaf21f0> (a java.lang.ref.Reference$Lock)
>>> at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
>>>
>>> "main" #1 prio=5 os_prio=0 tid=0x00007f8d3c00b800 nid=0x3595 in
>>> Object.wait() [0x00007f8d45902000]
>>> java.lang.Thread.State: TIMED_WAITING (on object monitor)
>>> at java.lang.Object.wait(Native Method)
>>> at
>>> org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
>>> - locked <0x00000000e26ec910> (a java.lang.Integer)
>>> at
>>> org.apache.manifoldcf.agents.system.AgentsDaemon.runAgents(AgentsDaemon.java:115)
>>> at org.apache.manifoldcf.agents.AgentRun.doExecute(AgentRun.java:64)
>>> at
>>> org.apache.manifoldcf.agents.BaseAgentsInitializationCommand.execute(BaseAgentsInitializationCommand.java:37)
>>> at org.apache.manifoldcf.agents.AgentRun.main(AgentRun.java:93)
>>>
>>> "VM Thread" os_prio=0 tid=0x00007f8d3c06f800 nid=0x3596 runnable
>>>
>>> "VM Periodic Task Thread" os_prio=0 tid=0x00007f8d3c0b9000 nid=0x359d
>>> waiting on condition
>>>
>>> JNI global references: 13
>>>
>>> Heap
>>> def new generation total 157248K, used 39902K [0x00000000e0000000,
>>> 0x00000000eaaa0000, 0x00000000eaaa0000)
>>> eden space 139776K, 28% used [0x00000000e0000000, 0x00000000e26f7a80,
>>> 0x00000000e8880000)
>>> from space 17472K, 0% used [0x00000000e9990000, 0x00000000e9990000,
>>> 0x00000000eaaa0000)
>>> to space 17472K, 0% used [0x00000000e8880000, 0x00000000e8880000,
>>> 0x00000000e9990000)
>>> tenured generation total 349568K, used 173322K [0x00000000eaaa0000,
>>> 0x0000000100000000, 0x0000000100000000)
>>> the space 349568K, 49% used [0x00000000eaaa0000, 0x00000000f53e2ac8,
>>> 0x00000000f53e2c00, 0x0000000100000000)
>>> Metaspace used 16548K, capacity 16750K, committed 17024K, reserved
>>> 1064960K
>>> class space used 1806K, capacity 1891K, committed 1920K, reserved
>>> 1048576K
>>>
>>> Best regards,
>>>
>>> Olivier
>>>
>>>> Le 7 mai 2019 à 13:02, Karl Wright <da...@gmail.com> a écrit :
>>>>
>>>> The thread dump is not helpful. I see no traces for any threads that
>>>> identify code from MCF at all. That's new and has nothing to do with
>>> MCF;
>>>> it's probably a new Java "feature".
>>>>
>>>> The OutOfMemoryException should, I've confirmed, be rethrown. The
>>> Worker
>>>> Thread code does in fact catch the exception and terminate the process:
>>>>
>>>>>>>>>>
>>>> catch (OutOfMemoryError e)
>>>> {
>>>> System.err.println("agents process ran out of memory - shutting
>>>> down");
>>>> e.printStackTrace(System.err);
>>>> System.exit(-200);
>>>> }
>>>> <<<<<<
>>>>
>>>> So that is what you should see happening.
>>>>
>>>> Are you providing the complete stack trace from your out-of-memory
>>>> exception? That would help confirm the picture. It had to have been
>>>> printed from somewhere; it goes to standard error, whatever that is.
>>>>
>>>> Karl
>>>>
>>>>
>>>> On Tue, May 7, 2019 at 6:42 AM Karl Wright <da...@gmail.com> wrote:
>>>>
>>>>> Hi Olivier,
>>>>>
>>>>> Any out-of-memory exception that makes it to the top level should cause
>>>>> the agents process to shut itself down.
>>>>>
>>>>> The reason for this is simple: in a multithread environment, with lots
>>> of
>>>>> third-party jars, an out-of-memory in one thread is usually indicative
>>> of
>>>>> an out-of-memory in other threads as well, and we cannot count on that
>>>>> third-party software being rigorous about letting an
>>> OutOfMemoryException
>>>>> be thrown to the top level. So we tend to get corrupted results that
>>> are
>>>>> hard to recover from.
>>>>>
>>>>> In this case, the exception is being thrown within the JDBCConnector,
>>> so
>>>>> it ought to rethrow the OutOfMemoryException. Let me confirm that is
>>> what
>>>>> the code indicates.
>>>>>
>>>>> Karl
>>>>>
>>>>>
>>>>> On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <
>>>>> olivier.tavard@francelabs.com> wrote:
>>>>>
>>>>>> Hi Karl,
>>>>>>
>>>>>> Thank you for your help.
>>>>>> Indeed I found a OoM error in the logs of the MCF-agent process :
>>>>>> java.lang.OutOfMemoryError: Java heap space
>>>>>> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
>>>>>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
>>>>>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>>>>>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>>>>>> at
>>>>>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>>>>>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>>>>>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>>>>>> at
>>> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>>>>>> at
>>>>>>
>>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>>>>>> at
>>>>>>
>>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>>>>>> at
>>>>>>
>>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>>>>>>
>>>>>>
>>>>>> But the MCF process agent was not killed, it is still active. Why is
>>> the
>>>>>> process still active in this case ? Since we know that we can get an
>>> OOM,
>>>>>> couldn't we find an elegant way to notify users of this problem from
>>> the
>>>>>> MCF admin UI, rather than just having the process endlessly active ?
>>>>>>
>>>>>> As for the OOM, the work around we decided to use is to increase the
>>>>>> values of xms and xmx java memory in options.env.unix.
>>>>>> I also attached the thread dump to this mail.
>>>>>>
>>>>>> Thanks,
>>>>>> Best regards,
>>>>>>
>>>>>> Olivier
>>>>>>
>>>>>> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>>>>>>
>>>>>> It sounds like there might be an out-of-memory situation, although if
>>>>>> that is the case I would expect that the MCF agents process would
>>> just shut
>>>>>> itself down.
>>>>>>
>>>>>> If the process is hung, it should be easy to get a thread dump. That
>>>>>> would be the first step.
>>>>>>
>>>>>> Some thoughts as to what might be happening: there might be an
>>>>>> out-of-memory condition that is being silently eaten somewhere. MCF
>>> relies
>>>>>> on its connectors to use streams rather than load documents into
>>> memory,
>>>>>> BUT we're at the mercy of the JDBC drivers and Tika. So another
>>> experiment
>>>>>> would be to try to crawl your documents without the tika extractor
>>> (just
>>>>>> send them to the null output connector) and see if that succeeds. If
>>> it
>>>>>> does, then maybe try the external Tika Service connector instead and
>>> see
>>>>>> what happens then.
>>>>>>
>>>>>> Karl
>>>>>>
>>>>>>
>>>>>> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
>>>>>> olivier.tavard@francelabs.com> wrote:
>>>>>>
>>>>>>> Hi MCF community,
>>>>>>>
>>>>>>> We have some issues with the JDBC connector to index database with
>>> large
>>>>>>> LONGBLOB into it : I mean files more than 100 MB.
>>>>>>> To reproduce the issue, I created a simple database on MySQL 5.7 with
>>>>>>> only one table into it with 2 columns : id (int) and data
>>> (longblob).
>>>>>>> There are 8 records in the table : two records with very small files
>>> :
>>>>>>> less than 5 KB and 6 records with a large file of 192 MB.
>>>>>>>
>>>>>>> If I include in my crawl only one big BLOB, the crawl is successful.
>>>>>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>>>>>>>
>>>>>>> But if I include more than 2 of these (with a WHERE IN condition or
>>> if
>>>>>>> select all the records of the table) the job stays in running
>>> condition but
>>>>>>> no document is processed :
>>>>>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> There is no message in the logs (even with debug mode activated).
>>>>>>> The tests were done in a Docker cluster on dedicated servers (4
>>> cores,
>>>>>>> 32 GB RAM each).
>>>>>>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx
>>>>>>> and xmx) the internal database is PostgreSQL 10.1 and we use
>>> Zookeeper
>>>>>>> based synchronization.
>>>>>>> We have a dump of the database here :
>>>>>>> https://www.datafari.com/files/mcftest.tar.gz
>>>>>>>
>>>>>>> In other cases, we also encounter this error :
>>>>>>> Error: Unexpected jobqueue status - record id 1555190422690,
>>> expecting
>>>>>>> active status, saw 0
>>>>>>>
>>>>>>> Any ideas of what the problem could be ? or at least why there is
>>>>>>> nothing in the debug log you think ?
>>>>>>>
>>>>>>> Thank you,
>>>>>>> Best regards,
>>>>>>>
>>>>>>> Olivier
>>>>>>>
>>>>>>
>>>>>>
>>>
>>>
Re: issue for indexing large blobs into databases
Posted by Karl Wright <da...@gmail.com>.
I committed a fix for this hang to trunk.
Karl
On Mon, May 13, 2019 at 11:40 AM Karl Wright <da...@gmail.com> wrote:
> Thanks -- this shows a classic deadlock occurring, where the System.exit()
> call effectively blocks the thread that does it from exiting, and thus
> blocks the system from shutting down. This is a change of behavior in the
> JVM; not sure when it happened, but this didn't happen before. But it
> easily addressed.
>
> Karl
>
>
> On Mon, May 13, 2019 at 10:58 AM Olivier Tavard <
> olivier.tavard@francelabs.com> wrote:
>
>> Hi Karl,
>>
>> Thank you for your mail.
>> I installed an ootb MCF 2.13 to have a clean installation. I launched the
>> File-based multiprocess example and I did the previous tests I mentioned.
>> I managed to see the error that you told me about :
>>
>> agents process ran out of memory - shutting down
>> java.lang.OutOfMemoryError: Java heap space
>> at com.mysql.jdbc.Buffer.ensureCapacity(Buffer.java:155)
>> at com.mysql.jdbc.Buffer.writeBytesNoNull(Buffer.java:513)
>> at
>> com.mysql.jdbc.MysqlIO.readRemainingMultiPackets(MysqlIO.java:3116)
>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2971)
>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:910)
>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1405)
>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>> at
>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>> at
>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>> at
>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>> at
>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>>
>> But the mcf-agent process is still active, it was not shut down.
>> I did a new thread dump, I obtained this :
>> Full thread dump OpenJDK 64-Bit Server VM (25.212-b01 mixed mode):
>>
>> "Shutdown thread" #8 prio=5 os_prio=0 tid=0x00007f8ccc014000 nid=0x436a
>> in Object.wait() [0x00007f8c2a9e8000]
>> java.lang.Thread.State: TIMED_WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at
>> org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
>> - locked <0x00000000e0930708> (a java.lang.Integer)
>> at
>> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopSystem(CrawlerAgent.java:617)
>> at
>> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopAgent(CrawlerAgent.java:249)
>> at
>> org.apache.manifoldcf.agents.system.AgentsDaemon.stopAgents(AgentsDaemon.java:168)
>> - locked <0x00000000eab32808> (a java.util.HashMap)
>> at
>> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsShutdownHook.doCleanup(AgentsDaemon.java:395)
>> at
>> org.apache.manifoldcf.core.system.ManifoldCF.cleanUpEnvironment(ManifoldCF.java:1540)
>> - locked <0x00000000eab24af8> (a java.util.ArrayList)
>> - locked <0x00000000eab24ca0> (a java.lang.Integer)
>> at
>> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread.run(ManifoldCF.java:1718)
>>
>> "MySQL Statement Cancellation Timer" #2567 daemon prio=5 os_prio=0
>> tid=0x00007f8c84061800 nid=0x4090 in Object.wait() [0x00007f8c2aeed000]
>> java.lang.Thread.State: WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at java.lang.Object.wait(Object.java:502)
>> at java.util.TimerThread.mainLoop(Timer.java:526)
>> - locked <0x00000000ebe79d20> (a java.util.TaskQueue)
>> at java.util.TimerThread.run(Timer.java:505)
>>
>> "Connection pool reaper" #2565 daemon prio=5 os_prio=0
>> tid=0x00007f8cf809d000 nid=0x408e waiting on condition [0x00007f8c2aceb000]
>> java.lang.Thread.State: TIMED_WAITING (sleeping)
>> at java.lang.Thread.sleep(Native Method)
>> at
>> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>>
>> "Worker thread '0'" #66 daemon prio=5 os_prio=0 tid=0x00007f8cfc209800
>> nid=0x35d8 in Object.wait() [0x00007f8d0c6f4000]
>> java.lang.Thread.State: WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at java.lang.Thread.join(Thread.java:1252)
>> - locked <0x00000000eab24b28> (a
>> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread)
>> at java.lang.Thread.join(Thread.java:1326)
>> at
>> java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:107)
>> at
>> java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
>> at java.lang.Shutdown.runHooks(Shutdown.java:123)
>> at java.lang.Shutdown.sequence(Shutdown.java:167)
>> at java.lang.Shutdown.exit(Shutdown.java:212)
>> - locked <0x00000000eaae4150> (a java.lang.Class for java.lang.Shutdown)
>> at java.lang.Runtime.exit(Runtime.java:109)
>> at java.lang.System.exit(System.java:971)
>> at
>> org.apache.manifoldcf.crawler.system.WorkerThread.run(WorkerThread.java:851)
>>
>> "Connection pool reaper" #13 daemon prio=5 os_prio=0
>> tid=0x00007f8cfc04b000 nid=0x35a0 waiting on condition [0x00007f8d2c47b000]
>> java.lang.Thread.State: TIMED_WAITING (sleeping)
>> at java.lang.Thread.sleep(Native Method)
>> at
>> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>>
>> "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b6000
>> nid=0x359c runnable [0x0000000000000000]
>> java.lang.Thread.State: RUNNABLE
>>
>> "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b3000
>> nid=0x359b waiting on condition [0x0000000000000000]
>> java.lang.Thread.State: RUNNABLE
>>
>> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b0800
>> nid=0x359a waiting on condition [0x0000000000000000]
>> java.lang.Thread.State: RUNNABLE
>>
>> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f8d3c0af000
>> nid=0x3599 waiting on condition [0x0000000000000000]
>> java.lang.Thread.State: RUNNABLE
>>
>> "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f8d3c07b800 nid=0x3598
>> in Object.wait() [0x00007f8d410d3000]
>> java.lang.Thread.State: WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
>> - locked <0x00000000eaaf2038> (a java.lang.ref.ReferenceQueue$Lock)
>> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
>> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
>>
>> "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f8d3c079000
>> nid=0x3597 in Object.wait() [0x00007f8d411d4000]
>> java.lang.Thread.State: WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at java.lang.Object.wait(Object.java:502)
>> at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
>> - locked <0x00000000eaaf21f0> (a java.lang.ref.Reference$Lock)
>> at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
>>
>> "main" #1 prio=5 os_prio=0 tid=0x00007f8d3c00b800 nid=0x3595 in
>> Object.wait() [0x00007f8d45902000]
>> java.lang.Thread.State: TIMED_WAITING (on object monitor)
>> at java.lang.Object.wait(Native Method)
>> at
>> org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
>> - locked <0x00000000e26ec910> (a java.lang.Integer)
>> at
>> org.apache.manifoldcf.agents.system.AgentsDaemon.runAgents(AgentsDaemon.java:115)
>> at org.apache.manifoldcf.agents.AgentRun.doExecute(AgentRun.java:64)
>> at
>> org.apache.manifoldcf.agents.BaseAgentsInitializationCommand.execute(BaseAgentsInitializationCommand.java:37)
>> at org.apache.manifoldcf.agents.AgentRun.main(AgentRun.java:93)
>>
>> "VM Thread" os_prio=0 tid=0x00007f8d3c06f800 nid=0x3596 runnable
>>
>> "VM Periodic Task Thread" os_prio=0 tid=0x00007f8d3c0b9000 nid=0x359d
>> waiting on condition
>>
>> JNI global references: 13
>>
>> Heap
>> def new generation total 157248K, used 39902K [0x00000000e0000000,
>> 0x00000000eaaa0000, 0x00000000eaaa0000)
>> eden space 139776K, 28% used [0x00000000e0000000, 0x00000000e26f7a80,
>> 0x00000000e8880000)
>> from space 17472K, 0% used [0x00000000e9990000, 0x00000000e9990000,
>> 0x00000000eaaa0000)
>> to space 17472K, 0% used [0x00000000e8880000, 0x00000000e8880000,
>> 0x00000000e9990000)
>> tenured generation total 349568K, used 173322K [0x00000000eaaa0000,
>> 0x0000000100000000, 0x0000000100000000)
>> the space 349568K, 49% used [0x00000000eaaa0000, 0x00000000f53e2ac8,
>> 0x00000000f53e2c00, 0x0000000100000000)
>> Metaspace used 16548K, capacity 16750K, committed 17024K, reserved
>> 1064960K
>> class space used 1806K, capacity 1891K, committed 1920K, reserved
>> 1048576K
>>
>> Best regards,
>>
>> Olivier
>>
>> > Le 7 mai 2019 à 13:02, Karl Wright <da...@gmail.com> a écrit :
>> >
>> > The thread dump is not helpful. I see no traces for any threads that
>> > identify code from MCF at all. That's new and has nothing to do with
>> MCF;
>> > it's probably a new Java "feature".
>> >
>> > The OutOfMemoryException should, I've confirmed, be rethrown. The
>> Worker
>> > Thread code does in fact catch the exception and terminate the process:
>> >
>> >>>>>>>
>> > catch (OutOfMemoryError e)
>> > {
>> > System.err.println("agents process ran out of memory - shutting
>> > down");
>> > e.printStackTrace(System.err);
>> > System.exit(-200);
>> > }
>> > <<<<<<
>> >
>> > So that is what you should see happening.
>> >
>> > Are you providing the complete stack trace from your out-of-memory
>> > exception? That would help confirm the picture. It had to have been
>> > printed from somewhere; it goes to standard error, whatever that is.
>> >
>> > Karl
>> >
>> >
>> > On Tue, May 7, 2019 at 6:42 AM Karl Wright <da...@gmail.com> wrote:
>> >
>> >> Hi Olivier,
>> >>
>> >> Any out-of-memory exception that makes it to the top level should cause
>> >> the agents process to shut itself down.
>> >>
>> >> The reason for this is simple: in a multithread environment, with lots
>> of
>> >> third-party jars, an out-of-memory in one thread is usually indicative
>> of
>> >> an out-of-memory in other threads as well, and we cannot count on that
>> >> third-party software being rigorous about letting an
>> OutOfMemoryException
>> >> be thrown to the top level. So we tend to get corrupted results that
>> are
>> >> hard to recover from.
>> >>
>> >> In this case, the exception is being thrown within the JDBCConnector,
>> so
>> >> it ought to rethrow the OutOfMemoryException. Let me confirm that is
>> what
>> >> the code indicates.
>> >>
>> >> Karl
>> >>
>> >>
>> >> On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <
>> >> olivier.tavard@francelabs.com> wrote:
>> >>
>> >>> Hi Karl,
>> >>>
>> >>> Thank you for your help.
>> >>> Indeed I found a OoM error in the logs of the MCF-agent process :
>> >>> java.lang.OutOfMemoryError: Java heap space
>> >>> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
>> >>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
>> >>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>> >>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>> >>> at
>> >>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>> >>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>> >>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>> >>> at
>> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>> >>> at
>> >>>
>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>> >>> at
>> >>>
>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>> >>> at
>> >>>
>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>> >>>
>> >>>
>> >>> But the MCF process agent was not killed, it is still active. Why is
>> the
>> >>> process still active in this case ? Since we know that we can get an
>> OOM,
>> >>> couldn't we find an elegant way to notify users of this problem from
>> the
>> >>> MCF admin UI, rather than just having the process endlessly active ?
>> >>>
>> >>> As for the OOM, the work around we decided to use is to increase the
>> >>> values of xms and xmx java memory in options.env.unix.
>> >>> I also attached the thread dump to this mail.
>> >>>
>> >>> Thanks,
>> >>> Best regards,
>> >>>
>> >>> Olivier
>> >>>
>> >>> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>> >>>
>> >>> It sounds like there might be an out-of-memory situation, although if
>> >>> that is the case I would expect that the MCF agents process would
>> just shut
>> >>> itself down.
>> >>>
>> >>> If the process is hung, it should be easy to get a thread dump. That
>> >>> would be the first step.
>> >>>
>> >>> Some thoughts as to what might be happening: there might be an
>> >>> out-of-memory condition that is being silently eaten somewhere. MCF
>> relies
>> >>> on its connectors to use streams rather than load documents into
>> memory,
>> >>> BUT we're at the mercy of the JDBC drivers and Tika. So another
>> experiment
>> >>> would be to try to crawl your documents without the tika extractor
>> (just
>> >>> send them to the null output connector) and see if that succeeds. If
>> it
>> >>> does, then maybe try the external Tika Service connector instead and
>> see
>> >>> what happens then.
>> >>>
>> >>> Karl
>> >>>
>> >>>
>> >>> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
>> >>> olivier.tavard@francelabs.com> wrote:
>> >>>
>> >>>> Hi MCF community,
>> >>>>
>> >>>> We have some issues with the JDBC connector to index database with
>> large
>> >>>> LONGBLOB into it : I mean files more than 100 MB.
>> >>>> To reproduce the issue, I created a simple database on MySQL 5.7 with
>> >>>> only one table into it with 2 columns : id (int) and data
>> (longblob).
>> >>>> There are 8 records in the table : two records with very small files
>> :
>> >>>> less than 5 KB and 6 records with a large file of 192 MB.
>> >>>>
>> >>>> If I include in my crawl only one big BLOB, the crawl is successful.
>> >>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>> >>>>
>> >>>> But if I include more than 2 of these (with a WHERE IN condition or
>> if
>> >>>> select all the records of the table) the job stays in running
>> condition but
>> >>>> no document is processed :
>> >>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>> >>>>
>> >>>>
>> >>>>
>> >>>> There is no message in the logs (even with debug mode activated).
>> >>>> The tests were done in a Docker cluster on dedicated servers (4
>> cores,
>> >>>> 32 GB RAM each).
>> >>>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx
>> >>>> and xmx) the internal database is PostgreSQL 10.1 and we use
>> Zookeeper
>> >>>> based synchronization.
>> >>>> We have a dump of the database here :
>> >>>> https://www.datafari.com/files/mcftest.tar.gz
>> >>>>
>> >>>> In other cases, we also encounter this error :
>> >>>> Error: Unexpected jobqueue status - record id 1555190422690,
>> expecting
>> >>>> active status, saw 0
>> >>>>
>> >>>> Any ideas of what the problem could be ? or at least why there is
>> >>>> nothing in the debug log you think ?
>> >>>>
>> >>>> Thank you,
>> >>>> Best regards,
>> >>>>
>> >>>> Olivier
>> >>>>
>> >>>
>> >>>
>>
>>
Re: issue for indexing large blobs into databases
Posted by Karl Wright <da...@gmail.com>.
Thanks -- this shows a classic deadlock occurring, where the System.exit()
call effectively blocks the thread that does it from exiting, and thus
blocks the system from shutting down. This is a change of behavior in the
JVM; not sure when it happened, but this didn't happen before. But it
easily addressed.
Karl
On Mon, May 13, 2019 at 10:58 AM Olivier Tavard <
olivier.tavard@francelabs.com> wrote:
> Hi Karl,
>
> Thank you for your mail.
> I installed an ootb MCF 2.13 to have a clean installation. I launched the
> File-based multiprocess example and I did the previous tests I mentioned.
> I managed to see the error that you told me about :
>
> agents process ran out of memory - shutting down
> java.lang.OutOfMemoryError: Java heap space
> at com.mysql.jdbc.Buffer.ensureCapacity(Buffer.java:155)
> at com.mysql.jdbc.Buffer.writeBytesNoNull(Buffer.java:513)
> at
> com.mysql.jdbc.MysqlIO.readRemainingMultiPackets(MysqlIO.java:3116)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2971)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:910)
> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1405)
> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
> at
> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
> at
> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
> at
> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>
> But the mcf-agent process is still active, it was not shut down.
> I did a new thread dump, I obtained this :
> Full thread dump OpenJDK 64-Bit Server VM (25.212-b01 mixed mode):
>
> "Shutdown thread" #8 prio=5 os_prio=0 tid=0x00007f8ccc014000 nid=0x436a in
> Object.wait() [0x00007f8c2a9e8000]
> java.lang.Thread.State: TIMED_WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
> - locked <0x00000000e0930708> (a java.lang.Integer)
> at
> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopSystem(CrawlerAgent.java:617)
> at
> org.apache.manifoldcf.crawler.system.CrawlerAgent.stopAgent(CrawlerAgent.java:249)
> at
> org.apache.manifoldcf.agents.system.AgentsDaemon.stopAgents(AgentsDaemon.java:168)
> - locked <0x00000000eab32808> (a java.util.HashMap)
> at
> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsShutdownHook.doCleanup(AgentsDaemon.java:395)
> at
> org.apache.manifoldcf.core.system.ManifoldCF.cleanUpEnvironment(ManifoldCF.java:1540)
> - locked <0x00000000eab24af8> (a java.util.ArrayList)
> - locked <0x00000000eab24ca0> (a java.lang.Integer)
> at
> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread.run(ManifoldCF.java:1718)
>
> "MySQL Statement Cancellation Timer" #2567 daemon prio=5 os_prio=0
> tid=0x00007f8c84061800 nid=0x4090 in Object.wait() [0x00007f8c2aeed000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:502)
> at java.util.TimerThread.mainLoop(Timer.java:526)
> - locked <0x00000000ebe79d20> (a java.util.TaskQueue)
> at java.util.TimerThread.run(Timer.java:505)
>
> "Connection pool reaper" #2565 daemon prio=5 os_prio=0
> tid=0x00007f8cf809d000 nid=0x408e waiting on condition [0x00007f8c2aceb000]
> java.lang.Thread.State: TIMED_WAITING (sleeping)
> at java.lang.Thread.sleep(Native Method)
> at
> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>
> "Worker thread '0'" #66 daemon prio=5 os_prio=0 tid=0x00007f8cfc209800
> nid=0x35d8 in Object.wait() [0x00007f8d0c6f4000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.Thread.join(Thread.java:1252)
> - locked <0x00000000eab24b28> (a
> org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread)
> at java.lang.Thread.join(Thread.java:1326)
> at
> java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:107)
> at
> java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
> at java.lang.Shutdown.runHooks(Shutdown.java:123)
> at java.lang.Shutdown.sequence(Shutdown.java:167)
> at java.lang.Shutdown.exit(Shutdown.java:212)
> - locked <0x00000000eaae4150> (a java.lang.Class for java.lang.Shutdown)
> at java.lang.Runtime.exit(Runtime.java:109)
> at java.lang.System.exit(System.java:971)
> at
> org.apache.manifoldcf.crawler.system.WorkerThread.run(WorkerThread.java:851)
>
> "Connection pool reaper" #13 daemon prio=5 os_prio=0
> tid=0x00007f8cfc04b000 nid=0x35a0 waiting on condition [0x00007f8d2c47b000]
> java.lang.Thread.State: TIMED_WAITING (sleeping)
> at java.lang.Thread.sleep(Native Method)
> at
> org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
>
> "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b6000
> nid=0x359c runnable [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b3000
> nid=0x359b waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b0800
> nid=0x359a waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f8d3c0af000
> nid=0x3599 waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f8d3c07b800 nid=0x3598
> in Object.wait() [0x00007f8d410d3000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
> - locked <0x00000000eaaf2038> (a java.lang.ref.ReferenceQueue$Lock)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
>
> "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f8d3c079000
> nid=0x3597 in Object.wait() [0x00007f8d411d4000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:502)
> at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
> - locked <0x00000000eaaf21f0> (a java.lang.ref.Reference$Lock)
> at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
>
> "main" #1 prio=5 os_prio=0 tid=0x00007f8d3c00b800 nid=0x3595 in
> Object.wait() [0x00007f8d45902000]
> java.lang.Thread.State: TIMED_WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
> - locked <0x00000000e26ec910> (a java.lang.Integer)
> at
> org.apache.manifoldcf.agents.system.AgentsDaemon.runAgents(AgentsDaemon.java:115)
> at org.apache.manifoldcf.agents.AgentRun.doExecute(AgentRun.java:64)
> at
> org.apache.manifoldcf.agents.BaseAgentsInitializationCommand.execute(BaseAgentsInitializationCommand.java:37)
> at org.apache.manifoldcf.agents.AgentRun.main(AgentRun.java:93)
>
> "VM Thread" os_prio=0 tid=0x00007f8d3c06f800 nid=0x3596 runnable
>
> "VM Periodic Task Thread" os_prio=0 tid=0x00007f8d3c0b9000 nid=0x359d
> waiting on condition
>
> JNI global references: 13
>
> Heap
> def new generation total 157248K, used 39902K [0x00000000e0000000,
> 0x00000000eaaa0000, 0x00000000eaaa0000)
> eden space 139776K, 28% used [0x00000000e0000000, 0x00000000e26f7a80,
> 0x00000000e8880000)
> from space 17472K, 0% used [0x00000000e9990000, 0x00000000e9990000,
> 0x00000000eaaa0000)
> to space 17472K, 0% used [0x00000000e8880000, 0x00000000e8880000,
> 0x00000000e9990000)
> tenured generation total 349568K, used 173322K [0x00000000eaaa0000,
> 0x0000000100000000, 0x0000000100000000)
> the space 349568K, 49% used [0x00000000eaaa0000, 0x00000000f53e2ac8,
> 0x00000000f53e2c00, 0x0000000100000000)
> Metaspace used 16548K, capacity 16750K, committed 17024K, reserved
> 1064960K
> class space used 1806K, capacity 1891K, committed 1920K, reserved
> 1048576K
>
> Best regards,
>
> Olivier
>
> > Le 7 mai 2019 à 13:02, Karl Wright <da...@gmail.com> a écrit :
> >
> > The thread dump is not helpful. I see no traces for any threads that
> > identify code from MCF at all. That's new and has nothing to do with
> MCF;
> > it's probably a new Java "feature".
> >
> > The OutOfMemoryException should, I've confirmed, be rethrown. The Worker
> > Thread code does in fact catch the exception and terminate the process:
> >
> >>>>>>>
> > catch (OutOfMemoryError e)
> > {
> > System.err.println("agents process ran out of memory - shutting
> > down");
> > e.printStackTrace(System.err);
> > System.exit(-200);
> > }
> > <<<<<<
> >
> > So that is what you should see happening.
> >
> > Are you providing the complete stack trace from your out-of-memory
> > exception? That would help confirm the picture. It had to have been
> > printed from somewhere; it goes to standard error, whatever that is.
> >
> > Karl
> >
> >
> > On Tue, May 7, 2019 at 6:42 AM Karl Wright <da...@gmail.com> wrote:
> >
> >> Hi Olivier,
> >>
> >> Any out-of-memory exception that makes it to the top level should cause
> >> the agents process to shut itself down.
> >>
> >> The reason for this is simple: in a multithread environment, with lots
> of
> >> third-party jars, an out-of-memory in one thread is usually indicative
> of
> >> an out-of-memory in other threads as well, and we cannot count on that
> >> third-party software being rigorous about letting an
> OutOfMemoryException
> >> be thrown to the top level. So we tend to get corrupted results that
> are
> >> hard to recover from.
> >>
> >> In this case, the exception is being thrown within the JDBCConnector, so
> >> it ought to rethrow the OutOfMemoryException. Let me confirm that is
> what
> >> the code indicates.
> >>
> >> Karl
> >>
> >>
> >> On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <
> >> olivier.tavard@francelabs.com> wrote:
> >>
> >>> Hi Karl,
> >>>
> >>> Thank you for your help.
> >>> Indeed I found a OoM error in the logs of the MCF-agent process :
> >>> java.lang.OutOfMemoryError: Java heap space
> >>> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
> >>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
> >>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
> >>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
> >>> at
> >>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
> >>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
> >>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
> >>> at
> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
> >>> at
> >>>
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
> >>> at
> >>>
> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
> >>> at
> >>>
> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
> >>>
> >>>
> >>> But the MCF process agent was not killed, it is still active. Why is
> the
> >>> process still active in this case ? Since we know that we can get an
> OOM,
> >>> couldn't we find an elegant way to notify users of this problem from
> the
> >>> MCF admin UI, rather than just having the process endlessly active ?
> >>>
> >>> As for the OOM, the work around we decided to use is to increase the
> >>> values of xms and xmx java memory in options.env.unix.
> >>> I also attached the thread dump to this mail.
> >>>
> >>> Thanks,
> >>> Best regards,
> >>>
> >>> Olivier
> >>>
> >>> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
> >>>
> >>> It sounds like there might be an out-of-memory situation, although if
> >>> that is the case I would expect that the MCF agents process would just
> shut
> >>> itself down.
> >>>
> >>> If the process is hung, it should be easy to get a thread dump. That
> >>> would be the first step.
> >>>
> >>> Some thoughts as to what might be happening: there might be an
> >>> out-of-memory condition that is being silently eaten somewhere. MCF
> relies
> >>> on its connectors to use streams rather than load documents into
> memory,
> >>> BUT we're at the mercy of the JDBC drivers and Tika. So another
> experiment
> >>> would be to try to crawl your documents without the tika extractor
> (just
> >>> send them to the null output connector) and see if that succeeds. If
> it
> >>> does, then maybe try the external Tika Service connector instead and
> see
> >>> what happens then.
> >>>
> >>> Karl
> >>>
> >>>
> >>> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
> >>> olivier.tavard@francelabs.com> wrote:
> >>>
> >>>> Hi MCF community,
> >>>>
> >>>> We have some issues with the JDBC connector to index database with
> large
> >>>> LONGBLOB into it : I mean files more than 100 MB.
> >>>> To reproduce the issue, I created a simple database on MySQL 5.7 with
> >>>> only one table into it with 2 columns : id (int) and data (longblob).
> >>>> There are 8 records in the table : two records with very small files :
> >>>> less than 5 KB and 6 records with a large file of 192 MB.
> >>>>
> >>>> If I include in my crawl only one big BLOB, the crawl is successful.
> >>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
> >>>>
> >>>> But if I include more than 2 of these (with a WHERE IN condition or if
> >>>> select all the records of the table) the job stays in running
> condition but
> >>>> no document is processed :
> >>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
> >>>>
> >>>>
> >>>>
> >>>> There is no message in the logs (even with debug mode activated).
> >>>> The tests were done in a Docker cluster on dedicated servers (4 cores,
> >>>> 32 GB RAM each).
> >>>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx
> >>>> and xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper
> >>>> based synchronization.
> >>>> We have a dump of the database here :
> >>>> https://www.datafari.com/files/mcftest.tar.gz
> >>>>
> >>>> In other cases, we also encounter this error :
> >>>> Error: Unexpected jobqueue status - record id 1555190422690, expecting
> >>>> active status, saw 0
> >>>>
> >>>> Any ideas of what the problem could be ? or at least why there is
> >>>> nothing in the debug log you think ?
> >>>>
> >>>> Thank you,
> >>>> Best regards,
> >>>>
> >>>> Olivier
> >>>>
> >>>
> >>>
>
>
Re: issue for indexing large blobs into databases
Posted by Olivier Tavard <ol...@francelabs.com>.
Hi Karl,
Thank you for your mail.
I installed an ootb MCF 2.13 to have a clean installation. I launched the File-based multiprocess example and I did the previous tests I mentioned.
I managed to see the error that you told me about :
agents process ran out of memory - shutting down
java.lang.OutOfMemoryError: Java heap space
at com.mysql.jdbc.Buffer.ensureCapacity(Buffer.java:155)
at com.mysql.jdbc.Buffer.writeBytesNoNull(Buffer.java:513)
at com.mysql.jdbc.MysqlIO.readRemainingMultiPackets(MysqlIO.java:3116)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2971)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:910)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1405)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
at org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
But the mcf-agent process is still active, it was not shut down.
I did a new thread dump, I obtained this :
Full thread dump OpenJDK 64-Bit Server VM (25.212-b01 mixed mode):
"Shutdown thread" #8 prio=5 os_prio=0 tid=0x00007f8ccc014000 nid=0x436a in Object.wait() [0x00007f8c2a9e8000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
- locked <0x00000000e0930708> (a java.lang.Integer)
at org.apache.manifoldcf.crawler.system.CrawlerAgent.stopSystem(CrawlerAgent.java:617)
at org.apache.manifoldcf.crawler.system.CrawlerAgent.stopAgent(CrawlerAgent.java:249)
at org.apache.manifoldcf.agents.system.AgentsDaemon.stopAgents(AgentsDaemon.java:168)
- locked <0x00000000eab32808> (a java.util.HashMap)
at org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsShutdownHook.doCleanup(AgentsDaemon.java:395)
at org.apache.manifoldcf.core.system.ManifoldCF.cleanUpEnvironment(ManifoldCF.java:1540)
- locked <0x00000000eab24af8> (a java.util.ArrayList)
- locked <0x00000000eab24ca0> (a java.lang.Integer)
at org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread.run(ManifoldCF.java:1718)
"MySQL Statement Cancellation Timer" #2567 daemon prio=5 os_prio=0 tid=0x00007f8c84061800 nid=0x4090 in Object.wait() [0x00007f8c2aeed000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.util.TimerThread.mainLoop(Timer.java:526)
- locked <0x00000000ebe79d20> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"Connection pool reaper" #2565 daemon prio=5 os_prio=0 tid=0x00007f8cf809d000 nid=0x408e waiting on condition [0x00007f8c2aceb000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
"Worker thread '0'" #66 daemon prio=5 os_prio=0 tid=0x00007f8cfc209800 nid=0x35d8 in Object.wait() [0x00007f8d0c6f4000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Thread.join(Thread.java:1252)
- locked <0x00000000eab24b28> (a org.apache.manifoldcf.core.system.ManifoldCF$ShutdownThread)
at java.lang.Thread.join(Thread.java:1326)
at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:107)
at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
at java.lang.Shutdown.runHooks(Shutdown.java:123)
at java.lang.Shutdown.sequence(Shutdown.java:167)
at java.lang.Shutdown.exit(Shutdown.java:212)
- locked <0x00000000eaae4150> (a java.lang.Class for java.lang.Shutdown)
at java.lang.Runtime.exit(Runtime.java:109)
at java.lang.System.exit(System.java:971)
at org.apache.manifoldcf.crawler.system.WorkerThread.run(WorkerThread.java:851)
"Connection pool reaper" #13 daemon prio=5 os_prio=0 tid=0x00007f8cfc04b000 nid=0x35a0 waiting on condition [0x00007f8d2c47b000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.manifoldcf.core.jdbcpool.ConnectionPoolManager$ConnectionCloserThread.run(ConnectionPoolManager.java:152)
"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b6000 nid=0x359c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b3000 nid=0x359b waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f8d3c0b0800 nid=0x359a waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f8d3c0af000 nid=0x3599 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f8d3c07b800 nid=0x3598 in Object.wait() [0x00007f8d410d3000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000000eaaf2038> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f8d3c079000 nid=0x3597 in Object.wait() [0x00007f8d411d4000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000eaaf21f0> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"main" #1 prio=5 os_prio=0 tid=0x00007f8d3c00b800 nid=0x3595 in Object.wait() [0x00007f8d45902000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at org.apache.manifoldcf.core.system.ManifoldCF.sleep(ManifoldCF.java:1248)
- locked <0x00000000e26ec910> (a java.lang.Integer)
at org.apache.manifoldcf.agents.system.AgentsDaemon.runAgents(AgentsDaemon.java:115)
at org.apache.manifoldcf.agents.AgentRun.doExecute(AgentRun.java:64)
at org.apache.manifoldcf.agents.BaseAgentsInitializationCommand.execute(BaseAgentsInitializationCommand.java:37)
at org.apache.manifoldcf.agents.AgentRun.main(AgentRun.java:93)
"VM Thread" os_prio=0 tid=0x00007f8d3c06f800 nid=0x3596 runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f8d3c0b9000 nid=0x359d waiting on condition
JNI global references: 13
Heap
def new generation total 157248K, used 39902K [0x00000000e0000000, 0x00000000eaaa0000, 0x00000000eaaa0000)
eden space 139776K, 28% used [0x00000000e0000000, 0x00000000e26f7a80, 0x00000000e8880000)
from space 17472K, 0% used [0x00000000e9990000, 0x00000000e9990000, 0x00000000eaaa0000)
to space 17472K, 0% used [0x00000000e8880000, 0x00000000e8880000, 0x00000000e9990000)
tenured generation total 349568K, used 173322K [0x00000000eaaa0000, 0x0000000100000000, 0x0000000100000000)
the space 349568K, 49% used [0x00000000eaaa0000, 0x00000000f53e2ac8, 0x00000000f53e2c00, 0x0000000100000000)
Metaspace used 16548K, capacity 16750K, committed 17024K, reserved 1064960K
class space used 1806K, capacity 1891K, committed 1920K, reserved 1048576K
Best regards,
Olivier
> Le 7 mai 2019 à 13:02, Karl Wright <da...@gmail.com> a écrit :
>
> The thread dump is not helpful. I see no traces for any threads that
> identify code from MCF at all. That's new and has nothing to do with MCF;
> it's probably a new Java "feature".
>
> The OutOfMemoryException should, I've confirmed, be rethrown. The Worker
> Thread code does in fact catch the exception and terminate the process:
>
>>>>>>>
> catch (OutOfMemoryError e)
> {
> System.err.println("agents process ran out of memory - shutting
> down");
> e.printStackTrace(System.err);
> System.exit(-200);
> }
> <<<<<<
>
> So that is what you should see happening.
>
> Are you providing the complete stack trace from your out-of-memory
> exception? That would help confirm the picture. It had to have been
> printed from somewhere; it goes to standard error, whatever that is.
>
> Karl
>
>
> On Tue, May 7, 2019 at 6:42 AM Karl Wright <da...@gmail.com> wrote:
>
>> Hi Olivier,
>>
>> Any out-of-memory exception that makes it to the top level should cause
>> the agents process to shut itself down.
>>
>> The reason for this is simple: in a multithread environment, with lots of
>> third-party jars, an out-of-memory in one thread is usually indicative of
>> an out-of-memory in other threads as well, and we cannot count on that
>> third-party software being rigorous about letting an OutOfMemoryException
>> be thrown to the top level. So we tend to get corrupted results that are
>> hard to recover from.
>>
>> In this case, the exception is being thrown within the JDBCConnector, so
>> it ought to rethrow the OutOfMemoryException. Let me confirm that is what
>> the code indicates.
>>
>> Karl
>>
>>
>> On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <
>> olivier.tavard@francelabs.com> wrote:
>>
>>> Hi Karl,
>>>
>>> Thank you for your help.
>>> Indeed I found a OoM error in the logs of the MCF-agent process :
>>> java.lang.OutOfMemoryError: Java heap space
>>> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
>>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
>>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>>> at
>>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>>> at
>>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>>> at
>>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>>> at
>>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>>>
>>>
>>> But the MCF process agent was not killed, it is still active. Why is the
>>> process still active in this case ? Since we know that we can get an OOM,
>>> couldn't we find an elegant way to notify users of this problem from the
>>> MCF admin UI, rather than just having the process endlessly active ?
>>>
>>> As for the OOM, the work around we decided to use is to increase the
>>> values of xms and xmx java memory in options.env.unix.
>>> I also attached the thread dump to this mail.
>>>
>>> Thanks,
>>> Best regards,
>>>
>>> Olivier
>>>
>>> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>>>
>>> It sounds like there might be an out-of-memory situation, although if
>>> that is the case I would expect that the MCF agents process would just shut
>>> itself down.
>>>
>>> If the process is hung, it should be easy to get a thread dump. That
>>> would be the first step.
>>>
>>> Some thoughts as to what might be happening: there might be an
>>> out-of-memory condition that is being silently eaten somewhere. MCF relies
>>> on its connectors to use streams rather than load documents into memory,
>>> BUT we're at the mercy of the JDBC drivers and Tika. So another experiment
>>> would be to try to crawl your documents without the tika extractor (just
>>> send them to the null output connector) and see if that succeeds. If it
>>> does, then maybe try the external Tika Service connector instead and see
>>> what happens then.
>>>
>>> Karl
>>>
>>>
>>> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
>>> olivier.tavard@francelabs.com> wrote:
>>>
>>>> Hi MCF community,
>>>>
>>>> We have some issues with the JDBC connector to index database with large
>>>> LONGBLOB into it : I mean files more than 100 MB.
>>>> To reproduce the issue, I created a simple database on MySQL 5.7 with
>>>> only one table into it with 2 columns : id (int) and data (longblob).
>>>> There are 8 records in the table : two records with very small files :
>>>> less than 5 KB and 6 records with a large file of 192 MB.
>>>>
>>>> If I include in my crawl only one big BLOB, the crawl is successful.
>>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>>>>
>>>> But if I include more than 2 of these (with a WHERE IN condition or if
>>>> select all the records of the table) the job stays in running condition but
>>>> no document is processed :
>>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>>>>
>>>>
>>>>
>>>> There is no message in the logs (even with debug mode activated).
>>>> The tests were done in a Docker cluster on dedicated servers (4 cores,
>>>> 32 GB RAM each).
>>>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx
>>>> and xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper
>>>> based synchronization.
>>>> We have a dump of the database here :
>>>> https://www.datafari.com/files/mcftest.tar.gz
>>>>
>>>> In other cases, we also encounter this error :
>>>> Error: Unexpected jobqueue status - record id 1555190422690, expecting
>>>> active status, saw 0
>>>>
>>>> Any ideas of what the problem could be ? or at least why there is
>>>> nothing in the debug log you think ?
>>>>
>>>> Thank you,
>>>> Best regards,
>>>>
>>>> Olivier
>>>>
>>>
>>>
Re: issue for indexing large blobs into databases
Posted by Karl Wright <da...@gmail.com>.
The thread dump is not helpful. I see no traces for any threads that
identify code from MCF at all. That's new and has nothing to do with MCF;
it's probably a new Java "feature".
The OutOfMemoryException should, I've confirmed, be rethrown. The Worker
Thread code does in fact catch the exception and terminate the process:
>>>>>>
catch (OutOfMemoryError e)
{
System.err.println("agents process ran out of memory - shutting
down");
e.printStackTrace(System.err);
System.exit(-200);
}
<<<<<<
So that is what you should see happening.
Are you providing the complete stack trace from your out-of-memory
exception? That would help confirm the picture. It had to have been
printed from somewhere; it goes to standard error, whatever that is.
Karl
On Tue, May 7, 2019 at 6:42 AM Karl Wright <da...@gmail.com> wrote:
> Hi Olivier,
>
> Any out-of-memory exception that makes it to the top level should cause
> the agents process to shut itself down.
>
> The reason for this is simple: in a multithread environment, with lots of
> third-party jars, an out-of-memory in one thread is usually indicative of
> an out-of-memory in other threads as well, and we cannot count on that
> third-party software being rigorous about letting an OutOfMemoryException
> be thrown to the top level. So we tend to get corrupted results that are
> hard to recover from.
>
> In this case, the exception is being thrown within the JDBCConnector, so
> it ought to rethrow the OutOfMemoryException. Let me confirm that is what
> the code indicates.
>
> Karl
>
>
> On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <
> olivier.tavard@francelabs.com> wrote:
>
>> Hi Karl,
>>
>> Thank you for your help.
>> Indeed I found a OoM error in the logs of the MCF-agent process :
>> java.lang.OutOfMemoryError: Java heap space
>> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
>> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
>> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
>> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
>> at
>> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
>> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
>> at
>> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
>> at
>> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
>> at
>> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>>
>>
>> But the MCF process agent was not killed, it is still active. Why is the
>> process still active in this case ? Since we know that we can get an OOM,
>> couldn't we find an elegant way to notify users of this problem from the
>> MCF admin UI, rather than just having the process endlessly active ?
>>
>> As for the OOM, the work around we decided to use is to increase the
>> values of xms and xmx java memory in options.env.unix.
>> I also attached the thread dump to this mail.
>>
>> Thanks,
>> Best regards,
>>
>> Olivier
>>
>> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>>
>> It sounds like there might be an out-of-memory situation, although if
>> that is the case I would expect that the MCF agents process would just shut
>> itself down.
>>
>> If the process is hung, it should be easy to get a thread dump. That
>> would be the first step.
>>
>> Some thoughts as to what might be happening: there might be an
>> out-of-memory condition that is being silently eaten somewhere. MCF relies
>> on its connectors to use streams rather than load documents into memory,
>> BUT we're at the mercy of the JDBC drivers and Tika. So another experiment
>> would be to try to crawl your documents without the tika extractor (just
>> send them to the null output connector) and see if that succeeds. If it
>> does, then maybe try the external Tika Service connector instead and see
>> what happens then.
>>
>> Karl
>>
>>
>> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
>> olivier.tavard@francelabs.com> wrote:
>>
>>> Hi MCF community,
>>>
>>> We have some issues with the JDBC connector to index database with large
>>> LONGBLOB into it : I mean files more than 100 MB.
>>> To reproduce the issue, I created a simple database on MySQL 5.7 with
>>> only one table into it with 2 columns : id (int) and data (longblob).
>>> There are 8 records in the table : two records with very small files :
>>> less than 5 KB and 6 records with a large file of 192 MB.
>>>
>>> If I include in my crawl only one big BLOB, the crawl is successful.
>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>>>
>>> But if I include more than 2 of these (with a WHERE IN condition or if
>>> select all the records of the table) the job stays in running condition but
>>> no document is processed :
>>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>>>
>>>
>>>
>>> There is no message in the logs (even with debug mode activated).
>>> The tests were done in a Docker cluster on dedicated servers (4 cores,
>>> 32 GB RAM each).
>>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx
>>> and xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper
>>> based synchronization.
>>> We have a dump of the database here :
>>> https://www.datafari.com/files/mcftest.tar.gz
>>>
>>> In other cases, we also encounter this error :
>>> Error: Unexpected jobqueue status - record id 1555190422690, expecting
>>> active status, saw 0
>>>
>>> Any ideas of what the problem could be ? or at least why there is
>>> nothing in the debug log you think ?
>>>
>>> Thank you,
>>> Best regards,
>>>
>>> Olivier
>>>
>>
>>
Re: issue for indexing large blobs into databases
Posted by Karl Wright <da...@gmail.com>.
Hi Olivier,
Any out-of-memory exception that makes it to the top level should cause the
agents process to shut itself down.
The reason for this is simple: in a multithread environment, with lots of
third-party jars, an out-of-memory in one thread is usually indicative of
an out-of-memory in other threads as well, and we cannot count on that
third-party software being rigorous about letting an OutOfMemoryException
be thrown to the top level. So we tend to get corrupted results that are
hard to recover from.
In this case, the exception is being thrown within the JDBCConnector, so it
ought to rethrow the OutOfMemoryException. Let me confirm that is what the
code indicates.
Karl
On Tue, May 7, 2019 at 6:14 AM Olivier Tavard <ol...@francelabs.com>
wrote:
> Hi Karl,
>
> Thank you for your help.
> Indeed I found a OoM error in the logs of the MCF-agent process :
> java.lang.OutOfMemoryError: Java heap space
> at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
> at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
> at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
> at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
> at
> com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
> at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
> at
> com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
> at
> org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
>
>
> But the MCF process agent was not killed, it is still active. Why is the
> process still active in this case ? Since we know that we can get an OOM,
> couldn't we find an elegant way to notify users of this problem from the
> MCF admin UI, rather than just having the process endlessly active ?
>
> As for the OOM, the work around we decided to use is to increase the
> values of xms and xmx java memory in options.env.unix.
> I also attached the thread dump to this mail.
>
> Thanks,
> Best regards,
>
> Olivier
>
> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>
> It sounds like there might be an out-of-memory situation, although if that
> is the case I would expect that the MCF agents process would just shut
> itself down.
>
> If the process is hung, it should be easy to get a thread dump. That
> would be the first step.
>
> Some thoughts as to what might be happening: there might be an
> out-of-memory condition that is being silently eaten somewhere. MCF relies
> on its connectors to use streams rather than load documents into memory,
> BUT we're at the mercy of the JDBC drivers and Tika. So another experiment
> would be to try to crawl your documents without the tika extractor (just
> send them to the null output connector) and see if that succeeds. If it
> does, then maybe try the external Tika Service connector instead and see
> what happens then.
>
> Karl
>
>
> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <
> olivier.tavard@francelabs.com> wrote:
>
>> Hi MCF community,
>>
>> We have some issues with the JDBC connector to index database with large
>> LONGBLOB into it : I mean files more than 100 MB.
>> To reproduce the issue, I created a simple database on MySQL 5.7 with
>> only one table into it with 2 columns : id (int) and data (longblob).
>> There are 8 records in the table : two records with very small files :
>> less than 5 KB and 6 records with a large file of 192 MB.
>>
>> If I include in my crawl only one big BLOB, the crawl is successful.
>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>>
>> But if I include more than 2 of these (with a WHERE IN condition or if
>> select all the records of the table) the job stays in running condition but
>> no document is processed :
>> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>>
>>
>>
>> There is no message in the logs (even with debug mode activated).
>> The tests were done in a Docker cluster on dedicated servers (4 cores, 32
>> GB RAM each).
>> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx and
>> xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper based
>> synchronization.
>> We have a dump of the database here :
>> https://www.datafari.com/files/mcftest.tar.gz
>>
>> In other cases, we also encounter this error :
>> Error: Unexpected jobqueue status - record id 1555190422690, expecting
>> active status, saw 0
>>
>> Any ideas of what the problem could be ? or at least why there is nothing
>> in the debug log you think ?
>>
>> Thank you,
>> Best regards,
>>
>> Olivier
>>
>
>
Re: issue for indexing large blobs into databases
Posted by Olivier Tavard <ol...@francelabs.com>.
Hi Karl,
Thank you for your help.
Indeed I found a OoM error in the logs of the MCF-agent process :
java.lang.OutOfMemoryError: Java heap space
at com.mysql.jdbc.Buffer.<init>(Buffer.java:58)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1441)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
at org.apache.manifoldcf.jdbc.JDBCConnection$PreparedStatementQueryThread.run(JDBCConnection.java:1392)
But the MCF process agent was not killed, it is still active. Why is the process still active in this case ? Since we know that we can get an OOM, couldn't we find an elegant way to notify users of this problem from the MCF admin UI, rather than just having the process endlessly active ?
As for the OOM, the work around we decided to use is to increase the values of xms and xmx java memory in options.env.unix.
I also attached the thread dump to this mail.
Thanks,
Best regards,
Olivier
> Le 6 mai 2019 à 12:55, Karl Wright <da...@gmail.com> a écrit :
>
> It sounds like there might be an out-of-memory situation, although if that is the case I would expect that the MCF agents process would just shut itself down.
>
> If the process is hung, it should be easy to get a thread dump. That would be the first step.
>
> Some thoughts as to what might be happening: there might be an out-of-memory condition that is being silently eaten somewhere. MCF relies on its connectors to use streams rather than load documents into memory, BUT we're at the mercy of the JDBC drivers and Tika. So another experiment would be to try to crawl your documents without the tika extractor (just send them to the null output connector) and see if that succeeds. If it does, then maybe try the external Tika Service connector instead and see what happens then.
>
> Karl
>
>
> On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <olivier.tavard@francelabs.com <ma...@francelabs.com>> wrote:
> Hi MCF community,
>
> We have some issues with the JDBC connector to index database with large LONGBLOB into it : I mean files more than 100 MB.
> To reproduce the issue, I created a simple database on MySQL 5.7 with only one table into it with 2 columns : id (int) and data (longblob).
> There are 8 records in the table : two records with very small files : less than 5 KB and 6 records with a large file of 192 MB.
>
> If I include in my crawl only one big BLOB, the crawl is successful.
> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>
>
> But if I include more than 2 of these (with a WHERE IN condition or if select all the records of the table) the job stays in running condition but no document is processed :
> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>
>
>
>
> There is no message in the logs (even with debug mode activated).
> The tests were done in a Docker cluster on dedicated servers (4 cores, 32 GB RAM each).
> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx and xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper based synchronization.
> We have a dump of the database here : https://www.datafari.com/files/mcftest.tar.gz <https://www.datafari.com/files/mcftest.tar.gz>
>
> In other cases, we also encounter this error :
> Error: Unexpected jobqueue status - record id 1555190422690, expecting active status, saw 0
>
> Any ideas of what the problem could be ? or at least why there is nothing in the debug log you think ?
>
> Thank you,
> Best regards,
>
> Olivier
Re: issue for indexing large blobs into databases
Posted by Karl Wright <da...@gmail.com>.
It sounds like there might be an out-of-memory situation, although if that
is the case I would expect that the MCF agents process would just shut
itself down.
If the process is hung, it should be easy to get a thread dump. That would
be the first step.
Some thoughts as to what might be happening: there might be an
out-of-memory condition that is being silently eaten somewhere. MCF relies
on its connectors to use streams rather than load documents into memory,
BUT we're at the mercy of the JDBC drivers and Tika. So another experiment
would be to try to crawl your documents without the tika extractor (just
send them to the null output connector) and see if that succeeds. If it
does, then maybe try the external Tika Service connector instead and see
what happens then.
Karl
On Mon, May 6, 2019 at 5:56 AM Olivier Tavard <ol...@francelabs.com>
wrote:
> Hi MCF community,
>
> We have some issues with the JDBC connector to index database with large
> LONGBLOB into it : I mean files more than 100 MB.
> To reproduce the issue, I created a simple database on MySQL 5.7 with only
> one table into it with 2 columns : id (int) and data (longblob).
> There are 8 records in the table : two records with very small files :
> less than 5 KB and 6 records with a large file of 192 MB.
>
> If I include in my crawl only one big BLOB, the crawl is successful.
> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id =6
>
> But if I include more than 2 of these (with a WHERE IN condition or if
> select all the records of the table) the job stays in running condition but
> no document is processed :
> seeding query : SELECT id AS $(IDCOLUMN) FROM data WHERE id IN (6,7)
>
>
>
> There is no message in the logs (even with debug mode activated).
> The tests were done in a Docker cluster on dedicated servers (4 cores, 32
> GB RAM each).
> Regarding MCF, the version is 2.12. The MCF agent has 1GB of RAM (xmx and
> xmx) the internal database is PostgreSQL 10.1 and we use Zookeeper based
> synchronization.
> We have a dump of the database here :
> https://www.datafari.com/files/mcftest.tar.gz
>
> In other cases, we also encounter this error :
> Error: Unexpected jobqueue status - record id 1555190422690, expecting
> active status, saw 0
>
> Any ideas of what the problem could be ? or at least why there is nothing
> in the debug log you think ?
>
> Thank you,
> Best regards,
>
> Olivier
>