Skip to content

postgres--seems hang during generating sql #777

Closed
Closed
postgres--seems hang during generating sql#777

Description

@showonlady
showonlady
opened on Apr 10, 2023

during running sqlancer on postgresql, the number of executed queries didn't increase any more after some time.

[2023/04/10 13:18:46] Executed 42691 queries (7 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:18:51] Executed 42727 queries (7 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:18:56] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:01] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:06] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:11] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:16] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:21] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:26] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:31] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:36] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:41] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:46] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.
[2023/04/10 13:19:51] Executed 42727 queries (0 queries/s; 0.00/s dbs, successful statements: 93%). Threads shut down: 0.

I had checked the db, there was not any more query running. The jstack looked like as the following

chqin@CHUNLINGQIN-MB0 ~ % jstack 84426    
2023-04-10 14:04:12
Full thread dump OpenJDK 64-Bit Server VM (16.0.1+9-24 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007f99f785d7e0, length=15, elements={
0x00007f99f7008200, 0x00007f99f70f8000, 0x00007f99f70fa800, 0x00007f99f801aa00,
0x00007f99f600c600, 0x00007f99f600cc00, 0x00007f99f600d200, 0x00007f99f600d800,
0x00007f99f600de00, 0x00007f99f600e400, 0x00007f99f70fd800, 0x00007f99f801a400,
0x00007f99f800fc00, 0x00007f99f8821e00, 0x00007f99ff021400
}

"main" #1 prio=5 os_prio=31 cpu=352.12ms elapsed=10566.31s tid=0x00007f99f7008200 nid=0x1703 waiting on condition  [0x0000700000224000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@16.0.1/Native Method)
	- parking to wait for  <0x0000000700000180> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@16.0.1/LockSupport.java:252)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@16.0.1/AbstractQueuedSynchronizer.java:1661)
	at java.util.concurrent.ThreadPoolExecutor.awaitTermination(java.base@16.0.1/ThreadPoolExecutor.java:1456)
	at sqlancer.Main.executeMain(Main.java:538)
	at sqlancer.Main.main(Main.java:263)

"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.65ms elapsed=10566.29s tid=0x00007f99f70f8000 nid=0x4003 waiting on condition  [0x0000700000939000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@16.0.1/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@16.0.1/Reference.java:243)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@16.0.1/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.37ms elapsed=10566.29s tid=0x00007f99f70fa800 nid=0x3e03 in Object.wait()  [0x0000700000a3c000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@16.0.1/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@16.0.1/ReferenceQueue.java:155)
	- locked <0x0000000700001df8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@16.0.1/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@16.0.1/Finalizer.java:171)

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=0.21ms elapsed=10566.28s tid=0x00007f99f801aa00 nid=0xa603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=31 cpu=6.83ms elapsed=10566.28s tid=0x00007f99f600c600 nid=0xa403 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=31 cpu=248.95ms elapsed=10566.28s tid=0x00007f99f600cc00 nid=0xa303 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=31 cpu=8525.43ms elapsed=10566.28s tid=0x00007f99f600d200 nid=0x5803 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #10 daemon prio=9 os_prio=31 cpu=1017.59ms elapsed=10566.28s tid=0x00007f99f600d800 nid=0x5a03 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #11 daemon prio=9 os_prio=31 cpu=15.93ms elapsed=10566.28s tid=0x00007f99f600de00 nid=0x5c03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Notification Thread" #12 daemon prio=9 os_prio=31 cpu=0.04ms elapsed=10566.28s tid=0x00007f99f600e400 nid=0x5e03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #13 daemon prio=8 os_prio=31 cpu=8.60ms elapsed=10566.28s tid=0x00007f99f70fd800 nid=0x6103 in Object.wait()  [0x000070000145d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@16.0.1/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@16.0.1/ReferenceQueue.java:155)
	- locked <0x0000000700000ca0> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@16.0.1/CleanerImpl.java:140)
	at java.lang.Thread.run(java.base@16.0.1/Thread.java:831)
	at jdk.internal.misc.InnocuousThread.run(java.base@16.0.1/InnocuousThread.java:134)

"pool-1-thread-1" #14 prio=5 os_prio=31 cpu=491.86ms elapsed=10566.14s tid=0x00007f99f801a400 nid=0xa003 waiting on condition  [0x0000700001560000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@16.0.1/Native Method)
	- parking to wait for  <0x0000000700002608> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@16.0.1/LockSupport.java:252)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@16.0.1/AbstractQueuedSynchronizer.java:1661)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@16.0.1/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@16.0.1/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@16.0.1/ThreadPoolExecutor.java:1056)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@16.0.1/ThreadPoolExecutor.java:1116)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@16.0.1/ThreadPoolExecutor.java:630)
	at java.lang.Thread.run(java.base@16.0.1/Thread.java:831)

