Issue 23620 - CVS commit takes very long
Summary: CVS commit takes very long
Status: CLOSED FIXED
Alias: None
Product: Infrastructure
Classification: Infrastructure
Component: Upgrade (show other issues)
Version: current
Hardware: All All
: P2 Trivial (vote)
Target Milestone: ---
Assignee: Unknown
QA Contact: issues@www
URL:
Keywords:
Depends on: 29983
Blocks: 23355
  Show dependency tree
 
Reported: 2003-12-17 13:04 UTC by stx123
Modified: 2004-07-06 18:33 UTC (History)
3 users (show)

See Also:
Issue Type: DEFECT
Latest Confirmation in: ---
Developer Difficulty: ---


Attachments

Note You need to log in before you can comment on or make changes to this issue.
Description stx123 2003-12-17 13:04:12 UTC
cvs commit takes from 35sec to 1m16.743s. Most of the action is done within the 
first 3 seconds.
The last 3 lines of the trace below need the rest of the time.

$ time cvs -t commit -m "add title" sitemap.html
 -> main loop with CVSROOT=:pserver:st@so-cvs-tunnel:/cvs
 -> Connecting to so-cvs-tunnel(172.17.11.188):2401
 -> Sending file `sitemap.html' to server
S-> checkout (/cvs/www/www/sitemap.html,v, 1.20, , (function))
 -> ParseInfo(/cvs/CVSROOT/commitinfo, www/www, ALL)
S-> system('/opt/sourcecast/runtime/scripts/case-
protect.py' '/cvs/www/www' 'sitemap.html')
S-> system('/opt/sourcecast/runtime/scripts/log-
project.py' '/cvs/www/www' 'sitemap.html')
 -> ParseInfo(/cvs/CVSROOT/verifymsg, www/www, not ALL)
S-> system('/opt/sourcecast/runtime/scripts/verify-cvs-commit-
msg.py' '/tmp/cvsPuayPi')
S-> unlink_file(/tmp/cvsPuayPi)
Checking in sitemap.html;
/cvs/www/www/sitemap.html,v  <--  sitemap.html
S-> checkout (/cvs/www/www/sitemap.html,v, 1.20, -ko, /tmp/cvsQuayPi)
new revision: 1.21; previous revision: 1.20
S-> rename(/cvs/www/www/,sitemap.html,,/cvs/www/www/sitemap.html,v)
S-> unlink_file(/tmp/cvsQuayPi)
S-> unlink_file(/tmp/cvsRuayPi)
done
S-> checkout (/cvs/www/www/sitemap.html,v, , , (function))
S-> checkout (/cvs/www/www/sitemap.html,v, , , sitemap.html)
S-> chmod(sitemap.html,100644)
S-> server_register(sitemap.html, 1.21, Wed Dec 17 11:17:42 2003, , , , )
S-> Register(sitemap.html, 1.21, Wed Dec 17 11:17:42 2003, ,  )
S-> fopen(/cvs/CVSROOT/history,a)
 -> rename(.new.sitemap.h,sitemap.html)
 -> unlink_file(CVS/Base/sitemap.html)
 -> Register(sitemap.html, 1.21, Wed Dec 17 11:17:42 2003, ,  )
S-> loginfo_xml(/cvs/www/www, ...)
S-> entry_xml(Modified, sitemap.html, ...)
 -> ParseInfo(/cvs/CVSROOT/loginfo, www/www, ALL)
S-> run_popen((cat > /dev/null ; /cvs/CVSROOT/publish "www/www sitemap.html" 
&),w)
S-> rename(CVS/Entries.Backup,CVS/Entries)
S-> unlink_file(CVS/Entries.Log)
 -> rename(CVS/Entries.Backup,CVS/Entries)
 -> unlink_file(CVS/Entries.Log)
 -> Lock_Cleanup()

real    0m35.474s
user    0m0.012s
sys     0m0.010s
Comment 1 Martin Hollmichel 2003-12-17 14:16:11 UTC
this behavior only applies to www subdirs, as already mentioned in 23160.
regualar commits to the code repository are working much faster.
Comment 2 Unknown 2003-12-17 23:47:26 UTC
Assigning to Priya to address.
Eric
Comment 3 lsuarezpotts 2003-12-17 23:57:13 UTC
thanks for updating, Eric. Priya, please see PCN 24611.
louis 
Comment 4 Unknown 2003-12-18 06:10:41 UTC
Waiting for the update form the engineers. Moving this issue in Support Queue 
for visibility.
Comment 5 Unknown 2004-02-03 22:26:55 UTC
reassigning to ST to follow up with permormance data/comments post-upgrade
Comment 6 stx123 2004-02-04 15:45:00 UTC
Hi Kenneth,
what do you expect me to do?
If the issue is resolved, change the status accordingly.
If you have to check whether the behaviour has changed since the change to
2.6.2.4, please do so.

$ time cvs commit -m "added title"
cvs commit: Examining .
Checking in readme.html;
/cvs/www/www/welcome/readme.html,v  <--  readme.html
new revision: 1.19; previous revision: 1.18
done

real    1m34.344s
user    0m0.006s
sys     0m0.006s
Comment 7 Unknown 2004-02-04 23:44:45 UTC
closing
Comment 8 stx123 2004-02-05 10:27:01 UTC
Sorry, but the issue is not resolved.
In my comment from Feb 4 you see the time a cvs commit took after the upgrade to
2.6.2.4. Here is another run 

$  time cvs -t commit -m "change ..."
 -> main loop with CVSROOT=:pserver:st@so-cvs-tunnel:/cvs
cvs commit: Examining .
cvs commit: Examining 1.0.0
cvs commit: Examining 1.0.3
cvs commit: Examining 1.1.0
cvs commit: Examining 1.1rc5
cvs commit: Examining 680
cvs commit: Examining latest_build
cvs commit: Examining sdk
cvs commit: Examining templates
 -> Connecting to so-cvs-tunnel(172.17.11.188):2401
 -> Sending file `get_tarballs.html' to server
