IN PROGRESS task can't be stopped

ianw · October 7, 2020, 7:10am

#bug:fault java.lang.OutOfMemoryError: Java heap space
SQ LTS 7.9.4.35981 on RHEL, Java11/OpenJDK11U_openj9/jdk-11.0.8+10
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
Java Code Quality and Security 6.3.2 (build 22818) SonarJS 6.2.2 (build 13315)

sonar.properties:sonar.web.javaOpts=-server -Xmx768m -XX:+HeapDumpOnOutOfMemoryError
sonar.properties:sonar.ce.javaOpts=-Xmx1024m -Xms128m -XX:+HeapDumpOnOutOfMemoryError
sonar.properties:sonar.search.javaOpts=-Xms2g -Xmx2g -XX:+HeapDumpOnOutOfMemoryError

Background Task which normally takes 3-4 mins to analyze project has been running for 28 hours. There is no mechanism to cancel this “In Progress” task.

The project has been scanned without issue over 75x since 2019-09
It’s ~245K lines, 145K Java, 60K JSP, 40K XML 4K HTML.
There were 5 files with < 20 lines changes since last successful scan the day before.

By comparison, our largest of 800+ project is 1.1M lines, 920K Java, 130K JSP,10K XML takes 11-15 mins to process.

DBA indicates no locks, plenty of processes, sessions available, no issues.

Observed in the main process logs is: java.lang.OutOfMemoryError: Java heap space and partial logs below. Can attach complete logs and cores if necessary.

Cannot “Restart Server” form UI, cannot sonar.sh stop or sonar.sh force-stop. Killed all UNIX PID and started app again , it’s still “in progress”. There are another 180+ Pending tasks behind this.

It’s been 28 hours since the crash and 2 since the restart.

Referred to this StackOverflow question from 2017 (SQ 5.6.6 era ?) where Julien L. - SonarSource Team advised “In-progress tasks cannot be canceled for the moment” and “Feel free to open a thread [here]”, so here is one. Approaching 3 years since the OP first reported and 18 months since Julien’s advice.

Before taking the guidance of “jrk”, " Deleting the project kills the task ; you’re welcome", is there a resolution to this problem? Is there another approach? It has been several LTS release (on latest as of Sept 29) since first reported. Seems like a real “Blocker Issue” for the Community Edition, where only one task can be processed at a time.

