Filter function for repository search gets slowly

[Chihiro Watanabe]

Hi

We upgraded Gerrit from v2.15.22 to v3.4.1.
Sometimes, the filter function for the repository search gets slowly.



We executed the query every 1 second and showed the results graphically.
  Horizontal axis: time the query is executed
  Vertical axis: response time outputted in http_log



We confirmed that the response time got slowly every few hours.
We referred about response time from the following document.
https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/logs.html

The below log in http_log showed the query took 1,139,998 milliseconds to response.

xxx.xxx.xxx.xxx [HTTP-224556] - xxxxx [2023-01-26T11:18:46.671+09:00] "GET /a/projects/?query=platform HTTP/1.1" 200 32768 1139998 - "curl/7.58.0" 6260 4480 2983452888


We checked thread dump when the query was slower, we found the processing of WindowCache.removeAll was "wait"

"HTTP GET /a/projects/?query=platform (0048800102 from 10.26.24.7)" #224556 prio=5 os_prio=0 cpu=67057.77ms elapsed=58111.20s tid=0x00007e930c006000 nid=0x6614 waiting for monitor entry  [0x00007e93dbaf7000]
./jstack.out_20230126_110453:   java.lang.Thread.State: BLOCKED (on object monitor)
   at org.eclipse.jgit.lib.RepositoryCache.openRepository(RepositoryCache.java:242)
   - waiting to lock <0x00007ea262bb85a0> (a org.eclipse.jgit.lib.RepositoryCache$Lock)


 "JGit-WorkQueue" #37 daemon prio=5 os_prio=0 cpu=129145320.78ms elapsed=769921.60s tid=0x00007e9c8c1aa800 nid=0x77b7 runnable  [0x00007e9cdd281000]
   java.lang.Thread.State: RUNNABLE
   at org.eclipse.jgit.internal.storage.file.WindowCache.removeAll(WindowCache.java:718)
   at org.eclipse.jgit.internal.storage.file.WindowCache.purge(WindowCache.java:398)
   at org.eclipse.jgit.internal.storage.file.Pack.close(Pack.java:286)
   at org.eclipse.jgit.internal.storage.file.PackDirectory.close(PackDirectory.java:102)
   at org.eclipse.jgit.internal.storage.file.ObjectDirectory.close(ObjectDirectory.java:199)
   at org.eclipse.jgit.lib.Repository.doClose(Repository.java:967)
   at org.eclipse.jgit.lib.RepositoryCache.unregisterAndCloseRepository(RepositoryCache.java:276)
   - locked <0x00007ea262bb85a0> (a org.eclipse.jgit.lib.RepositoryCache$Lock)
   

We have not confirmed this behavior in Gerrit 2.15.22.

Does anyone know why the filter function for repository search gets slow in Gerrit 3.4.1?
Is there any solution to fix this issue?

[natali...@gmail.com]

Hi,

In my case, it's a side effect from this change.

https://gerrit-review.googlesource.com/c/gerrit/+/341594

The change would run match for each predicate(i.e. file:<query>, message:<query>,etc.) instead of using the search results from index.

That would require a lot of read from git repository to get change file list or commit message, hence slows down the query.

I end up reverting the change to restore the performance.

[Luca Milanesio]

On 21 Feb 2023, at 08:41, natali...@gmail.com <natali...@gmail.com> wrote:

Hi,

In my case, it's a side effect from this change.

https://gerrit-review.googlesource.com/c/gerrit/+/341594

The change would run match for each predicate(i.e. file:<query>, message:<query>,etc.) instead of using the search results from index.

That would require a lot of read from git repository to get change file list or commit message, hence slows down the query.

I end up reverting the change to restore the performance.

Thanks for reporting this: can you please raise an issue with the steps to reproduce the issue?

Luca.

--
--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/e9ad504a-94fc-4721-b8ad-c97ebf099fddn%40googlegroups.com.

[Nasser Grainawi]

On Tue, Feb 21, 2023 at 1:39 PM Luca Milanesio <luca.mi...@gmail.com> wrote:

On 21 Feb 2023, at 08:41, natali...@gmail.com <natali...@gmail.com> wrote:

Hi,

In my case, it's a side effect from this change.

https://gerrit-review.googlesource.com/c/gerrit/+/341594

The change would run match for each predicate(i.e. file:<query>, message:<query>,etc.) instead of using the search results from index.

That would require a lot of read from git repository to get change file list or commit message, hence slows down the query.

I end up reverting the change to restore the performance.

Thanks for reporting this: can you please raise an issue with the steps to reproduce the issue?

I'll second that request. The change linked above only affects the 'label' operator when used with group= or with a group as a positional arg (like in 'label:Code-Review=1,externalGroupName') and should have no impacts on operators like 'file:' or 'message:'.

 

To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/51C7824C-B272-45B4-8D4E-DB1CA1268072%40gmail.com.

[Nasser Grainawi]

On Sun, Feb 19, 2023 at 8:48 PM Chihiro Watanabe <chihiro.a...@gmail.com> wrote:

Hi

We upgraded Gerrit from v2.15.22 to v3.4.1.
Sometimes, the filter function for the repository search gets slowly.



We executed the query every 1 second and showed the results graphically.
  Horizontal axis: time the query is executed
  Vertical axis: response time outputted in http_log



We confirmed that the response time got slowly every few hours. 

We referred about response time from the following document.
https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/logs.html

The below log in http_log showed the query took 1,139,998 milliseconds to response.

xxx.xxx.xxx.xxx [HTTP-224556] - xxxxx [2023-01-26T11:18:46.671+09:00] "GET /a/projects/?query=platform HTTP/1.1" 200 32768 1139998 - "curl/7.58.0" 6260 4480 2983452888


We checked thread dump when the query was slower, we found the processing of WindowCache.removeAll was "wait"

Does that "every few hours" timing correlate to your setting value for https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/config-gerrit.html#core.repositoryCacheExpireAfter ? That configuration will force unused repositories to actually close (instead of being returned to the RepositoryCache) which will call WindowCache.removeAll for all of those repositories.

 

"HTTP GET /a/projects/?query=platform (0048800102 from 10.26.24.7)" #224556 prio=5 os_prio=0 cpu=67057.77ms elapsed=58111.20s tid=0x00007e930c006000 nid=0x6614 waiting for monitor entry  [0x00007e93dbaf7000]
./jstack.out_20230126_110453:   java.lang.Thread.State: BLOCKED (on object monitor)
   at org.eclipse.jgit.lib.RepositoryCache.openRepository(RepositoryCache.java:242)
   - waiting to lock <0x00007ea262bb85a0> (a org.eclipse.jgit.lib.RepositoryCache$Lock)


 "JGit-WorkQueue" #37 daemon prio=5 os_prio=0 cpu=129145320.78ms elapsed=769921.60s tid=0x00007e9c8c1aa800 nid=0x77b7 runnable  [0x00007e9cdd281000]
   java.lang.Thread.State: RUNNABLE
   at org.eclipse.jgit.internal.storage.file.WindowCache.removeAll(WindowCache.java:718)
   at org.eclipse.jgit.internal.storage.file.WindowCache.purge(WindowCache.java:398)
   at org.eclipse.jgit.internal.storage.file.Pack.close(Pack.java:286)
   at org.eclipse.jgit.internal.storage.file.PackDirectory.close(PackDirectory.java:102)
   at org.eclipse.jgit.internal.storage.file.ObjectDirectory.close(ObjectDirectory.java:199)
   at org.eclipse.jgit.lib.Repository.doClose(Repository.java:967)
   at org.eclipse.jgit.lib.RepositoryCache.unregisterAndCloseRepository(RepositoryCache.java:276)
   - locked <0x00007ea262bb85a0> (a org.eclipse.jgit.lib.RepositoryCache$Lock)
   

We have not confirmed this behavior in Gerrit 2.15.22.

Does anyone know why the filter function for repository search gets slow in Gerrit 3.4.1?
Is there any solution to fix this issue?

--

