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.

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

WIP: Duplicate Issue.Index stress test #8005

Closed
wants to merge 5 commits into from

Conversation

guillep2k
Copy link
Member

@guillep2k guillep2k commented Aug 27, 2019

This is a stress test for the models.newIssue() function, which is expected to fail under big server loads. The problem is a duplicate key error due to the way the function calculates the value for the Index column. See #7887 and #7898.

The test only compiles when the stress tag is specified because it always fails (as expected). EDIT: except for SQLite with sqlite_unlock_notify.

Note: I know the code needs refactoring. I'd like some help with that, as I couldn't figure out the proper way to do it.

The code is meant to be run under integrations/ so one day, when the duplicate key is resolved, the test can be run for every database in the CI (AFAIK the CI does not run tests in the models package for all databases; only for SQLite).

What the test does

First the test creates a relatively large number of rows in the Issues table (default=1000) to make the table grow by at least two blocks.

Then, the test spawns several goroutines (default=8) to simulate multiple users attempting to create issues on the server at the same time.

The goroutines keep calling models.newIssue() as quickly as they can, and stop when any of the following is true:

  • A predetermined time has passed (default=60 seconds).
  • It gets an error when attempting to insert.
  • Any other goroutine gets an error.

So, the test should take at most ~60 seconds if successful, or less if it fails.

The reason the code attempts with 8 goroutines and not -say- 1000 is because it's not realistic to expect the database to have a connection pool that big. As long as the goroutines keep inserting continuously, this test is equivalent and gets the server to spend more time doing database stuff and less time doing process synchronization.

@guillep2k
Copy link
Member Author

guillep2k commented Aug 27, 2019

Example output expected from the test (PostgreSQL, FAIL):

GO111MODULE=on go build -mod=vendor -v  -tags 'pgsql stress' -ldflags '-s -w  -X "main.MakeVersion=GNU Make 3.82" -X "main.Version=1.10.0+dev-223-gc48156e67" -X "main.Tags=pgsql stress"' -o gitea
code.gitea.io/gitea/models
code.gitea.io/gitea/modules/private
code.gitea.io/gitea/models/migrations
code.gitea.io/gitea/modules/auth
code.gitea.io/gitea/modules/context
code.gitea.io/gitea/modules/cron
code.gitea.io/gitea/modules/indexer/issues
code.gitea.io/gitea/modules/ssh
code.gitea.io/gitea/modules/lfs
code.gitea.io/gitea/modules/migrations
code.gitea.io/gitea/modules/pull
code.gitea.io/gitea/modules/repofiles
code.gitea.io/gitea/modules/templates
code.gitea.io/gitea/routers/api/v1/convert
code.gitea.io/gitea/routers/repo
code.gitea.io/gitea/routers/dev
code.gitea.io/gitea/routers/user/setting
code.gitea.io/gitea/routers/org
code.gitea.io/gitea/routers/private
code.gitea.io/gitea/routers/user
code.gitea.io/gitea/routers/api/v1/repo
code.gitea.io/gitea/routers/api/v1/user
code.gitea.io/gitea/routers
code.gitea.io/gitea/routers/api/v1/admin
code.gitea.io/gitea/routers/admin
code.gitea.io/gitea/routers/api/v1/org
code.gitea.io/gitea/routers/api/v1
code.gitea.io/gitea/routers/routes
code.gitea.io/gitea/cmd
code.gitea.io/gitea
go test -c code.gitea.io/gitea/integrations \
    -o integrations.pgsql.test -tags 'pgsql stress' &&
    GITEA_ROOT="/home/gprandi/src/code.gitea.io/gitea" \
    GITEA_CONF=integrations/pgsql.ini ./integrations.pgsql.test \
    -test.v -test.run TestStressCreateIssue
