Re-index after 8.5.1 upgrade taking 16days

[jeremy.taylor]

 I'm upgrading 7.13.1 to 8.5.1. The upgrade goes fine but the post upgrade full re-index is taking forever, like on pace to take 16 days. I've tried increasing the index threads, increasing jvm memory, and upping the database connections, nothing is making a difference. I disabled AV (Windows Defender) and confirmed the disk access speeds improved, but that still didn't have an impact on the re-index. The log is showing a few "Script field failed on issue: xxxx" errors but nothing serious. It looks like a lot has changed with indexing in version 8. Anyone know any other tips, tweaks, tuneup options?

[Petr Vaníček · Accepted solution]

Hi @jeremy.taylor ,

as @Fadoua mentioned - it's possible that this problem is related to scripts.

So first try to repair scripts (not only imports on first lines of scripts). As I can suggest you didn't check this part of documentation - Preparing for Jira 8.0 - I guess corectly?

In Jira 8 there has been moved ComponentManager and you should start using ComponentAccessor - also Scriptrunner documentation can help you - here.

Try that and let us know, because if there is some kind of problem like that than that can slow down indexing. 

[Fadoua]

Yep @Petr Vaníček  there are lot of troubleshooting steps to find the reason behind Jira extreme slowness.

@jeremy.taylor This is really an unusual behavior, find out what are those scripts for will be there first step.

Let us know if you have any questions. I would love to help you.

Also check this document out regarding sizing recommendations

Best,

Fadoua

[jeremy.taylor]

Thanks guys, I'll have to refer back to the developers on those scripts. I'm just a DevOps Admin on loan for this, I don't know the details of their environment very well, and I haven't run a Jira instance myself in 10 years. I did look back at the old logs and see those same script errors were occurring before I even did the upgrade. So I don't think they're causing the issue.

Petr, I don't know if they read that document and did any preparation in that regard. I went through this document to perform the upgrade. All the update checks in Jira passed and the install itself went fine.

I can really only speak here from an infrastructure standpoint, what has me confused is why the tuning parameters I changed have had no impact? I would think increasing the index threads from 10 to 50 would have a noticeable impact on CPU utilization, and increasing the JVM memory would show more ram utilization. I'm not seeing any change no matter what I set those values to.

[Fadoua]

@jeremy.taylor 

Please check the link I sent you.

There must be something over using the system resources. Can you please check Catalina log? Let's see what's in there.

Best,

Fadoua

[jeremy.taylor]

I reviewed the sizing guide document you linked, thank you. The instance is in line with the recommendations. It's on a VMware VM, 8 core CPU, 20GB RAM, 500GB free space, and the SAN is plenty fast enough.

I've set Jvm memory and index threads to several different values, the last test I set xmx to 10GB and index threads to 100, I was trying to overload it. No matter what I set, the tomcat exe stays consistent at around 15% CPU utilization and 5GB memory consumption.

I've tried setting the Jvm memory in the registry and directly on the Windows service. I'm setting the index threads in the jira-config.properties file. I confirm the settings by viewing the System info page in Jira.

Here's the Catalina log file, I don't see anything of issue here

