SVN Mirror sync takes too long for all repositories

santhosh · December 12, 2022, 9:49am

Hi Ildar,

This is regarding the synchronisation time (from SVN to Bitbucket) that takes too long (15 minutes to 25 minutes) even though there are no revisions on SVN.

I have enabled the debug logs as suggested by you in another support ticket. I wanted a separate ticket for this issue.

I still see the same logs that I got before enabling the Debug Logging.

The same logs show up even after enabling the Debug logging as suggested by you.

2022-12-09 09:15:07,513 sync - Refs were successfully updated
2022-12-09 09:15:07,561 sync - Location ‘1244’ fetch completed, fetch took 1098413 ms.
2022-12-09 09:15:07,561 sync - Repository fetch completed, fetch took 1098440 ms.
2022-12-09 09:15:07,578 sync - about to refresh repository
2022-12-09 09:15:08,393 sync - ===
2022-12-09 10:15:09,577 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes
2022-12-09 10:15:10,206 sync - Repository fetch started.
2022-12-09 10:15:10,394 sync - svn authentication manager for ''http://yyyyy.com/svn/src’’
2022-12-09 10:15:10,563 sync - added user name credentials: ChakiSa
2022-12-09 10:15:10,563 sync - explicit user name credentials: ChakiSa
2022-12-09 10:15:10,583 sync - Checking remote 'http://yyyyy.com/svn/src’.
2022-12-09 10:15:10,712 sync - Revisions: <fetched=85126; last=85126>
2022-12-09 10:15:10,888 sync - svn authentication manager for ''http://yyyyy.com/svn/src’’
2022-12-09 10:15:10,888 sync - added user name credentials: ChakiSa
2022-12-09 10:15:10,888 sync - explicit user name credentials: ChakiSa
2022-12-09 10:20:35,144 sync - Restoring refs to reflect SVN state.

Can you please check?

Thanks,
Sitaram

ildar.khusainov · December 13, 2022, 4:16am

Hello Sitaram,

