Invalid index - third time

Håvard Ottestad

unread,

Feb 1, 2017, 5:42:38 AM2/1/17

to Stardog

Hi,

I restarted stardog while it was loading data and got an invalid index again!

INFO 2017-01-30 15:59:02,411 [main] com.complexible.stardog.StardogKernel:initDatabases(1944): Database testSesame will not be available because there was an error initializing the database: java.io.EOFException

Now it is also very slow, while inserting data, and is spending a lot of time updating dictionaries/stas.

Logs


### RESTART ###

INFO  2017-01-30 15:58:47,934 [main] com.complexible.stardog.virtual.DefaultVirtualGraphRegistry:syncCache(162): Initializing R2RML registry

INFO  2017-01-30 15:58:48,121 [main] com.complexible.stardog.virtual.DefaultVirtualGraphRegistry:syncCache(171): Loaded R2RML registry with 0 sources

INFO  2017-01-30 15:59:02,349 [main] com.complexible.stardog.StardogKernel:start(1878): Initializing Stardog

WARN  2017-01-30 15:59:02,410 [main] com.complexible.stardog.db.DatabaseFactoryImpl:read(137): Database testSesame is invalid and the repair failed: null

INFO  2017-01-30 15:59:02,411 [main] com.complexible.stardog.StardogKernel:initDatabases(1944): Database testSesame will not be available because there was an error initializing the database: java.io.EOFException

INFO  2017-01-30 15:59:11,312 [main] com.complexible.stardog.StardogKernel:handleUnusableIndex(1999): Moving irreparable database testSesame to /home/stardog/data/.unusable/testSesame



INFO  2017-01-30 15:59:11,752 [main] com.complexible.stardog.StardogKernel:write(77): Loading Databases: 50% complete in 00:00:09

INFO  2017-01-30 15:59:13,037 [main] com.complexible.stardog.StardogKernel:write(77): Loading Databases: 100% complete in 00:00:10

INFO  2017-01-30 15:59:13,050 [main] com.complexible.stardog.StardogKernel:write(77): Loading Databases: 100% complete in 00:00:10

INFO  2017-01-30 15:59:13,064 [main] com.complexible.stardog.StardogKernel:write(77): 

INFO  2017-01-30 15:59:13,184 [main] com.complexible.stardog.StardogKernel:write(77): Loading Databases finished in 00:00:10.662

WARN  2017-01-30 15:59:22,136 [main] io.netty.util.internal.ThreadLocalRandom:warn(136): Failed to generate a seed from SecureRandom within 3 seconds. Not enough entrophy?

INFO  2017-01-30 15:59:22,587 [main] com.complexible.stardog.cli.impl.ServerStart:call(260): Memory options

INFO  2017-01-30 15:59:22,588 [main] com.complexible.stardog.cli.impl.ServerStart:call(261): Min Heap Size: 252M

INFO  2017-01-30 15:59:22,589 [main] com.complexible.stardog.cli.impl.ServerStart:call(262): Max Heap Size: 3.6G

INFO  2017-01-30 15:59:22,590 [main] com.complexible.stardog.cli.impl.ServerStart:call(263): Max Off-Heap : 2.0G

INFO  2017-01-30 15:59:22,591 [main] com.complexible.stardog.cli.impl.ServerStart:call(264): System Memory: 16G

ERROR 2017-01-30 15:59:48,048 [Stardog.Executor-19] com.complexible.common.protocols.server.rpc.ServerHandler:exceptionCaught(428): exceptionCaughtServerHandler

com.complexible.stardog.server.UnknownDatabaseException: Database 'testSesame' does not exist.

        at com.complexible.stardog.server.UnknownDatabaseException.create(UnknownDatabaseException.java:28) ~[stardog-core-shared-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.get(StardogKernel.java:2283) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.assertOnline(StardogKernel.java:2288) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.authenticate(StardogKernel.java:707) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.auth(SPECServerFunction.java:193) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.handleMessage(SPECServerFunction.java:149) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.common.protocols.server.rpc.ServerHandler.lambda$handleMessage$1(ServerHandler.java:337) ~[stardog-protocols-api-server-4.2.2.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92-internal]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92-internal]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92-internal]

ERROR 2017-01-30 15:59:48,737 [Stardog.Executor-26] com.complexible.common.protocols.server.rpc.ServerHandler:exceptionCaught(428): exceptionCaughtServerHandler

com.complexible.stardog.server.UnknownDatabaseException: Database 'testSesame' does not exist.

        at com.complexible.stardog.server.UnknownDatabaseException.create(UnknownDatabaseException.java:28) ~[stardog-core-shared-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.get(StardogKernel.java:2283) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.assertOnline(StardogKernel.java:2288) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.authenticate(StardogKernel.java:707) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.auth(SPECServerFunction.java:193) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.handleMessage(SPECServerFunction.java:149) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.common.protocols.server.rpc.ServerHandler.lambda$handleMessage$1(ServerHandler.java:337) ~[stardog-protocols-api-server-4.2.2.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92-internal]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92-internal]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92-internal]

INFO  2017-01-30 15:59:52,509 [Stardog.Executor-20] com.complexible.stardog.docs.db.StardocsConnectableFactory:createDocumentStore(117): Creating document store for testSesame at file:////home/stardog/data/testSesame/docs

INFO  2017-01-30 15:59:52,633 [Stardog.Executor-20] com.complexible.stardog.StardogKernel:write(77): Successfully created database 'testSesame'.

ERROR 2017-01-30 16:01:32,689 [Stardog.Executor-39] com.complexible.common.protocols.server.rpc.ServerHandler:exceptionCaught(428): exceptionCaughtServerHandler

com.complexible.stardog.server.DatabaseExistsException: Database already exists: brukere

        at com.complexible.stardog.StardogKernel.assertDbNotExists(StardogKernel.java:2157) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel.createDatabase(StardogKernel.java:1039) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.admin.AdminServerFunction.create(AdminServerFunction.java:700) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.admin.AdminServerFunction.handleMessage(AdminServerFunction.java:148) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.common.protocols.server.rpc.ServerHandler.lambda$handleMessage$1(ServerHandler.java:337) ~[stardog-protocols-api-server-4.2.2.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92-internal]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92-internal]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92-internal]

ERROR 2017-01-30 16:57:42,400 [Stardog.Executor-220] com.complexible.common.protocols.server.rpc.ServerHandler:exceptionCaught(428): exceptionCaughtServerHandler

java.lang.NullPointerException

        at com.complexible.stardog.security.ShiroUtils.getAuthenticatedUsername(ShiroUtils.java:97) ~[stardog-core-security-4.2.2.jar:?]

        at com.complexible.stardog.Kernels.event(Kernels.java:338) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel$NotifyingDatabaseConnection.close(StardogKernel.java:3014) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.beginTx(SPECServerFunction.java:366) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.handleMessage(SPECServerFunction.java:161) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.common.protocols.server.rpc.ServerHandler.lambda$handleMessage$1(ServerHandler.java:337) ~[stardog-protocols-api-server-4.2.2.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_92-internal]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_92-internal]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92-internal]

ERROR 2017-01-30 16:57:42,413 [StardogServer.WorkerGroup-9] com.complexible.stardog.protocols.http.server.HttpMessageEncoder:createErrorResponse(293): The result encoder received an error message it could not encode, error was:

java.lang.NullPointerException

        at com.complexible.stardog.security.ShiroUtils.getAuthenticatedUsername(ShiroUtils.java:97) ~[stardog-core-security-4.2.2.jar:?]

        at com.complexible.stardog.Kernels.event(Kernels.java:338) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.StardogKernel$NotifyingDatabaseConnection.close(StardogKernel.java:3014) ~[stardog-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.beginTx(SPECServerFunction.java:366) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.stardog.protocols.server.SPECServerFunction.handleMessage(SPECServerFunction.java:161) ~[stardog-protocols-spec-server-4.2.2.jar:?]

        at com.complexible.common.protocols.server.rpc.ServerHandler.lambda$handleMessage$1(ServerHandler.java:337) ~[stardog-protocols-api-server-4.2.2.jar:?]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_92-internal]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_92-internal]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_92-internal]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92-internal]

WARN  2017-01-30 18:00:00,005 [3f4286fe-a95b-4fc3-a6f0-5d5c0aef7e3d_Worker-6] com.complexible.stardog.db.DatabaseImpl:lambda$new$34(1282): Closing connection to database testSesame due to inactivity for 1h

INFO  2017-01-30 18:08:16,422 [Stardog.Executor-549] com.complexible.stardog.StardogKernel:printInternal(314): Creating index: 100% complete in 00:00:05 (0.0K triples/sec)

INFO  2017-01-30 18:08:16,424 [Stardog.Executor-549] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-30 18:08:16,424 [Stardog.Executor-549] com.complexible.stardog.StardogKernel:stop(329): Creating index finished in 00:00:05.402

