Sqlite fixes #17874

mheon · 2023-03-21T14:01:31Z

Two fixes:

Ensure that SQLite schema migration happens before we init any part of the database, so we never access a database with a bad schema.
Fix a flake where we were getting database locked errors due to concurrent read/write of the same table.

NONE

It now can safely run on bare databases, before any tables are created. Signed-off-by: Matthew Heon <[email protected]>

I was searching the SQLite docs for a fix, but apparently that was the wrong place; it's a common enough error with the Go frontend for SQLite that the fix is prominently listed in the API docs for go-sqlite3. Setting cache mode to 'shared' and using a maximum of 1 simultaneous open connection should fix. Performance implications of this are unclear, but cache=shared sounds like it will be a benefit, not a curse. [NO NEW TESTS NEEDED] This fixes a flake with concurrent DB access. Signed-off-by: Matthew Heon <[email protected]>

openshift-ci · 2023-03-21T14:01:44Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: mheon

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [mheon]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

mheon · 2023-03-21T14:01:57Z

@edsantiago This should get rid of the database locked flake, but I haven't been able to reproduce locally so I can't be 100% on that.

edsantiago · 2023-03-21T14:04:33Z

libpod/sqlite_state.go

@@ -45,7 +45,7 @@ func NewSqliteState(runtime *Runtime) (_ State, defErr error) {
 		return nil, fmt.Errorf("creating root directory: %w", err)
 	}

-	conn, err := sql.Open("sqlite3", filepath.Join(basePath, "db.sql?_loc=auto"))
+	conn, err := sql.Open("sqlite3", filepath.Join(basePath, "db.sql?_loc=auto&cache=shared"))


This is going to conflict with #17867

vrothberg · 2023-03-21T14:38:37Z

Can we make a mix of #17867 and this PR?

I really think that setting the PRAGMAs as done in #17867 is 1) faster and 2) easier to read.

vrothberg · 2023-03-21T14:40:27Z

libpod/sqlite_state.go

@@ -57,6 +57,9 @@ func NewSqliteState(runtime *Runtime) (_ State, defErr error) {
 		}
 	}()

+	// Necessary to avoid database locked errors.
+	conn.SetMaxOpenConns(1)


Isn't that effectively excluding all other processes from opening a connection?

edsantiago · 2023-03-21T15:46:28Z

FWIW, the string "UNIQUE" (case-sensitive, caps) does not appear in the CI logs, nor do any of the following case-insensitive strings:

"constraint fail"
"config row"
"adding db"
"dbconfig.id"

Timings, with a reminder that this is not equivalent to serious performance benchmarks

type	distro	user	DB	local	remote	container
int	fedora-37	root		30:45	33:11	27:59
int	fedora-37	root	sqlite	30:59	33:33
int	fedora-37	rootless		29:41
int	fedora-37	rootless	sqlite	28:50

edsantiago · 2023-03-21T16:29:48Z

System test runs in #17831 are done. Saw lots of "database is locked", but no "unique etc" errors.

The symptoms in containers#17859 indicate that setting the PRAGMAs in individual EXECs outside of a transaction can lead to concurrency issues and failures when the DB is locked. Hence set all PRAGMAs when opening the connection. Move them into individual constants to improve documentation and readability. Further make transactions exclusive as containers#17859 also mentions an error that the DB is locked during a transaction. [NO NEW TESTS NEEDED] - existing tests cover the code. Fixes: containers#17859 Signed-off-by: Valentin Rothberg <[email protected]> <MH: Cherry-picked on top of my branch> Signed-off-by: Matthew Heon <[email protected]>

mheon · 2023-03-21T16:54:20Z

I have pulled in #17867 from @vrothberg

mheon · 2023-03-21T16:55:03Z

Marking as WIP: I'm going to perf test max connections vs transaction locking.

mheon · 2023-03-21T16:55:51Z

@edsantiago Did you pull in Valentin's earlier PR, and if so did it resolve the database locked issue?

edsantiago · 2023-03-21T16:57:17Z

@mheon yes I made an earlier run of #17831 using @vrothberg's fixes, and saw no instances of the "is locked" bug. I'm now rerebasing on this PR, and will resubmit in a few seconds.

mheon · 2023-03-21T18:12:35Z

Benchmark 1: /home/mheon/code/podman/bin/podman --db-backend=sqlite ps -a
  Time (mean ± σ):      21.7 ms ±   1.0 ms    [User: 27.1 ms, System: 11.8 ms]
  Range (min … max):    19.1 ms …  24.1 ms    100 runs
 
