ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) #2858

shinsenter · 2021-08-26T06:19:03Z

Issue

Updated on 2021/09/15: I found that ApiRepositoryContentsControllerBase.scala is slow because of Disk I/O.

Impacted version: 4.36.1 (docker)

Deployment mode:
It is OK when viewing file history on webapp.
Fetching resource via API /api/v3/repos/<user>/<repo>/contents/<path> got too much errors.

Problem description:

ERROR g.c.servlet.GitAuthenticationFilter - error
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30004ms.
        at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
        at slick.jdbc.DataSourceJdbcDataSource.createConnection(JdbcDataSource.scala:71)
        at slick.jdbc.JdbcBackend$BaseSession.<init>(JdbcBackend.scala:494)
        at slick.jdbc.JdbcBackend$DatabaseDef.createSession(JdbcBackend.scala:46)
        at com.github.takezoe.slick.blocking.BlockingJdbcProfile$BlockingAPI$BlockingDatabase.withSession(BlockingProfile.scala:198)
        at gitbucket.core.servlet.GitAuthenticationFilter.defaultRepository(GitAuthenticationFilter.scala:98)
        at gitbucket.core.servlet.GitAuthenticationFilter.$anonfun$doFilter$2(GitAuthenticationFilter.scala:54)
        at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
        at scala.Option.getOrElse(Option.scala:201)
        at gitbucket.core.servlet.GitAuthenticationFilter.doFilter(GitAuthenticationFilter.scala:54)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
        at gitbucket.core.servlet.TransactionFilter.doFilter(TransactionFilter.scala:28)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:179)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:516)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
        at java.lang.Thread.run(Thread.java:748)

The text was updated successfully, but these errors were encountered:

takezoe · 2021-08-29T07:37:27Z