S-> checkout (/cvs/www/www/dev_docs/source/get_tarballs.html,v, 1.47, , (function))
 -> ParseInfo(/cvs/CVSROOT/commitinfo, www/www/dev_docs/source, ALL)
S-> system('/opt/sourcecast/runtime/scripts/log-project.py'
'/cvs/www/www/dev_docs/source' 'get_tarballs.html')
 -> ParseInfo(/cvs/CVSROOT/verifymsg, www/www/dev_docs/source, not ALL)
S-> system('/opt/sourcecast/runtime/scripts/verify-cvs-commit-msg.py'
'/tmp/cvsFPaajr')
S-> unlink_file(/tmp/cvsFPaajr)
Checking in get_tarballs.html;
/cvs/www/www/dev_docs/source/get_tarballs.html,v  <--  get_tarballs.html
S-> checkout (/cvs/www/www/dev_docs/source/get_tarballs.html,v, 1.47, -ko,
/tmp/cvsGPaajr)
new revision: 1.48; previous revision: 1.47
S->
rename(/cvs/www/www/dev_docs/source/,get_tarballs.html,,/cvs/www/www/dev_docs/source/get_tarballs.html,v)
S-> unlink_file(/tmp/cvsGPaajr)
S-> unlink_file(/tmp/cvsHPaajr)
done
S-> checkout (/cvs/www/www/dev_docs/source/get_tarballs.html,v, , , (function))
S-> server_register(get_tarballs.html, 1.48, Thu Feb  5 10:21:57 2004, , , , )
S-> Register(get_tarballs.html, 1.48, Thu Feb  5 10:21:57 2004, ,  )
S-> fopen(/cvs/CVSROOT/history,a)
 -> unlink_file(CVS/Base/get_tarballs.html)
 -> Register(get_tarballs.html, 1.48, Thu Feb  5 10:21:27 2004, ,  )
S-> loginfo_xml(/cvs/www/www/dev_docs/source, ...)
S-> entry_xml(Modified, get_tarballs.html, ...)
 -> ParseInfo(/cvs/CVSROOT/loginfo, www/www/dev_docs/source, ALL)