Benchmark 2: /home/mheon/code/podman/bin/podman_maxcons --db-backend=sqlite ps -a
  Time (mean ± σ):      22.2 ms ±   1.2 ms    [User: 28.8 ms, System: 11.9 ms]
  Range (min … max):    19.5 ms …  26.4 ms    100 runs
 
Summary
  '/home/mheon/code/podman/bin/podman --db-backend=sqlite ps -a' ran
    1.03 ± 0.08 times faster than '/home/mheon/code/podman/bin/podman_maxcons --db-backend=sqlite ps -a'

mheon · 2023-03-21T18:13:04Z

Maxcons is definitely slowing us down somewhat, at least at high container counts (that was 500)

mheon · 2023-03-21T18:16:24Z

It goes down to ~1% slower at lower container counts

mheon · 2023-03-21T18:20:06Z

Based on current numbers, the tx lock seems slightly faster. I'm going to remove the connection count limit.

The SQLite transaction lock Valentin found is (slightly) faster. So let's go with that. Signed-off-by: Matthew Heon <[email protected]>

mheon · 2023-03-21T18:21:28Z

Re-pushed. Max connections logic is gone. Removing WIP. Going to switch to sqlite vs bolt perf comparisons.

edsantiago · 2023-03-21T19:29:17Z

Followup: I did not see UNIQUE constraint nor 'database is locked` in system tests, yay, but I do see one new failure I've never seen before, in f37 rootless sqlite:

  stop podman.service
  ...
  Execing /var/tmp/go/src/github.com/containers/podman/bin/podman --root /tmp/podman_test2489001336/server_root inspect --format={{.State.Running}} top_ccwvMutB
  Error: inspecting object: no such object: "top_ccwvMutB"

What's really curious is that this is an e2e test that says Execing, whereas usually they say "Running". And the "Execing" line does not include the --db-backend or any of the other long list of options usually shown in "Running" log lines. Is this some weird different way of running podman?

Worth pointing out that this PR is being run on a system with /etc/containers/containers.conf force-modified to use sqlite, so this is different from the current CI situation in which testing is happening via command-line --db-backend options.

edsantiago · 2023-03-21T21:03:00Z

@mheon @vrothberg I'm sorry to report that f37 rootless sqlite had one failure in my PR:

$ podman [options] ps -q
Error: adding DB config row: UNIQUE constraint failed: DBConfig.ID