GitAuthenticationFilter is applied to only /git/*. What pass did you request?

shinsenter · 2021-08-30T05:13:27Z

@takezoe
I sent /api/v3/repos/<user>/<repo>/contents/<path> requests with these headers:

Accept: application/vnd.github.v3.raw
Authorization: token %the_access_token%

The ratio of successful queries with HTTP status 200 is about 40% (request timeout is 10 seconds).

takezoe · 2021-09-12T16:25:41Z

I confirmed that GitAuthenticationFilter isn't applied to that endpoint, anyway.

gitbucket/src/main/scala/ScalatraBootstrap.scala

Lines 24 to 26 in ab822a3

    
           context 
        
             .getFilterRegistration("gitAuthenticationFilter") 
        
             .addMappingForUrlPatterns(EnumSet.allOf(classOf[DispatcherType]), true, "/git/*")

Could you provide more information? For example, the following information would be helpful:

your setup details (how you launch docker image? whether external DB is used? etc)
the number and size of repositories
the number of users, tokens, etc
whether this error doesn't happen on other APIs?

Or it would be great if you can provide the step-by-step procedure to reproduce the issue from scratch.

shinsenter · 2021-09-15T01:23:19Z

Could you provide more information? For example, the following information would be helpful:

your setup details (how you launch docker image? whether external DB is used? etc)

the number and size of repositories

the number of users, tokens, etc

whether this error doesn't happen on other APIs?

Or it would be great if you can provide the step-by-step procedure to reproduce the issue from scratch.

This is my setup with docker-compose.yml (with MySQL is running on host machine):

version: '3'
services:
  gitbucket:
    image: gitbucket/gitbucket:4.36.1
    container_name: gitbucket
    ports:
      - "80:8080"
    volumes:
      - "/root/.gitbucket:/gitbucket"
    environment:
      GITBUCKET_DB_URL: jdbc:mysql://mysql:3306/gitbucket?useUnicode=true&characterEncoding=utf8
      GITBUCKET_DB_USER: root
      GITBUCKET_DB_PASSWORD: password

The repository size is around 56MB, with around 9000 commits.
There is only 1 user and 1 token for the repository.

[root@gitbucket]# du -sh WWW.git
56M     WWW.git

Request Timeout errors happen when retrieving content via API. It is OK when view raw content via Web URLs.

curl --location --request GET 'https://gitbucket.private.com/api/v3/repos/Global/WWW/contents/css/base.css?ref=master' \
--header 'Authorization: token 86086264b87af55e616fea522b783889b6b12230' \
--header 'Accept: application/vnd.github.v3.raw' \

takezoe · 2021-09-15T05:13:16Z

Sorry, one more question. Was this error started to happen after upgrading to a particular GitBucket version? or happens even on a fresh GitBucket instance?

shinsenter · 2021-09-15T08:44:41Z

@takezoe
It also happens with older version of docker image (gitbucket/gitbucket:4).
I have not tested with any binary version.
But I think there may be different logic for serving raw files of API and Webview.

shinsenter · 2021-09-15T09:06:36Z

After digging your source code, i found these parts:

■ This part (for webapp) is good, response is fast:

gitbucket/src/main/scala/gitbucket/core/controller/RepositoryViewerController.scala

Line 664 in ab822a3

get("/:owner/:repository/raw/*")(referrersOnly { repository =>

▼

gitbucket/src/main/scala/gitbucket/core/util/JGitUtil.scala

Line 1001 in ab822a3

    
           def getContentFromPath(git: Git, revTree: RevTree, path: String, fetchLargeFile: Boolean): Option[Array[Byte]] = {

■ This part (for API) is much slower:

gitbucket/src/main/scala/gitbucket/core/controller/api/ApiRepositoryContentsControllerBase.scala

Line 40 in ab822a3

get("/api/v3/repos/:owner/:repository/contents")(referrersOnly { repository =>

▼

gitbucket/src/main/scala/gitbucket/core/controller/api/ApiRepositoryContentsControllerBase.scala

Line 68 in ab822a3

private def getContents(

I think using the getContents() in this case is pretty slow because of Disk I/O.

Hope this helps.

takezoe · 2021-09-15T16:04:03Z

Ah, yes. That's a known issue also reported in #2674.

takezoe · 2021-09-15T16:05:34Z

And you have already commented on the PR :-) #2686 (comment)

shinsenter · 2021-09-15T22:57:04Z

@takezoe
I hope this problem will be fixed soon.
I'm implementing an ultra assets server system that allows accessing any version of files from gitbucket.

shinsenter · 2021-09-15T22:58:55Z

btw, GitAuthenticationFilter errors still exist.

gitbucket/src/main/scala/ScalatraBootstrap.scala

Line 29 in ab822a3

.getFilterRegistration("apiAuthenticationFilter")

takezoe · 2021-09-15T23:49:39Z

It's ApiAuthenticationFilter, not GitAuthenticationFilter.

takezoe added question APIv3 GitHub compatible API and removed question labels Aug 28, 2021

takezoe added waiting 4 user feedback and removed APIv3 GitHub compatible API labels Aug 29, 2021

shinsenter mentioned this issue Sep 15, 2021

Error with MySQL DB when migrating to v4.35.0 #2840

Open

shinsenter changed the title ~~GitAuthenticationFilter - error (Docker 4.36.1)~~ ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) Sep 15, 2021

takezoe mentioned this issue Sep 16, 2021

Optimize Get-Contents API #2873

Open

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) #2858

ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) #2858

shinsenter commented Aug 26, 2021 •

edited

takezoe commented Aug 29, 2021

shinsenter commented Aug 30, 2021 •

edited

takezoe commented Sep 12, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited

takezoe commented Sep 15, 2021

shinsenter commented Sep 15, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited

takezoe commented Sep 15, 2021

takezoe commented Sep 15, 2021

shinsenter commented Sep 15, 2021

shinsenter commented Sep 15, 2021 •

edited

takezoe commented Sep 15, 2021

ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) #2858

ApiRepositoryContentsControllerBase.scala is very slow (Docker 4.36.1) #2858

Comments

shinsenter commented Aug 26, 2021 • edited

Issue

takezoe commented Aug 29, 2021

shinsenter commented Aug 30, 2021 • edited

takezoe commented Sep 12, 2021 • edited

shinsenter commented Sep 15, 2021 • edited

takezoe commented Sep 15, 2021

shinsenter commented Sep 15, 2021 • edited

shinsenter commented Sep 15, 2021 • edited

takezoe commented Sep 15, 2021

takezoe commented Sep 15, 2021

shinsenter commented Sep 15, 2021

shinsenter commented Sep 15, 2021 • edited

takezoe commented Sep 15, 2021

shinsenter commented Aug 26, 2021 •

edited

shinsenter commented Aug 30, 2021 •

edited

takezoe commented Sep 12, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited

shinsenter commented Sep 15, 2021 •

edited