S-> run_popen((cat > /dev/null ; /cvs/CVSROOT/publish "www/www/dev_docs/source
get_tarballs.html" &),w)
S-> rename(CVS/Entries.Backup,CVS/Entries)
S-> unlink_file(CVS/Entries.Log)
 -> rename(CVS/Entries.Backup,CVS/Entries)
 -> unlink_file(CVS/Entries.Log)
 -> Lock_Cleanup()

real    3m51.372s
user    0m0.010s
sys     0m0.016s
Comment 9 Unknown 2004-02-12 22:27:40 UTC
reassigning to reporter for performance testing post- hardware upgrade.
Comment 10 Martin Hollmichel 2004-02-17 10:25:58 UTC
cvs commits to www subdirectories still last significantly longer than regular
commits to the code repository (about 1 min per commit).
Comment 11 Unknown 2004-02-17 21:26:10 UTC
postupgrade data has been very favorable. we've sent some preliminary
performance data to Eric @ Sun. after another week we'll send another report and
will move to close out these issues.
Comment 12 Unknown 2004-03-12 12:50:45 UTC
Changing the whiteboard.
Comment 13 Unknown 2004-03-24 22:18:38 UTC
st:
when/if there's a long commit time:
1) please reassign the issue to support@
2) the filename/directory of the file
3) the time of the attempt
4) copies of the user's errors (if they have cvs output and timestamps it'd be
beneficial)
5) any other relevant information
once this is done, support will pass this information on to our response
engineers  who will research the problem immediately
Comment 14 stx123 2004-03-25 11:19:59 UTC
Hope that helps:

$ time cvs  commit -m "update to test update" sitemap.html ; date -u
Checking in sitemap.html;
/cvs/www/www/sitemap.html,v  <--  sitemap.html
new revision: 1.26; previous revision: 1.25
done

real    0m56.193s
user    0m0.010s
sys     0m0.002s
Thu Mar 25 11:09:21 UTC 2004

$ time cvs  commit -m "update to test update" readme.html ; date -u
Checking in readme.html;
/cvs/www/www/welcome/readme.html,v  <--  readme.html
new revision: 1.21; previous revision: 1.20
done

real    0m38.618s
user    0m0.006s
sys     0m0.008s
Thu Mar 25 11:11:42 UTC 2004

$ time cvs  commit -m "update to test update" faq.html ; date -u
Checking in faq.html;
/cvs/api/www/faq.html,v  <--  faq.html
new revision: 1.14; previous revision: 1.13
done

real    4m44.083s
user    0m0.002s
sys     0m0.008s
Thu Mar 25 11:17:09 UTC 2004
Comment 15 Unknown 2004-03-26 10:17:54 UTC
Updated these info to the engineer in the internal issue 27526 to look at. Will 
update as soon as i get the update from him.

- Priya
Comment 16 Unknown 2004-03-31 06:24:09 UTC
The engineer is working on this issue may come up with a patch for the OO 
instance. Will update further once he updates further. 

Thanks,
Priya
Comment 17 Unknown 2004-04-13 22:23:03 UTC
The new instance set which covers this fix is in the final stages of work and
should be ready to roll out to the live site by the end of the week. We can
discuss this during our weekly call on Thursday and discuss possible windows to
do this.
Comment 18 Unknown 2004-04-15 02:03:04 UTC
Engineering has applied the patch to openoffice stage and building new instance set.
Still waiting for completion.
Eric
Comment 19 Unknown 2004-04-21 19:44:52 UTC
Update:

The status of this is that the patch is complete and will appear with the next
instance set rollout.
Eric
Comment 20 Unknown 2004-05-06 04:30:56 UTC
I am trying to get an estimate of when this can be rolled to stage.
Eric
Comment 21 Unknown 2004-05-11 23:46:55 UTC
I am trying to get this rolled to stage by tomorrow.
Eric
Comment 22 Unknown 2004-05-12 23:45:58 UTC
Hi Stefan,
I just received confirmation that this instance set has been rolled out onto the
stage box.
Please verify & give feedback concerning this one.
Thanks,
Eric
Comment 23 stx123 2004-05-13 10:02:10 UTC
I commited changes to 2 pages in the www project. See
http://www.solstage2..../servlets/ReadMsg?list=cvs&msgNo=5423

