High CPU usage - due to scheduled tasks

TonyMonast · February 15, 2021, 4:27pm

Hi,

What is the best way to find out why the Lucee CPU usage is so high? 50% with Lucee 5.3.7.47 and 75% with Lucee 5.3.8.139-RC. I did a fresh restart of Lucee and all scheduled tasks are on pause. Nobody have access to the website on this server, so no activity at all and still, the CPU is high and stay high.

OS: Windows Server 2016 (10.0) 64bit
Java Version: 1.8.0_181 (Oracle Corporation) 64bit
Tomcat Version: Apache Tomcat/8.5.33
Lucee Version: 5.3.7.47 and 5.3.8.139-RC

Lucee 5.3.7.47 Overview

5.3.8.139-RC Overview

Thank you!

Zackster · February 15, 2021, 6:18pm

try renaming any \WEB-INF\lucee\scheduler.xml file(s), to completely rule out scheduled tasks

also my Performance Analyzer plugin for Lucee will show you which threads are running

TonyMonast · February 15, 2021, 7:09pm

I removed the scheduler.xml file. There is no scheduled tasks showing in the web admin and the CPU is still at 75% on Lucee 5.3.8.139-RC.

I’ll try your plugin.

Zackster · February 15, 2021, 7:10pm

did you restart lucee?

TonyMonast · February 15, 2021, 7:15pm

Yes. And I didn’t visit my website and boom 75% CPU already.

I see the threads now with your plugin. Something particular to look at? . I see a lot of threads with status TIMED_WAITING and the stack mention ScheduledTaskThread.

TonyMonast · February 15, 2021, 7:20pm

Oh! Now I used the Lucee-Tomcat Service Control to restart, instead of the restart Lucee button in the admin, and the CPU is at 0%, and go at 7% when I visit a page, then 0%. Sound good! No more threads about ScheduledTaskThread.

bdw429s · February 15, 2021, 7:21pm

Use FusionReactor and it will show you which threads in the JVM are consuming the most CPU. Simply click on “Resources” > “Thread Visualizer” then click the “CPU(ms)” column to sort and you’ll have your answer right away.

TonyMonast · February 15, 2021, 7:26pm

Good idea for FusionReactor. I’ll take a look at that.

So I suppose my problem was provoked by my scheduled tasks. I’ll take them back and restart the same way I did to see if the CPU stay low. I know I worked on my scheduled tasks few days ago and I had problem with the characters encoding. I did a lot of try/fail and I reported a bug about it. So maybe something got stuck in the memory and the restart button in the admin don’t do as much as restarting Lucee from Lucee-Tomcat Service Control.

Zackster · February 15, 2021, 7:30pm

There’s some certain combinations of scheduled task intervals which get stuck in an infinite loop trying to find the next schedule

TonyMonast · February 15, 2021, 7:40pm

As soon as I put back my scheduled tasks and restart Lucee with Lucee-Tomcat Service Control, CPU at 50% again. Many threads about ScheduledTaskThread. I’ll try to add my scheduled tasks one by one to see which combination provoke that. Note that all scheduled tasks are on pause…

There’s some certain combinations of scheduled task intervals which get stuck in an infinite loop trying to find the next schedule

Is this bug has been already reported?

I wonder if I should use something else than Lucee to manage the scheduled tasks…

bdw429s · February 15, 2021, 7:42pm

This is sort of a side-question, but the fact that the Lucee restart button didn’t stop those scheduled task threads is probably a bug in itself. The Lucee service restart actually shuts down the JVM and starts a fresh one. The Lucee restart button leaves the JVM and the servlet container (tomcat) and simply unloads and reloads the Lucee context in memory. IMO, that should include any scheduled task threads.

Is this bug has been already reported?

Yes. That’s how Zac knows about it

Zackster · February 15, 2021, 7:43pm

https://luceeserver.atlassian.net/browse/LDEV-3214

TonyMonast · February 15, 2021, 7:53pm

Thank you @Zackster and @bdw429s

I’ll wait for a patch and if the patch don’t come in time, I will track down the scheduled task that provoke it or use another tool to manage the scheduled tasks instead of Lucee.

Zackster · February 15, 2021, 7:56pm

If you could isolate which task(s) are causing the problem before it get addressed, that would be super useful…

TonyMonast · February 15, 2021, 7:57pm

I’ll do that with pleasure then!

Zackster · February 15, 2021, 8:23pm

Cool.

The admin restart bug may have been fixed in 5.3.8 btw

TonyMonast · February 15, 2021, 8:28pm

I found one of the scheduled task. This one alone provoke a 25% CPU usage non-stop. When I try a different interval like 1000 it’s okay.

<?xml version="1.0" encoding="ISO-8859-1" standalone="no"?><schedule><task autoDelete="false" endTime="{t '23:59:59'}" hidden="false" interval="14400" name="To Infinity and Beyond" paused="true" port="443" proxyHost="" proxyPassword="" proxyPort="0" proxyUser="" publish="false" readonly="false" resolveUrl="false" startDate="{d '2021-01-01'}" startTime="{t '00:00:00'}" timeout="90000" unique="true" url="https://www.example.com/infinity/"/></schedule>

bdw429s · February 15, 2021, 9:03pm

Use the profile feature in FR to profile the thread for a few seconds and then see what it is doing. The previous issues with scheduled tasks was due to an infinite loop int he code trying to figure out when to run the task next.

Zackster · February 16, 2021, 3:05pm

I just added in thread CPU time to my Performance Analyzer plugin v1.0.1.2 (available via admin)

github.com

zspitzer/lucee-performance-analyzer/blob/master/source/cfml/plugins/threads.cfm#L46


		// loop stacktraces
		loop array=st item="ste" {
			str&=ste;
			str&="<br>";
		}
		r = queryAddRow(q_threads);
		//if(!find("PageContextImpl",str)) continue;
		QuerySetCell(q_threads, "name", t.name, r);
		QuerySetCell(q_threads, "threadState", t.getState().toString(), r);
		QuerySetCell(q_threads, "stack",trim(str), r);
		QuerySetCell(q_threads, "cpuTime", threadMXBean.getThreadCpuTime(t.getId())/1000/1000, r);
	}
	q_threads = q_threads.sort("cputime","desc");
	//dump(q_threads); 	abort;
</cfscript>
<cfquery name="q_summary" dbtype="query">
	select threadState, count(threadState) as threads, sum(cpuTime) as cpuTotal
	from  q_threads
	group by threadState

TonyMonast · February 16, 2021, 6:20pm

Hi! I installed the new version of your plugin @Zackster.

As soon I add the scheduled task To Infinity and Beyond and restart Lucee, I see this :

After few seconds I see CPU time jumping at 286,281.25, then 316,234.38, then 332,750.00, and going up and up and up…