2019/08/27 20:14:42 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:14:42 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:14:42 routers/init.go:72:GlobalInit() [T] AppPath: /home/gprandi/src/code.gitea.io/gitea/gitea
2019/08/27 20:14:42 routers/init.go:73:GlobalInit() [T] AppWorkPath: /home/gprandi/src/code.gitea.io/gitea
2019/08/27 20:14:42 routers/init.go:74:GlobalInit() [T] Custom path: /home/gprandi/src/code.gitea.io/gitea/custom
2019/08/27 20:14:42 routers/init.go:75:GlobalInit() [T] Log path: sqlite-log
=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 0
TestIssueNoDupIndex(): rows created in thread #2: 0
TestIssueNoDupIndex(): rows created in thread #3: 0
TestIssueNoDupIndex(): rows created in thread #4: 0
TestIssueNoDupIndex(): rows created in thread #5: 0
TestIssueNoDupIndex(): rows created in thread #6: 0
TestIssueNoDupIndex(): rows created in thread #7: 0
TestIssueNoDupIndex(): rows created in thread #8: 2
--- FAIL: TestStressCreateIssue (1.91s)
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:99: newIssue(): pq: current transaction is aborted, commands ignored until end of transaction block
    issue_stress.go:120:
                Error Trace:    issue_stress.go:120
                                                        issue_stress_test.go:19
                Error:          Not equal:
                                expected: 0
                                actual  : 1
                Test:           TestStressCreateIssue
                Messages:       Synchronization errors detected.
FAIL

@GiteaBot GiteaBot added the lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. label Aug 27, 2019
@codecov-io
Copy link

codecov-io commented Aug 27, 2019

Codecov Report

❗ No coverage uploaded for pull request base (master@a45909b). Click here to learn what that means.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff            @@
##             master    #8005   +/-   ##
=========================================
  Coverage          ?   41.59%           
=========================================
  Files             ?      479           
  Lines             ?    64106           
  Branches          ?        0           
=========================================
  Hits              ?    26668           
  Misses            ?    33982           
  Partials          ?     3456

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update a45909b...882129f. Read the comment docs.

@guillep2k
Copy link
Member Author

Example output expected from the test (SQLite, only database engine to PASS):

$ GO111MODULE=on go build -mod=vendor -v  -tags 'sqlite sqlite_unlock_notify stress' -ldflags '-s -w  -X "main.MakeVersion=GNU Make 3.82" -X "main.Version=1.10.0+dev-223-gc48156e67" -X "main.Tags=sqlite sqlite_unlock_notify stress"' -o gitea
code.gitea.io/gitea
code.gitea.io/gitea/models
code.gitea.io/gitea/modules/private
code.gitea.io/gitea/models/migrations
code.gitea.io/gitea/modules/auth
code.gitea.io/gitea/modules/context
code.gitea.io/gitea/modules/cron
code.gitea.io/gitea/modules/indexer/issues
code.gitea.io/gitea/modules/ssh
code.gitea.io/gitea/modules/lfs
code.gitea.io/gitea/modules/migrations
code.gitea.io/gitea/modules/pull
code.gitea.io/gitea/modules/repofiles
code.gitea.io/gitea/modules/templates
code.gitea.io/gitea/routers/api/v1/convert
code.gitea.io/gitea/routers/repo
code.gitea.io/gitea/routers/dev
code.gitea.io/gitea/routers/user/setting
code.gitea.io/gitea/routers/org
code.gitea.io/gitea/routers/private
code.gitea.io/gitea/routers/user
code.gitea.io/gitea/routers/api/v1/repo
code.gitea.io/gitea/routers/api/v1/user
code.gitea.io/gitea/routers
code.gitea.io/gitea/routers/api/v1/admin
code.gitea.io/gitea/routers/admin
code.gitea.io/gitea/routers/api/v1/org
code.gitea.io/gitea/routers/api/v1
code.gitea.io/gitea/routers/routes
code.gitea.io/gitea/cmd
code.gitea.io/gitea

$ go test -c code.gitea.io/gitea/integrations \
    -o integrations.sqlite.test -tags 'sqlite sqlite_unlock_notify stress' &&
    GITEA_ROOT="/home/gprandi/src/code.gitea.io/gitea" \
    GITEA_CONF=integrations/sqlite.ini ./integrations.sqlite.test \
    -test.v -test.run TestStressCreateIssue
2019/08/27 20:11:14 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:11:14 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:11:14 routers/init.go:72:GlobalInit() [T] AppPath: /home/gprandi/src/code.gitea.io/gitea/gitea
2019/08/27 20:11:14 routers/init.go:73:GlobalInit() [T] AppWorkPath: /home/gprandi/src/code.gitea.io/gitea
2019/08/27 20:11:14 routers/init.go:74:GlobalInit() [T] Custom path: /home/gprandi/src/code.gitea.io/gitea/custom
2019/08/27 20:11:14 routers/init.go:75:GlobalInit() [T] Log path: sqlite-log
=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 897
TestIssueNoDupIndex(): rows created in thread #2: 1022
TestIssueNoDupIndex(): rows created in thread #3: 719
TestIssueNoDupIndex(): rows created in thread #4: 944
TestIssueNoDupIndex(): rows created in thread #5: 836
TestIssueNoDupIndex(): rows created in thread #6: 817
TestIssueNoDupIndex(): rows created in thread #7: 857
TestIssueNoDupIndex(): rows created in thread #8: 601
--- PASS: TestStressCreateIssue (63.01s)
PASS

