Hello,
I have a local docker for development, with the default postgres(9.5) and tomcat images.(stable)
My sites take a long time to startup (99%) msg. It takes longer every time I start the images.
I see a lot of these messages from my database image:
xwikidb_1 | LOG: invalid length of startup packet
In the start there was only one message. Now it seems to be more and getting more each time I start the engine.
Any ideas?
A restart of the docker-instance takes a very long time to restart. c.a. 15 minutes.
Running 12.0 at the moment.
Is this a known issue?
What docker image? If you’re referring to the official XWiki docker image using Tomcat then no it’s not normal. Tomcat takes about 1mn to start.
Nothing in the docker container logs?
Besides the LOG about LOG: invalid length of startup packet. Nothing.
But maybe I am looking in the wrong places. Any suggestions on where to look for clues?
I found this on the LOG: postgresql-archive.org
Looks like the WIKI is making connections, but not sending data.
The main wiki (which is empty, out of the box) starts reasonably fast. The subwiki’s with all our content and custom components is slow. Stuck on 99% for a long time. CPU spikes on the database docker.
Besides the LOG: invalid. I see this:
Blockquote
2020-03-13 13:00:55,763 [localhost-startStop-1] INFO iPropertiesConfigurationSource - loading xwiki.properties from file:/usr/local/tomcat/webapps/ROOT/WEB-INF/xwiki.properties
xwiki_1 | 2020-03-13 13:00:58,654 [localhost-startStop-1] INFO o.x.e.i.ServletEnvironment - Using permanent directory [/usr/local/xwiki/data]
xwiki_1 | WARNING: An illegal reflective access operation has occurred
xwiki_1 | WARNING: Illegal reflective access by com.thoughtworks.xstream.core.util.Fields (file:/usr/local/tomcat/webapps/ROOT/WEB-INF/lib/xstream-1.4.11.1.jar) to field java.util.TreeMap.comparator
xwiki_1 | WARNING: Please consider reporting this to the maintainers of com.thoughtworks.xstream.core.util.Fields
xwiki_1 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
xwiki_1 | WARNING: All illegal access operations will be denied in a future release
xwiki_1 | 2020-03-13 13:02:06,053 [localhost-startStop-1] INFO o.x.s.f.i.FilesystemStoreTools - Using filesystem store directory [/usr/local/xwiki/data/store/file]
xwiki_1 | 2020-03-13 13:02:06,877 [localhost-startStop-1] INFO o.x.s.s.i.EmbeddedSolrInstance - Starting embedded Solr server…
xwiki_1 | 2020-03-13 13:02:06,877 [localhost-startStop-1] INFO o.x.s.s.i.EmbeddedSolrInstance - Using Solr home directory: [/usr/local/xwiki/data/solr]
xwiki_1 | 2020-03-13 13:03:09,984 [localhost-startStop-1] INFO o.x.s.s.i.EmbeddedSolrInstance - Started embedded Solr server.
xwiki_1 | 2020-03-13 13:03:17,736 [OfficeProcessThread-0] WARN o.j.o.ConnectRetryable - Office process died with exit code 81; restarting it
xwiki_1 | 2020-03-13 13:03:20,083 [localhost-startStop-1] INFO o.x.o.i.s.DefaultOfficeServer - Open Office instance started.
xwiki_1 | 13-Mar-2020 13:03:43.329 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/ROOT] has finished in [250,595] ms
xwiki_1 | 13-Mar-2020 13:03:43.336 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [“http-nio-8080”]
xwiki_1 | 13-Mar-2020 13:03:43.351 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 251045 ms
xwiki_1 | 2020-03-13 13:04:39,451 [XWiki initialization] INFO .HibernateDataMigrationManager - Storage schema updates and data migrations are enabled
xwiki_1 | 2020-03-13 13:04:43,917 [XWiki initialization] INFO .HibernateDataMigrationManager - No data migration to apply for wiki [xwiki] currently in version [1138000]
xwiki_1 | 2020-03-13 13:04:43,967 [XWiki initialization] INFO .HibernateDataMigrationManager - Checking Hibernate mapping and updating schema if needed for wiki [xwiki]
xwiki_1 | 2020-03-13 13:04:47,311 [XWiki initialization] INFO .HibernateDataMigrationManager - No data migration to apply for wiki [dev] currently in version [1138000]
xwiki_1 | 2020-03-13 13:04:47,315 [XWiki initialization] INFO .HibernateDataMigrationManager - Checking Hibernate mapping and updating schema if needed for wiki [dev]
xwiki_1 | 2020-03-13 13:04:48,586 [XWiki initialization] INFO .HibernateDataMigrationManager - No data migration to apply for wiki [nextgen] currently in version [1138000]
xwiki_1 | 2020-03-13 13:04:48,590 [XWiki initialization] INFO .HibernateDataMigrationManager - Checking Hibernate mapping and updating schema if needed for wiki [nextgen]
xwiki_1 | 2020-03-13 13:05:51,736 [org.xwiki.search.solr.internal.job.IndexerJob@51c482ea([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - Starting job of type [solr.indexer] with identifier [[solr, indexer]]
xwiki_1 | 2020-03-13 13:06:00,427 [org.xwiki.search.solr.internal.job.IndexerJob@51c482ea([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - 7967 documents added, 187 deleted and 0 updated during the synchronization of the Solr index.
xwiki_1 | 2020-03-13 13:06:00,433 [org.xwiki.search.solr.internal.job.IndexerJob@51c482ea([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - Finished job of type [solr.indexer] with identifier [[solr, indexer]]
Somehow I had a git running on the data volumes used by docker. That slowed things down a lot.
Removed that, starting the main wiki is now 25 sec, instead of 250 sec. De sub wiki is still slow and remains on 99% for a long time, without logging anything.
@vmassol I figured out that the SOLR proces is the thing that slows the startup. It has to reindex 25000+ documents, taking 10 minutes.
I put the .cfg on solr.synchronizeAtStartup=false
In the SEARCH part of the admin I put everything on database instead of SOLR. But still it starts with:
xwiki_1 | 2020-03-13 20:32:39,653 [org.xwiki.search.solr.internal.job.IndexerJob@57fdab23([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - Starting job of type [solr.indexer] with identifier [[solr, indexer]]
xwiki_1 | 2020-03-13 20:32:49,058 [org.xwiki.search.solr.internal.job.IndexerJob@57fdab23([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - 2804 documents added, 2801 deleted and 2 updated during the synchronization of the Solr index.
xwiki_1 | 2020-03-13 20:32:49,071 [org.xwiki.search.solr.internal.job.IndexerJob@57fdab23([solr, indexer])] INFO o.x.s.s.i.j.IndexerJob - Finished job of type [solr.indexer] with identifier [[solr, indexer]]
For development purposes I do not need SOLR to start and index every time. Have I made a config error somewhere?
Solr checks if the index is up to date at each startup but it does the indexing only once. I see in your log that it’s indexing " 2804 documents added, 2801 deleted and 2 updated during the synchronization of the Solr index.". That’s ok and not a lot and shouldn’t take long. If it takes long there’s a problem on your system. Also, once it’s done they won’t be reindexed.
There are three indexes. One is for a filled sub wiki containing 70k documents.
I have deleted the SOLR directory and reindex everything to see what happens after that.
Something is indeed not as expected:
The number of entities that are left to be indexed, re-indexed or deleted from the index (depending on the executed action).
100002(Estimated time remaining: 23h 21m)
We found a solution for the slow SOLR.
Change the Volume bind once created locally to:
- type: bind
source: ~/locationondisk/data
target: /var/lib/postgresql/data
consistency: cached
read_only: false
Now the startup and the solr index only takes a minute.