"mysql-cj-abandoned-connection-cleanup" #16 daemon prio=5 os_prio=31 cpu=196.62ms elapsed=10566.08s tid=0x00007f99f800fc00 nid=0x9e03 in Object.wait()  [0x0000700001663000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@16.0.1/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@16.0.1/ReferenceQueue.java:155)
	- locked <0x00000007000014a0> (a java.lang.ref.ReferenceQueue$Lock)
	at com.mysql.cj.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:91)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@16.0.1/ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@16.0.1/ThreadPoolExecutor.java:630)
	at java.lang.Thread.run(java.base@16.0.1/Thread.java:831)

"database0" #17 prio=5 os_prio=31 cpu=40815.50ms elapsed=10564.23s tid=0x00007f99f8821e00 nid=0x6303 runnable  [0x0000700001766000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.SocketDispatcher.read0(java.base@16.0.1/Native Method)
	at sun.nio.ch.SocketDispatcher.read(java.base@16.0.1/SocketDispatcher.java:47)
	at sun.nio.ch.NioSocketImpl.tryRead(java.base@16.0.1/NioSocketImpl.java:261)
	at sun.nio.ch.NioSocketImpl.implRead(java.base@16.0.1/NioSocketImpl.java:312)
	at sun.nio.ch.NioSocketImpl.read(java.base@16.0.1/NioSocketImpl.java:350)
	at sun.nio.ch.NioSocketImpl$1.read(java.base@16.0.1/NioSocketImpl.java:803)
	at java.net.Socket$SocketInputStream.read(java.base@16.0.1/Socket.java:976)
	at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
	at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
	at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)
	at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:450)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2118)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:354)
	- locked <0x00000007066020a8> (a org.postgresql.core.v3.QueryExecutorImpl)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:484)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:404)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:325)
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:311)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:287)
	at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:239)
	at sqlancer.postgres.PostgresSchema$PostgresTables.getRandomRowValue(PostgresSchema.java:77)
	at sqlancer.postgres.oracle.PostgresPivotedQuerySynthesisOracle.getRectifiedQuery(PostgresPivotedQuerySynthesisOracle.java:47)
	at sqlancer.postgres.oracle.PostgresPivotedQuerySynthesisOracle.getRectifiedQuery(PostgresPivotedQuerySynthesisOracle.java:1)
	at sqlancer.common.oracle.PivotedQuerySynthesisBase.check(PivotedQuerySynthesisBase.java:39)
	at sqlancer.ProviderAdapter.generateAndTestDatabase(ProviderAdapter.java:49)
	at sqlancer.Main$DBMSExecutor.run(Main.java:327)
	at sqlancer.Main$2.run(Main.java:511)
	at sqlancer.Main$2.runThread(Main.java:489)
	at sqlancer.Main$2.run(Main.java:479)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@16.0.1/ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@16.0.1/ThreadPoolExecutor.java:630)
	at java.lang.Thread.run(java.base@16.0.1/Thread.java:831)

"Attach Listener" #18 daemon prio=9 os_prio=31 cpu=0.59ms elapsed=0.10s tid=0x00007f99ff021400 nid=0x6803 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=31 cpu=287.51ms elapsed=10566.30s tid=0x00007f99f790ea80 nid=0x4203 runnable  

"GC Thread#0" os_prio=31 cpu=32.62ms elapsed=10566.31s tid=0x00007f99f5c155a0 nid=0x5003 runnable  

"GC Thread#1" os_prio=31 cpu=33.20ms elapsed=10533.20s tid=0x00007f99f794dcb0 nid=0xa90b runnable  

"GC Thread#2" os_prio=31 cpu=31.58ms elapsed=10533.20s tid=0x00007f99f78586c0 nid=0x6503 runnable  

"GC Thread#3" os_prio=31 cpu=31.90ms elapsed=10533.20s tid=0x00007f99f7859100 nid=0x9b03 runnable  

"GC Thread#4" os_prio=31 cpu=31.64ms elapsed=10533.20s tid=0x00007f99f9f29920 nid=0x9903 runnable  

"GC Thread#5" os_prio=31 cpu=33.20ms elapsed=10533.20s tid=0x00007f99f7859b70 nid=0x9703 runnable  

"G1 Main Marker" os_prio=31 cpu=0.03ms elapsed=10566.31s tid=0x00007f99f5c16500 nid=0x4e03 runnable  

"G1 Conc#0" os_prio=31 cpu=0.02ms elapsed=10566.31s tid=0x00007f99f5c173e0 nid=0x3403 runnable  

"G1 Refine#0" os_prio=31 cpu=0.04ms elapsed=10566.31s tid=0x00007f99f5c34650 nid=0x4903 runnable  

"G1 Service" os_prio=31 cpu=1811.35ms elapsed=10566.31s tid=0x00007f99f5c354e0 nid=0x4703 runnable  

"VM Periodic Task Thread" os_prio=31 cpu=5479.99ms elapsed=10566.28s tid=0x00007f99f5c3e0e0 nid=0x5f03 waiting on condition  

JNI global refs: 14, weak refs: 0

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions