Slow rendering time when browsing repositories

redrabbit commented 5 years ago

We introduced a bunch of new features to improve browsing repositories. With #52 we are reaching a limit because rendering time gets excessively slow:

[info] GET /redrabbit/elixir
[info] Sent 200 in 2880ms

Now elixir is quite a big repository with >15.800 commits.

Neverless, the current implementation is rendering the page around 15x slower than before. Each time we want to render a tree, we have to

1) Create a commit history stream (with :pathspec option) starting at the given revision. 2) Find the first commit for each tree-entry from the history stream. 3) Render each tree entry and associated commit message and timestamp.

The slow part here is definitely 2). The new GitRekt.GitAgent.tree_entries_with_commits/3 is responsible for fetching tree-entries and their associated commits in one pass.

Because this operation is by design very inefficient, it can take forever if the tree in question contains lots of entries. Taking even longer if the entry's last commit is old.

First step for improving performances would be to refactor tree_entries_with_commits/3 and try to optimise things there.

If that doesn't bring enough, we will have to let the browser load tree entries commits asynchronously via GraphQL.

redrabbit commented 5 years ago

When showing a tree such as git-limo/apps/gitrekt containing 7 tree entries, we have to go through 134 commits to resolve all entries.

Here's a basic output log to better understand:

parse 7 tree entries
1 match
1 match
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/Makefile", "apps/gitrekt/c_src", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/Makefile", "apps/gitrekt/c_src", "apps/gitrekt/config", "apps/gitrekt/test"]
1 match
1 match
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/.gitignore", "apps/gitrekt/config", "apps/gitrekt/test"]
1 match
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
no match for ["apps/gitrekt/config", "apps/gitrekt/test"]
1 match
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
no match for ["apps/gitrekt/config"]
1 match

redrabbit commented 5 years ago

And here the newly :telemetry implemented logs for GitRekt.GitAgent....

Rendering GitGud.Web.CodebaseController.show/2 in 2674ms.

Counting total amount of commits (SQL) takes 69.3ms
Retrieving tree entries and associated commits takes 2585.6ms
Each other action take no more than a few µs.

[info] GET /redrabbit/elixir
[debug] Processing with GitGud.Web.CodebaseController.show/2
  Parameters: %{"repo_name" => "elixir", "user_login" => "redrabbit"}
  Pipelines: [:browser]
[debug] QUERY OK source="users" db=0.3ms
SELECT u0."id", u0."login", u0."name", u0."primary_email_id", u0."public_email_id", u0."bio", u0."location", u0."website_url", u0."avatar_url", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."id" = $1) [1]
[debug] QUERY OK source="repositories" db=0.5ms
SELECT r0."id", r0."owner_id", r0."name", r0."public", r0."description", r0."inserted_at", r0."updated_at", r0."pushed_at", u1."id", u1."login", u1."name", u1."primary_email_id", u1."public_email_id", u1."bio", u1."location", u1."website_url", u1."avatar_url", u1."inserted_at", u1."updated_at" FROM "repositories" AS r0 INNER JOIN "users" AS u1 ON u1."id" = r0."owner_id" LEFT OUTER JOIN "maintainers" AS m2 ON r0."id" = m2."repo_id" WHERE (u1."login" = $1) AND (r0."name" = $2) AND (((r0."public" = TRUE) OR (r0."owner_id" = $3)) OR (m2."user_id" = $4)) ["redrabbit", "elixir", 1, 1]
[debug] [Git Agent] empty?() executed in 230 µs
[debug] [Git Agent] head() executed in 65 µs
[debug] [Git Agent] peel(<GitRef:refs/heads/master>, :commit) executed in 111 µs
[debug] [Git Agent] tree(<GitCommit:ec14cb67>) executed in 48 µs
[debug] [Git Agent] references("refs/heads/*") executed in 49 µs
[debug] [Git Agent] references("refs/tags/*") executed in 61 µs
[debug] [Git Agent] peel(<GitRef:refs/heads/master>, :commit) executed in 27 µs
[debug] QUERY OK source="commits" db=69.3ms
SELECT count(c0."oid") FROM "commits" AS c0 INNER JOIN commits_dag_desc($1, $2) AS f1 ON c0."oid" = f1."oid" [4, <<236, 20, 203, 103, 99, 161, 65, 19, 137, 178, 3, 125, 204, 5, 246, 113, 101, 33, 223, 117>>]
[debug] [Git Agent] tree_entries_with_commits(<GitRef:refs/heads/master>) executed in 2585.588 ms
[debug] [Git Agent] message(<GitCommit:ae8502d8>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:ae8502d8>) executed in 8 µs
[debug] [Git Agent] message(<GitCommit:88037483>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:88037483>) executed in 6 µs
[debug] [Git Agent] message(<GitCommit:45862f84>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:45862f84>) executed in 6 µs
[debug] [Git Agent] message(<GitCommit:c93cd33e>) executed in 13 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:c93cd33e>) executed in 4 µs
[debug] [Git Agent] message(<GitCommit:5aa31f4a>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:5aa31f4a>) executed in 3 µs
[debug] [Git Agent] message(<GitCommit:1d170281>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:1d170281>) executed in 3 µs
[debug] [Git Agent] message(<GitCommit:786a3d2a>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:786a3d2a>) executed in 3 µs
[debug] [Git Agent] message(<GitCommit:786a3d2a>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:786a3d2a>) executed in 4 µs
[debug] [Git Agent] message(<GitCommit:1c914f13>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:1c914f13>) executed in 5 µs
[debug] [Git Agent] message(<GitCommit:5f502d0b>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:5f502d0b>) executed in 3 µs
[debug] [Git Agent] message(<GitCommit:d4f8d419>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:d4f8d419>) executed in 5 µs
[debug] [Git Agent] message(<GitCommit:9f03c38d>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:9f03c38d>) executed in 5 µs
[debug] [Git Agent] message(<GitCommit:b98c5acf>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:b98c5acf>) executed in 5 µs
[debug] [Git Agent] message(<GitCommit:b98c5acf>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:b98c5acf>) executed in 6 µs
[debug] [Git Agent] message(<GitCommit:b98c5acf>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:b98c5acf>) executed in 4 µs
[debug] [Git Agent] message(<GitCommit:25972a4a>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:25972a4a>) executed in 4 µs
[debug] [Git Agent] message(<GitCommit:ec14cb67>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:ec14cb67>) executed in 5 µs
[debug] [Git Agent] message(<GitCommit:e18d46f6>) executed in 2 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:e18d46f6>) executed in 4 µs
[debug] [Git Agent] tree_entry(<GitTree:a41dbaf9>, {:path, "README.md"}) executed in 5 µs
[debug] [Git Agent] tree_entry_target(<GitTreeEntry:README.md>) executed in 189 µs
[debug] [Git Agent] blob_content(<GitBlob:066a356b>) executed in 12 µs
[info] Sent 200 in 2674ms

