[Swift-devel] slow swift startup time

Mihael Hategan hategan at mcs.anl.gov
Mon Nov 5 20:45:42 CST 2007 

It's a warning. warning != error.

On Mon, 2007-11-05 at 18:56 -0600, Michael Wilde wrote:
> The lock error I was referring to is this, on stdout/err:
> 
>    Failed to acquire exclusive lock on log file.
> 
> Below is the log file text that accompanied it.
> 
> Note that Im not complaining about this error - it went away when I 
> started compiling on terminable again.
> 
> Im just pointing it out as a suspect in the slow startup. It surprised 
> me that we bother to lock the logfile, unless Java is gratuituously doig 
> it for us.
> 
> - Mike
> 
> Logfile head showed:
> 
> 2007-11-04 10:15:28,949-0600 INFO  Loader awf3.swift: source file is 
> new. Recompiling.
> 2007-11-04 10:15:31,315-0600 INFO  Karajan Validation of XML 
> intermediate file was successful
> 2007-11-04 10:15:34,597-0600 INFO  unknown Using sites file: ./sites.xml
> 2007-11-04 10:15:34,599-0600 INFO  unknown Using tc.data: ./tc.data
> 2007-11-04 10:15:36,606-0600 INFO  unknown Swift v0.3-dev 
> libexec/svn-revision: line 1: svn: command not found
> libexec/svn-revision: line 1: svn: command not found
> 
> 
> 2007-11-04 10:15:36,607-0600 INFO  unknown RunID: 20071104-1015-afgc18i3
> 2007-11-04 10:15:36,825-0600 INFO  AbstractDataNode Found data 
> pcapfiles.$[]/1.[0]
> 2007-11-04 10:15:36,825-0600 INFO  AbstractDataNode Found data 
> pcapfiles.$[]/2.[1]
> 2007-11-04 10:15:36,825-0600 INFO  AbstractDataNode Found data 
> pcapfiles.$[]/3.[2]
> 2007-11-04 10:15:36,825-0600 INFO  AbstractDataNode Found data 
> pcapfiles.$[]/4.[3]
> 2007-11-04 10:15:36,825-0600 INFO  AbstractDataNode Found data 
> pcapfiles.$[]/5.[4]
> 2007-11-04 10:16:26,917-0600 INFO  FlushableLockedFileWriter Could not 
> acquire lock on /home/wilde/angle/data/./awf3-20071104-1015
> -afgc18i3.0.rlog
> java.io.IOException: No locks available
>          at sun.nio.ch.FileChannelImpl.lock0(Native Method)
>          at sun.nio.ch.FileChannelImpl.tryLock(FileChannelImpl.java:804)
>          at java.nio.channels.FileChannel.tryLock(FileChannel.java:983)
>          at 
> org.globus.cog.karajan.workflow.nodes.restartLog.FlushableLockedFileWriter.<init>(FlushableLockedFileWriter.java:26)
>          at 
> org.globus.cog.karajan.workflow.nodes.restartLog.RestartLog.create(RestartLog.java:123)
>          at 
> org.globus.cog.karajan.workflow.nodes.restartLog.RestartLog.partialArgumentsEvaluated(RestartLog.java:55)
>          at 
> org.globus.cog.karajan.workflow.nodes.PartialArgumentsContainer.executeChildren(PartialArgumentsContainer.java:51)
>          at 
> org.globus.cog.karajan.workflow.nodes.FlowContainer.execute(FlowContainer.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.nodes.FlowNode.restart(FlowNode.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.nodes.FlowNode.start(FlowNode.java(Inlined 
> Compiled Code))
>          at 
> org.globus.cog.karajan.workflow.nodes.FlowNode.controlEvent(FlowNode.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.nodes.FlowNode.event(FlowNode.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.FlowElementWrapper.event(FlowElementWrapper.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.events.EventBus.send(EventBus.java(Compiled 
> Code))
>          at 
> org.globus.cog.karajan.workflow.events.EventBus.sendHooked(EventBus.java(Inlined 
> Compiled Code))
>          at 
> org.globus.cog.karajan.workflow.events.EventWorker.run(EventWorker.java(Compiled 
> Code))
> 2007-11-04 10:16:26,921-0600 WARN  RestartLog Failed to acquire 
> exclusive lock on log file.
> 2007-11-04 10:16:26,999-0600 INFO  vdl:execute START thread=0-4 tr=angle4
> 2007-11-04 10:16:26,999-0600 INFO  vdl:execute START thread=0-1 tr=angle4
> 2007-11-04 10:16:26,999-0600 INFO  vdl:execute START thread=0-5 tr=angle4
> 2007-11-04 10:16:27,000-0600 INFO  vdl:execute START thread=0-3 tr=angle4
> 2007-11-04 10:16:27,001-0600 INFO  vdl:execute START thread=0-2 tr=angle4
> 
> 
> 
> On 11/5/07 6:46 PM, Michael Wilde wrote:
> > Im running on tg-login.uc.teragrid.org (IA64) and seeing very long swift 
> > start times.
> > 
> > My swift command wrapper prints the wf start and end times with the 
> > swift stdout sandwiched in between.  Here's an example of those, 
> > followed by the swift log file. In this run, i start swift in the 
> > background, then tail the stdout file. it was about 70 seconds (on my 
> > watch) before swift responded with its initial messages on stdout. (I 
> > dont think its being buffered, but thats worth checking...)
> > 
> > Note that swift was launched at 18:30:49 and its logfile entry with the 
> > runid came at 18:32:05.  32:05-30:49 = 76 seconds!
> > 
> > This was swift 1456 compiled on terminable (or login, i forget).
> > 
> > Suspicious: when I was running a version compiled in tg-login under Java 
> > 1.4 I would get an error message from a Java method trying to lock the 
> > log file. Not sure if this logging action (which now does not give a 
> > message) is related to this slow start time.
> > 
> > - Mike
> > 
> > UC64$ cat swift.out
> > Swift Script local-noks.swift starting at Mon Nov 5 18:30:49 CST 2007
> > 
> > Swift v0.3-dev r1456
> > 
> > RunID: 20071105-1831-d7t5l2n3
> > angle4 started
> > angle4 started
> > angle4 started
> > angle4 started
> > angle4 started
> > angle4 completed
> > angle4 completed
> > angle4 completed
> > angle4 completed
> > angle4 completed
> > 
> > Swift Script local-noks.swift ended at Mon Nov 5 18:32:34 CST 2007 with 
> > exit code 0
> > 
> > 
> > UC64$ head awf*.log
> > 2007-11-05 18:31:09,566-0600 INFO  Loader awf6.swift: source file is 
> > new. Recompiling.
> > 2007-11-05 18:31:30,454-0600 INFO  Karajan Validation of XML 
> > intermediate file was successful
> > 2007-11-05 18:31:55,465-0600 INFO  unknown Using sites file: ./sites.xml
> > 2007-11-05 18:31:55,466-0600 INFO  unknown Using tc.data: ./tc.data
> > 2007-11-05 18:32:05,518-0600 INFO  unknown Swift v0.3-dev r1456
> > 
> > 2007-11-05 18:32:05,520-0600 INFO  unknown RunID: 20071105-1831-d7t5l2n3
> > 2007-11-05 18:32:06,701-0600 INFO  AbstractDataNode Found data 
> > pcapfiles.$[]/1.[0]
> > 2007-11-05 18:32:06,702-0600 INFO  AbstractDataNode Found data 
> > pcapfiles.$[]/2.[1]
> > 2007-11-05 18:32:06,702-0600 INFO  AbstractDataNode Found data 
> > pcapfiles.$[]/3.[2]
> > UC64$
> > _______________________________________________
> > Swift-devel mailing list
> > Swift-devel at ci.uchicago.edu
> > http://mail.ci.uchicago.edu/mailman/listinfo/swift-devel
> > 
> > 
> _______________________________________________
> Swift-devel mailing list
> Swift-devel at ci.uchicago.edu
> http://mail.ci.uchicago.edu/mailman/listinfo/swift-devel
>

More information about the Swift-devel mailing list