2020/09/30 01:44:51 | jvm 1    | 2020.09.30 01:44:51 INFO  app[][o.s.a.SchedulerImpl] SonarQube is up
2020/10/06 02:26:36 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:26:36 - please wait.
2020/10/06 02:26:36 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:26:36 - please wait.
2020/10/06 02:26:36 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:26:36 - please wait.
2020/10/06 02:26:36 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:26:36 - please wait.
2020/10/06 02:26:36 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:26:36 - please wait.
2020/10/06 02:26:43 | jvm 1    | JVMDUMP032I JVM requested Heap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0001.phd' in response to an event
2020/10/06 02:26:52 | jvm 1    | JVMDUMP010I Heap dump written to /apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0001.phd
2020/10/06 02:26:52 | jvm 1    | JVMDUMP032I JVM requested Heap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0002.phd' in response to an event
2020/10/06 02:27:01 | jvm 1    | JVMDUMP010I Heap dump written to /apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0002.phd
2020/10/06 02:27:01 | jvm 1    | JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2020/10/06 02:27:01 - please wait.
2020/10/06 02:27:01 | jvm 1    | JVMDUMP032I JVM requested System dump using '/apps/infra/sonarqube/sonarqube-7.9.4/core.20201006.022636.24204.0005.dmp' in response to an event
2020/10/06 02:27:04 | jvm 1    | JVMDUMP010I System dump written to /apps/infra/sonarqube/sonarqube-7.9.4/core.20201006.022636.24204.0005.dmp
2020/10/06 02:27:04 | jvm 1    | JVMDUMP032I JVM requested Heap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0004.phd' in response to an event
2020/10/06 02:27:13 | jvm 1    | JVMDUMP010I Heap dump written to /apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0004.phd
2020/10/06 02:27:13 | jvm 1    | JVMDUMP032I JVM requested Java dump using '/apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0006.txt' in response to an event
2020/10/06 02:27:13 | jvm 1    | JVMDUMP010I Java dump written to /apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0006.txt
2020/10/06 02:27:13 | jvm 1    | JVMDUMP032I JVM requested Heap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0003.phd' in response to an event
2020/10/06 02:27:23 | jvm 1    | JVMDUMP010I Heap dump written to /apps/infra/sonarqube/sonarqube-7.9.4/heapdump.20201006.022636.24204.0003.phd
2020/10/06 02:27:23 | jvm 1    | JVMDUMP032I JVM requested Java dump using '/apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022701.24204.0007.txt' in response to an event
2020/10/06 02:27:23 | jvm 1    | JVMDUMP010I Java dump written to /apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022701.24204.0007.txt
2020/10/06 02:27:23 | jvm 1    | JVMDUMP032I JVM requested Java dump using '/apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0008.txt' in response to an event
2020/10/06 02:27:23 | jvm 1    | JVMDUMP010I Java dump written to /apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0008.txt
2020/10/06 02:27:23 | jvm 1    | JVMDUMP032I JVM requested Snap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/Snap.20201006.022636.24204.0010.trc' in response to an event
2020/10/06 02:27:23 | jvm 1    | JVMDUMP010I Snap dump written to /apps/infra/sonarqube/sonarqube-7.9.4/Snap.20201006.022636.24204.0010.trc
2020/10/06 02:27:23 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:23 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:23 | jvm 1    | JVMDUMP032I JVM requested Java dump using '/apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0009.txt' in response to an event
2020/10/06 02:27:23 | jvm 1    | JVMDUMP010I Java dump written to /apps/infra/sonarqube/sonarqube-7.9.4/javacore.20201006.022636.24204.0009.txt
2020/10/06 02:27:23 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:30 | jvm 1    | JVMDUMP032I JVM requested Snap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/Snap.20201006.022636.24204.0011.trc' in response to an event
2020/10/06 02:27:30 | jvm 1    | JVMDUMP010I Snap dump written to {nothing to snap}
2020/10/06 02:27:30 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:32 | jvm 1    | Exception in thread "MemoryMXBean notification dispatcher" java.lang.OutOfMemoryError: Java heap space
2020/10/06 02:27:32 | jvm 1    | 	at java.base/java.util.HashMap.newNode(HashMap.java:1797)
2020/10/06 02:27:32 | jvm 1    | 	at java.base/java.util.HashMap.putVal(HashMap.javaJVMDUMP032I JVM requested Snap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/Snap.20201006.022636.24204.0012.trc' in response to an event
2020/10/06 02:27:32 | jvm 1    | JVMDUMP010I Snap dump written to {nothing to snap}
2020/10/06 02:27:32 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:33 | jvm 1    | JVMDUMP032I JVM requested Snap dump using '/apps/infra/sonarqube/sonarqube-7.9.4/Snap.20201006.022701.24204.0013.trc' in response to an event
2020/10/06 02:27:33 | jvm 1    | JVMDUMP010I Snap dump written to {nothing to snap}
2020/10/06 02:27:33 | jvm 1    | JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
2020/10/06 02:27:37 | jvm 1    | :626)

dmeneses · October 7, 2020, 9:55pm

Hello,
Since you’re having problems with the memory, can you try to increate the heap size of the CE process? I’d say at least 2gb.

sonar.properties:sonar.ce.javaOpts=-Xmx2g -Xms128m -XX:+HeapDumpOnOutOfMemoryError

ianw · October 8, 2020, 2:48am

As I noted, we have many far larger (LOC) projects which all process fine. Prior passes all process fine and there was minimal change in the code to be analyzed.

In fact, based on some (possibly risky advice), I stopped SQ, logged into the DB directly, deleted the stuck “In Progress” record from the ce_queue table and restarted SQ. The next pass of the same project completed fine in the usual manner, in just over 3 minutes, with no configuration changes whatsoever and again, just a minor code change.

