Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[YSQL] Encountered Restart read required error when writing to YSQL keyvalue table #892

Closed
ajcaldera1 opened this issue Feb 22, 2019 · 3 comments
Closed

[YSQL] Encountered Restart read required error when writing to YSQL keyvalue table #892

ajcaldera1 opened this issue Feb 22, 2019 · 3 comments
Labels
kind/bug This issue is a bug

Comments

@ajcaldera1
Copy link
Contributor

ajcaldera1 commented Feb 22, 2019 •
edited
Loading

While using the sample_apps application with the SqlInserts workload with YB 1.1.15.0-b1, I encountered the following errors during the run:

[centos@ip-172-152-25-20 ac_benchmark]$ java -jar yb-sample-apps.jar --workload SqlInserts --nodes 172.152.16.114:5433 --num_threads_write 2 --num_threads_read 0 --num_unique_keys 1000000 --default_postgres_database postgres --create_table_name pgkeyvalue4 --nouuid
0 [main] INFO com.yugabyte.sample.Main  - Starting sample app...
8 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Using NO UUID
16 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - App: SqlInserts
16 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Run time (seconds): -1
16 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Adding node: 172.152.16.114:5433
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Num reader threads: 0, num writer threads: 2
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Create table name: pgkeyvalue4
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Default postgres database: postgres
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Num unique keys to insert: 1000000
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Num keys to update: -1000001
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Num keys to read: -1
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Value size: 0
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Restrict values to ASCII strings: false
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Perform sanity check at end of app run: false
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Table TTL (secs): -1
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Local reads: false
17 [main] INFO com.yugabyte.sample.common.CmdLineOpts  - Read only load: false
1389 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Checking for database existence...
1389 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Found database name postgres ...
1389 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Found database name ybdemo_database ...
1389 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Database ybdemo_database already exists
1389 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Database checking complete.
6836 [main] INFO com.yugabyte.sample.apps.SqlInserts  - Created table: pgkeyvalue4
10622 [Thread-2] FATAL com.yugabyte.sample.apps.SqlInserts  - Failed writing key: key:118
org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1550856891139494 logical: 22 } local_limit: { physical: 1550856891141410 logical: 10 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
	at com.yugabyte.sample.apps.SqlInserts.doWrite(SqlInserts.java:183)
	at com.yugabyte.sample.apps.AppBase.performWrite(AppBase.java:707)
	at com.yugabyte.sample.common.IOPSThread.run(IOPSThread.java:87)
10626 [Thread-2] FATAL com.yugabyte.sample.apps.SqlInserts  - Failed writing key: key:121
org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1550856891146251 logical: 8 } local_limit: { physical: 1550856891147755 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
	at com.yugabyte.sample.apps.SqlInserts.doWrite(SqlInserts.java:183)
	at com.yugabyte.sample.apps.AppBase.performWrite(AppBase.java:707)
	at com.yugabyte.sample.common.IOPSThread.run(IOPSThread.java:87)
11138 [Thread-3] FATAL com.yugabyte.sample.apps.SqlInserts  - Failed writing key: key:465
org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1550856891657751 } local_limit: { physical: 1550856891658975 logical: 1 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2433)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2178)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
	at com.yugabyte.sample.apps.SqlInserts.doWrite(SqlInserts.java:183)
	at com.yugabyte.sample.apps.AppBase.performWrite(AppBase.java:707)
	at com.yugabyte.sample.common.IOPSThread.run(IOPSThread.java:87)
11841 [Thread-1] INFO com.yugabyte.sample.common.metrics.MetricsTracker  - Read: 0.00 ops/sec (0.00 ms/op), 0 total ops  |  Write: 187.94 ops/sec (10.62 ms/op), 940 total ops  |  Uptime: 5004 ms |
16842 [Thread-1] INFO com.yugabyte.sample.common.metrics.MetricsTracker  - Read: 0.00 ops/sec (0.00 ms/op), 0 total ops  |  Write: 677.12 ops/sec (2.95 ms/op), 4327 total ops  |  Uptime: 10005 ms |
21843 [Thread-1] INFO com.yugabyte.sample.common.metrics.MetricsTracker  - Read: 0.00 ops/sec (0.00 ms/op), 0 total ops  |  Write: 682.71 ops/sec (2.93 ms/op), 7741 total ops  |  Uptime: 15006 ms |

After a while it did settle down, but as you add threads the error becomes more prominent.
@ajcaldera1 ajcaldera1 added the kind/bug This issue is a bug label Feb 22, 2019
@dobesv
Copy link