such an issue (including the “the server is busy" error) may as well be caused by lack of resources, namely, lack of threads to run the tasks SVN Mirror add-on receives. Could it be possible to raise number of threads for SVN Mirror, at least to check out if the situation changes or not? It could be done in global add-on settings, in the Administration - SVN Mirror - Global SVN Mirror Settings - Add-on Settings tab - Performance section - Thread Pool Size list:

If this does not change the situation, then we would need more information about the issue, namely, full logs for at least one affected repository (the can be collected in the repository SVN Mirror settings), Bitbucket logs, and also it would be very useful to have the jstack output collected:

jstack -l <Bitbucket process PID>

note that jstack is part of JDK, not JRE, so it may require a JDK installation or download.

santhosh · December 15, 2022, 12:08pm

Hi Ildar,

I tried to create a branch even when the sync was not running. As soon as I enter the new branch name and select “Create branch”, the sync starts immediately and throws the error that says “The server is busy with ongoing migration”
This means I cannot create a branch at any time. Please find the screenshots that explain the issue.

I do not see any change in this behaviour with the Thread Pool Size being increased from 8 to 32.

Also, is jcmd a better option that jstack? Can you confirm?
Reference: The jstack Utility

Thanks,
Sitaram

ildar.khusainov · December 15, 2022, 5:10pm

Hi Sitaram,

this behaviour that the synchronization starts once a change is made to a mirrored repository is expected, SVN Mirror add-on always performs synchronization prior to applying changes to the repository to avoid any inconsistencies. But the “Server is busy” message is of course unexpected and is not supposed to appear. As far as I see on the screenshot, the “build” repository is still fetching revisions – do I understand correctly this is the initial replication for that repository? If so, could it be possible to pause it for a while and test branch creation while it’s stopped? Also, could it be possible to try to disable and re-enable the add-on, or, better, to restart the Bitbucket cluster?
Also, I’m afraid that the screenshots while depict the situation, give us very little clues on what is happening under the hood and we definitely need more information about that. May I ask you to provide us with the full SVN Mirror logs from the config-core and build repositories along with Bitbucket logs? We would need the full logs, not only parts of them since short parts of logs also release very little information. And, of course, jstack command output would also be very helpful.

santhosh · December 16, 2022, 5:44am

Hi Ildar,

This is not the initial replication. The initial replication completed months ago. The sync process has been happening for a few months now with a poll interval of 3600 seconds (60 minutes).

I had to disable the sync and create the branches and then enable the sync again.
It appears it is not possible to perform any actions when the sync is enabled and even though the actual sync is not in progress. This is a concern for us.

The screenshots:
I wanted to show you the next synchronisation time for config-core repository which was supposed to happen at 17:39:38 from the first screenshot. But as soon as I try to create a branch in config-core repo, the sync starts as per the last screenshot. We still had 20 minutes for the next sync but the sync started at 17:20:xx even though it was supposed to happen at 17:39:38.

I will get back with the jstack logs once it is installed.

Is jcmd a better option when compared to jstack?
Reference: The jstack Utility

Please find the latest src repo logs:

022-12-15 17:56:35,425 sync - Location '1244' fetch completed, fetch took 964372 ms. 
2022-12-15 17:56:35,425 sync - Repository fetch completed, fetch took 964398 ms. 
2022-12-15 17:56:35,444 sync - about to refresh repository 
2022-12-15 17:56:36,212 sync - === 
2022-12-15 18:56:36,936 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 18:56:37,543 sync - Repository fetch started. 
2022-12-15 18:56:37,680 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 18:56:37,680 sync -   added user name credentials: ChakiSa 
2022-12-15 18:56:37,680 sync -   explicit user name credentials: ChakiSa 
2022-12-15 18:56:37,703 sync - Checking remote 'http://yyyyy.com/svn/src'. 
2022-12-15 18:56:38,099 sync - Revisions: <fetched=85161; last=85161> 
2022-12-15 18:56:38,927 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 18:56:39,120 sync -   added user name credentials: ChakiSa 
2022-12-15 18:56:39,120 sync -   explicit user name credentials: ChakiSa 
2022-12-15 19:01:19,120 sync - Restoring refs to reflect SVN state. 
2022-12-15 19:12:29,316 sync - Refs were successfully updated 
2022-12-15 19:12:29,361 sync - Location '1244' fetch completed, fetch took 951765 ms. 
2022-12-15 19:12:29,630 sync - Repository fetch completed, fetch took 952087 ms. 
2022-12-15 19:12:29,644 sync - about to refresh repository 
2022-12-15 19:12:30,476 sync - === 
2022-12-15 20:12:31,134 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 20:12:31,523 sync - Repository fetch started. 
2022-12-15 20:12:31,657 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 20:12:31,657 sync -   added user name credentials: ChakiSa 
2022-12-15 20:12:31,657 sync -   explicit user name credentials: ChakiSa 
2022-12-15 20:12:31,683 sync - Checking remote 'http://yyyyy.com/svn/src'. 
2022-12-15 20:12:33,056 sync - Revisions: <fetched=85161; last=85161> 
2022-12-15 20:12:33,206 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 20:12:33,265 sync -   added user name credentials: ChakiSa 
2022-12-15 20:12:33,265 sync -   explicit user name credentials: ChakiSa 
2022-12-15 20:16:38,519 sync - Restoring refs to reflect SVN state. 
2022-12-15 20:27:12,877 sync - Refs were successfully updated 
2022-12-15 20:27:12,902 sync - Location '1244' fetch completed, fetch took 881353 ms. 
2022-12-15 20:27:12,902 sync - Repository fetch completed, fetch took 881379 ms. 
2022-12-15 20:27:12,918 sync - about to refresh repository 
2022-12-15 20:27:13,502 sync - === 
2022-12-15 21:27:14,122 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 21:27:14,592 sync - Repository fetch started. 
2022-12-15 21:27:14,745 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 21:27:14,745 sync -   added user name credentials: ChakiSa 
2022-12-15 21:27:14,745 sync -   explicit user name credentials: ChakiSa 
2022-12-15 21:27:14,762 sync - Checking remote 'http://yyyyy.com/svn/src'. 
2022-12-15 21:27:15,183 sync - Revisions: <fetched=85161; last=85165> 
2022-12-15 21:27:15,318 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 21:27:15,706 sync -   added user name credentials: ChakiSa 
2022-12-15 21:27:15,706 sync -   explicit user name credentials: ChakiSa 
2022-12-15 21:27:22,851 sync - progress range: Fetching revisions from r85161 to r85165 
2022-12-15 21:27:23,606 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 21:27:23,606 sync -   added user name credentials: ChakiSa 
2022-12-15 21:27:23,606 sync -   explicit user name credentials: ChakiSa 
2022-12-15 21:27:24,861 sync - Starting fetch-back preventing procedure. 
2022-12-15 21:27:24,965 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 21:27:24,965 sync -   added user name credentials: ChakiSa 
2022-12-15 21:27:24,965 sync -   explicit user name credentials: ChakiSa 
2022-12-15 21:27:25,811 sync - Checking for fetch-back phase prevention feasibility. 
2022-12-15 21:27:26,096 sync - svn authentication manager for ''http://yyyyy.com/svn/src'' 
2022-12-15 21:27:26,096 sync -   added user name credentials: ChakiSa 
2022-12-15 21:27:26,096 sync -   explicit user name credentials: ChakiSa 
2022-12-15 21:27:26,213 sync - Fetching http://yyyyy.com/svn/src up to revision=HEAD 
2022-12-15 21:27:30,354 sync - SET_PATH '' 85165 not empty depth=infinity 
2022-12-15 21:27:30,365 sync - SET_PATH 'branches' 85165 not empty depth=infinity 
2022-12-15 21:27:30,365 sync - SET_PATH 'branches/PECVD_XL_XT_6_0' 85164 not empty depth=infinity 
2022-12-15 21:27:31,441 sync - fetching: branch = refs/svn/root/branches/PECVD_XL_XT_6_0, revision = 85165, receivedFileCount=0 
2022-12-15 21:27:31,763 sync - successfully received 'branches/PECVD_XL_XT_6_0/sqa/system/JunitFramework/EndToEndAutomation/PatchInstall.bat' with size=1359 
2022-12-15 21:27:31,838 sync - successfully received 'branches/PECVD_XL_XT_6_0/sqa/system/JunitFramework/EndToEndAutomation/RestoreBackupUpgrade.bat' with size=8339 
2022-12-15 21:27:36,523 sync - fetched: hash = 0a6aecdd58141271d96483cc0922a0f96ba63a94, branch = refs/svn/root/branches/PECVD_XL_XT_6_0, revision = 85165 
2022-12-15 21:27:37,369 sync - Updating latest fetched revision for svn-remote "svn" to r85165 
2022-12-15 21:31:13,394 sync - Restoring refs to reflect SVN state. 
2022-12-15 21:40:46,111 sync - Refs were successfully updated 
2022-12-15 21:40:46,134 sync - Location '1244' fetch completed, fetch took 811511 ms. 
2022-12-15 21:40:46,150 sync - Repository fetch completed, fetch took 811557 ms. 
2022-12-15 21:40:46,164 sync - about to refresh repository 
2022-12-15 21:40:46,164 sync -     ref delta: 42424f1fe29bef7d2cca163615f3fd805d3d212e 0a6aecdd58141271d96483cc0922a0f96ba63a94 refs/heads/PECVD_XL_XT_6_0 
2022-12-15 21:40:51,799 sync - ===

build repo logs:

2022-12-15 12:16:44,622 sync - Refs were successfully updated 
2022-12-15 12:16:44,680 sync - Location '1223' fetch completed, fetch took 994261 ms. 
2022-12-15 12:16:44,999 sync - Repository fetch completed, fetch took 994623 ms. 
2022-12-15 12:16:45,014 sync - about to refresh repository 
2022-12-15 12:16:46,318 sync - === 
2022-12-15 13:16:47,182 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 13:16:47,775 sync - Repository fetch started. 
2022-12-15 13:16:47,899 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 13:16:47,899 sync -   added user name credentials: ChakiSa 
2022-12-15 13:16:47,899 sync -   explicit user name credentials: ChakiSa 
2022-12-15 13:16:47,919 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 13:16:48,462 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 13:16:48,628 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 13:16:48,711 sync -   added user name credentials: ChakiSa 
2022-12-15 13:16:48,711 sync -   explicit user name credentials: ChakiSa 
2022-12-15 13:22:12,802 sync - Restoring refs to reflect SVN state. 
2022-12-15 13:34:10,123 sync - Refs were successfully updated 
2022-12-15 13:34:10,167 sync - Location '1223' fetch completed, fetch took 1042345 ms. 
2022-12-15 13:34:10,167 sync - Repository fetch completed, fetch took 1042371 ms. 
2022-12-15 13:34:10,190 sync - about to refresh repository 
2022-12-15 13:34:10,808 sync - === 
2022-12-15 14:34:11,850 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 14:34:12,302 sync - Repository fetch started. 
2022-12-15 14:34:12,398 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 14:34:12,398 sync -   added user name credentials: ChakiSa 
2022-12-15 14:34:12,398 sync -   explicit user name credentials: ChakiSa 
2022-12-15 14:34:12,427 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 14:34:12,605 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 14:34:12,710 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 14:34:12,781 sync -   added user name credentials: ChakiSa 
2022-12-15 14:34:12,781 sync -   explicit user name credentials: ChakiSa 
2022-12-15 14:38:52,358 sync - Restoring refs to reflect SVN state. 
2022-12-15 14:50:24,632 sync - Refs were successfully updated 
2022-12-15 14:50:24,660 sync - Location '1223' fetch completed, fetch took 972336 ms. 
2022-12-15 14:50:24,660 sync - Repository fetch completed, fetch took 972358 ms. 
2022-12-15 14:50:24,671 sync - about to refresh repository 
2022-12-15 14:50:25,489 sync - === 
2022-12-15 15:50:26,334 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 15:50:26,820 sync - Repository fetch started. 
2022-12-15 15:50:26,909 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 15:50:26,909 sync -   added user name credentials: ChakiSa 
2022-12-15 15:50:26,909 sync -   explicit user name credentials: ChakiSa 
2022-12-15 15:50:26,927 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 15:50:27,314 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 15:50:27,468 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 15:50:27,519 sync -   added user name credentials: ChakiSa 
2022-12-15 15:50:27,519 sync -   explicit user name credentials: ChakiSa 
2022-12-15 15:54:53,395 sync - Restoring refs to reflect SVN state. 
2022-12-15 16:06:11,266 sync - Refs were successfully updated 
2022-12-15 16:06:11,414 sync - Location '1223' fetch completed, fetch took 944574 ms. 
2022-12-15 16:06:11,414 sync - Repository fetch completed, fetch took 944594 ms. 
2022-12-15 16:06:11,429 sync - about to refresh repository 
2022-12-15 16:06:12,030 sync - === 
2022-12-15 17:06:13,081 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 17:06:13,564 sync - Repository fetch started. 
2022-12-15 17:06:13,677 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 17:06:13,677 sync -   added user name credentials: ChakiSa 
2022-12-15 17:06:13,677 sync -   explicit user name credentials: ChakiSa 
2022-12-15 17:06:13,701 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 17:06:15,154 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 17:06:15,226 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 17:06:15,226 sync -   added user name credentials: ChakiSa 
2022-12-15 17:06:15,226 sync -   explicit user name credentials: ChakiSa 
2022-12-15 17:10:55,389 sync - Restoring refs to reflect SVN state. 
2022-12-15 17:22:18,536 sync - Refs were successfully updated 
2022-12-15 17:22:18,560 sync - Location '1223' fetch completed, fetch took 964953 ms. 
2022-12-15 17:22:18,560 sync - Repository fetch completed, fetch took 964996 ms. 
2022-12-15 17:22:18,575 sync - about to refresh repository 
2022-12-15 17:22:19,407 sync - === 
2022-12-15 18:22:20,436 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 18:22:21,168 sync - Repository fetch started. 
2022-12-15 18:22:21,291 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 18:22:21,373 sync -   added user name credentials: ChakiSa 
2022-12-15 18:22:21,432 sync -   explicit user name credentials: ChakiSa 
2022-12-15 18:22:21,455 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 18:22:21,812 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 18:22:21,907 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 18:22:21,966 sync -   added user name credentials: ChakiSa 
2022-12-15 18:22:21,966 sync -   explicit user name credentials: ChakiSa 
2022-12-15 18:27:22,556 sync - Restoring refs to reflect SVN state. 
2022-12-15 18:39:56,182 sync - Refs were successfully updated 
2022-12-15 18:39:56,224 sync - Location '1223' fetch completed, fetch took 1055026 ms. 
2022-12-15 18:39:56,288 sync - Repository fetch completed, fetch took 1055120 ms. 
2022-12-15 18:39:56,304 sync - about to refresh repository 
2022-12-15 18:39:57,067 sync - === 
2022-12-15 19:39:57,837 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 19:39:58,348 sync - Repository fetch started. 
2022-12-15 19:39:58,452 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 19:39:58,452 sync -   added user name credentials: ChakiSa 
2022-12-15 19:39:58,452 sync -   explicit user name credentials: ChakiSa 
2022-12-15 19:39:58,472 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 19:40:01,828 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 19:40:02,460 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 19:40:02,460 sync -   added user name credentials: ChakiSa 
2022-12-15 19:40:02,460 sync -   explicit user name credentials: ChakiSa 
2022-12-15 19:44:29,351 sync - Restoring refs to reflect SVN state. 
2022-12-15 19:55:17,100 sync - Refs were successfully updated 
2022-12-15 19:55:17,145 sync - Location '1223' fetch completed, fetch took 918768 ms. 
2022-12-15 19:55:17,145 sync - Repository fetch completed, fetch took 918797 ms. 
2022-12-15 19:55:17,159 sync - about to refresh repository 
2022-12-15 19:55:17,867 sync - === 
2022-12-15 20:55:18,474 sync - server 7.21.3 7021003; add-on 4.0.7; cluster has 2 nodes 
2022-12-15 20:55:19,096 sync - Repository fetch started. 
2022-12-15 20:55:19,207 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 20:55:19,207 sync -   added user name credentials: ChakiSa 
2022-12-15 20:55:19,207 sync -   explicit user name credentials: ChakiSa 
2022-12-15 20:55:19,226 sync - Checking remote 'http://yyyyy.com/svn/build'. 
2022-12-15 20:55:19,530 sync - Revisions: <fetched=85163; last=85163> 
2022-12-15 20:55:20,123 sync - svn authentication manager for ''http://yyyyy.com/svn/build'' 
2022-12-15 20:55:20,123 sync -   added user name credentials: ChakiSa 
2022-12-15 20:55:20,123 sync -   explicit user name credentials: ChakiSa 
2022-12-15 20:59:00,510 sync - Restoring refs to reflect SVN state. 
2022-12-15 21:08:28,842 sync - Refs were successfully updated 
2022-12-15 21:08:28,864 sync - Location '1223' fetch completed, fetch took 789746 ms. 
2022-12-15 21:08:28,864 sync - Repository fetch completed, fetch took 789768 ms. 
2022-12-15 21:08:28,879 sync - about to refresh repository 
2022-12-15 21:08:29,603 sync - ===

Thanks,
Sitaram

ildar.khusainov · December 16, 2022, 5:56am

Hi Sitaram,

ok, thank you for explanation.
Regarding the icmd/jstack – the main idea is to get the complete stack trace, the tool itself matters less.
As for the logs – I’m afraid that is exactly what I meant saying that parts on logs don’t bring much information, we definitely need full logs, both SVN Mirror and Bitbucket’s logs, could it be possible to collect full logs instead?

santhosh · December 16, 2022, 10:17am

Hi Ildar,

Do we need any restart after thread pool size is increased?

Thanks,
Sitaram

ildar.khusainov · December 16, 2022, 12:00pm

Hi Sitaram,

no, that setting does not require server restart, it’s being applied on the fly. However, we suspect some error conditions on the server or in the add-on, that’s why we mentioned possible restart.

santhosh · February 16, 2023, 6:02am

Hi ildar,
I’m trying to upload full SVN mirror logs of size 17MB but that is throwing an error though the max allowed size is 50MB. Please let me know if any other to share the logs.
I’m checking with my team for bitbucket logs. Will share it asap.
Thanks
Venkat