After update to v7.x CPU is loaded on 100% (OD-711)

After update to v7.x CPU is loaded on 100% #711

Kruzya opened 4 years ago

After update to v7.0.3, my OneDev installation started load CPU to 100%. Also response time is greatly increased (i can wait load index page (with projects) 2 minutes).

I tried yesterday update to v7.1.2, but this don't helped. My environment:

Home server with 4 CPUs cores (or 8 with HyperThreading)
OneDev is running in Docker on host with 2 vCPU and 1GB RAM
PostgreSQL is placed on same server, but in another virtual machine with 6 vCPUs and 2GB RAM

OneDev VM:

PostgreSQL VM:

Also when this problem started, i see this error periodically:

05:27:29 ERROR o.a.w.p.w.a.AbstractWebSocketProcessor - An error occurred during processing of a WebSocket message
java.lang.IllegalStateException: This time is in the future
        at org.apache.wicket.util.time.Time.elapsedSince(Time.java:262)
        at org.apache.wicket.page.PageAccessSynchronizer.lockPage(PageAccessSynchronizer.java:108)
        at org.apache.wicket.page.PageAccessSynchronizer$2.getPage(PageAccessSynchronizer.java:245)
        at org.apache.wicket.protocol.ws.api.AbstractWebSocketProcessor.getPage(AbstractWebSocketProcessor.java:336)
        at org.apache.wicket.protocol.ws.api.AbstractWebSocketProcessor.broadcastMessage(AbstractWebSocketProcessor.java:250)
        at org.apache.wicket.protocol.ws.api.AbstractWebSocketProcessor.onConnect(AbstractWebSocketProcessor.java:186)
        at io.onedev.server.web.websocket.WebSocketProcessor.access$200(WebSocketProcessor.java:43)
        at io.onedev.server.web.websocket.WebSocketProcessor$1.run(WebSocketProcessor.java:74)
        at io.onedev.server.persistence.DefaultSessionManager$2.call(DefaultSessionManager.java:100)
        at io.onedev.server.persistence.DefaultSessionManager$2.call(DefaultSessionManager.java:96)
        at io.onedev.server.persistence.DefaultSessionManager.call(DefaultSessionManager.java:79)
        at io.onedev.server.persistence.DefaultSessionManager.run(DefaultSessionManager.java:96)
        at io.onedev.server.web.websocket.WebSocketProcessor.run(WebSocketProcessor.java:86)
        at io.onedev.server.web.websocket.WebSocketProcessor.onWebSocketConnect(WebSocketProcessor.java:68)
        at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onConnect(JettyListenerEventDriver.java:159)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.openSession(AbstractEventDriver.java:217)
        at org.eclipse.jetty.websocket.common.WebSocketSession.open(WebSocketSession.java:493)
        at org.eclipse.jetty.websocket.common.WebSocketSession.onOpened(WebSocketSession.java:459)
        at org.eclipse.jetty.io.AbstractConnection.onOpened(AbstractConnection.java:213)
        at org.eclipse.jetty.io.AbstractConnection.onOpen(AbstractConnection.java:205)
        at org.eclipse.jetty.io.AbstractEndPoint.upgrade(AbstractEndPoint.java:444)
        at org.eclipse.jetty.server.HttpConnection.onCompleted(HttpConnection.java:407)
        at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:820)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:368)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
        at java.lang.Thread.run(Thread.java:748)

Time on servers is set correctly.

Copy

Robin Shen commented 4 years ago
Please increase the memory to 2G to see if it works. If CPU is still 100%, please login to the docker container and get the stack trace by running:

jstack <QB JVM process id>

Copy
Kruzya commented 4 years ago

Increased RAM to 2GB, restarted VM and looks like it not helped. CPU continue be loaded on 100%, but i noticed strange behavior: before any request to web, OneDev loads only one CPU core. When i try perform request, it starts load 2 CPU core.

Found java in /usr/bin, but don't see jstack. Can i run from host OS or I need download jstack in Docker container?

Copy
Robin Shen commented 4 years ago
My mistake. jstack is not available in onedev image, please login to the container and install openjdk to get jstack:

apt update apt install openjdk-8-jdk

This command needs to run inside container.

Copy
Kruzya commented 4 years ago

https://pastebin.com/2WfQV7ii

Uploaded to Pastebin. It does not fit here by the number of characters

Copy
Robin Shen commented 4 years ago

This is a bug of Hibernate library used by OneDev: https://hibernate.atlassian.net/browse/HHH-13664

To solve the issue, please make sure the system time is not set back in the past.

Copy
Kruzya commented 4 years ago

As I said previously, my time is set correctly. But on VMs set different time zones: on VM with PostgreSQL set my real timezone (GMT+4), on VM with OneDev - UTC. Different timezones may be the reason of this behavior?

I will try change timezone on VM with OneDev. Looks like it helped: OneDev stopped loading CPU on 100% since start. Solved 🤦

Copy
Kruzya commented 4 years ago

As I understand, OneDev writes current time in DB via PostgreSQL functions, which return the current time according to the timezone. It is possible use UTC time in this cases and allow admin set required for displaying timezone in options?

Copy
Robin Shen commented 4 years ago

I guess you want to show time in your local timezone? If so, please watch this issue:

https://code.onedev.io/projects/160/issues/639

Copy
OneDev changed state to 'Closed' 4 years ago
Previous Value Current Value
Open

Closed
OneDev commented 4 years ago

State changed as code fixing the issue is committed

Copy
OneDev changed state to 'Released' 4 years ago
Previous Value Current Value
Closed

Released
OneDev commented 4 years ago

State changed as build #2645 is successful

Copy
Robin Shen commented 4 years ago

The 7.1.4 version should work fine even if you are using different timezone for OneDev.

Copy
Kruzya commented 4 years ago

Yes, it fixed, thanks!

Copy
Login to comment

Previous Value	Current Value
Open	Closed

Previous Value	Current Value
Closed	Released

Type	Bug
Priority	Normal
Assignee	Robin Shen

Issue Votes (1)

Watchers (4)

Reference

OD-711