redrabbit commented 5 years ago

Rendering GitGud.Web.CodebaseController.blob/2 in 931ms.

Here GitRekt.GitAgent.tree_entry_with_commit/2 takes 924.18ms...

[info] GET /redrabbit/elixir/blob/master/.formatter.exs
[debug] Processing with GitGud.Web.CodebaseController.blob/2
  Parameters: %{"path" => [".formatter.exs"], "repo_name" => "elixir", "revision" => "master", "user_login" => "redrabbit"}
  Pipelines: [:browser]
[debug] QUERY OK source="users" db=0.4ms
SELECT u0."id", u0."login", u0."name", u0."primary_email_id", u0."public_email_id", u0."bio", u0."location", u0."website_url", u0."avatar_url", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."id" = $1) [1]
[debug] QUERY OK source="repositories" db=0.5ms
SELECT r0."id", r0."owner_id", r0."name", r0."public", r0."description", r0."inserted_at", r0."updated_at", r0."pushed_at", u1."id", u1."login", u1."name", u1."primary_email_id", u1."public_email_id", u1."bio", u1."location", u1."website_url", u1."avatar_url", u1."inserted_at", u1."updated_at" FROM "repositories" AS r0 INNER JOIN "users" AS u1 ON u1."id" = r0."owner_id" LEFT OUTER JOIN "maintainers" AS m2 ON r0."id" = m2."repo_id" WHERE (u1."login" = $1) AND (r0."name" = $2) AND (((r0."public" = TRUE) OR (r0."owner_id" = $3)) OR (m2."user_id" = $4)) ["redrabbit", "elixir", 1, 1]
[debug] [Git Agent] revision("master") executed in 968 µs
[debug] [Git Agent] tree_entry_with_commit(<GitCommit:ec14cb67>, ".formatter.exs") executed in 924.185 ms
[debug] [Git Agent] tree_entry_target(<GitTreeEntry:.formatter.exs>) executed in 490 µs
[debug] [Git Agent] author(<GitCommit:88037483>) executed in 21 µs
[debug] QUERY OK source="users" db=0.5ms queue=0.5ms
SELECT u0."id", u0."login", u0."name", u0."primary_email_id", u0."public_email_id", u0."bio", u0."location", u0."website_url", u0."avatar_url", u0."inserted_at", u0."updated_at" FROM "users" AS u0 INNER JOIN "emails" AS e1 ON e1."user_id" = u0."id" WHERE ((e1."verified" = TRUE) AND (e1."address" = $1)) ["jose.valim@plataformatec.com.br"]
[debug] [Git Agent] committer(<GitCommit:88037483>) executed in 8 µs
[debug] [Git Agent] message(<GitCommit:88037483>) executed in 1 µs
[debug] [Git Agent] commit_timestamp(<GitCommit:88037483>) executed in 4 µs
[debug] [Git Agent] blob_content(<GitBlob:5af4d505>) executed in 2 µs
[info] Sent 200 in 931ms

redrabbit commented 5 years ago

First step for improving performances would be to refactor tree_entries_with_commits/3 and try to optimise things there.

Done a few things here and there but no big improvements.

If that doesn't bring enough, we will have to let the browser load tree entries commits asynchronously via GraphQL.

We now have new GraphQL query functions for fetching tree entries from a revision.

query {
  user(login:"redrabbit") {
    repo(name:"git-limo") {
      revision(spec:"master") {
        treeEntryWithLastCommit(path:"README.md") {
          commit {
            message
            timestamp
          }
        }
      }
    }
  }
}

Offloading the load to an asynchronous Javascript query offers a much better browsing experience.

redrabbit / git.limo

Slow rendering time when browsing repositories #53