High CPU usage - due to scheduled tasks

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 array=st item="local.ste" {
          			str &= ste;
          			str &= "<br>";
          		}
          		local.servlet = find( "lucee.loader.servlet.CFMLServlet.service", str );
          		if ( local.servlet gt 1 )
          			str = mid( str , 1, local.servlet-1 ) & "...";
          
          
		local.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="local.q_summary" dbtype="query">

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…

TonyMonast · February 16, 2021, 7:39pm

I tried to find a pattern for the bug. It’s directly related to the scheduled task interval :

10000 (2,777778 hours) ok
10400 (2,8888889 hours) ok
10800 (3 hours) bug
10810 (3,0027778 hours) ok
14400 (4 hours) bug
14700 (4,0833333 hours) ok
18000 (5 hours) ok

At first I thought it was coming from a rounding issue and/or data type (int vs float), because it was buggy just with whole number like 3 and 4 hours, but it’s okay with 5 hours. It’s strange.

For now I just changed the interval 14400 to 14700 for my problematics scheduled tasks and the Lucee CPU dropped at 0%.

I wonder if it’s specific to our server configuration or if anybody who use an interval of 14400 will have this issue…

If I can help in anyway to solve this issue, let me know!

Zackster · February 16, 2021, 7:47pm

I think it’s maybe something to do with this while(true) loop in revertDST

the code is slightly different in 5.3 as it includes a fix for this issue with DST

github.com

lucee/Lucee/blob/5.3/core/src/main/java/lucee/runtime/schedule/ScheduledTaskThread.java#L464


      
          			}
          		}
          		// print.e("next2:" + new Date(next));
          		return next;
          	}
          
          
	private static void revertDST(Calendar c, int hourExpected, int intervall, int amount) {
          		int hour = c.get(Calendar.HOUR_OF_DAY);
          		if (hour == hourExpected) return;
          		// go back until it shifts
          		while (true) {
          			// print.e("- " + c.getTime());
          			c.add(intervall, -amount);
          			hour = c.get(Calendar.HOUR_OF_DAY);
          			if (hour <= hourExpected) {
          				c.add(intervall, amount);
          				break;
          			}
          		}
          	}

github.com

lucee/Lucee/blob/5.3.7.47/core/src/main/java/lucee/runtime/schedule/ScheduledTaskThread.java#L422


      
          		c.setTimeInMillis(now);
          		c.set(Calendar.HOUR_OF_DAY, 0);
          		c.set(Calendar.MINUTE, 0);
          		c.set(Calendar.SECOND, 0);
          		c.set(Calendar.MILLISECOND, 0);
          		c.setTimeInMillis(c.getTimeInMillis() + endTime);
          		long end = c.getTimeInMillis();
          
          
		c.setTimeInMillis(now);
          		c.set(Calendar.HOUR_OF_DAY, startHour);
          		revertDST(c, Calendar.HOUR_OF_DAY, startHour, Calendar.SECOND, amount);
          		c.set(Calendar.MINUTE, startMinute);
          		c.set(Calendar.SECOND, startSecond);
          		c.set(Calendar.MILLISECOND, startMilliSecond);
          		long next = c.getTimeInMillis();
          
          
		// is it already in the future or we want not now
          		while (next <= now) {
          			// we allow now
          			if (!notNow) {
          				long diff = now - next;

TonyMonast · February 16, 2021, 8:07pm

It makes sense.

Note that if my scheduled task use an interval of 14400 and start at {t ‘06:00:00’}, it’s fine. But if it’s start at 00:00:00, or 00:30:00, or 01:00:00 the bug still occur. This is indeed a bug depending on the combination of start time and interval, and maybe end time as well.

Zackster · February 16, 2021, 9:48pm

good detective work, can you post your findings in the task

TonyMonast · February 17, 2021, 1:08pm

I posted my findings in the bug report [LDEV-3214] - Lucee.

Zackster · March 8, 2021, 10:39pm

this was addressed in 5.3.8.156, please try it out (when the build finishes)

kpetrow · March 9, 2021, 2:43pm

I too also had scheduled tasks high cpu when converting from railo to lucee. I binnary searched around 250 tasks and found 5 offenders. No rhyme or reason to what they were

TonyMonast · March 16, 2021, 5:17pm

Hi @Zackster,

I don’t see the version 5.3.8.156 in the Update section of the server admin. Is it normal?

I suppose the version 5.3.8.159-SNAPSHOT should be fine too? I tried the version 5.3.8.159-SNAPSHOT with my old scheduled tasks settings and everything look normal in the CPU usage.

Thank you!

harryf · October 31, 2021, 11:58am

I had the same problem and by turning off Debugging*, everything was fine again.

I turned on Debugging to use the fantastic Performance Analyzer plugin.