Gocd elastic agent takes upto 90 sec to complete the bootstrap in many
cases. we are using k8s elastic agent in gocd.
- after starting to search for high bootstrap time i found out the main
culprit was pluing loader. it aws loading plugin sequentially. so after
removing plugin which we don't need, i was able to bring bootup time to 36
second.
```
jvm 1 | 2022-02-07 16:27:31,128 [stdout] - 2022-02-07 16:27:31,127 INFO
[main] DefaultPluginJarChangeListener:67 - Plugin load starting:
/go/plugins/external/github_feature_branch.jar
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - 2022-02-07 16:27:34,773 ERROR
[scheduler-3] RemotingClient:166 - Server responded to action `ping` with:
status[422 Unprocessable Entity], body[{
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - "message" : "Agent [Agent
[prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86,
226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set; nested
exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e,
10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set"
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - }]
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - 2022-02-07 16:27:34,773 ERROR
[scheduler-3] AgentHTTPClientController:114 - Error occurred when agent
tried to ping server:
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - java.lang.RuntimeException:
org.apache.http.client.ClientProtocolException: The server returned status
code 422. Possible reasons include:
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - - This agent has been
deleted from the configuration
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - - This agent is pending
approval
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - - There is possibly a
reverse proxy (or load balancer) that has been misconfigured. See
https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
for details.
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:118)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
Source)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
Source)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
java.base/java.lang.reflect.Method.invoke(Unknown Source)
jvm 1 | 2022-02-07 16:27:34,774 [stdout] - at
org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
java.base/java.lang.Thread.run(Unknown Source)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - Caused by:
org.apache.http.client.ClientProtocolException: The server returned status
code 422. Possible reasons include:
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - - This agent has been
deleted from the configuration
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - - This agent is pending
approval
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - - There is possibly a
reverse proxy (or load balancer) that has been misconfigured. See
https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
for details.
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:114)
jvm 1 | 2022-02-07 16:27:34,775 [stdout] - ... 14 common frames
omitted
jvm 1 | 2022-02-07 16:27:35,544 [stdout] - 2022-02-07 16:27:35,544 INFO
[main] DefaultPluginJarChangeListener:74 - Plugin load finished:
/go/plugins/external/github_feature_branch.jar
jvm 1 | 2022-02-07 16:27:35,553 [stdout] - 2022-02-07 16:27:35,552 INFO
[main] DefaultPluginJarChangeListener:67 - Plugin load starting:
/go/plugins/external/git-path-material-plugin.jar
jvm 1 | 2022-02-07 16:27:35,674 [stdout] - 2022-02-07 16:27:35,674 INFO
[main] p.G.c.t.g.s.p.GitPathMaterialPlugin:72 [plugin-GitPathMaterial] -
Loading GitPathMaterialPlugin...
jvm 1 | 2022-02-07 16:27:39,782 [stdout] - 2022-02-07 16:27:39,781 ERROR
[scheduler-3] RemotingClient:166 - Server responded to action `ping` with:
status[422 Unprocessable Entity], body[{
jvm 1 | 2022-02-07 16:27:39,782 [stdout] - "message" : "Agent [Agent
[prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86,
226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set; nested
exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e,
10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set"
jvm 1 | 2022-02-07 16:27:39,782 [stdout] - }]
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - 2022-02-07 16:27:39,782 ERROR
[scheduler-3] AgentHTTPClientController:114 - Error occurred when agent
tried to ping server:
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - java.lang.RuntimeException:
org.apache.http.client.ClientProtocolException: The server returned status
code 422. Possible reasons include:
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - This agent has been
deleted from the configuration
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - This agent is pending
approval
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - There is possibly a
reverse proxy (or load balancer) that has been misconfigured. See
https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
for details.
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:118)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.lang.reflect.Method.invoke(Unknown Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
java.base/java.lang.Thread.run(Unknown Source)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - Caused by:
org.apache.http.client.ClientProtocolException: The server returned status
code 422. Possible reasons include:
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - This agent has been
deleted from the configuration
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - This agent is pending
approval
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - - There is possibly a
reverse proxy (or load balancer) that has been misconfigured. See
https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
for details.
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - at
com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:114)
jvm 1 | 2022-02-07 16:27:39,783 [stdout] - ... 14 common frames
omitted
jvm 1 | 2022-02-07 16:27:40,213 [stdout] - 2022-02-07 16:27:40,212 INFO
[main] DefaultPluginJarChangeListener:74 - Plugin load finished:
/go/plugins/external/git-path-material-plugin.jar
```
- after above steps there 2 log lines which had 10 sec gap each if we can
tune it, it can reduce the bootstrap time considerably.
1st one is
```
jvm 1 | 2022-02-07 16:26:47,893 INFO [WrapperJarAppMain]
DefaultAgentLauncherCreatorImpl:87 - Attempt No: 1 to cleanup launcher temp
files
jvm 1 | 2022-02-07 16:26:47,919 INFO [WrapperJarAppMain]
AgentBootstrapper:104 - Waiting for 10000 ms before re-launch....
jvm 1 | 2022-02-07 16:26:58,018 INFO [WrapperJarAppMain]
DefaultAgentLauncherCreatorImpl:67 - Attempting to load
com.thoughtworks.go.agent.launcher.AgentLauncherImpl as specified by
manifest key Go-Agent-Launcher-Class
```
i found out the system property which we can use to reduce this time. but
still haven't tried it
2nd one is
```
jvm 1 | 2022-02-07 16:27:40,230 [stdout] - 2022-02-07 16:27:40,230 INFO
[scheduler-1] AgentHTTPClientController:142 - Got cookie:
2df451e8-a5fb-4d9a-b8e2-e38efb52b27f
jvm 1 | 2022-02-07 16:27:50,362 [stdout] - 2022-02-07 16:27:50,361 INFO
[scheduler-1] HttpService:125 - Got back 200 from server
```
i couldn't find out as to why there is this 10 sec gap. so reason of this
ticket to understand this 10 sec wait time.
* Go Version: 21.3.0 (13067-4c4bb4780eb0d3fc4cacfc4cfcc0b07e2eaf0595)
--
You received this message because you are subscribed to the Google Groups
"go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/go-cd/17ea46f5-88c2-4ce8-9c05-4672cb5757e4n%40googlegroups.com.
