Build periodically Schedule time difference vs actual execute time

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Build periodically Schedule time difference vs actual execute time

james C

To Hudson Users,

 

We’re observing a time lag in the “proposed schedule time” verses the “actual execution time”.

I scheduled a test job to run every 5,10,15,20,25,30,35,40,45,50,55 mins but for some reason it’s running 80 secs behind the scheduled time…

 

Can anyone help explain this behaviour or let me know how to fix it?

 

Note: Test #1 and #9 Manual Builds were just to see if there was some sliding logic or functionality that was affected if a manual build was thrown in…

Re-loading Configuration from disk didn’t alter the timing issue…

 

My belief is that since the Schedule/CRON time doesn’t support a “SECS” it uses the Listener start time secs as base “0”  so if it started at 13:29:15 secs then this is considered “0” secs…

Then Hudson adds any Quiet time on “5” secs (by default unless overwridden) therefore executing at 20 secs past the minute…   [I’m ok with this…]

But why does it wait for 1 minute after the scheduled minute??

I would have expected the first job to execute at 13:30:15 secs not 13:31:15 + (plus 5 secs quiet time)

 

 [My Workings:]

Thought it might have been a slow box but or appserver issue, but have seen this occurring on various hosted applications e.g. laptop (via Test Drive (https://hudson.dev.java.net/hudson.jnlp )), Solaris (Glassfish V2.0)

Both versions run Hudson ver 1.254 (but have observed this behaviour dating back to v1.9xx versions)

Thought it might have been attributed to startup overhead but you can see it only takes 15 secs not 80 secs.. (1 min 20 sec)

Changing the “Advanced Option” Quiet period to 0 secs dropped the time to 75 secs (1 min 15 secs) so was wondering if there was a magic 1 min + Startup Timer overhead (i.e.15 secs) in play…

 

I created simple stub job to test it…  You can see it constantly executing 80 to 81 secs behind the “Scheduled” time…

Obviously on Windows we ran a Windows Batch script or in Unix it was a simple <command>echo “hello `date`”</command>

 

${HOME}\.hudson\test\config.xml

 

<?xml version='1.0' encoding='UTF-8'?>

<project>

  <actions class="java.util.concurrent.CopyOnWriteArrayList"/>

  <description>Simple Hello test to test Hudson Scheduling accuracy</description>

  <keepDependencies>false</keepDependencies>

  <properties/>

  <scm class="hudson.scm.NullSCM"/>

  <canRoam>true</canRoam>

  <disabled>false</disabled>

  <triggers class="vector">

    <hudson.triggers.TimerTrigger>

      <spec>0,5,10,15,20,25,30,35,40,45,50,55 * * * *</spec>

    </hudson.triggers.TimerTrigger>

  </triggers>

  <builders>

    <hudson.tasks.BatchFile>

      <command>echo. | time</command>

    </hudson.tasks.BatchFile>

  </builders>

  <publishers/>

  <buildWrappers/>

</project>

 

Log output from the “Test Drive” Java Web Start

 

[Winstone 2008/09/30 13:24:02] - Beginning extraction from war file

[Winstone 2008/09/30 13:24:14] - No webapp classes folder found - C:\Documents and Settings\clarkeja\.hudson\war\WEB-INF\classes

hudson home directory: C:\Documents and Settings\clarkeja\.hudson

30/09/2008 13:24:15 hudson.model.Hudson load

INFO: Took 171 ms to load

30/09/2008 13:24:15 hudson.TcpSlaveAgentListener <init>

INFO: JNLP slave agent listener started on TCP port 3205

30/09/2008 13:24:16 org.springframework.context.support.AbstractApplicationContext prepareRefresh

INFO: Refreshing org.springframework.web.context.support.StaticWebApplicationContext@825cf3: display name [Root WebApplicationContext]; startup date [Tue Sep 30 13:24:16 EST 2008]; root of context hierarchy

30/09/2008 13:24:16 org.springframework.context.support.AbstractApplicationContext obtainFreshBeanFactory

INFO: Bean factory for application context [org.springframework.web.context.support.StaticWebApplicationContext@825cf3]: org.springframework.beans.factory.support.DefaultListableBeanFactory@11dd95c

30/09/2008 13:24:16 org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons

INFO: Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@11dd95c: defining beans [filter,legacy]; root of factory hierarchy

[Winstone 2008/09/30 13:24:16] - HTTP Listener started: port=8080

[Winstone 2008/09/30 13:24:16] - AJP13 Listener started: port=8009

[Winstone 2008/09/30 13:24:16] - Winstone Servlet Engine v0.9.10 running: controlPort=disabled

30/09/2008 13:29:15 hudson.model.UpdateCenter doPostBack

INFO: Obtained the latest update center data file

30/09/2008 13:30:21 hudson.model.Run run

INFO: test #1 main build action completed: SUCCESS

30/09/2008 13:31:21 hudson.model.Run run

INFO: test #2 main build action completed: SUCCESS

30/09/2008 13:36:21 hudson.model.Run run

INFO: test #3 main build action completed: SUCCESS

30/09/2008 13:41:21 hudson.model.Run run

INFO: test #4 main build action completed: SUCCESS

30/09/2008 13:46:21 hudson.model.Run run

INFO: test #5 main build action completed: SUCCESS

30/09/2008 13:51:21 hudson.model.Run run

INFO: test #6 main build action completed: SUCCESS

30/09/2008 13:56:21 hudson.model.Run run

INFO: test #7 main build action completed: SUCCESS

30/09/2008 14:01:20 hudson.model.Run run

INFO: test #8 main build action completed: SUCCESS

30/09/2008 14:06:21 hudson.model.Run run

INFO: test #9 main build action completed: SUCCESS

30/09/2008 14:09:09 hudson.model.Run run

INFO: test #10 main build action completed: SUCCESS

30/09/2008 14:11:21 hudson.model.Run run

INFO: test #11 main build action completed: SUCCESS

30/09/2008 14:16:21 hudson.model.Run run

INFO: test #12 main build action completed: SUCCESS

30/09/2008 14:21:21 hudson.model.Run run

INFO: test #13 main build action completed: SUCCESS

 

 [Pat on the back to the developers / contributors]

 

Awesome product / project …. 

We’ve been using this for 12 months now and it rocks… 

Obviously every app has its bugs but you constantly surprise me with the stability of releases….  

Keep up the good work…

Notice:

This e-mail and any attachments are confidential
and may contain legally privileged information
and/or copyright material of Hansen Technologies
Limited or third parties. Copying, distributing,
disclosing, commercialising or otherwise acting in
reliance on this e-mail and any attachments is
strictly prohibited unless you are the addressee of
this e-mail and have written permission to do so. If
you have received this e-mail in error please
delete this e-mail (including any copies and
attachments) and contact Hansen Technologies
Limited by return e-mail or by telephone on + 61 3
9840 3000. Any views expressed in this e-mail are
those of the individual sender and may not
necessarily reflect the views of or be a
commitment by the organisation, except where the
individual sender has the authority and expressly
states them to be so.
Reply | Threaded
Open this post in threaded view
|

Re: Build periodically Schedule time difference vs actual execute time

gradopado
james C wrote
To Hudson Users,

We're observing a time lag in the "proposed schedule time" verses the
"actual execution time".

I scheduled a test job to run every 5,10,15,20,25,30,35,40,45,50,55 mins
but for some reason it's running 80 secs behind the scheduled time...

Can anyone help explain this behaviour or let me know how to fix it?

[...]
No, but "me too" see this behavior on our Hudson installation! We run 1.210. I have a job scheduled at 5:20 AM but according to Hudson's records it started with these delays (min:sec) (each value listed below has been maintained for some days in a row):
1:22
2:07
1:29
1:53
1:28
1:25
1:17
1:53
1:16
1:17
1:26
1:35
1:46
1:49
1:20

I'm quite sure that there were no other jobs competing for free executors or CPU time.

Wolfram
Reply | Threaded
Open this post in threaded view
|

Re: Build periodically Schedule time difference vs actual execute time

Kohsuke Kawaguchi
Administrator
In reply to this post by james C
James Clarke wrote:
> To Hudson Users,
>
>  
>
> We're observing a time lag in the "proposed schedule time" verses the
> "actual execution time".
>
> I scheduled a test job to run every 5,10,15,20,25,30,35,40,45,50,55 mins
> but for some reason it's running 80 secs behind the scheduled time...

Hudson only has 1 minute accuracy of scheduling, so that alone can have
up to 60 second delay.

And then the code is written to observe the quiet period of a job. So
perhaps that explains the additional delay?

I fixed this in 1.255 so that it will ignore the quiet period setting.


> Can anyone help explain this behaviour or let me know how to fix it?
>
>  
>
> Note: Test #1 and #9 Manual Builds were just to see if there was some
> sliding logic or functionality that was affected if a manual build was
> thrown in...
>
> Re-loading Configuration from disk didn't alter the timing issue...
>
>  
>
> My belief is that since the Schedule/CRON time doesn't support a "SECS"
> it uses the Listener start time secs as base "0"  so if it started at
> 13:29:15 secs then this is considered "0" secs...
>
> Then Hudson adds any Quiet time on "5" secs (by default unless
> overwridden) therefore executing at 20 secs past the minute...   [I'm ok
> with this...]
>
> But why does it wait for 1 minute after the scheduled minute??
>
> I would have expected the first job to execute at 13:30:15 secs not
> 13:31:15 + (plus 5 secs quiet time)
>
>  
>
>  [My Workings:]
>
> Thought it might have been a slow box but or appserver issue, but have
> seen this occurring on various hosted applications e.g. laptop (via Test
> Drive (https://hudson.dev.java.net/hudson.jnlp )), Solaris (Glassfish
> V2.0)
>
> Both versions run Hudson ver 1.254 (but have observed this behaviour
> dating back to v1.9xx versions)
>
> Thought it might have been attributed to startup overhead but you can
> see it only takes 15 secs not 80 secs.. (1 min 20 sec)
>
> Changing the "Advanced Option" Quiet period to 0 secs dropped the time
> to 75 secs (1 min 15 secs) so was wondering if there was a magic 1 min +
> Startup Timer overhead (i.e.15 secs) in play...
>
>  
>
> I created simple stub job to test it...  You can see it constantly
> executing 80 to 81 secs behind the "Scheduled" time...
>
> Obviously on Windows we ran a Windows Batch script or in Unix it was a
> simple <command>echo "hello `date`"</command>
>
>  
>
> ${HOME}\.hudson\test\config.xml
>
>  
>
> <?xml version='1.0' encoding='UTF-8'?>
>
> <project>
>
>   <actions class="java.util.concurrent.CopyOnWriteArrayList"/>
>
>   <description>Simple Hello test to test Hudson Scheduling
> accuracy</description>
>
>   <keepDependencies>false</keepDependencies>
>
>   <properties/>
>
>   <scm class="hudson.scm.NullSCM"/>
>
>   <canRoam>true</canRoam>
>
>   <disabled>false</disabled>
>
>   <triggers class="vector">
>
>     <hudson.triggers.TimerTrigger>
>
>       <spec>0,5,10,15,20,25,30,35,40,45,50,55 * * * *</spec>
>
>     </hudson.triggers.TimerTrigger>
>
>   </triggers>
>
>   <builders>
>
>     <hudson.tasks.BatchFile>
>
>       <command>echo. | time</command>
>
>     </hudson.tasks.BatchFile>
>
>   </builders>
>
>   <publishers/>
>
>   <buildWrappers/>
>
> </project>
>
>  
>
> Log output from the "Test Drive" Java Web Start
>
>  
>
> [Winstone 2008/09/30 13:24:02] - Beginning extraction from war file
>
> [Winstone 2008/09/30 13:24:14] - No webapp classes folder found -
> C:\Documents and Settings\clarkeja\.hudson\war\WEB-INF\classes
>
> hudson home directory: C:\Documents and Settings\clarkeja\.hudson
>
> 30/09/2008 13:24:15 hudson.model.Hudson load
>
> INFO: Took 171 ms to load
>
> 30/09/2008 13:24:15 hudson.TcpSlaveAgentListener <init>
>
> INFO: JNLP slave agent listener started on TCP port 3205
>
> 30/09/2008 13:24:16
> org.springframework.context.support.AbstractApplicationContext
> prepareRefresh
>
> INFO: Refreshing
> org.springframework.web.context.support.StaticWebApplicationContext@825c
> f3: display name [Root WebApplicationContext]; startup date [Tue Sep 30
> 13:24:16 EST 2008]; root of context hierarchy
>
> 30/09/2008 13:24:16
> org.springframework.context.support.AbstractApplicationContext
> obtainFreshBeanFactory
>
> INFO: Bean factory for application context
> [org.springframework.web.context.support.StaticWebApplicationContext@825
> cf3]:
> org.springframework.beans.factory.support.DefaultListableBeanFactory@11d
> d95c
>
> 30/09/2008 13:24:16
> org.springframework.beans.factory.support.DefaultListableBeanFactory
> preInstantiateSingletons
>
> INFO: Pre-instantiating singletons in
> org.springframework.beans.factory.support.DefaultListableBeanFactory@11d
> d95c: defining beans [filter,legacy]; root of factory hierarchy
>
> [Winstone 2008/09/30 13:24:16] - HTTP Listener started: port=8080
>
> [Winstone 2008/09/30 13:24:16] - AJP13 Listener started: port=8009
>
> [Winstone 2008/09/30 13:24:16] - Winstone Servlet Engine v0.9.10
> running: controlPort=disabled
>
> 30/09/2008 13:29:15 hudson.model.UpdateCenter doPostBack
>
> INFO: Obtained the latest update center data file
>
> 30/09/2008 13:30:21 hudson.model.Run run
>
> INFO: test #1 main build action completed: SUCCESS
>
> 30/09/2008 13:31:21 hudson.model.Run run
>
> INFO: test #2 main build action completed: SUCCESS
>
> 30/09/2008 13:36:21 hudson.model.Run run
>
> INFO: test #3 main build action completed: SUCCESS
>
> 30/09/2008 13:41:21 hudson.model.Run run
>
> INFO: test #4 main build action completed: SUCCESS
>
> 30/09/2008 13:46:21 hudson.model.Run run
>
> INFO: test #5 main build action completed: SUCCESS
>
> 30/09/2008 13:51:21 hudson.model.Run run
>
> INFO: test #6 main build action completed: SUCCESS
>
> 30/09/2008 13:56:21 hudson.model.Run run
>
> INFO: test #7 main build action completed: SUCCESS
>
> 30/09/2008 14:01:20 hudson.model.Run run
>
> INFO: test #8 main build action completed: SUCCESS
>
> 30/09/2008 14:06:21 hudson.model.Run run
>
> INFO: test #9 main build action completed: SUCCESS
>
> 30/09/2008 14:09:09 hudson.model.Run run
>
> INFO: test #10 main build action completed: SUCCESS
>
> 30/09/2008 14:11:21 hudson.model.Run run
>
> INFO: test #11 main build action completed: SUCCESS
>
> 30/09/2008 14:16:21 hudson.model.Run run
>
> INFO: test #12 main build action completed: SUCCESS
>
> 30/09/2008 14:21:21 hudson.model.Run run
>
> INFO: test #13 main build action completed: SUCCESS
>
>  
>
>  [Pat on the back to the developers / contributors]
>
>  
>
> Awesome product / project ....  
>
> We've been using this for 12 months now and it rocks...  
>
> Obviously every app has its bugs but you constantly surprise me with the
> stability of releases....  
>
> Keep up the good work...
>
>
> Notice:
>
> This e-mail and any attachments are confidential
> and may contain legally privileged information
> and/or copyright material of Hansen Technologies
> Limited or third parties. Copying, distributing,
> disclosing, commercialising or otherwise acting in
> reliance on this e-mail and any attachments is
> strictly prohibited unless you are the addressee of
> this e-mail and have written permission to do so. If
> you have received this e-mail in error please
> delete this e-mail (including any copies and
> attachments) and contact Hansen Technologies
> Limited by return e-mail or by telephone on + 61 3
> 9840 3000. Any views expressed in this e-mail are
> those of the individual sender and may not
> necessarily reflect the views of or be a
> commitment by the organisation, except where the
> individual sender has the authority and expressly
> states them to be so.
>

--
Kohsuke Kawaguchi
Sun Microsystems                   http://weblogs.java.net/blog/kohsuke/

smime.p7s (4K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

hudson upgrade crashes glassfish domain

james C
In reply to this post by james C

Folks,

 

Problem : We recently upgraded Hudson from version V1.255 to V1.279 and found we could not successfully restart Hudson and found it crashed the domain silently (i.e. no real log entries indicating why).  Also important to note we were deploying Hudson through an ssh session so no X windows involvement…. And we had email-ext plugin (2.1) previously installed with the V1.255 version.

.

We kept on getting the following log output during what seemed to be the Hudson initialisation step :

 

[#|2009-02-11T05:46:11.172+0000|INFO|sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=10;_ThreadName=main;4852;|WEB071

2: Starting Sun-Java-System/Application-Server HTTP/1.1 on 4852|#]

 

[#|2009-02-11T05:46:12.147+0000|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=12;_ThreadName=pool-1-thread-7;|

hudson home directory: ${HOME}/.hudson|#]

 

X connection to localhost:10.0 broken (explicit kill or server shutdown).

 

Analysis : As we’re not using an “X” connection we were suspicious…..   Turns out somewhere in between V1.255 and V1.279 (suggest around V1.266) an AWT dependency was introduced, which is “normally” ok as the Hudson application displays a browser warning like the following : “AWT is not properly configured on this server. Perhaps you need to run your container with “-Djava.awt.headless=true”” i.e. modify your domain $DOMHOME/config/domain.xml file to contain the following  <jvm-option>–Djava.awt.headless=true</jvm-option> and restart the domain….

 

We also placed a new email-ext.hpi (2.2.1) into the plugins directory so effectively it was upgrading Hudson and the Email-ext plug-in at the same time….

 

However it seems that when the domain has some upgrade work to do, maybe related to existing $HOME/.hudson/config.xml or plug-ins such as email-ext (and the container didn’t already have this AWT headless instruction set) the deployment/upgrade fails and we never get to see this nice warning error message in the browser client nor the server logfile…..   Suspect the email-ext plugin may have an assumption AWT is available and is trying to warn accordingly of an initialisation failure or upgrade failure …..

 

Solution : So once, we set the awt.headless instruction and re-deployed Hudson.war the site came back up ok…

 

Suggestion : Might be worth putting in some protection inside the “upgrade / initialisation” to make sure the message “AWT is not properly configured on this server” gets written to the server log file (as well as the current browser screen) so at least if a plug-in or some other downstream issue causes the application to fail initialisation, the AWT error can be identified and resolved… 

 

Also suggest on upgrades, it might be worth upgrading Hudson.war first, then upgrading the email-ext plug-in as a second round change as this may have obscured the issue…

 

Hope this helps someone in the future avoid or resolve this issue…

 

Cheers

 

Notice:

This e-mail and any attachments are confidential
and may contain legally privileged information
and/or copyright material of Hansen Technologies
Limited or third parties. Copying, distributing,
disclosing, commercialising or otherwise acting in
reliance on this e-mail and any attachments is
strictly prohibited unless you are the addressee of
this e-mail and have written permission to do so. If
you have received this e-mail in error please
delete this e-mail (including any copies and
attachments) and contact Hansen Technologies
Limited by return e-mail or by telephone on + 61 3
9840 3000. Any views expressed in this e-mail are
those of the individual sender and may not
necessarily reflect the views of or be a
commitment by the organisation, except where the
individual sender has the authority and expressly
states them to be so.
Reply | Threaded
Open this post in threaded view
|

Re: Build periodically Schedule time difference vs actual execute time

dromeyn
This post has NOT been accepted by the mailing list yet.
In reply to this post by gradopado
Sorry for bringing back an old thread but we are dealing with this issue ourselves now.

We are evaluating Hudson as a cron replacement but the start times of jobs are causing issues.  If a job were to start at least in the same minute it was scheduled for, it wouldn't be an issue.  But, I am seeing jobs start in the following minute.

For example, with this schedule:

01,06,11,16,21,26,31,36,41,46,51,56 * * * *

The job might not actually start till HH:02:SS instead of within HH:01:SS.

Is there anyway to improve this?  I wrote a wrapper around hudson so that it starts up at exactly HH:MM:00, hoping that would help things but it didn't seem to make any real difference.   Currently everything is starting at :46 in the right minute with this change but I have no confidence it won't have drifted for some reason into the next minute same time tomorrow.

Derek