XWiki v13.10.9 stuck on initialing (12%) after acquired change log lock

1780yz · September 13, 2022, 6:01pm

For upgrading from XWiki v7.0.1 to v13.10.9, I am in the second stage of bringing up the newer version.

The tomcat started and proceeded past acquiring the change log lock; however, the browser stuck forever with the message XWiki is initializing (12%).... I know of a previous post about a similar symptom on XWiki v9.4, but not sure whether it is the same issue.

By the way, I resolved a JDBC driver issue following the advice in this post. Also, I noticed the below warning in catalina.out mentioning the older version of v7.0.1, but I am unsure how critical the message is.

2022-09-13 10:47:35,689 [localhost-startStop-1] WARN  ltInstalledExtensionRepository - Invalid extension [org.xwiki.enterprise:xwiki-enterprise-ui-mainwiki/7.0.1] on namespace [wiki:xwiki] (InvalidExtensionException: No compatible extension is installed for dependency [org.xwiki.platform:xwiki-platform-watchlist-api-7.0.1])

Question:

I wonder mostly about 1) what caused the system to get stuck in this state of XWiki is initializing (12%)..., how to resolve it, and if necessary, 2) how to resolve the warning of Invalid extension [org.xwiki.enterprise:xwiki-enterprise-ui-mainwiki/7.0.1] .

I will highly appreciate any hints or suggestions.

The output in catalina.out:

13-Sep-2022 10:47:23.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/8.5.82
13-Sep-2022 10:47:23.466 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Aug 8 2022 21:26:07 UTC
13-Sep-2022 10:47:23.466 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 8.5.82.0
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-1160.76.1.el7.x86_64
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.342.b07-1.el7_9.x86_64/jre
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_342-b07
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Red Hat, Inc.
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /www/tomcat8
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /www/tomcat8
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/www/tomcat8/conf/logging.properties
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/www/tomcat8
13-Sep-2022 10:47:23.467 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/www/tomcat8
13-Sep-2022 10:47:23.468 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/www/tomcat8/temp
13-Sep-2022 10:47:23.469 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The Apache Tomcat Native library which allows using OpenSSL was not found on the java.library.path: [/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib]
13-Sep-2022 10:47:23.510 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
13-Sep-2022 10:47:23.523 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 329 ms
13-Sep-2022 10:47:23.540 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
13-Sep-2022 10:47:23.540 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/8.5.82]
13-Sep-2022 10:47:23.547 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/docs]
13-Sep-2022 10:47:23.678 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/docs] has finished in [131] ms
13-Sep-2022 10:47:23.678 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/examples]
13-Sep-2022 10:47:23.785 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/examples] has finished in [107] ms
13-Sep-2022 10:47:23.786 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/host-manager]
13-Sep-2022 10:47:23.797 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/host-manager] has finished in [11] ms
13-Sep-2022 10:47:23.797 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/manager]
13-Sep-2022 10:47:23.814 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/manager] has finished in [17] ms
13-Sep-2022 10:47:23.814 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/ROOT.original]
13-Sep-2022 10:47:23.820 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/ROOT.original] has finished in [6] ms
13-Sep-2022 10:47:23.821 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/www/tomcat8/webapps/ROOT]
2022-09-13 10:47:29,611 [localhost-startStop-1] INFO  iPropertiesConfigurationSource - Loading [xwiki.properties] from [file:/media/sf_cmy/work/sets/upgrade/notes-my/xwiki/webapps/ROOT.v13.10.9/WEB-INF/xwiki.properties]
2022-09-13 10:47:29,752 [localhost-startStop-1] INFO  o.x.e.i.ServletEnvironment     - Using permanent directory [/data/xwiki]
2022-09-13 10:47:35,645 [localhost-startStop-1] WARN  .x.e.m.i.MavenExtensionScanner - Collision between core extension [org.mariadb.jdbc:mariadb-java-client/3.0.7 (jar:file:/media/sf_cmy/work/sets/upgrade/notes-my/xwiki/webapps/ROOT.v13.10.9/WEB-INF/lib/mariadb-java-client-3.0.7.jar!/META-INF/maven/org.mariadb.jdbc/mariadb-java-client/pom.xml)] and [org.mariadb.jdbc:mariadb-java-client/3.0.5 (jar:file:/media/sf_cmy/work/sets/upgrade/notes-my/xwiki/webapps/ROOT.v13.10.9/WEB-INF/lib/mariadb-java-client-3.0.5-sources.jar!/META-INF/maven/org.mariadb.jdbc/mariadb-java-client/pom.xml)]
2022-09-13 10:47:35,645 [localhost-startStop-1] WARN  .x.e.m.i.MavenExtensionScanner - [org.mariadb.jdbc:mariadb-java-client/3.0.7 (jar:file:/media/sf_cmy/work/sets/upgrade/notes-my/xwiki/webapps/ROOT.v13.10.9/WEB-INF/lib/mariadb-java-client-3.0.7.jar!/META-INF/maven/org.mariadb.jdbc/mariadb-java-client/pom.xml)] is selected
2022-09-13 10:47:35,689 [localhost-startStop-1] WARN  ltInstalledExtensionRepository - Invalid extension [org.xwiki.enterprise:xwiki-enterprise-ui-mainwiki/7.0.1] on namespace [wiki:xwiki] (InvalidExtensionException: No compatible extension is installed for dependency [org.xwiki.platform:xwiki-platform-watchlist-api-7.0.1])
2022-09-13 10:47:39,432 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolr         - Starting embedded Solr server...
2022-09-13 10:47:39,432 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolr         - Using Solr home directory: [/data/xwiki/store/solr]
2022-09-13 10:47:40,584 [localhost-startStop-1] WARN  o.e.j.u.s.S.config             - Trusting all certificates configured for Client@d4d25cb[provider=null,keyStore=null,trustStore=null]
2022-09-13 10:47:40,584 [localhost-startStop-1] WARN  o.e.j.u.s.S.config             - No Client EndPointIdentificationAlgorithm configured for Client@d4d25cb[provider=null,keyStore=null,trustStore=null]
2022-09-13 10:47:40,725 [localhost-startStop-1] WARN  o.e.j.u.s.S.config             - Trusting all certificates configured for Client@3ab8be8e[provider=null,keyStore=null,trustStore=null]
2022-09-13 10:47:40,725 [localhost-startStop-1] WARN  o.e.j.u.s.S.config             - No Client EndPointIdentificationAlgorithm configured for Client@3ab8be8e[provider=null,keyStore=null,trustStore=null]
2022-09-13 10:47:40,789 [localhost-startStop-1] WARN  o.a.s.c.CoreContainer          - Not all security plugins configured!  authentication=disabled authorization=disabled.  Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external.  See https://s.apache.org/solrsecurity for more info
2022-09-13 10:47:42,986 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolr         - Started embedded Solr server.
2022-09-13 10:47:44,812 [localhost-startStop-1] INFO  o.x.s.f.i.FilesystemStoreTools - Using filesystem store directory [/data/xwiki/store/file]
13-Sep-2022 10:47:44.945 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/www/tomcat8/webapps/ROOT] has finished in [21,124] ms
13-Sep-2022 10:47:44.948 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
13-Sep-2022 10:47:44.956 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 21433 ms
2022-09-13 10:47:55,731 [XWiki initialization] INFO  .HibernateDataMigrationManager - Storage schema updates and data migrations are enabled
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager - The following data migration(s) will be applied for wiki [xwiki] currently in version [70000]:
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R72000XWIKI12153 - Convert document space name into space reference
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R72001XWIKI12228 - Make sure xwikidocument and xwikispace tables are in sync
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R73000XWIKI12277 - Migrate TemplateProviderClass' removed 'type' property values to the new 'terminal' property.
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R90000XWIKI13474 - Convert attachment size type to BIGINT to allow attachments bigger than 2GB.
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R93000RecordableEventMigrator - https://jira.xwiki.org/browse/XWIKI-14172
2022-09-13 10:47:56,049 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R910000XWIKI14697 - Make sure all attachments have the right content store id.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R910001XWIKI14697 - Make sure all attachments have the right archive store id.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R910100XWIKI14871 - Make sure all existing deleted attachments have a store id and move back metadata to the database.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R911000XWIKI14889 - Remove the non-null=true from deleted attachments table.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R911001XWIKI14895 - Remove the non-null=true from deleted documents table.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1004000XWIKI15249 - Make sure all attachments have the right content store id.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1004001XWIKI15249 - Make sure all attachments have the right archive store id.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1008010XWIKI10092 - Add missing properties to existing objects.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1100000XWIKI15620 - Move the store to a new location. Change the path from URL encoding to hash based to support long references.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1130000WatchlistLeftoversCleaner - Remove some mandatory documents created by the Watchlist Application that the notification email notifier replaces.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1130040XWIKI16682 - Fix attachments content store id missed because of a bug in migration R1100000XWIKI15620
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R1138000XWIKI16709 - Remove disable property and add checked_email property in XWikiUser documents.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R120901000XWIKI17761 - Move old Ratings XObject to the default Solr rating store.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R130200000XWIKI17200 - Make sure the database follow the currently expected type for some large string columns.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R130407000XWIKI19207 - Increase the maximum size of the columns to the maximum index supported by MySQL
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   R131007000XWIKI15460 - Remove the notification filters preferences remaining from removed sub-wikis.
2022-09-13 10:47:56,050 [XWiki initialization] INFO  .HibernateDataMigrationManager -   140600000XWIKI19869 - Migrate wrongly stored passwords information.
2022-09-13 10:47:56,059 [XWiki initialization] INFO  0200000XWIKI17200DataMigration - Updating the type of [xwikistatsvisit.XWV_USER_AGENT] to [longtext not null]
2022-09-13 10:47:56,060 [XWiki initialization] INFO  0200000XWIKI17200DataMigration - Updating the type of [xwikistatsvisit.XWV_COOKIE] to [longtext not null]
2022-09-13 10:47:56,061 [XWiki initialization] INFO  0200000XWIKI17200DataMigration - Updating the type of [xwikipreferences.XWP_LEFT_PANELS] to [longtext]
2022-09-13 10:47:56,062 [XWiki initialization] INFO  0200000XWIKI17200DataMigration - Updating the type of [xwikipreferences.XWP_RIGHT_PANELS] to [longtext]
2022-09-13 10:47:56,062 [XWiki initialization] INFO  0200000XWIKI17200DataMigration - Updating the type of [xwikipreferences.XWP_DOCUMENT_BUNDLES] to [longtext]
2022-09-13 10:47:56,187 [XWiki initialization] INFO  .HibernateDataMigrationManager - Running early schema updates (using liquibase) for database [xwiki]
13-Sep-2022 10:47:56.893 INFO [XWiki initialization] liquibase.lockservice.null Successfully acquired change log lock
13-Sep-2022 10:47:57.978 INFO [XWiki initialization] liquibase.changelog.null Reading from xwiki.DATABASECHANGELOG