ERROR 2017-01-30 21:16:43,997 [Stardog.Executor-1263] com.complexible.common.protocols.server.rpc.ServerHandler:exceptionCaught(428): exceptionCaughtServerHandler

java.lang.NullPointerException

ERROR 2017-01-30 21:16:44,011 [StardogServer.WorkerGroup-2] com.complexible.stardog.protocols.http.server.HttpMessageEncoder:createErrorResponse(293): The result encoder received an error message it could not encode, error was:

java.lang.NullPointerException

WARN  2017-01-31 10:18:53,426 [Stardog.Executor-12463] com.complexible.stardog.reasoning.blackout.TypeOracle:inferTypes(226): The type of variable http://www.arkivverket.no/standarder/noark5/arkivstruktur/motested is ambiguous; it will be assumed to be PROPERTY.

WARN  2017-01-31 12:04:30,621 [Stardog.Executor-14019] com.complexible.stardog.reasoning.blackout.TypeOracle:inferTypes(226): The type of variable http://www.arkivverket.no/standarder/noark5/arkivstruktur/motested is ambiguous; it will be assumed to be PROPERTY.

INFO  2017-01-31 15:16:32,892 [Stardog.Executor-16691] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 57% complete in 00:00:06 (98.0K triples/sec)

INFO  2017-01-31 15:16:33,949 [Stardog.Executor-16691] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 72% complete in 00:00:07 (105.3K triples/sec)

INFO  2017-01-31 15:16:34,753 [Stardog.Executor-16697] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 100% complete in 00:00:07 (131.4K triples/sec)

INFO  2017-01-31 15:16:34,754 [Stardog.Executor-16697] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-31 15:16:34,754 [Stardog.Executor-16697] com.complexible.stardog.StardogKernel:stop(329): Computing statistics finished in 00:00:07.948

INFO  2017-01-31 15:26:39,571 [Stardog.Executor-16735] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 100% complete in 00:00:05 (212.0K triples/sec)

INFO  2017-01-31 15:26:39,572 [Stardog.Executor-16735] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-31 15:26:39,572 [Stardog.Executor-16735] com.complexible.stardog.StardogKernel:stop(329): Computing statistics finished in 00:00:05.130

INFO  2017-01-31 16:06:32,565 [Stardog.Stats.ObjCountPersister] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 75% complete in 00:00:06 (155.0K triples/sec)

INFO  2017-01-31 16:06:32,899 [Stardog.Executor-16957] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 100% complete in 00:00:06 (196.0K triples/sec)

INFO  2017-01-31 16:06:32,899 [Stardog.Executor-16957] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-31 16:06:32,900 [Stardog.Executor-16957] com.complexible.stardog.StardogKernel:stop(329): Computing statistics finished in 00:00:06.430

INFO  2017-01-31 16:17:31,953 [Stardog.Executor-17039] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 64% complete in 00:00:06 (136.7K triples/sec)

INFO  2017-01-31 16:17:33,258 [Stardog.Executor-17020] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 76% complete in 00:00:07 (133.8K triples/sec)

INFO  2017-01-31 16:17:33,657 [Stardog.Executor-16976] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 100% complete in 00:00:07 (167.0K triples/sec)

INFO  2017-01-31 16:17:33,665 [Stardog.Executor-16976] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-31 16:17:33,665 [Stardog.Executor-16976] com.complexible.stardog.StardogKernel:stop(329): Computing statistics finished in 00:00:07.812

INFO  2017-01-31 16:30:17,302 [Stardog.Executor-17111] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 44% complete in 00:00:06 (99.0K triples/sec)

INFO  2017-01-31 16:30:18,297 [Stardog.Executor-17111] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 53% complete in 00:00:07 (102.1K triples/sec)

INFO  2017-01-31 16:30:19,392 [Stardog.Executor-17111] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 62% complete in 00:00:08 (103.5K triples/sec)

INFO  2017-01-31 16:30:20,512 [Stardog.Executor-17111] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 72% complete in 00:00:09 (105.8K triples/sec)

INFO  2017-01-31 16:30:21,555 [Stardog.Executor-17107] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 79% complete in 00:00:10 (104.4K triples/sec)

INFO  2017-01-31 16:30:21,778 [Stardog.Executor-17039] com.complexible.stardog.StardogKernel:printInternal(314): Computing statistics: 100% complete in 00:00:10 (129.4K triples/sec)

INFO  2017-01-31 16:30:21,779 [Stardog.Executor-17039] com.complexible.stardog.StardogKernel:stop(326): 