--
To unsubscribe, email repo-discuss...@googlegroups.com
More info at http://groups.google.com/group/repo-discuss?hl=en

---
You received this message because you are subscribed to the Google Groups "Repo and Gerrit Discussion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to repo-discuss...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/repo-discuss/291a80bb-2c20-4b8b-b0b2-9a670a9ef719n%40googlegroups.com.

[natali...@gmail.com]

On Wednesday, February 22, 2023 at 7:25:40 AM UTC+8 Nasser Grainawi wrote:

On Tue, Feb 21, 2023 at 1:39 PM Luca Milanesio <luca.mi...@gmail.com> wrote:

On 21 Feb 2023, at 08:41, natali...@gmail.com <natali...@gmail.com> wrote:

Hi,

In my case, it's a side effect from this change.

https://gerrit-review.googlesource.com/c/gerrit/+/341594

The change would run match for each predicate(i.e. file:<query>, message:<query>,etc.) instead of using the search results from index.

That would require a lot of read from git repository to get change file list or commit message, hence slows down the query.

I end up reverting the change to restore the performance.

Thanks for reporting this: can you please raise an issue with the steps to reproduce the issue?

I'll second that request. The change linked above only affects the 'label' operator when used with group= or with a group as a positional arg (like in 'label:Code-Review=1,externalGroupName') and should have no impacts on operators like 'file:' or 'message:'.

https://bugs.chromium.org/p/gerrit/issues/detail?id=16713

Thank you.

 

[Chihiro Watanabe]

On Wednesday, February 22, 2023 at 8:29:42 AM UTC+9 Nasser Grainawi wrote:

On Sun, Feb 19, 2023 at 8:48 PM Chihiro Watanabe <chihiro.a...@gmail.com> wrote:

Hi

We upgraded Gerrit from v2.15.22 to v3.4.1.
Sometimes, the filter function for the repository search gets slowly.



We executed the query every 1 second and showed the results graphically.
  Horizontal axis: time the query is executed
  Vertical axis: response time outputted in http_log



We confirmed that the response time got slowly every few hours. We referred about response time from the following document.
https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/logs.html

The below log in http_log showed the query took 1,139,998 milliseconds to response.

xxx.xxx.xxx.xxx [HTTP-224556] - xxxxx [2023-01-26T11:18:46.671+09:00] "GET /a/projects/?query=platform HTTP/1.1" 200 32768 1139998 - "curl/7.58.0" 6260 4480 2983452888


We checked thread dump when the query was slower, we found the processing of WindowCache.removeAll was "wait"

Does that "every few hours" timing correlate to your setting value for https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/config-gerrit.html#core.repositoryCacheExpireAfter ? That configuration will force unused repositories to actually close (instead of being returned to the RepositoryCache) which will call WindowCache.removeAll for all of those repositories.

We have not configured core.repositoryCacheExpireAfter in gerrit.config, so it is 1h, default.

but the timing is not every 1h. the timing is not regularly.

[Martin Fick]

On Tue, Feb 21, 2023 at 04:29:23PM -0700, Nasser Grainawi wrote:
> On Sun, Feb 19, 2023 at 8:48 PM Chihiro Watanabe <
> chihiro.a...@gmail.com> wrote:
>
> > We checked thread dump when the query was slower, we found the processing
> > of WindowCache.removeAll was "wait"
> >
>
> Does that "every few hours" timing correlate to your setting value for
> https://gerrit-documentation.storage.googleapis.com/Documentation/3.4.1/config-gerrit.html#core.repositoryCacheExpireAfter
> ? That configuration will force unused repositories to actually close
> (instead of being returned to the RepositoryCache) which will call
> WindowCache.removeAll for all of those repositories.

The jgit RepositoryCache expiry looks racy to me, it removes and closes
expired Repositories without preventing the Repository from being handed
out to be used again after the it was deemed expired. The behavior your
are seeing is likely symptomatic of Repositories being closed over and
over, as if it had expired over and over, or as if a Repository which is
not in the RepoitoryCache is being used over and over. I am not sure if
these two things can be linked, but there is a chance they are,

-Martin