@guillep2k
Copy link
Member Author

Example output expected from the test (MSSQL, FAIL):

go test -c code.gitea.io/gitea/integrations \
    -o integrations.mssql.test -tags 'mssql stress' &&
    GITEA_ROOT="/home/gprandi/src/code.gitea.io/gitea" \
    GITEA_CONF=integrations/mssql.ini ./integrations.mssql.test \
    -test.v -test.run TestStressCreateIssue
2019/08/27 20:25:42 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:25:42 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:25:42 routers/init.go:72:GlobalInit() [T] AppPath: /home/gprandi/src/code.gitea.io/gitea/gitea
2019/08/27 20:25:42 routers/init.go:73:GlobalInit() [T] AppWorkPath: /home/gprandi/src/code.gitea.io/gitea
2019/08/27 20:25:42 routers/init.go:74:GlobalInit() [T] Custom path: /home/gprandi/src/code.gitea.io/gitea/custom
2019/08/27 20:25:42 routers/init.go:75:GlobalInit() [T] Log path: sqlite-log
=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 10
TestIssueNoDupIndex(): rows created in thread #2: 2
TestIssueNoDupIndex(): rows created in thread #3: 2
TestIssueNoDupIndex(): rows created in thread #4: 1
TestIssueNoDupIndex(): rows created in thread #5: 7
TestIssueNoDupIndex(): rows created in thread #6: 9
TestIssueNoDupIndex(): rows created in thread #7: 6
TestIssueNoDupIndex(): rows created in thread #8: 2
--- FAIL: TestStressCreateIssue (6.28s)
    issue_stress.go:99: newIssue(): <nil>
    issue_stress.go:120:
                Error Trace:    issue_stress.go:120
                                                        issue_stress_test.go:19
                Error:          Not equal:
                                expected: 0
                                actual  : 1
                Test:           TestStressCreateIssue
                Messages:       Synchronization errors detected.
FAIL

@guillep2k
Copy link
Member Author

Example output expected from the test (MYSQL, FAIL):

go test -c code.gitea.io/gitea/integrations \
    -o integrations.mysql.test -tags 'mysql stress' &&
    GITEA_ROOT="/home/gprandi/src/code.gitea.io/gitea" \
    GITEA_CONF=integrations/mysql.ini ./integrations.mysql.test \
    -test.v -test.run TestStressCreateIssue
2019/08/27 20:27:30 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:27:30 ...dules/setting/git.go:87:newGit() [I] Git Version: 2.22.0, Wire Protocol Version 2 Enabled
2019/08/27 20:27:30 routers/init.go:72:GlobalInit() [T] AppPath: /home/gprandi/src/code.gitea.io/gitea/gitea
2019/08/27 20:27:30 routers/init.go:73:GlobalInit() [T] AppWorkPath: /home/gprandi/src/code.gitea.io/gitea
2019/08/27 20:27:30 routers/init.go:74:GlobalInit() [T] Custom path: /home/gprandi/src/code.gitea.io/gitea/custom
2019/08/27 20:27:30 routers/init.go:75:GlobalInit() [T] Log path: sqlite-log
=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 0
TestIssueNoDupIndex(): rows created in thread #2: 0
TestIssueNoDupIndex(): rows created in thread #3: 0
TestIssueNoDupIndex(): rows created in thread #4: 0
TestIssueNoDupIndex(): rows created in thread #5: 2
TestIssueNoDupIndex(): rows created in thread #6: 1
TestIssueNoDupIndex(): rows created in thread #7: 1
TestIssueNoDupIndex(): rows created in thread #8: 0
--- FAIL: TestStressCreateIssue (5.72s)
    issue_stress.go:99: newIssue(): Error 1213: Deadlock found when trying to get lock; try restarting transaction
    issue_stress.go:99: newIssue(): Error 1213: Deadlock found when trying to get lock; try restarting transaction
    issue_stress.go:99: newIssue(): Error 1213: Deadlock found when trying to get lock; try restarting transaction
    issue_stress.go:99: newIssue(): Error 1213: Deadlock found when trying to get lock; try restarting transaction
    issue_stress.go:99: newIssue(): Error 1213: Deadlock found when trying to get lock; try restarting transaction
    issue_stress.go:120:
                Error Trace:    issue_stress.go:120
                                                        issue_stress_test.go:19
                Error:          Not equal:
                                expected: 0
                                actual  : 1
                Test:           TestStressCreateIssue
                Messages:       Synchronization errors detected.
