java.lang.OutOfMemoryError: Java heap space on sonarqube server

Christophe_R · January 30, 2023, 12:25pm

SonarQube community edition 9.7.1.62043

Hello everyone,
our sonarqube server crashes from time to time with out of memory errors.
I know I have to increase memory, but reading the logs, I’m not sure if I have to increase sonar web process (it was increased from 512m to 1G one month ago) or sonar search process.

Environment: Linux - OpenJDK 11
projects: ~500 / number lines of code: >13M
memory configuration (sonar.properties):

sonar.web.javaOpts=-Xmx1G -Xms512m -XX:+HeapDumpOnOutOfMemoryError
sonar.ce.javaOpts=-Xmx4048m -Xms128m -XX:+HeapDumpOnOutOfMemoryError
sonar.search.javaOpts: default values: #sonar.search.javaOpts=-Xmx512m -Xms512m -XX:MaxDirectMemorySize=256m -XX:+HeapDumpOnOutOfMemoryError

error log in web.log (no errors in other log files):

2023.01.27 17:14:18 ERROR web[][o.s.s.p.w.RootFilter] Processing of request /sonarqube/api/rules/search.protobuf?f=repo,name,severity,lang,internalKey,templateKey,params,actives,createdAt,updatedAt,deprecatedKeys&activation=true&qprofile=AYS9_IljcN5xRm8o9kUB&ps=500&p=2 failed
java.lang.OutOfMemoryError: Java heap space
        at java.base/java.util.Arrays.copyOf(Arrays.java:3745)
        at java.base/java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:172)
        at java.base/java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:686)
        at java.base/java.lang.StringBuilder.append(StringBuilder.java:232)
        at org.apache.ibatis.parsing.GenericTokenParser.parse(GenericTokenParser.java:68)
        at org.apache.ibatis.scripting.xmltags.ForEachSqlNode$FilteredDynamicContext.appendSql(ForEachSqlNode.java:176)
        at org.apache.ibatis.scripting.xmltags.StaticTextSqlNode.apply(StaticTextSqlNode.java:30)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.lambda$apply$0(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode$$Lambda$254/0x00000008402a9c40.accept(Unknown Source)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.apply(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.ForEachSqlNode.apply(ForEachSqlNode.java:94)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.lambda$apply$0(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode$$Lambda$254/0x00000008402a9c40.accept(Unknown Source)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.apply(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.TrimSqlNode.apply(TrimSqlNode.java:55)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.lambda$apply$0(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode$$Lambda$254/0x00000008402a9c40.accept(Unknown Source)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        at org.apache.ibatis.scripting.xmltags.MixedSqlNode.apply(MixedSqlNode.java:32)
        at org.apache.ibatis.scripting.xmltags.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:39)
        at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:305)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:87)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:151)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:145)
        at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140)
        at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:147)
        at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:80)
        at org.apache.ibatis.binding.MapperProxy$PlainMethodInvoker.invoke(MapperProxy.java:145)
        at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:86)
        at com.sun.proxy.$Proxy82.selectParamsByActiveRuleUuids(Unknown Source)

2023.01.27 17:14:47 ERROR ce[][o.s.s.es.BulkIndexer] index [projectmeasures], type [auth], id [AYXEWEeDQpqE-sEfZSo0], message [ElasticsearchException[Elasticsearch exception [type=cluster_block_exception, reason=index [projectmeasures] blocked by: [TOO_MANY_REQUESTS/12/disk usage exceeded flood-stage watermark, index has read-only-allow-delete block];]]]
2023.01.27 17:14:47 INFO  ce[AYX0AnRfQpqE-sEfZS7r][o.s.c.t.s.ComputationStepExecutor] Index analysis | status=FAILED | time=5284ms
2023.01.27 17:14:47 INFO  ce[AYX0AnRfQpqE-sEfZS7r][o.s.c.t.p.a.p.PostProjectAnalysisTasksExecutor] Webhooks | globalWebhooks=0 | projectWebhooks=0 | status=SUCCESS | time=3ms
2023.01.27 17:14:47 ERROR ce[AYX0AnRfQpqE-sEfZS7r][o.s.c.t.CeWorkerImpl] Failed to execute task AYX0AnRfQpqE-sEfZS7r
java.lang.IllegalStateException: Unrecoverable indexation failures: 1 errors among 1 requests. Check Elasticsearch logs for further details.
        at org.sonar.server.es.IndexingListener$1.onFinish(IndexingListener.java:42)
        at org.sonar.server.es.BulkIndexer.stop(BulkIndexer.java:131)
        at org.sonar.server.measure.index.ProjectMeasuresIndexer.doIndex(ProjectMeasuresIndexer.java:162)
        at org.sonar.server.measure.index.ProjectMeasuresIndexer.indexOnAnalysis(ProjectMeasuresIndexer.java:87)
        at org.sonar.ce.task.projectanalysis.step.IndexAnalysisStep.execute(IndexAnalysisStep.java:45)
        at org.sonar.ce.task.step.ComputationStepExecutor.executeStep(ComputationStepExecutor.java:79)
        at org.sonar.ce.task.step.ComputationStepExecutor.executeSteps(ComputationStepExecutor.java:70)
        at org.sonar.ce.task.step.ComputationStepExecutor.execute(ComputationStepExecutor.java:57)
        at org.sonar.ce.task.projectanalysis.taskprocessor.ReportTaskProcessor.process(ReportTaskProcessor.java:75)
        at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.executeTask(CeWorkerImpl.java:212)
        at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.run(CeWorkerImpl.java:194)
        at org.sonar.ce.taskprocessor.CeWorkerImpl.findAndProcessTask(CeWorkerImpl.java:160)
        at org.sonar.ce.taskprocessor.CeWorkerImpl$TrackRunningState.get(CeWorkerImpl.java:135)
        at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:87)
        at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:53)
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:131)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:74)
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:82)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2023.01.27 17:14:47 INFO  ce[AYX0AnRfQpqE-sEfZS7r][o.s.c.t.CeWorkerImpl] Executed task | project=com.tessi.vidoc:explorer-dashboard | type=REPORT | id=AYX0AnRfQpqE-sEfZS7r | submitter=ritim | status=FAILED | time=7567ms