tmortagne · September 14, 2022, 7:06am

Impossible to say with the given information, unfortunately. We would need a thread dump to pinpoint exactly where it’s blocked and by what.

This is a perfectly expected warning: you upgraded the XWiki WAR, so the flavor is not compatible anymore, and it will be resolved when you upgrade it in the Distribution Wizard.

1780yz · September 14, 2022, 7:03pm

Thank you, @tmortagne.

On a testing virtual machine of RHEL-7, I dumped threads with the command jstack -l -m <pid> at the following three moments:

after tomcat starts, then
when access http://hostname:8080/ and the browser gets stuck at XWiki is initializing (12%)...., then
after tomcat stops, the Java process remains forever. Eventually, I finished the testing by calling kill -9 <pid> to kill the Java process of tomcat.

So, could you please look at the text files below and let me know your thoughts? Thank you for your help.

thread.6170.1-lm-tomcat-started.txt (82.1 KB)
thread.6170.2-lm-initializing12.txt (81.9 KB)
thread.6170.3-lm-tomcat-stopped.txt (21.4 KB)

logging.txt (21.3 KB)

The Java process of tomcat, after systemctl stop tomcat:

[root@hostname threads]# ps -elf | grep java
0 S root      6170     1  2  80   0 - 1337068 futex_ 11:54 ?      00:00:47 /usr/bin/java -Djava.util.logging.config.file=/www/tomcat8/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -server -Xmx2048m -Dfile.encoding=utf-8 -Djava.awt.headless=true -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true -Dlog4j2.formatMsgNoLookups=true -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dorg.apache.catalina.security.SecurityListener.UMASK=0027 -Dignore.endorsed.dirs= -classpath /www/tomcat8/bin/bootstrap.jar:/www/tomcat8/bin/tomcat-juli.jar -Dcatalina.base=/www/tomcat8 -Dcatalina.home=/www/tomcat8 -Djava.io.tmpdir=/www/tomcat8/temp org.apache.catalina.startup.Bootstrap start
0 S root      7255  6318  0  80   0 - 28204 pipe_w 12:32 pts/2    00:00:00 grep --color=auto java

