open-vsx.org outage 2022/10/14
See https://github.com/EclipseFdn/open-vsx.org/issues/1296
Logs in pods
2022-10-14 06:52:30.001 WARN 1 --- [taskScheduler-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null
2022-10-14 06:52:30.001 ERROR 1 --- [taskScheduler-1] o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms.
2022-10-14 06:52:30.002 ERROR 1 --- [taskScheduler-1] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:467) ~[spring-orm-5.3.1.jar:5.3.1]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.1.jar:5.3.1]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.1.jar:5.3.1]
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:137) ~[spring-tx-5.3.1.jar:5.3.1]
at org.springframework.session.jdbc.JdbcIndexedSessionRepository.cleanUpExpiredSessions(JdbcIndexedSessionRepository.java:556) ~[spring-session-jdbc-2.4.1.jar:2.4.1]
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.1.jar:5.3.1]
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95) ~[spring-context-5.3.1.jar:5.3.1]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:273) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:281) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.1.jar:5.3.1]
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.1.jar:5.3.1]
... 12 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
... 19 common frames omitted
2022-10-14 06:52:33.339 WARN 1 --- [ Timer-0] o.j.storage.AbstractStorageProvider : Error notifying JobStorageChangeListeners
org.jobrunr.storage.StorageException: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.getJobStats(DefaultSqlStorageProvider.java:346) ~[jobrunr-5.1.2.jar:5.1.2]
at org.jobrunr.storage.AbstractStorageProvider.notifyJobStatsOnChangeListeners(AbstractStorageProvider.java:73) ~[jobrunr-5.1.2.jar:5.1.2]
at org.jobrunr.storage.AbstractStorageProvider$NotifyOnChangeListeners.run(AbstractStorageProvider.java:177) ~[jobrunr-5.1.2.jar:5.1.2]
at java.base/java.util.TimerThread.mainLoop(Timer.java:556) ~[na:na]
at java.base/java.util.TimerThread.run(Timer.java:506) ~[na:na]
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.getJobStats(DefaultSqlStorageProvider.java:343) ~[jobrunr-5.1.2.jar:5.1.2]
... 4 common frames omitted
2022-10-14 06:53:03.339 WARN 1 --- [ Timer-0] o.j.storage.AbstractStorageProvider : Error notifying JobStorageChangeListeners
org.jobrunr.storage.StorageException: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.getJobStats(DefaultSqlStorageProvider.java:346) ~[jobrunr-5.1.2.jar:5.1.2]
at org.jobrunr.storage.AbstractStorageProvider.notifyJobStatsOnChangeListeners(AbstractStorageProvider.java:73) ~[jobrunr-5.1.2.jar:5.1.2]
at org.jobrunr.storage.AbstractStorageProvider$NotifyOnChangeListeners.run(AbstractStorageProvider.java:177) ~[jobrunr-5.1.2.jar:5.1.2]
at java.base/java.util.TimerThread.mainLoop(Timer.java:556) ~[na:na]
at java.base/java.util.TimerThread.run(Timer.java:506) ~[na:na]
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.getJobStats(DefaultSqlStorageProvider.java:343) ~[jobrunr-5.1.2.jar:5.1.2]
... 4 common frames omittedload average on postgres is low: 0.02, 0.12, 0.18
I see a high time for rcu_sched, may be related?
11 root 20 0 0 0 0 I 0.0 0.0 595:55.83 rcu_schedI installed iotop-c (with yum --disablerepo appstream --disablerepo baseos install iotop, had to disable some repos because of error Failed to download metadata for repo 'appstream': Cannot prepare internal mirrorlist: No URLs in mirrorlist)
There was basically no io:
4166808 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.08 % ⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⡀⣀⢀⢀⢀⢀⢀⢀⢀⢀⢀⢀⢀⢀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ kworker/14:0-events ▲
4188412 be/7 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⢠⣄⣄⡀⠀⡀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ mandb █
4188023 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⡀⠀⠀⠀⠀⠀⠀⢀⠀⠀⠀⠀⠀⠀⢠⠀⠀⠀⠀⠀⠀⢀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ postgres: openvsx-staging-rw openvsx-staging 172.30.50.27(36084) idle █
1224 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⢀⢀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ postgres: checkpointer ▃
1226 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⢀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ postgres: walwriter
4187667 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⢀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ kworker/u256:0-events_unbound
769 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⢀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ xfsaild/dm-0
4108612 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ kworker/2:1-mm_percpu_wq
4187496 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ kworker/7:1-mm_percpu_wq
1 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % ⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ systemd