Hang with 1.20.2/1.20.3 #11519

@lunny commented on GitHub (Aug 23, 2023):

Hm, you are using SQLite for 2.5k users. It's amazing. Maybe you can use MySQL or Postgres.

2023/08/23 02:25:04 ...eb/routing/logger.go:68:func1() [W] router: slow POST /api/internal/ssh/1985/update/3 for :0, elapsed 3354.7ms @ private/key.go:16(private.UpdatePublicKeyInRepo) 2023/08/23 02:25:06 ...eb/routing/logger.go:68:func1() [W] router: slow POST /api/internal/ssh/1985/update/3 for :0, elapsed 3269.4ms @ private/key.go:16(private.UpdatePublicKeyInRepo)

From this request, it will only do database operations, so the database operation is too slow. Since SQLite is shared read and locked write, it expected very slow when there are many operations at the same time.

@lunny commented on GitHub (Aug 23, 2023): Hm, you are using SQLite for 2.5k users. It's amazing. Maybe you can use MySQL or Postgres. > 2023/08/23 02:25:04 ...eb/routing/logger.go:68:func1() [W] router: slow POST /api/internal/ssh/1985/update/3 for <redacted>:0, elapsed 3354.7ms @ private/key.go:16(private.UpdatePublicKeyInRepo) 2023/08/23 02:25:06 ...eb/routing/logger.go:68:func1() [W] router: slow POST /api/internal/ssh/1985/update/3 for <redacted>:0, elapsed 3269.4ms @ private/key.go:16(private.UpdatePublicKeyInRepo) From this request, it will only do database operations, so the database operation is too slow. Since SQLite is shared read and locked write, it expected very slow when there are many operations at the same time.

GiteaMirror commented

@elburb commented on GitHub (Aug 23, 2023):

Thanks for the super quick response.

Moving the database is certainly something I can look at doing though I'm curious as to why it should only be a problem with 1.20.2 onward.

Is there any additional debug or stats I can look at to confirm this is problem before attempting to move everything ?

@elburb commented on GitHub (Aug 23, 2023): Thanks for the super quick response. Moving the database is certainly something I can look at doing though I'm curious as to why it should only be a problem with 1.20.2 onward. Is there any additional debug or stats I can look at to confirm this is problem before attempting to move everything ?

GiteaMirror commented

@lunny commented on GitHub (Aug 23, 2023):

According to the code it should be a random event. Even 1.20.1 or previous version should have the same problem. You can have a test to push 10 times at the same time.

@lunny commented on GitHub (Aug 23, 2023): According to the code it should be a random event. Even 1.20.1 or previous version should have the same problem. You can have a test to push 10 times at the same time.

GiteaMirror commented

@wxiaoguang commented on GitHub (Aug 23, 2023):

To debug the hanging problem:

If the admin panel still works, go to admin panel -> monitor -> stacktrace, and download a diagnosis report
If the admin panel stops working, use "pprof" tool get some profiling reports.e8b990999f/custom/conf/app.example.ini (L292)

About "pprof":

Set app.ini:
```
[server]
ENABLE_PPROF = true
```
Restart Gitea
Try to trigger the bug, when the requests get stuck for a while, use curl or browser to visit: http://127.0.0.1:6060/debug/pprof/goroutine?debug=1

But I would also suggest to use a dedicated database server, SQLite is not suitable for such a large instance, SQLite itself doesn't work for concurrent requests well.

@wxiaoguang commented on GitHub (Aug 23, 2023): To debug the hanging problem: * If the admin panel still works, go to admin panel -> monitor -> stacktrace, and download a diagnosis report * If the admin panel stops working, use "pprof" tool get some profiling reports.https://github.com/go-gitea/gitea/blob/e8b990999f89535269d20983079a40a0a9488eff/custom/conf/app.example.ini#L292 About "pprof": 1. Set `app.ini`: ``` [server] ENABLE_PPROF = true ``` 2. Restart Gitea 3. Try to trigger the bug, when the requests get stuck for a while, use `curl` or browser to visit: `http://127.0.0.1:6060/debug/pprof/goroutine?debug=1` ---- But I would also suggest to use a dedicated database server, SQLite is not suitable for such a large instance, SQLite itself doesn't work for concurrent requests well.

GiteaMirror commented

@elburb commented on GitHub (Aug 23, 2023):

Many thanks for the responses and suggestions, much appreciated.
I'll close this issue for now whilst I take a look at the additional debug and test migrating away from sqlite.

@elburb commented on GitHub (Aug 23, 2023): Many thanks for the responses and suggestions, much appreciated. I'll close this issue for now whilst I take a look at the additional debug and test migrating away from sqlite.

GiteaMirror commented

@smartEBL commented on GitHub (Aug 25, 2023):

We experience exactly the same behaviour with 1.20.3 (also with a sqlite3 database). We have ~100 users and everything was fine before with 1.19.3.
We're also trying to get more logs.

@smartEBL commented on GitHub (Aug 25, 2023): We experience exactly the same behaviour with 1.20.3 (also with a sqlite3 database). We have ~100 users and everything was fine before with 1.19.3. We're also trying to get more logs.

GiteaMirror commented

@wxiaoguang commented on GitHub (Aug 25, 2023):

Feel free to provide more details, including the diagnosis report and stacktrace.

@wxiaoguang commented on GitHub (Aug 25, 2023): Feel free to provide more details, including the diagnosis report and stacktrace.

GiteaMirror commented

@elburb commented on GitHub (Aug 25, 2023):

For my instance, I was able to get both stacktrace and debug outputs.
The debug clearly showed a bunch of processes stuck with sqlite, here's just one example (of ~300+)

1 @ 0x43df36 0x408f1d 0x408a18 0x89950d 0x890a0b 0x884818 0x8710fd 0x878e95 0x881c0c 0x8787e6 0x878508 0x8782f5 0x877867 0x87820c 0xeb43e5 0xf3c3fb 0xf41271 0x1773ce7 0x2664238 0x2664fb
c 0x4a818b 0x4a743c 0x2312c46 0x9b4b8f 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc
# labels: {"graceful-lifecycle":"with-hammer", "pid":"64e63796-2", "ppid":"", "process-description":"GET: /dn42/registry", "process-type":"request"}
#	0x89950c	github.com/mattn/go-sqlite3.(*SQLiteStmt).exec+0x22c		/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2067
#	0x890a0a	github.com/mattn/go-sqlite3.(*SQLiteConn).exec+0x26a		/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:877
#	0x884817	github.com/mattn/go-sqlite3.(*SQLiteConn).ExecContext+0x157	/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3_go18.go:41
#	0x8710fc	database/sql.ctxDriverExec+0xdc					/usr/local/go/src/database/sql/ctxutil.go:31
#	0x878e94	database/sql.(*DB).execDC.func2+0x174				/usr/local/go/src/database/sql/sql.go:1675
#	0x881c0b	database/sql.withLock+0x8b					/usr/local/go/src/database/sql/sql.go:3405
#	0x8787e5	database/sql.(*DB).execDC+0x265					/usr/local/go/src/database/sql/sql.go:1670
#	0x878507	database/sql.(*DB).exec+0xe7					/usr/local/go/src/database/sql/sql.go:1655
#	0x8782f4	database/sql.(*DB).ExecContext.func1+0x54			/usr/local/go/src/database/sql/sql.go:1634
#	0x877866	database/sql.(*DB).retry+0x46					/usr/local/go/src/database/sql/sql.go:1538
#	0x87820b	database/sql.(*DB).ExecContext+0xcb				/usr/local/go/src/database/sql/sql.go:1633
#	0xeb43e4	xorm.io/xorm/core.(*DB).ExecContext+0x1e4			/go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/core/db.go:273
#	0xf3c3fa	xorm.io/xorm.(*Session).exec+0x25a				/go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/session_raw.go:178
#	0xf41270	xorm.io/xorm.(*Session).Update+0x1190				/go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/session_update.go:196
#	0x1773ce6	code.gitea.io/gitea/models/activities.SetRepoReadBy+0x226	/source/models/activities/notification.go:777
#	0x2664237	code.gitea.io/gitea/routers/web/repo.checkHomeCodeViewable+0x77	/source/routers/web/repo/view.go:645
#	0x2664fbb	code.gitea.io/gitea/routers/web/repo.Home+0x5b			/source/routers/web/repo/view.go:727
#	0x4a818a	reflect.Value.call+0xb0a					/usr/local/go/src/reflect/value.go:586
#	0x4a743b	reflect.Value.Call+0xbb						/usr/local/go/src/reflect/value.go:370
#	0x2312c45	code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x1c5	/source/modules/web/handler.go:176
#	0x9b4b8e	net/http.HandlerFunc.ServeHTTP+0x2e				/usr/local/go/src/net/http/server.go:2122
#	0x9b4b8e	net/http.HandlerFunc.ServeHTTP+0x2e				/usr/local/go/src/net/http/server.go:2122
#	0x2312cdb	code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b	/source/modules/web/handler.go:186
#	0x9b4b8e	net/http.HandlerFunc.ServeHTTP+0x2e				/usr/local/go/src/net/http/server.go:2122
#	0x2312cdb	code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b	/source/modules/web/handler.go:186
#	0x9b4b8e	net/http.HandlerFunc.ServeHTTP+0x2e				/usr/local/go/src/net/http/server.go:2122
#	0x2312cdb	code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b	/source/modules/web/handler.go:186
#	0x9b4b8e	net/http.HandlerFunc.ServeHTTP+0x2e				/usr/local/go/src/net/http/server.go:2122
#	0x2312cdb	code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b	/source/modules/web/handler.go:186

Whilst I completely understand the point that sqlite isn't really suited to our usage, we had zero issues for the past 2.5 years and only started getting issues with 1.20.2, something clearly did change in that version to trigger the problem.

My intention is to migrate away from sqlite this weekend, and expect that will resolve it for us.

@elburb commented on GitHub (Aug 25, 2023): For my instance, I was able to get both stacktrace and debug outputs. The debug clearly showed a bunch of processes stuck with sqlite, here's just one example (of ~300+) ``` 1 @ 0x43df36 0x408f1d 0x408a18 0x89950d 0x890a0b 0x884818 0x8710fd 0x878e95 0x881c0c 0x8787e6 0x878508 0x8782f5 0x877867 0x87820c 0xeb43e5 0xf3c3fb 0xf41271 0x1773ce7 0x2664238 0x2664fb c 0x4a818b 0x4a743c 0x2312c46 0x9b4b8f 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc 0x9b4b8f 0x2312cdc # labels: {"graceful-lifecycle":"with-hammer", "pid":"64e63796-2", "ppid":"", "process-description":"GET: /dn42/registry", "process-type":"request"} # 0x89950c github.com/mattn/go-sqlite3.(*SQLiteStmt).exec+0x22c /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2067 # 0x890a0a github.com/mattn/go-sqlite3.(*SQLiteConn).exec+0x26a /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:877 # 0x884817 github.com/mattn/go-sqlite3.(*SQLiteConn).ExecContext+0x157 /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3_go18.go:41 # 0x8710fc database/sql.ctxDriverExec+0xdc /usr/local/go/src/database/sql/ctxutil.go:31 # 0x878e94 database/sql.(*DB).execDC.func2+0x174 /usr/local/go/src/database/sql/sql.go:1675 # 0x881c0b database/sql.withLock+0x8b /usr/local/go/src/database/sql/sql.go:3405 # 0x8787e5 database/sql.(*DB).execDC+0x265 /usr/local/go/src/database/sql/sql.go:1670 # 0x878507 database/sql.(*DB).exec+0xe7 /usr/local/go/src/database/sql/sql.go:1655 # 0x8782f4 database/sql.(*DB).ExecContext.func1+0x54 /usr/local/go/src/database/sql/sql.go:1634 # 0x877866 database/sql.(*DB).retry+0x46 /usr/local/go/src/database/sql/sql.go:1538 # 0x87820b database/sql.(*DB).ExecContext+0xcb /usr/local/go/src/database/sql/sql.go:1633 # 0xeb43e4 xorm.io/xorm/core.(*DB).ExecContext+0x1e4 /go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/core/db.go:273 # 0xf3c3fa xorm.io/xorm.(*Session).exec+0x25a /go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/session_raw.go:178 # 0xf41270 xorm.io/xorm.(*Session).Update+0x1190 /go/pkg/mod/xorm.io/xorm@v1.3.3-0.20230725140238-59b727260d35/session_update.go:196 # 0x1773ce6 code.gitea.io/gitea/models/activities.SetRepoReadBy+0x226 /source/models/activities/notification.go:777 # 0x2664237 code.gitea.io/gitea/routers/web/repo.checkHomeCodeViewable+0x77 /source/routers/web/repo/view.go:645 # 0x2664fbb code.gitea.io/gitea/routers/web/repo.Home+0x5b /source/routers/web/repo/view.go:727 # 0x4a818a reflect.Value.call+0xb0a /usr/local/go/src/reflect/value.go:586 # 0x4a743b reflect.Value.Call+0xbb /usr/local/go/src/reflect/value.go:370 # 0x2312c45 code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x1c5 /source/modules/web/handler.go:176 # 0x9b4b8e net/http.HandlerFunc.ServeHTTP+0x2e /usr/local/go/src/net/http/server.go:2122 # 0x9b4b8e net/http.HandlerFunc.ServeHTTP+0x2e /usr/local/go/src/net/http/server.go:2122 # 0x2312cdb code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b /source/modules/web/handler.go:186 # 0x9b4b8e net/http.HandlerFunc.ServeHTTP+0x2e /usr/local/go/src/net/http/server.go:2122 # 0x2312cdb code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b /source/modules/web/handler.go:186 # 0x9b4b8e net/http.HandlerFunc.ServeHTTP+0x2e /usr/local/go/src/net/http/server.go:2122 # 0x2312cdb code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b /source/modules/web/handler.go:186 # 0x9b4b8e net/http.HandlerFunc.ServeHTTP+0x2e /usr/local/go/src/net/http/server.go:2122 # 0x2312cdb code.gitea.io/gitea/modules/web.toHandlerProvider.func2.1+0x25b /source/modules/web/handler.go:186 ``` Whilst I completely understand the point that sqlite isn't really suited to our usage, we had zero issues for the past 2.5 years and only started getting issues with 1.20.2, something clearly did change in that version to trigger the problem. My intention is to migrate away from sqlite this weekend, and expect that will resolve it for us.

GiteaMirror commented

@elburb commented on GitHub (Aug 25, 2023):

and just for reference, another slightly different example:

1 @ 0x43df36 0x408f1d 0x408a18 0x89d1fe 0x89e5c5 0x406651 0x406309 0x4724d4 0x4704e1 0x406185 0x88582c 0x899a85 0x899805 0x899752 0x472701
# labels: {"graceful-lifecycle":"with-hammer", "pid":"64e635a3-2", "ppid":"", "process-description":"GET: /dn42/registry.git/info/refs?service=git-upload-pack", "process-type":"request"
}
#	0x89d1fd	github.com/mattn/go-sqlite3.unlock_notify_wait+0x15d			/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3_opt_unlock_notify.go:90
#	0x89e5c4	_cgoexp_2a83583a9b45_unlock_notify_wait+0x24				_cgo_gotypes.go:1419
#	0x406650	runtime.cgocallbackg1+0x2b0						/usr/local/go/src/runtime/cgocall.go:315
#	0x406308	runtime.cgocallbackg+0x108						/usr/local/go/src/runtime/cgocall.go:234
#	0x4724d3	runtime.cgocallback+0xb3						/usr/local/go/src/runtime/asm_amd64.s:998
#	0x4704e0	runtime.systemstack_switch+0x0						/usr/local/go/src/runtime/asm_amd64.s:463
#	0x406184	runtime.cgocall+0x84							/usr/local/go/src/runtime/cgocall.go:167
#	0x88582b	github.com/mattn/go-sqlite3._Cfunc__sqlite3_step_row_internal+0x4b	_cgo_gotypes.go:387
#	0x899a84	github.com/mattn/go-sqlite3.(*SQLiteStmt).execSync.func3+0x64		/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2084
#	0x899804	github.com/mattn/go-sqlite3.(*SQLiteStmt).execSync+0x64			/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2084
#	0x899751	github.com/mattn/go-sqlite3.(*SQLiteStmt).exec.func1+0x31		/go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2055

@elburb commented on GitHub (Aug 25, 2023): and just for reference, another slightly different example: ``` 1 @ 0x43df36 0x408f1d 0x408a18 0x89d1fe 0x89e5c5 0x406651 0x406309 0x4724d4 0x4704e1 0x406185 0x88582c 0x899a85 0x899805 0x899752 0x472701 # labels: {"graceful-lifecycle":"with-hammer", "pid":"64e635a3-2", "ppid":"", "process-description":"GET: /dn42/registry.git/info/refs?service=git-upload-pack", "process-type":"request" } # 0x89d1fd github.com/mattn/go-sqlite3.unlock_notify_wait+0x15d /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3_opt_unlock_notify.go:90 # 0x89e5c4 _cgoexp_2a83583a9b45_unlock_notify_wait+0x24 _cgo_gotypes.go:1419 # 0x406650 runtime.cgocallbackg1+0x2b0 /usr/local/go/src/runtime/cgocall.go:315 # 0x406308 runtime.cgocallbackg+0x108 /usr/local/go/src/runtime/cgocall.go:234 # 0x4724d3 runtime.cgocallback+0xb3 /usr/local/go/src/runtime/asm_amd64.s:998 # 0x4704e0 runtime.systemstack_switch+0x0 /usr/local/go/src/runtime/asm_amd64.s:463 # 0x406184 runtime.cgocall+0x84 /usr/local/go/src/runtime/cgocall.go:167 # 0x88582b github.com/mattn/go-sqlite3._Cfunc__sqlite3_step_row_internal+0x4b _cgo_gotypes.go:387 # 0x899a84 github.com/mattn/go-sqlite3.(*SQLiteStmt).execSync.func3+0x64 /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2084 # 0x899804 github.com/mattn/go-sqlite3.(*SQLiteStmt).execSync+0x64 /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2084 # 0x899751 github.com/mattn/go-sqlite3.(*SQLiteStmt).exec.func1+0x31 /go/pkg/mod/github.com/mattn/go-sqlite3@v1.14.16/sqlite3.go:2055 ```

GiteaMirror commented

@smartEBL commented on GitHub (Aug 25, 2023):

When I hear 1.20.2, sqlite and bug I have to think of https://github.com/go-gitea/gitea/issues/26280
This bug was fixed with a backport in 1.20.3 (https://github.com/go-gitea/gitea/pull/26339)

Just a quick thought.

@smartEBL commented on GitHub (Aug 25, 2023): When I hear `1.20.2`, `sqlite` and `bug` I have to think of https://github.com/go-gitea/gitea/issues/26280 This bug was fixed with a backport in 1.20.3 (https://github.com/go-gitea/gitea/pull/26339) Just a quick thought.

GiteaMirror commented

@elburb commented on GitHub (Aug 25, 2023):

When I hear 1.20.2, sqlite and bug I have to think of #26280 This bug was fixed with a backport in 1.20.3 (#26339)

Sadly, 1.20.3 has the same problem.

@elburb commented on GitHub (Aug 25, 2023): > When I hear `1.20.2`, `sqlite` and `bug` I have to think of #26280 This bug was fixed with a backport in 1.20.3 (#26339) Sadly, 1.20.3 has the same problem.

GiteaMirror commented

@smartEBL commented on GitHub (Aug 25, 2023):

Sadly, 1.20.3 has the same problem.

Hmm, okay. Nevermind then.

@smartEBL commented on GitHub (Aug 25, 2023): > Sadly, 1.20.3 has the same problem. Hmm, okay. Nevermind then.

GiteaMirror commented

@wxiaoguang commented on GitHub (Aug 25, 2023):

What's the full stacktrace? Partial information doesn't show the whole picture.

@wxiaoguang commented on GitHub (Aug 25, 2023): What's the full stacktrace? Partial information doesn't show the whole picture.

GiteaMirror commented

@lunny commented on GitHub (Aug 25, 2023):

I will take a look at this problem.

@lunny commented on GitHub (Aug 25, 2023): I will take a look at this problem.

GiteaMirror commented

https://gist.github.com/sesa-me/7ed3050ae68576f73017c9362cdf7c90

@elburb commented on GitHub (Aug 25, 2023):

Output from pprof, and the goroutine-before.txt and goroutine-after.txt are here:

@elburb commented on GitHub (Aug 25, 2023): Output from pprof, and the goroutine-before.txt and goroutine-after.txt are here: https://gist.github.com/sesa-me/7ed3050ae68576f73017c9362cdf7c90

GiteaMirror commented

@elburb commented on GitHub (Aug 27, 2023):

Just an update for my instance, I migrated the database to mariadb yesterday and have been happily running 1.20.3 for the past 24hrs. With sqlite, we typically saw it hang within a few hours so migrating looks like it has resolved/worked around the issue for us.

@elburb commented on GitHub (Aug 27, 2023): Just an update for my instance, I migrated the database to mariadb yesterday and have been happily running 1.20.3 for the past 24hrs. With sqlite, we typically saw it hang within a few hours so migrating looks like it has resolved/worked around the issue for us.

GiteaMirror commented