Long delay until starting build on agent

Answered

Hi, 

there's a ~ 2-3 minute delay until build is started on agent. There's this message in build log:

"The build is removed from the queue to be prepared for the start"

Then couple minutes later it continues with the build:

"Starting the build on the agent "...""

 

The same same situation happens with all agents, both linux and windows, agents seem to be idle during that period. Any ideas how this can be improved?

6 comments
Comment actions Permalink

Hi,

Can you post more details of your build log? Generally speaking, there are some tasks that need to happen before the build can start. You should see some information between `The build is removed from the queue to be prepared for the start` and `Starting the build on the agent`, such as `Collecting changes in n VCS roots`. 

Thanks,

Eric

0
Comment actions Permalink
Hi, 
 
I've created an empty build, with no VCS and tried looking at verbose build log, but not much useful info there:
 
11:37:58 TeamCity server version is 2020.2 (build 85487)
11:37:58 The build is removed from the queue to be prepared for the start
11:40:05 Starting the build on the agent "[...]"
11:40:05 Agent time zone: GMT
11:40:06 Agent is running under JRE: 1.8.0_282-b08
 
Is there any other way I could extract more logs?
 
Thanks,
Justinas
0
Comment actions Permalink

You can download the full build log from the build results page. There may be some additional information found in that log, but not always. Click on the "Download Full Build Log" link as shown below:

It may also be worth looking in the teamcity-server.log for more information. This can be found at <teamcity home directory>/logs/teamcity-server.log. I have sometimes seen some third-party plugins slow down this process. If you're using any third-party plugins, you could try disabling them to see if there is any effect on build start time.

0
Comment actions Permalink

I have a similar problem. Here is an excerpt from my downloaded logs:

[17:26:23]E: bt275 (running for 9m:51s)
[17:26:23]i: TeamCity server version is 10.0.4 (build 42538)
[17:26:23] : Finalize build settings
[17:26:28] : The build is removed from the queue to be prepared for the start
[17:35:55] : Collecting changes in 2 VCS roots (1s)
[17:35:55] :     [Collecting changes in 2 VCS roots] VCS Root details

There is a ~ 10 minutes constant delay before collecting changes starts.

There is a similar delay at the end:

[17:36:00] : Publishing internal artifacts
[17:36:00] :     [Publishing internal artifacts] Publishing 1 file using [WebPublisher]
[17:36:00] :     [Publishing internal artifacts] Publishing 1 file using [ArtifactsCachePublisher]
[17:45:27] : Build finished

I can't find more helpful logs. 

0
Comment actions Permalink

Found that the delays are caused by cleaning file system:

[2022-03-02 17:25:13,337]   INFO - dDirectoryBasedCleanupRegistry - Removing files from /data/cloud/TeamCityAgents/agent/temp/.old 
[2022-03-02 17:27:50,616]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestDirectoryStructureFast" {id = 25} 
[2022-03-02 17:27:52,760]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestFile" {id = 26} 
[2022-03-02 17:28:06,440]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestDirectoryStructureFast" {id = 27} 
[2022-03-02 17:28:08,690]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestFile" {id = 28} 
[2022-03-02 17:28:23,398]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestDirectoryStructureFast" {id = 29} 
[2022-03-02 17:28:25,503]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestFile" {id = 30} 
[2022-03-02 17:28:27,413]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestDirectoryStructureFast" {id = 31} 
[2022-03-02 17:28:36,771]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestFile" {id = 32} 
[2022-03-02 17:28:45,641]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "agentFileManager.requestDirectoryStructureFast" {id = 33} 
[2022-03-02 17:30:13,318]   INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds 

[...]

[2022-03-02 17:30:13,338]   INFO - dDirectoryBasedCleanupRegistry - Removing files from /data/cloud/TeamCityAgents/agent/temp/.old 
[2022-03-02 17:35:13,318]   INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds 

[...]

[2022-03-02 17:36:02,251]   INFO -    jetbrains.buildServer.AGENT - Updating agent parameters on the server: AgentDetails{Name='builder6.xx.com', [...] 
[2022-03-02 17:41:00,862]   INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds 

 [...]

[2022-03-02 17:41:00,885]   INFO - dDirectoryBasedCleanupRegistry - Removing files from /data/cloud/TeamCityAgents/agent/temp/.old 
[2022-03-02 17:46:00,862]   INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds 

 

0
Comment actions Permalink

Issue was caused by plugins. Was not trivial to find. Logs were not in the agent's logs, but TeamCity's main logs.

0

Please sign in to leave a comment.