FAIL

@guillep2k
Copy link
Member Author

guillep2k commented Aug 27, 2019

All the tests again, but with useTransactions = false

SQLite

PASS (same result)

PostgreSQL

FAIL (different error, more rows inserted)

=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 6
TestIssueNoDupIndex(): rows created in thread #2: 6
TestIssueNoDupIndex(): rows created in thread #3: 5
TestIssueNoDupIndex(): rows created in thread #4: 7
TestIssueNoDupIndex(): rows created in thread #5: 4
TestIssueNoDupIndex(): rows created in thread #6: 6
TestIssueNoDupIndex(): rows created in thread #7: 6
TestIssueNoDupIndex(): rows created in thread #8: 6
--- FAIL: TestStressCreateIssue (2.17s)
    issue_stress.go:99: newIssue(): pq: duplicate key value violates unique constraint "UQE_issue_repo_index"

MySQL

FAIL (different error)
Very strange error indeed...

=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 0
TestIssueNoDupIndex(): rows created in thread #2: 0
TestIssueNoDupIndex(): rows created in thread #3: 0
TestIssueNoDupIndex(): rows created in thread #4: 0
TestIssueNoDupIndex(): rows created in thread #5: 0
TestIssueNoDupIndex(): rows created in thread #6: 0
TestIssueNoDupIndex(): rows created in thread #7: 0
TestIssueNoDupIndex(): rows created in thread #8: 0
--- FAIL: TestStressCreateIssue (53.53s)
    issue_stress.go:99: newIssue(): getUserByID.(poster) [-1]: dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): getAttachmentsByIssueID [9818]: dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): getUserByID.(poster) [-1]: dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:99: newIssue(): getAssignees: dial tcp 127.0.0.1:3306: connect: cannot assign requested address
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:116:
                Error Trace:    issue_stress.go:116
                                                        issue_stress_test.go:19
                Error:          Received unexpected error:
                                dial tcp 127.0.0.1:3306: connect: cannot assign requested address
                Test:           TestStressCreateIssue
                Messages:       Failed counting generated issues count
    issue_stress.go:120:
                Error Trace:    issue_stress.go:120
                                                        issue_stress_test.go:19
                Error:          Not equal:
                                expected: 0
                                actual  : 1
                Test:           TestStressCreateIssue
                Messages:       Synchronization errors detected.
FAIL

MSSQL

FAIL (same error, more rows inserted)

=== RUN   TestStressCreateIssue
TestIssueNoDupIndex(): 1000 rows created
TestIssueNoDupIndex(): 8 threads created
TestIssueNoDupIndex(): rows created in thread #1: 50
TestIssueNoDupIndex(): rows created in thread #2: 50
TestIssueNoDupIndex(): rows created in thread #3: 48
TestIssueNoDupIndex(): rows created in thread #4: 49
TestIssueNoDupIndex(): rows created in thread #5: 50
TestIssueNoDupIndex(): rows created in thread #6: 50
TestIssueNoDupIndex(): rows created in thread #7: 49
TestIssueNoDupIndex(): rows created in thread #8: 50
--- FAIL: TestStressCreateIssue (12.31s)
    issue_stress.go:99: newIssue(): insert successfully but not returned id
    issue_stress.go:120:
                Error Trace:    issue_stress.go:120
                                                        issue_stress_test.go:19
                Error:          Not equal:
                                expected: 0
                                actual  : 1
                Test:           TestStressCreateIssue
                Messages:       Synchronization errors detected.
FAIL

@stale
Copy link

stale bot commented Oct 27, 2019

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs during the next 2 months. Thank you for your contributions.

@stale stale bot added the issue/stale label Oct 27, 2019
@guillep2k
Copy link
Member Author

This research is indeed stalled. It was partially fixed elsewhere, anyway.

@guillep2k guillep2k closed this Oct 27, 2019
@go-gitea go-gitea locked and limited conversation to collaborators Nov 24, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
issue/stale lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants