After update to v7.x CPU is loaded on 100% (OD-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.

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>
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?
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.
Kruzya commented 4 years ago

https://pastebin.com/2WfQV7ii

Uploaded to Pastebin. It does not fit here by the number of characters
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.
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 🤦
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?
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
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
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
Robin Shen commented 4 years ago

The 7.1.4 version should work fine even if you are using different timezone for OneDev.
Kruzya commented 4 years ago

Yes, it fixed, thanks!
Login to comment

Previous Value	Current Value
Open	Closed

Previous Value	Current Value
Closed	Released

Type	Bug
Priority	Normal
Assignee	Robin Shen
Affected Versions	Not Found

Issue Votes (1)

Watchers (4)

Reference

OD-711