14-Nov-2019 13:51:46.156 WARNING [main] org.apache.catalina.startup.SetAllPropertiesRule.begin [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'maxSpareThreads' to '75' did not find a matching property.
14-Nov-2019 13:51:46.156 WARNING [main] org.apache.tomcat.util.net.SSLHostConfig.setProtocols The protocol [TLSv1.3] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version: Apache Tomcat/8.5.42
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Jun 4 2019 20:29:04 UTC
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number: 8.5.42.0
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Windows Server 2016
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 10.0
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: E:\Program Files\Atlassian\JIRA\jre
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 1.8.0_202-b08
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Oracle Corporation
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: E:\Program Files\Atlassian\JIRA
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: E:\Program Files\Atlassian\JIRA
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=true
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Datlassian.standalone=JIRA
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dmail.mime.decodeparameters=true
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.dom4j.factory=com.atlassian.core.xml.InterningDocumentFactory
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:-OmitStackTraceInFastThrow
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+PrintGCDetails
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+PrintGCDateStamps
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+PrintGCTimeStamps
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+PrintGCCause
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+UseGCLogFileRotation
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:NumberOfGCLogFiles=5
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:GCLogFileSize=20M
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xloggc:E:\Program Files\Atlassian\JIRA\logs\atlassian-jira-gc-%t.log
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:InitialCodeCacheSize=32m
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:ReservedCodeCacheSize=512m
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=E:\Program Files\Atlassian\JIRA
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=E:\Program Files\Atlassian\JIRA
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=E:\Program Files\Atlassian\JIRA\endorsed
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=E:\Program Files\Atlassian\JIRA\temp
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=E:\Program Files\Atlassian\JIRA\conf\logging.properties
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: exit
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: abort
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms384m
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx8192m
14-Nov-2019 13:51:46.234 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [E:\Program Files\Atlassian\JIRA\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;x:C:\Program Files (x86)\Common Files\Oracle\Java\javapath;E:\Program Files\Atlassian\JIRA\jre\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;E:\Program Files\Microsoft SQL Server\Client SDK\ODBC\110\Tools\Binn\;E:\Program Files (x86)\Microsoft SQL Server\120\Tools\Binn\;E:\Program Files\Microsoft SQL Server\120\Tools\Binn\;E:\Program Files\Microsoft SQL Server\120\DTS\Binn\;E:\Program Files (x86)\Microsoft SQL Server\120\Tools\Binn\ManagementStudio\;E:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\;C:\Windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;.]
14-Nov-2019 13:51:46.391 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-80"]
14-Nov-2019 13:51:46.406 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-jsse-nio-443"]
14-Nov-2019 13:51:46.531 WARNING [main] org.apache.tomcat.util.net.SSLUtilBase.getEnabled Some of the specified [protocols] are not supported by the SSL engine and have been skipped: [[TLSv1.3]]
14-Nov-2019 13:51:46.609 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
14-Nov-2019 13:51:46.625 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 809 ms
14-Nov-2019 13:51:46.625 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
14-Nov-2019 13:51:46.625 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.42
14-Nov-2019 13:51:52.152 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-80"]
14-Nov-2019 13:51:52.153 SEVERE [main] org.apache.catalina.core.StandardService.startInternal Failed to start connector [Connector[HTTP/1.1-80]]
org.apache.catalina.LifecycleException: Failed to start component [Connector[HTTP/1.1-80]]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:167)
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:440)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:793)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.startup.Catalina.start(Catalina.java:688)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:353)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:493)
Caused by: org.apache.catalina.LifecycleException: Protocol handler start failed
at org.apache.catalina.connector.Connector.startInternal(Connector.java:1020)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
... 11 more
Caused by: java.net.BindException: Address already in use: bind
at sun.nio.ch.Net.bind0(Native Method)
at sun.nio.ch.Net.bind(Net.java:433)
at sun.nio.ch.Net.bind(Net.java:425)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:219)
at org.apache.tomcat.util.net.AbstractEndpoint.start(AbstractEndpoint.java:1191)
at org.apache.coyote.AbstractProtocol.start(AbstractProtocol.java:591)
at org.apache.catalina.connector.Connector.startInternal(Connector.java:1018)
... 12 more
14-Nov-2019 13:51:52.154 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-jsse-nio-443"]
14-Nov-2019 13:51:52.166 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 5539 ms

[Fadoua]

@jeremy.taylor 

Yep the JVM is set to the right number since you have 20 GB RAM

Your Catalina is not showing any errors.

Can you install JavaMelody? Remember you will have to do it after work hours as it needs a Jira restart.

This is really an interesting issue.

You can also open a support ticket with Atlassian, since they will ask you for the support.zip file. Click here

I will appreciate if you can share with us any findings once you submit your support ticket and Atlassian gets back to you. Please include Support.Zip file so that they get back to you with an answer.

Best,

Fadoua

[Petr Vaníček]

@jeremy.taylor Yes, you are right with that documentation, but everytime you must keep in mind instance customizations like scripting with Scriprunner or JMWE.

So as first try to repair all scripts in conditions, validators, post functions and also services/listeners if they are also used.

[jeremy.taylor]

Thanks for the assistance gentlemen! It ended being a combination of a corrupt plugin and the scripts using the deprecated jira.ComponentManager. After removing the bad plugin and updating scripts to use ComponentAccessor, everything is working great.

[Rishikesh Dugyala]

@jeremy.taylor you can disable scripted fields module under script runner plugin or you can disable scriptrunner plugin before reindex after completion of reindex you can turn back on scripted field or script runner plugin this reduces more time while reindexing.

[Jens Kisters __SeibertSolutions]

@Fadoua : 
i tried this today:

• uninstall script runner before the upgrade
• do the upgrade
• install script runner again
• do a background index

and it worked well.

With Script runner active:
Foreground reindex had an estimated duration of 5 hours, but reindex aborted at 61%.

Disabled Script runner, ran full foreground index in 25 minutes, activated script runner and the background index took another 35 minutes.

I think the problem is:
A scripted field tries to run a search.
SearchService is unavailable during full reindex and this produces a exception, probably after a timeout.

[Fadoua]

@Jens Kisters __SeibertSolutions How is the instance running? Everything good?

Best,

Fadoua

[Jens Kisters __SeibertSolutions]

Hey @Fadoua

the solution worked fine.

Cheers

Jens

[Jens Kisters __SeibertSolutions]

By the way i just stumbled over some documentation how to handle this error:

https://scriptrunner.adaptavist.com/latest/jira/scripted-fields.html?_ga=2.205056404.502615708.1589186444-515719914.1542286934#_jql_searches_in_script_fields

[Jens Kisters __SeibertSolutions]