Given the Community Edition can only process one project at a time, I can’t see where any extra resources would have been consumed. There should be clear instructions for what to do when an “In progress” task is “stuck” if there is not presently an option to cancel it, otherwise the entire instance is rendered useless.

dmeneses · October 8, 2020, 2:58pm

I’m glad you found a way to fix the problem.
The memory use might be very close to the limit when it succeeds. Many things can make the memory use vary, even when analyzing the same project. You had OOO errors so I’d increate heap size (1gb is pretty low in any case).
You can also use a JVM monitoring tool to check what’s the memory situation.

ianw · October 8, 2020, 6:56pm

Yes, I will increase the memory, but the real question is WHAT TO DO WHEN IT’S STUCK?

I should not have to rely on some untrusted advice from StackOveflow to workaround the problem, especially if it’s “access the DB directly”.

Could someone from SonarSource provide authoritative guidance on the proper mechanism to unblock the queue?

ianw · October 8, 2020, 11:30pm

Further investigation reveals there was in fact an analysis which had a Java heap space error, but it was not the one stuck in the queue.

105651 had the crash,
105652 ran successfully,
105863 to 105811 were in the queue and cancelled
105808 was the the stuck job, after the queue was drained.
Server was stopped at: 2020/10/07 05:38:13 UTC
Server was stopped at: 2020/10/07 06:06:23 UTC

Again, the real question is what to do when it’s stuck?
Secondary, how an admin should be notified system is stuck? Do we have to add our own monitoring? Can the system do this and notify admins ?
Tertiary, why was that job stuck after the heap crash occurred? If the ce process had crashed on a previous activity, nothing from the queue should have transitioned to In progress.

None of this makes any sense.

JOB	Status	Activity	Task_ID	users	Date	Submitted	Started	Finished	Duration
JOB A	Success	105516	AXTsVlzJAaDTnyQdExfp	Anonymous	‎October‎ ‎2‎, ‎2020	‎7‎:‎41‎:‎58‎ ‎PM	‎7‎:‎41‎:‎59‎ ‎PM	‎7‎:‎44‎:‎58‎ ‎PM	2min 58s
JOB B	Success	105649	AXT7jVG9AaDTnyQdExja	user	‎October‎ ‎5‎, ‎2020	‎6‎:‎36‎:‎16‎ ‎PM	‎6‎:‎36‎:‎18‎ ‎PM	‎6‎:‎36‎:‎19‎ ‎PM	1.144s
JOB B	Failed	105651	AXT7tRFuAaDTnyQdExjc	user	‎October‎ ‎5‎, ‎2020	‎7‎:‎20‎:‎22‎ ‎PM	‎7‎:‎20‎:‎24‎ ‎PM	‎7‎:‎28‎:‎34‎ ‎PM	8min 10s
JOB C	SUCCESS	105652	AXP9gs70xMaCq7nnrKgK	Anonymous
	Canceled	105653	First Canceled Job
JOB D	Canceled	105657	AXT8MD3JAaDTnyQdExjk	Anonymous	‎October‎ ‎5‎, ‎2020	‎9‎:‎34‎:‎14‎ ‎PM
JOB B	Canceled	105802	AXUAvLJhAaDTnyQdExmQ	user	‎October‎ ‎6‎, ‎2020	‎6‎:‎47‎:‎00‎ ‎PM
JOB A	Canceled	105808	AXUA7j_PAaDTnyQdExmX	Anonymous	‎October‎ ‎6‎, ‎2020	‎7‎:‎40‎:‎16‎ ‎PM
	Canceled	105811	Last Canceled Job
JOB D	Success	105812	AXUBVo5sAaDTnyQdExmb	Anonymous	‎October‎ ‎6‎, ‎2020	‎9‎:‎34‎:‎11‎ ‎PM	‎11‎:‎08‎:‎08‎ ‎PM	‎11‎:‎09‎:‎37‎ ‎PM	1min 28s
JOB A	Success	105885	AXUGED_EQLNcvbuLXJy1	Anonymous	‎October‎ ‎7‎, ‎2020	‎7‎:‎35‎:‎30‎ ‎PM	‎7‎:‎35‎:‎30‎ ‎PM	‎7‎:‎38‎:‎36‎ ‎PM	3min 6s