[...]

		2023.01.27 17:16:41 WARN  web[][c.z.h.pool.PoolBase] HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@57069ab5 (java.lang.OutOfMemoryError: Java heap space). Possibly consider using a shorter maxLifetime value.
2023.01.27 17:16:41 ERROR web[][o.s.s.p.w.RootFilter] Processing of request /sonarqube/api/l10n/index?locale=fr-FR failed
java.lang.OutOfMemoryError: Java heap space
2023.01.27 17:16:41 ERROR web[][o.s.s.m.ElasticSearchMetricTask] Failed to query ES status
org.sonar.server.es.ElasticsearchException: Fail to execute es requestES cluster health request
        at org.sonar.server.es.EsClient.execute(EsClient.java:313)
        at org.sonar.server.es.EsClient.clusterHealth(EsClient.java:206)
        at org.sonar.server.monitoring.ElasticSearchMetricTask.updateElasticSearchHealthStatus(ElasticSearchMetricTask.java:56)
        at org.sonar.server.monitoring.ElasticSearchMetricTask.run(ElasticSearchMetricTask.java:50)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.RuntimeException: Request cannot be executed; I/O reactor status: STOPPED
        at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:940)
        at org.elasticsearch.client.RestClient.performRequest(RestClient.java:300)
        at org.elasticsearch.client.RestClient.performRequest(RestClient.java:288)
        at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2699)
        at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:2171)
        at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:2137)
        at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:2105)
        at org.elasticsearch.client.ClusterClient.health(ClusterClient.java:151)
        at org.sonar.server.es.EsClient.lambda$clusterHealth$27(EsClient.java:206)
        at org.sonar.server.es.EsClient.execute(EsClient.java:311)
        ... 9 common frames omitted
Caused by: java.lang.IllegalStateException: Request cannot be executed; I/O reactor status: STOPPED
        at org.apache.http.util.Asserts.check(Asserts.java:46)
        at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase.ensureRunning(CloseableHttpAsyncClientBase.java:90)
        at org.apache.http.impl.nio.client.InternalHttpAsyncClient.execute(InternalHttpAsyncClient.java:123)
        at org.elasticsearch.client.RestClient.performRequest(RestClient.java:296)
        ... 17 common frames omitted

ganncamp · January 31, 2023, 3:29pm

Hi,

As a pair, these are interesting errors.

First, you have an out-of-memory error in the web process. Yes, you would address this by adjusting sonar.web.javaOpts.

Less than a second later, your disk usage hits a watermark and ES locks its indices. It would be interesting to see what’s taking up your filespace and how/whether it’s caused by the first error. Long-term, you’ll want to deal with this by clearing out disk space or giving SonarQube a larger partition. Unfortunately, the underlying Elasticsearch instance requires a certain percentage of free disk space, and will lock its indices when free space falls below that - even if you have multiple gigs free.

Even though they happen pretty much together for you, these errors are generally unrelated within SonarQube. I suspect some external (logging?) process is triggered by the first error; it gobbles disk space and causes the second.

HTH,
Ann

Christophe_R · February 7, 2023, 11:34am

Hello Ann, thank you for your answer.

I’ve increased max memory in sonar.web.javaOpts from 1 to 2 GB. I hope it will be ok this time.

Your second observation is right: we use a small-sized filesystem for sonarqube program (and elasticsearch data), and disk space has become insufficient when java heap dump (due to the initial memory error) was written to disk…
So I changed jvm options to write heap dump to another filesystem

(-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/path/…)

Christophe