(where "my PR" is #17831 rebased against 0c313b6e5)

mheon · 2023-03-22T02:51:09Z

Damn. Alright, have to add even more validation there, I guess.

vrothberg · 2023-03-22T09:58:59Z

Damn. Alright, have to add even more validation there, I guess.

I think there's a race condition in creating the table. Checking for the table existence should be part of the transaction:

diff --git a/libpod/sqlite_state.go b/libpod/sqlite_state.go
index e1007dbc3709..9df98dc4b465 100644
--- a/libpod/sqlite_state.go
+++ b/libpod/sqlite_state.go
@@ -336,23 +336,21 @@ func (s *SQLiteState) ValidateDBConfig(runtime *Runtime) (defErr error) {
 		runtimeGraphDriver = storeOpts.GraphDriverName
 	}
 
-	row := s.conn.QueryRow("SELECT Os, StaticDir, TmpDir, GraphRoot, RunRoot, GraphDriver, VolumeDir FROM DBConfig;")
-
+	tx, err := s.conn.Begin()
+	if err != nil {
+		return fmt.Errorf("beginning DB config transaction: %w", err)
+	}
+	defer func() {
+		if defErr != nil {
+			if err := tx.Rollback(); err != nil {
+				logrus.Errorf("Rolling back transaction to create DB config: %v", err)
+			}
+		}
+	}()
+	row := tx.QueryRow("SELECT Os, StaticDir, TmpDir, GraphRoot, RunRoot, GraphDriver, VolumeDir FROM DBConfig;")
 	if err := row.Scan(&os, &staticDir, &tmpDir, &graphRoot, &runRoot, &graphDriver, &volumePath); err != nil {
 		if errors.Is(err, sql.ErrNoRows) {
 			// Need to create runtime config info in DB
-			tx, err := s.conn.Begin()
-			if err != nil {
-				return fmt.Errorf("beginning DB config transaction: %w", err)
-			}
-			defer func() {
-				if defErr != nil {
-					if err := tx.Rollback(); err != nil {
-						logrus.Errorf("Rolling back transaction to create DB config: %v", err)
-					}
-				}
-			}()
-
 			if _, err := tx.Exec(createRow, 1, schemaVersion, runtimeOS,
 				runtimeStaticDir, runtimeTmpDir, runtimeGraphRoot,
 				runtimeRunRoot, runtimeGraphDriver, runtimeVolumePath); err != nil {

vrothberg · 2023-03-22T09:59:43Z

@edsantiago, could you apply the upper diff to your PR and see whether it fixes the flake?

edsantiago · 2023-03-22T11:23:20Z

@vrothberg done, run is in progress. Quick note that this flake is rare: it did not happen at all on my last CI rerun, and it did not happen in this PR's most recent run. (As in: I downloaded all the logs and grep'ed them for even single failures). I will of course continue to download-and-grep all logs for this and my PR and report my findings.

edsantiago · 2023-03-22T11:50:33Z

Well, doesn't look good. Didn't even make it past the image fetch:

Caching quay.io/libpod/cirros:latest at /tmp/quay.io-libpod-cirros-latest.tar...
$ podman [options] pull quay.io/libpod/cirros:latest
Error: beginning refresh transaction: database is locked

vrothberg

LGTM
I vote for merging this PR as is. It's already an improvement and we can tackle the remaining flake(s) separately.

vrothberg · 2023-03-22T12:04:44Z

Well, doesn't look good. Didn't even make it past the image fetch:

Caching quay.io/libpod/cirros:latest at /tmp/quay.io-libpod-cirros-latest.tar...
$ podman [options] pull quay.io/libpod/cirros:latest
Error: beginning refresh transaction: database is locked

This error is really weird. @mheon, shouldn't Podman just busy-wait until the DB is unlocked by another thread/process?

edsantiago · 2023-03-22T12:08:39Z

Incremental progress is totally fine with me.

/lgtm
/hold

baude · 2023-03-22T12:09:49Z

/hold cancel

mheon added 2 commits March 17, 2023 13:24

Fix SQLite DB schema migration code

94f905a

It now can safely run on bare databases, before any tables are created. Signed-off-by: Matthew Heon <[email protected]>

openshift-ci bot added the release-note-none label Mar 21, 2023

openshift-ci bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Mar 21, 2023

edsantiago reviewed Mar 21, 2023

View reviewed changes

mheon mentioned this pull request Mar 21, 2023

sqlite: set connection attributes on open #17867

Closed

vrothberg reviewed Mar 21, 2023

View reviewed changes

mheon changed the title ~~Sqlite fixes~~ [WIP] Sqlite fixes Mar 21, 2023

openshift-ci bot added the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Mar 21, 2023

Drop SQLite max connections

3925cd6

The SQLite transaction lock Valentin found is (slightly) faster. So let's go with that. Signed-off-by: Matthew Heon <[email protected]>

mheon changed the title ~~[WIP] Sqlite fixes~~ Sqlite fixes Mar 21, 2023

openshift-ci bot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Mar 21, 2023

vrothberg reviewed Mar 22, 2023

View reviewed changes

openshift-ci bot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 22, 2023

openshift-ci bot assigned edsantiago Mar 22, 2023

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Mar 22, 2023

openshift-ci bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 22, 2023

openshift-merge-robot merged commit 6b9f314 into containers:main Mar 22, 2023

github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 4, 2023

github-actions bot locked as resolved and limited conversation to collaborators Sep 4, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sqlite fixes #17874

Sqlite fixes #17874

mheon commented Mar 21, 2023

openshift-ci bot commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago Mar 21, 2023

vrothberg commented Mar 21, 2023

vrothberg Mar 21, 2023

edsantiago commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 22, 2023

vrothberg commented Mar 22, 2023

vrothberg commented Mar 22, 2023

edsantiago commented Mar 22, 2023

edsantiago commented Mar 22, 2023

vrothberg left a comment

vrothberg commented Mar 22, 2023

edsantiago commented Mar 22, 2023

baude commented Mar 22, 2023

Sqlite fixes #17874

Sqlite fixes #17874

Conversation

mheon commented Mar 21, 2023

openshift-ci bot commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago Mar 21, 2023

Choose a reason for hiding this comment

vrothberg commented Mar 21, 2023

vrothberg Mar 21, 2023

Choose a reason for hiding this comment

edsantiago commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

mheon commented Mar 21, 2023

edsantiago commented Mar 21, 2023

edsantiago commented Mar 21, 2023

mheon commented Mar 22, 2023

vrothberg commented Mar 22, 2023

vrothberg commented Mar 22, 2023

edsantiago commented Mar 22, 2023

edsantiago commented Mar 22, 2023

vrothberg left a comment

Choose a reason for hiding this comment

vrothberg commented Mar 22, 2023

edsantiago commented Mar 22, 2023

baude commented Mar 22, 2023