dobesv commented Aug 4, 2020

I get this error constantly when doing bulk upserts, I don't really understand what it means.

@ghost
Copy link

ghost commented Mar 23, 2021 •
edited by ghost
Loading

I am adding sqlancer support to yugabytedb. In this task, I am using multiple threads to create multiple databases. I found the following errors:

org.postgresql.util.PSQLException: ERROR: Operation failed. Try again.: Unknown transaction, could be recently aborted: 00f5b822-4667-4c20-ba76-6b22ceecac1e
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:261)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
	at sqlancer.Main$2.run(Main.java:508)
	at sqlancer.Main$2.runThread(Main.java:486)
	at sqlancer.Main$2.run(Main.java:476)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1616499917370712 } local_limit: { physical: 1616499917370712 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:258)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
	at sqlancer.Main$2.run(Main.java:508)
	at sqlancer.Main$2.runThread(Main.java:486)
	at sqlancer.Main$2.run(Main.java:476)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
--org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1616499917370712 } local_limit: { physical: 1616499917370712 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
--	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
--	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
--	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
--	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
--	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
--	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
--	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:258)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
--	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
--	at sqlancer.Main$2.run(Main.java:508)
--	at sqlancer.Main$2.runThread(Main.java:486)
--	at sqlancer.Main$2.run(Main.java:476)
--	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
--	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
--	at java.lang.Thread.run(Thread.java:748)
--
--org.postgresql.util.PSQLException: ERROR: Operation failed. Try again.: Unknown transaction, could be recently aborted: 00f5b822-4667-4c20-ba76-6b22ceecac1e
--	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
--	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
--	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
--	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
--	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
--	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
--	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:261)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
--	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
--	at sqlancer.Main$2.run(Main.java:508)
--	at sqlancer.Main$2.runThread(Main.java:486)
--	at sqlancer.Main$2.run(Main.java:476)
--	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
--	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
--	at java.lang.Thread.run(Thread.java:748)
--
-- Time: 2021/03/23 19:45:17
-- Database: database1
-- Database version: null
-- seed value: 1616499917093
\c test;
DROP DATABASE IF EXISTS database1;
CREATE DATABASE database1  TEMPLATE template0;

-- Time: 2021/03/23 19:45:17
-- Database: database2
-- Database version: null
-- seed value: 1616499917095
\c test;
DROP DATABASE IF EXISTS database2;
CREATE DATABASE database2 WITH ENCODING 'utf8'  TEMPLATE template0;

org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1616499918415218 } local_limit: { physical: 1616499918415218 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:258)
	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
	at sqlancer.Main$2.run(Main.java:508)
	at sqlancer.Main$2.runThread(Main.java:486)
	at sqlancer.Main$2.run(Main.java:476)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
--org.postgresql.util.PSQLException: ERROR: Query error: Restart read required at: { read: { physical: 1616499918415218 } local_limit: { physical: 1616499918415218 } global_limit: <min> in_txn_limit: <max> serial_no: 0 }
--	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
--	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
--	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
--	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
--	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
--	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
--	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:279)
--	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
--	at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:258)
--	at sqlancer.yugabytedb.YugabyteDBProvider.createDatabase(YugabyteDBProvider.java:1)
--	at sqlancer.Main$DBMSExecutor.run(Main.java:311)
--	at sqlancer.Main$2.run(Main.java:508)
--	at sqlancer.Main$2.runThread(Main.java:486)
--	at sqlancer.Main$2.run(Main.java:476)
--	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
--	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
--	at java.lang.Thread.run(Thread.java:748)
--
-- Time: 2021/03/23 19:45:18
-- Database: database4
-- Database version: null
-- seed value: 1616499917097
\c test;
DROP DATABASE IF EXISTS database4;
CREATE DATABASE database4  TEMPLATE template0;

After the problem occurred, I restarted the database.

./yugabyted stop
./yugabyted start
./ysqlsh --username yugabyte --host localhost --port 5433

When I start the program again to create multiple databases, I still find the same error. Why is that?

This seems to be a multi-threaded bug.

@m-iancu
Copy link
Contributor

m-iancu commented Mar 7, 2022

Closing since this roadmap is tracked as part of #5683.
See also #1237, #9467, and #11572.

@m-iancu m-iancu closed this as completed Mar 7, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug This issue is a bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@dobesv @m-iancu @ajcaldera1