Quantcast

timing out tests

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

timing out tests

Radim Kubacki
We have a few tests that are failing sporadically due to some timeouts:
ToolingApiLoggingCrossVersionSpec."logging is live" is one of them.
CancellingDaemonIntegrationSpec."cancels correct build" seem to fall into this category too.

They fail more often on our Windows CI box and the failure are usual when there is higher CPU load. I added debug logging to see where the time is spent and here are some numbers (based on http://builds.gradle.org/viewLog.html?buildId=112016&tab=buildResultsDiv&buildTypeId=Gradle_Master_Coverage_WindowsJava18#testNameId1103271250747874825)

Output starts at 22:05:08.897 and there will be some time before to spawn the process.
Daemon setup ends at with '22:05:10.892 [INFO] [
org.gradle.launcher.daemon.server.exec.ExecuteBuild] Executing build with daemon context...'
Then there is a gap 1.5s before '22:05:12.333 [INFO] [org.gradle.BuildLogger] Starting Build'

Next chunk is '22:05:13.051 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.669 secs'

Another 1+s to get lock and write build script to a cache - 22:05:14.344 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\buildscript\classes took: 0.48 secs

3.5s to compile the build script is a biggest part - 22:05:17.864 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\no_buildscript\classes took: 3.482 secs

Task is executed soon after (22:05:18.253 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter] Executing actions for task ':t1'.) but it is too late for the test that has 10secs timeout to read output from the test.

My questions:
Can we make the test faster? Like adding empty settings.gradle? Can we speed up script compilation? Do we know what is happening before '[org.gradle.BuildLogger] Starting Build'?

Of course I can increase the timeout but before that I'd like to see why it is not sufficient in some cases.

-Radim



Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: timing out tests

Radim Kubacki
More observations:
I've tried this today with my Windows and it seems that there is a big difference between maxParallelForks 3 and 4. The test consistently passes with 3 is lower value on my VMWare box with 6GB RAM and 2 CPUs. It also consistently fails with maxParallelForks=4. I know that our Windows machines and much better hardware but it seems that especially :launcher:integTest starts a lot of processes and probably hits some I/O threshold where things get noticeably slower. Reducing the throughput at this level seems better/more reliable to me than increasing various timeouts.

My suggestion is to reduce maxParallelForks to 3. Possibly we can do it only for :launcher (and perhaps :toolingApi) where we have these tests that run multiple child processes per test. Other subprojects can live with current settings at the moment. Opinions?

-Radim


On Sun, Jul 20, 2014 at 9:29 PM, Radim Kubacki <[hidden email]> wrote:
We have a few tests that are failing sporadically due to some timeouts:
ToolingApiLoggingCrossVersionSpec."logging is live" is one of them.
CancellingDaemonIntegrationSpec."cancels correct build" seem to fall into this category too.

They fail more often on our Windows CI box and the failure are usual when there is higher CPU load. I added debug logging to see where the time is spent and here are some numbers (based on http://builds.gradle.org/viewLog.html?buildId=112016&tab=buildResultsDiv&buildTypeId=Gradle_Master_Coverage_WindowsJava18#testNameId1103271250747874825)

Output starts at 22:05:08.897 and there will be some time before to spawn the process.
Daemon setup ends at with '22:05:10.892 [INFO] [
org.gradle.launcher.daemon.server.exec.ExecuteBuild] Executing build with daemon context...'
Then there is a gap 1.5s before '22:05:12.333 [INFO] [org.gradle.BuildLogger] Starting Build'

Next chunk is '22:05:13.051 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.669 secs'

Another 1+s to get lock and write build script to a cache - 22:05:14.344 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\buildscript\classes took: 0.48 secs

3.5s to compile the build script is a biggest part - 22:05:17.864 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\no_buildscript\classes took: 3.482 secs

Task is executed soon after (22:05:18.253 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter] Executing actions for task ':t1'.) but it is too late for the test that has 10secs timeout to read output from the test.

My questions:
Can we make the test faster? Like adding empty settings.gradle? Can we speed up script compilation? Do we know what is happening before '[org.gradle.BuildLogger] Starting Build'?

Of course I can increase the timeout but before that I'd like to see why it is not sufficient in some cases.

-Radim




Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: timing out tests

Luke Daley-2
+1 to reducing maxParallelForks.

On 22 July 2014 at 12:28:24 am, Radim Kubacki ([hidden email]) wrote:

More observations:
I've tried this today with my Windows and it seems that there is a big difference between maxParallelForks 3 and 4. The test consistently passes with 3 is lower value on my VMWare box with 6GB RAM and 2 CPUs. It also consistently fails with maxParallelForks=4. I know that our Windows machines and much better hardware but it seems that especially :launcher:integTest starts a lot of processes and probably hits some I/O threshold where things get noticeably slower. Reducing the throughput at this level seems better/more reliable to me than increasing various timeouts.

My suggestion is to reduce maxParallelForks to 3. Possibly we can do it only for :launcher (and perhaps :toolingApi) where we have these tests that run multiple child processes per test. Other subprojects can live with current settings at the moment. Opinions?