The result was that further commits led to
cvs server: [01:51:33] waiting for httpd's lock in /cvs/www/www
for over 10 minutes.
I was too impatient to see whether it finally finished and whether the page
changes were visible for browsers.
Comment 24 Unknown 2004-05-26 06:46:15 UTC
You are still going to see the locking situation: the performance
enhancement that was effected doesn't make the update any faster, it merely
means that the committer doesn't have to wait for the update to complete
on the server. The update still plants a read lock on the directory (so
the files aren't changed while the website is being "charged up"), and
any attempt to commit while that's going on will still have to wait out
the lock.

At this point, CVS behavior with respect to www/ publishing should be
identical to what existed in version 1.1.3 before the upgrade:
- CVS commits underneath www/ complete reasonably quickly
- the website is updated in the background
- during that update, any other commit attempt under www/ has to wait on
the lock
- it can take a long time, because there is a considerable amount of
content under www/

If there is some amount of data under www/ which can be moved out of the project 
entirely, perhaps to a sub-project, it could reduce the amount of processing 
time for cvs activity in such a vital project; especially given a single cvs 
commit operation for all changed files in the project should provide for greater 
cvs efficiency.
Comment 25 stx123 2004-05-26 11:30:56 UTC
Our tests failed in the projects api, www. Checkouts and commits are not
possible because the locks don't disappear after hours.
Even commits in the project cvstest and testcvs (created by hemaadmin) are not
possible.
Comment 26 Unknown 2004-06-03 07:27:08 UTC
Here are the numbers from my testing on the stage box as of this evening:

(brian@localhost)-(Wed Jun 02)-(22:39:55)-(~/repos/SUN/openoffice)
 $ l -h www/www/sitemap.html
-rw-rw-r--    1 brian    brian        7.2K May 13 01:24 www/www/sitemap.html
 
(brian@localhost)-(Wed Jun 02)-(22:40:01)-(~/repos/SUN/openoffice)
 $ time cvs -d :pserver:bnoble@localhost:/cvs ci -f -m'update to test update' 
www/www/sitemap.html ; date -u
Checking in www/www/sitemap.html;
/cvs/www/www/sitemap.html,v  <--  sitemap.html
new revision: 1.12; previous revision: 1.11
done
 
real    0m7.098s
user    0m0.010s
sys     0m0.000s
Thu Jun  3 05:40:25 UTC 2004
.
.
.
(brian@localhost)-(Wed Jun 02)-(22:41:47)-(~/repos/SUN/openoffice)
 $ l -h www/www/welcome/readme.html
-rw-rw-r--    1 brian    brian         13K Sep 30  2003 www/www/welcome/readme.
html
(brian@localhost)-(Wed Jun 02)-(22:42:12)-(~/repos/SUN/openoffice)
 $ time cvs -d :pserver:bnoble@localhost:/cvs ci -f -m'update to test update' 
www/www/welcome/readme.html ; date -u
Checking in www/www/welcome/readme.html;
/cvs/www/www/welcome/readme.html,v  <--  readme.html
new revision: 1.18; previous revision: 1.17
done
 
real    0m7.287s
user    0m0.000s
sys     0m0.010s
Thu Jun  3 05:42:54 UTC 2004
(brian@localhost)-(Wed Jun 02)-(22:42:54)-(~/repos/SUN/openoffice)
.
.
.
(brian@localhost)-(Wed Jun 02)-(22:45:16)-(~/repos/SUN/openoffice)
 $ l -h api/www/faq.html
-rw-rw-r--    1 brian    brian         10K Dec 17  2002 api/www/faq.html
 
(brian@localhost)-(Wed Jun 02)-(22:45:20)-(~/repos/SUN/openoffice)
 $ time cvs -d :pserver:bnoble@localhost:/cvs ci -f -m'update to test update' 
api/www/faq.html ; date -u
Checking in api/www/faq.html;
/cvs/api/www/faq.html,v  <--  faq.html
new revision: 1.8; previous revision: 1.7
done
 
real    0m7.176s
user    0m0.010s
sys     0m0.000s
Thu Jun  3 05:45:38 UTC 2004
(brian@localhost)-(Wed Jun 02)-(22:45:38)-(~/repos/SUN/openoffice)
.
.
.
(brian@localhost)-(Wed Jun 02)-(22:45:38)-(~/repos/SUN/openoffice)
 $ time cvs -d :pserver:bnoble@localhost:/cvs ci -f -m'update to test update' 
www/www/sitemap.html ; date -u
Checking in www/www/sitemap.html;
/cvs/www/www/sitemap.html,v  <--  sitemap.html
new revision: 1.13; previous revision: 1.12
done
 
real    0m7.190s
user    0m0.000s
sys     0m0.010s
Thu Jun  3 05:47:01 UTC 2004
(brian@localhost)-(Wed Jun 02)-(22:47:01)-(~/repos/SUN/openoffice)

The average time for all these checkins is somewhere between 7 and 8 seconds and 
I encountered no lock files in my testing.  I cannot be sure these are the tests 
attempted to be run in the previous comment but they are the files mentioned 
farther above.
Comment 27 stx123 2004-06-03 12:56:29 UTC
I verified that the locking problem is solved and that the time for the commits
are in the the range of 5-10 secs.

But I have the impression that static pages like
http://de.solstage2.sfo.collab.net/index.html and
http://www.solstage2.sfo.collab.net/index.html
are not updated in a reasonable timeframe (5-10min).

I would guess that the daily refresh will bring the prerendered version of
de/index.html to revision 1.113 and www/index.html to 1.1073.
But I would expect a timely feedback of changes to static pages.

Could you please elaborate what behaviour is implemented?
Comment 28 Unknown 2004-06-08 17:04:03 UTC
Setting this issue as resolved on stage and opened OpenOffice issue 29983 for 
the staticization concern.  I have opened another issue to track the new problem 
as it is fundamentally different than the primary focus of this issue.
Comment 29 stx123 2004-06-08 19:21:38 UTC
I'm fine with the creation of the new issue.
Please make sure that the change to resolve this issue 23620 isn't installed on
the production site with the resolution for 29983.
Comment 30 Unknown 2004-06-08 19:29:54 UTC
All changes will be first placed on the stage system prior to production.
Comment 31 stx123 2004-06-08 20:17:04 UTC
> All changes will be first placed on the stage system prior to production.

... which doesn't ensure that a resolution for issue 29983 is available on stage
before issue 23620 goes live on production ...

Comment 32 Unknown 2004-06-08 22:26:12 UTC
I'm not sure I understand.  

Stefan, first you say, "Please make sure that the change to resolve this issue 
23620 isn't installed on the production site with the resolution for 29983," 
meaning you don't want both fixes or at least not both installed on production 
at the same time (why I do not know).

Then you state, ".. which doesn't ensure that a resolution for issue 29983 is 
available on stage before issue 23620 goes live on production ...,"  which seems 
to imply you do want both fixes installed after staging but in a particular 
order (again I could use some clarification on why).

Can you edify me?
Comment 33 stx123 2004-06-08 22:50:07 UTC
I'm sorry for the misleading omission.
"Please make sure that the change to resolve this issue 23620 isn't installed on
the production site with the resolution for 29983,"
should read
"Please make sure that the change to resolve this issue 23620 isn't installed on
the production site without the resolution for 29983,".

In other words:
I would like to see both fixes installed at the same time and would not agree to
install the performance fix only.
Comment 34 Unknown 2004-06-10 06:55:21 UTC
Now I understand and agree.
Comment 35 Unknown 2004-06-10 07:31:30 UTC
Can we resolve this given the cvs times on the stage system?
Comment 36 stx123 2004-06-10 19:51:08 UTC
Following your example I added the entry "verified_on_stage".
I would like to track the issue until it's available on the production site.
If you think we should clarify the issue handling feel free to contact me via
direct mail.
Comment 37 Unknown 2004-07-06 15:59:29 UTC
 $ time cvs -d :pserver:bnoble@localhost:/cvs ci -f -m'no change, test update' 
collabnet/www/index.html
Checking in collabnet/www/index.html;
/cvs/collabnet/www/index.html,v  <--  index.html
new revision: 1.15; previous revision: 1.14
done
 
real    0m4.524s
user    0m0.010s
sys     0m0.000s

This is on the present production system.
Comment 38 stx123 2004-07-06 18:33:34 UTC
verified and closing