tmortagne · September 15, 2022, 9:06am

What I see in that file does not really match the 12% display: I can’t find the thread which is in charge of initializing XWiki. In fact I cannot find any of the threads I would expect to find after you access XWiki with your browser. It very much looks like what you would have right after starting Tomcat.

1780yz · September 15, 2022, 4:38pm

Thank you for pointing it out, @tmortagne. I tested again and called jstack <java_pid> without any optional argument. Please see the attached text files, and let me know your thoughts.

If necessary, it might be helpful to share a sample thread collected on your side so that I know what a valid dump looks like. An example command would also be helpful.

I appreciate your patience and help.

thread.1078.txt (50.5 KB)
logging.txt (7.1 KB)

tmortagne · September 16, 2022, 2:18pm

Much better

I see that XWiki is waiting for liquibase which is in charge of migrating the database (which is also what your log suggests). According to the thread dump at the instant you took it, it was waiting for the result of a MariaDB query (but I’m not sure which one since it does not appear in the log, but you should be able to see that on MariaDB side with a tool like mytop, you will also see if it’s blocked on a specific query or if it’s just that it’s doing a lot of things).

If it stays stuck with that log forever, I noticed in the past that sometimes a given version of liquibase can have a hard time reading previous log (which is also something your last log seems to be mentioning) it left in the database for a previous migration, and it can help to delete those branches (namely DATABASECHANGELOG and DATABASECHANGELOGLOCK).

1780yz · September 16, 2022, 5:21pm

Thank you, @tmortagne, for your pointers.

Please see below for the screenshot of mytop when the initialization got stuck at 12%. Just let me know if you have some thoughts.

About the schema’s definition, the command show create database xwiki; gets CREATE DATABASE xwiki /*!40100 DEFAULT CHARACTER SET latin1 */, as it comes from an old instance.

In addition, I generated a script of the DDL statements without any data by adding argument --no-data in command mysqldump.exe --skip-lock-tables --routines --add-drop-table --disable-keys --extended-insert --no-data ... . Please see the attached schema definitions if necessary. Trying to save you some communication time, but I am not sure if helpful.

xwikiv-mariadb-v10.9-structure-only-xwiki-202209161220.sql.txt (30.2 KB)

Details of the mytop screenshots:

The correct test, after releasing the DATABASECHANGELOGLOCK by SQL statement UPDATE DATABASECHANGELOGLOCK SET locked=0, lockgranted=null, lockedby=null WHERE id=1;:

MariaDB 10.9.2 on localhost                                                load (1.35 0.94 0.49) up 0+00:07:32 [11:33:09]
 Queries: 692.0    qps:    2 Slow:     0.0         Se/In/Up/De(%):    39/00/00/00
 Sorts:      0 qps now:    1 Slow qps: 0.0  Threads:    4 (   2/   0) 25/00/00/00
 Handler: (R/W/U/D)     0/ 1762/    0/    0        Tmp: R/W/U:   113/  113/    0
 MyISAM Key Cache Efficiency: 100.0%  Bps in/out: 493.0/ 4.2k   Now in/out:  97.8/ 3.9k

       Id     User         Host/IP        DB   Time     %    Cmd           State Query
       --     ----         -------        --   ----     -    ---           ----- ----------
        5    xwiki localhost:41290     xwiki  361.4   0.0  Sleep
        7    xwiki localhost:41294     xwiki  360.9   0.0  Sleep
        6    xwiki localhost:41292     xwiki  358.9  29.2  Query 1/2 copy to tmp Alter table xwikistatsvisit MODIFY XWV

After stopping tomcat, the stuck SQL query Alter table xwikistatsvisit MODIFY XWV_NAME varchar(768) not null remains:

MariaDB 10.9.2 on localhost                                                                                                                                                                   load (1.29 1.17 0.70) up 0+00:12:03 [11:37:40]
 Queries: 909.0    qps:    1 Slow:     0.0         Se/In/Up/De(%):    36/00/00/00
 Sorts:      0 qps now:    1 Slow qps: 0.0  Threads:    2 (   2/   2) 25/00/00/00
 Handler: (R/W/U/D)     0/ 1820/    0/    0        Tmp: R/W/U:   113/  113/    0
 MyISAM Key Cache Efficiency: 100.0%  Bps in/out: 345.0/ 4.1k   Now in/out:  97.8/ 3.9k

       Id     User         Host/IP        DB   Time     %    Cmd           State Query
       --     ----         -------        --   ----     -    ---           ----- ----------
        6    xwiki localhost:41292     xwiki  630.3  35.3  Query 1/2 copy to tmp Alter table xwikistatsvisit MODIFY XWV_NAME varchar(768) not null

In a previous test, I didn’t release the DATABASECHANGELOGLOCK, so I guess the below result is incorrect:

MariaDB 10.9.2 on localhost                                                load (0.00 0.08 0.08) up 0+02:08:37 [11:20:01]
 Queries: 2.2k     qps:    0 Slow:     0.0         Se/In/Up/De(%):    30/00/00/00
 Sorts:      0 qps now:    1 Slow qps: 0.0  Threads:    4 (   1/   0) 25/00/00/00
 Handler: (R/W/U/D)     0/    0/    0/    0        Tmp: R/W/U:   113/  113/    0
 MyISAM Key Cache Efficiency: 100.0%  Bps in/out:  49.9/ 1.2k   Now in/out:  97.6/ 3.9k

       Id     User         Host/IP        DB   Time     %    Cmd           State Query
       --     ----         -------        --   ----     -    ---           ----- ----------
       11    xwiki localhost:40412     xwiki  298.1   0.0  Sleep
       13    xwiki localhost:40416     xwiki  297.5   0.0  Sleep
       12    xwiki localhost:40414     xwiki    6.5   0.0  Sleep

1780yz · September 20, 2022, 8:30pm

It turns out that table xwikistatsvisit contains too many items, and the size is over 3GB. Therefore the initialization was unable to complete before tomcat timing out. And I suspect the XWiki instance had been through automatic testing for years, and each time of testing access will generate a record in this table.

I resolved the issue by deleting all records in the table before starting tomcat. However, the SQL delete command took over two hours to complete on a medium testing virtual machine with SSD, 4 CPUs of Intel i9 and 8GB of RAM, running MariaDB v10.9.2. Also, the hypervisor needs to enable “PAE/NX” and “Nested Vt-x/ADM-V” for higher performance; otherwise, the computing task will get stuck forever.

I am still open to suggestions about how to handle this situation better.

tmortagne · September 29, 2022, 8:06am

Note that statistics are disabled by default in XWiki, mainly because they don’t scale very well, and we usually recommend to use projects which are better than us at this, like Matomo.

We still need to move all that into a contrib extension to make more clear that this part is not really maintained anymore…