-Radim


On Sun, Jul 20, 2014 at 9:29 PM, Radim Kubacki <[hidden email]> wrote:
We have a few tests that are failing sporadically due to some timeouts:
ToolingApiLoggingCrossVersionSpec."logging is live" is one of them.
CancellingDaemonIntegrationSpec."cancels correct build" seem to fall into this category too.

They fail more often on our Windows CI box and the failure are usual when there is higher CPU load. I added debug logging to see where the time is spent and here are some numbers (based on http://builds.gradle.org/viewLog.html?buildId=112016&tab=buildResultsDiv&buildTypeId=Gradle_Master_Coverage_WindowsJava18#testNameId1103271250747874825)

Output starts at 22:05:08.897 and there will be some time before to spawn the process.
Daemon setup ends at with '22:05:10.892 [INFO] [
org.gradle.launcher.daemon.server.exec.ExecuteBuild] Executing build with daemon context...'
Then there is a gap 1.5s before '22:05:12.333 [INFO] [org.gradle.BuildLogger] Starting Build'

Next chunk is '22:05:13.051 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.669 secs'

Another 1+s to get lock and write build script to a cache - 22:05:14.344 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\buildscript\classes took: 0.48 secs

3.5s to compile the build script is a biggest part - 22:05:17.864 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\no_buildscript\classes took: 3.482 secs

Task is executed soon after (22:05:18.253 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter] Executing actions for task ':t1'.) but it is too late for the test that has 10secs timeout to read output from the test.

My questions:
Can we make the test faster? Like adding empty settings.gradle? Can we speed up script compilation? Do we know what is happening before '[org.gradle.BuildLogger] Starting Build'?

Of course I can increase the timeout but before that I'd like to see why it is not sufficient in some cases.

-Radim




Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: timing out tests

Daz DeBoer-2
We need to stabilise the tests. If reducing the parallel forks does this, then we should.


On Mon, Jul 21, 2014 at 4:41 PM, Luke Daley <[hidden email]> wrote:
+1 to reducing maxParallelForks.

On 22 July 2014 at 12:28:24 am, Radim Kubacki ([hidden email]) wrote:

More observations:
I've tried this today with my Windows and it seems that there is a big difference between maxParallelForks 3 and 4. The test consistently passes with 3 is lower value on my VMWare box with 6GB RAM and 2 CPUs. It also consistently fails with maxParallelForks=4. I know that our Windows machines and much better hardware but it seems that especially :launcher:integTest starts a lot of processes and probably hits some I/O threshold where things get noticeably slower. Reducing the throughput at this level seems better/more reliable to me than increasing various timeouts.

My suggestion is to reduce maxParallelForks to 3. Possibly we can do it only for :launcher (and perhaps :toolingApi) where we have these tests that run multiple child processes per test. Other subprojects can live with current settings at the moment. Opinions?

-Radim


On Sun, Jul 20, 2014 at 9:29 PM, Radim Kubacki <[hidden email]> wrote:
We have a few tests that are failing sporadically due to some timeouts:
ToolingApiLoggingCrossVersionSpec."logging is live" is one of them.
CancellingDaemonIntegrationSpec."cancels correct build" seem to fall into this category too.

They fail more often on our Windows CI box and the failure are usual when there is higher CPU load. I added debug logging to see where the time is spent and here are some numbers (based on http://builds.gradle.org/viewLog.html?buildId=112016&tab=buildResultsDiv&buildTypeId=Gradle_Master_Coverage_WindowsJava18#testNameId1103271250747874825)

Output starts at 22:05:08.897 and there will be some time before to spawn the process.
Daemon setup ends at with '22:05:10.892 [INFO] [
org.gradle.launcher.daemon.server.exec.ExecuteBuild] Executing build with daemon context...'
Then there is a gap 1.5s before '22:05:12.333 [INFO] [org.gradle.BuildLogger] Starting Build'

Next chunk is '22:05:13.051 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.669 secs'

Another 1+s to get lock and write build script to a cache - 22:05:14.344 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\buildscript\classes took: 0.48 secs

3.5s to compile the build script is a biggest part - 22:05:17.864 [DEBUG] [org.gradle.groovy.scripts.internal.DefaultScriptCompilationHandler] Timing: Writing script to cache at C:\tcagent2\work\2d33fa4c6d642769\intTestHomeDir\worker-1\caches\2.1-20140719192339+0000\scripts\build_td6v684jmvp2dj2md0b4vs8dr\ProjectScript\no_buildscript\classes took: 3.482 secs

Task is executed soon after (22:05:18.253 [DEBUG] [org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter] Executing actions for task ':t1'.) but it is too late for the test that has 10secs timeout to read output from the test.

My questions:
Can we make the test faster? Like adding empty settings.gradle? Can we speed up script compilation? Do we know what is happening before '[org.gradle.BuildLogger] Starting Build'?

Of course I can increase the timeout but before that I'd like to see why it is not sufficient in some cases.

-Radim







--
Darrell (Daz) DeBoer
Loading...