INFO  2017-01-31 16:30:21,779 [Stardog.Executor-17039] com.complexible.stardog.StardogKernel:stop(329): Computing statistics finished in 00:00:10.595

INFO  2017-01-31 17:00:43,747 [Stardog.Executor-17470] com.complexible.stardog.StardogKernel:printInternal(314): Persisting dictionary: 100% complete in 00:00:09

Message has been deleted

Håvard Ottestad

unread,

Feb 1, 2017, 5:48:45 AM2/1/17

to sta...@clarkparsia.com

System status:

bash-4.3# ./stardog-admin server status

Backup Storage Directory : .backup

CPU Load : 8.8439 %

Connection Timeout : 1h

Export Storage Directory : .exports

Memory Heap : 3.8G (Allocated: 3.9G Max: 3.9G)

Memory Non-Heap : 117M (Allocated: 121M Max: 2.0G)

Named Graph Security : false

Platform Arch : amd64

Platform OS : Linux 4.4.0-45-generic, Java 1.8.0_92-internal

Query All Graphs : false

Query Timeout : 5m

Stardog Home : /home/stardog/data

Stardog Version : 4.2.2

Strict Parsing : true

Uptime : 1 day 19 hours 48 minutes 44 seconds

Watchdog Enabled : true

Watchdog Port : 5833

Watchdog Remote Access : true

Databases :

+------------+------------+-------------+-----------------+----------------------+-----------+

+------------+------------+-------------+-----------------+----------------------+-----------+

| brukere | 0 | 0 | 0 | 0.0 | 0.0 |

| testSesame | 1 | 1 | 0 | 2.0 | 500.0 |

+------------+------------+-------------+-----------------+----------------------+-----------+

Håvard Ottestad

unread,

Feb 1, 2017, 5:50:48 AM2/1/17

to Stardog

Full logs since restart

stardog.logs

Michael Grove

unread,

Feb 1, 2017, 8:56:09 AM2/1/17

to stardog

On Wed, Feb 1, 2017 at 5:50 AM, Håvard Ottestad <hmott...@gmail.com> wrote:

Full logs since restart

It looks like you're constantly doing writes to 1 or more databases, is that correct? We have to maintain the statistics as their accuracy affects query planning. If you're constantly writing to the database, we'd need to be frequently updating them.

Cheers,

MIke

--
-- --
You received this message because you are subscribed to the C&P "Stardog" group.
To post to this group, send email to sta...@clarkparsia.com
To unsubscribe from this group, send email to
stardog+unsubscribe@clarkparsia.com
For more options, visit this group at
http://groups.google.com/a/clarkparsia.com/group/stardog?hl=en

Håvard Ottestad

unread,

Feb 1, 2017, 10:46:15 AM2/1/17

to Stardog

Yep. Constantly doing writes.

I've restarted stardog and imported the data that was lost due to the invalid database (from a turtle file). It's still doing both constant writes and reads, same as before. There is still a lot of data in our message queues being processed.

However, there are no more log messages about statistics.

Cheers,

Håvard

PS: Restarting has also brought the memory usage way down.

bash-4.3# ./stardog-admin server status

Backup Storage Directory : .backup

CPU Load : 7.0564 %

Connection Timeout : 1h

Export Storage Directory : .exports

Memory Heap : 1.1G (Allocated: 3.5G Max: 3.6G)

Memory Non-Heap : 104M (Allocated: 107M Max: 2.0G)

Named Graph Security : false

Platform Arch : amd64

Platform OS : Linux 4.4.0-45-generic, Java 1.8.0_92-internal

Query All Graphs : false

Query Timeout : 5m

Stardog Home : /home/stardog/data

Stardog Version : 4.2.2

Strict Parsing : true

Uptime : 2 hours 56 minutes 13 seconds

Watchdog Enabled : true

Watchdog Port : 5833

Watchdog Remote Access : true

Databases :

+------------+------------+-------------+-----------------+----------------------+-----------+

+------------+------------+-------------+-----------------+----------------------+-----------+

| brukere | 0 | 0 | 0 | 0.0 | 0.0 |

| testSesame | 1 | 1 | 0 | 3.0 | 333.3 |

+------------+------------+-------------+-----------------+----------------------+-----------+

Håvard Ottestad

unread,

Feb 1, 2017, 10:46:59 AM2/1/17

to Stardog

Is there any way to ask Stardog if there are any open resources, to check if I have a leak?

Reply all

Reply to author

Forward