I have stumbled over the same problem even though i already made my scripts be compatbile with Jira 8, but some scripts fail because foreground indexing is in progress.

/secure/admin/IndexReIndex!reindex.jspa [c.o.scriptrunner.customfield.GroovyCustomField] Script field failed on issue: ERG-3715, field: Summary neues Ticket
com.atlassian.jira.issue.index.SearchUnavailableException
at com.atlassian.jira.issue.index.DefaultIndexManager.getEntitySearcher(DefaultIndexManager.java:885)
at com.atlassian.jira.issue.index.DefaultIndexManager.getIssueSearcher(DefaultIndexManager.java:865)
at com.atlassian.jira.config.component.SwitchingInvocationHandler.invoke(SwitchingInvocationHandler.java:38)
at com.sun.proxy.$Proxy8.getIssueSearcher(Unknown Source)
at com.atlassian.jira.issue.search.SearchProviderFactoryImpl.getSearcher(SearchProviderFactoryImpl.java:17)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.getIssueSearcher(LuceneSearchProvider.java:130)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.searchDocuments(LuceneSearchProvider.java:443)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.searchDocuments(LuceneSearchProvider.java:450)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.runSearch(LuceneSearchProvider.java:439)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.getHits(LuceneSearchProvider.java:218)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.search(LuceneSearchProvider.java:362)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.search(LuceneSearchProvider.java:135)
at com.atlassian.jira.issue.search.providers.LuceneSearchProvider.search(LuceneSearchProvider.java:140)
at com.atlassian.jira.bc.issue.search.DefaultSearchService.search(DefaultSearchService.java:118)
at com.atlassian.jira.bc.issue.search.SearchService$search$0.call(Unknown Source)
at ScriptedFieldTicketSummary.run(ScriptedFieldTicketSummary.groovy:57)

I will try the following procedure:

• uninstall script runner before the upgrade
• do the upgrade
• install script runner again
• do a background index

[Fadoua]

@Jens Kisters __SeibertSolutions let us know how it goes.

Best,

Fadoua

[Fadoua]

@jeremy.taylor 

That is very odd!!! Actually indexing is one the features that has been improved in Jira 8.x.x

What are you seeing on the logs? How big is your instance? How big is the Data folder?

This is not a normal situation.

Best,

Fadoua

[jeremy.taylor]

In the log I'm seeing a fair amount of "Script field failed on issue: xxxx" errors, but didn't think that should cause the lag I'm seeing. Instance is pretty large >2 million issues, data folder is around 30GB. Before upgrading a background re-index could take up to 10-12 hours, I expected something on par with that. I let this run for 35 hours and it only got to 10%.

[Fadoua]

@jeremy.taylor 

 I understand for a big instance an indexing will take time, however not running for days 🤔. It will slow Jira as well. Are you running the background one? or the one that locks Jira?

What are those scripts for? You will have to dig little bit inside your instance, remove any unneeded custom fields, workflows,... you need to cleanup.

Then run the full indexing that locks Jira.

I am not advertising here for any vendor however there is a plugin called Optmizer for Jira that can help you a lot.

Did you check the best practices from Atlassian for an instance with this size?

Best,

Fadoua

[jeremy.taylor]

Yes, running the lock out re-index, apparently the upgrade from 7.x to 8.x invalidates the existing index and requires a full rebuild. 
The errors I'm seeing in the log are things like this

2019-11-13 21:17:31,802 Caesium-1-3 ERROR ServiceRunner [c.o.scriptrunner.customfield.GroovyCustomField] *************************************************************************************
2019-11-13 21:17:31,817 Caesium-1-3 ERROR ServiceRunner [c.o.scriptrunner.customfield.GroovyCustomField] Script field failed on issue: AER-2060165, field: Business Complexity
java.lang.NullPointerException: Cannot invoke method multiply() on null object
at Script2.run(Script2.groovy:17)
2019-11-13 21:17:32,145 Caesium-1-3 ERROR ServiceRunner [c.o.scriptrunner.customfield.GroovyCustomField] *************************************************************************************
2019-11-13 21:17:32,145 Caesium-1-3 ERROR ServiceRunner [c.o.scriptrunner.customfield.GroovyCustomField] Script field failed on issue: AER-2060165, field: Service Line (Extended)
org.codehaus.groovy.control.MultipleCompilationErrorsException: startup failed:
Script3.groovy: 1: unable to resolve class com.atlassian.jira.ComponentManager
@ line 1, column 1.
import com.atlassian.jira.ComponentManager

I haven't done any Jira administration for a number of years, I'm helping out one of our sister company's with this. If these script errors are causing the issue I'm not sure how to resolve them.

What's bugging me though is I tuned several config options and have not seen any difference in resource utilization. I increased the Jvm memory, upped xmx from 2GB to 8GB and increased the index threads with the following lines in jira-config.properties
jira.index.issue.threads=50
jira.index.sharedentity.threads=50
I expected to see tomcat8.exe using more cpu and memory after making those changes but there was no noticeable affect.