You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@subversion.apache.org by Dirck Blaskey <li...@danbala.com> on 2008/09/25 21:30:45 UTC
explaining inexplicable delay in svn diff
Recently upgraded to svn client 1.5.2, and all of a sudden simple diff
commands take 12+ seconds.
Using sysinternals processmonitor, it looks like svn is trying to create
a file "tmp" in the TEMP folder;
in my case (for some reason) there was already a folder called "tmp" in
the TEMP folder, so
svn burns about 12 seconds trying again repeatedly, until it moves on
and tries tmp.2.
If there is a file called "tmp" instead of a folder, it gets a name
collision and moves on to tmp.2.
Maybe you could check for the "IS DIRECTORY" result from CreateFile and
not sit and spin.
Here's some of the log from procmon:
starts playing in the temp folder
"41095","2:07:55.3374974
PM","svn.exe","3716","CreateFile","D:\temp","SUCCESS","Desired Access:
Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO
Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete,
AllocationSize: n/a, OpenResult: Opened"
"41096","2:07:55.3375524
PM","svn.exe","3716","QueryInformationVolume","D:\temp","BUFFER
OVERFLOW","VolumeCreationTime: 4/29/2006 12:22:33 PM,
VolumeSerialNumber: BC46-4855, SupportsObjects: True, VolumeLabel: dat?"
"41097","2:07:55.3375894
PM","svn.exe","3716","QueryAllInformationFile","D:\temp","BUFFER
OVERFLOW","CreationTime: 4/30/2006 1:58:17 PM, LastAccessTime: 9/25/2008
2:07:21 PM, LastWriteTime: 9/25/2008 2:07:21 PM, ChangeTime: 9/25/2008
2:07:21 PM, FileAttributes: D, AllocationSize: 0, EndOfFile: 0,
NumberOfLinks: 1, DeletePending: False, Directory: True, IndexNumber:
0x500000000497d, EaSize: 0, Access: Read Attributes, Synchronize,
Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"41098","2:07:55.3376282
PM","svn.exe","3716","CloseFile","D:\temp","SUCCESS",""
"41100","2:07:55.3377366
PM","svn.exe","3716","CreateFile","D:\temp\apr-tmp.bQ1jpe","SUCCESS","Desired
Access: Generic Read/Write, Delete, Disposition: Create, Options:
Synchronous IO Non-Alert, Non-Directory File, Delete On Close,
Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: 0,
OpenResult: Created"
"41101","2:07:55.3379078
PM","svn.exe","3716","WriteFile","D:\temp\apr-tmp.bQ1jpe","SUCCESS","Offset:
0, Length: 1"
"41102","2:07:55.3380203
PM","svn.exe","3716","CloseFile","D:\temp\apr-tmp.bQ1jpe","SUCCESS",""
"41103","2:07:55.3381749
PM","svn.exe","3716","CreateFile","D:\temp\tmp","IS DIRECTORY","Desired
Access: Generic Read/Write, Disposition: Create, Options: Synchronous IO
Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: 0"
last entry repeats 100 or so times, then it tries again read only:
"65137","2:08:08.6889370
PM","svn.exe","3716","CreateFile","D:\temp\tmp","SUCCESS","Desired
Access: Read Attributes, Synchronize, Disposition: Open, Options:
Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: n/a, OpenResult: Opened"
"65138","2:08:08.6890511
PM","svn.exe","3716","QueryInformationVolume","D:\temp\tmp","BUFFER
OVERFLOW","VolumeCreationTime: 4/29/2006 12:22:33 PM,
VolumeSerialNumber: BC46-4855, SupportsObjects: True, VolumeLabel: dat?"
"65139","2:08:08.6891139
PM","svn.exe","3716","QueryAllInformationFile","D:\temp\tmp","BUFFER
OVERFLOW","CreationTime: 8/5/2008 3:28:41 PM, LastAccessTime: 8/5/2008
3:28:41 PM, LastWriteTime: 8/5/2008 3:28:41 PM, ChangeTime: 8/5/2008
3:28:41 PM, FileAttributes: D, AllocationSize: 0, EndOfFile: 0,
NumberOfLinks: 1, DeletePending: False, Directory: True, IndexNumber:
0x71000000008488, EaSize: 0, Access: Read Attributes, Synchronize,
Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"65140","2:08:08.6891765
PM","svn.exe","3716","CloseFile","D:\temp\tmp","SUCCESS",""
gives up and moves on:
"65142","2:08:08.6892793
PM","svn.exe","3716","CreateFile","D:\temp\tmp.2","SUCCESS","Desired
Access: Generic Read/Write, Disposition: Create, Options: Synchronous IO
Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write,
Delete, AllocationSize: 0, OpenResult: Created"
"65143","2:08:08.6875464
PM","svn.exe","3716","CloseFile","D:\temp\tmp.2","SUCCESS",""
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@subversion.tigris.org
For additional commands, e-mail: dev-help@subversion.tigris.org
Re: explaining inexplicable delay in svn diff
Posted by Bert Huijben <be...@vmoo.com>.
2008/9/25 Dirck Blaskey <li...@danbala.com>:
> Recently upgraded to svn client 1.5.2, and all of a sudden simple diff
> commands take 12+ seconds.
> Using sysinternals processmonitor, it looks like svn is trying to create a
> file "tmp" in the TEMP folder;
> in my case (for some reason) there was already a folder called "tmp" in the
> TEMP folder, so
> svn burns about 12 seconds trying again repeatedly, until it moves on and
> tries tmp.2.
>
> If there is a file called "tmp" instead of a folder, it gets a name
> collision and moves on to tmp.2.
>
> Maybe you could check for the "IS DIRECTORY" result from CreateFile and not
> sit and spin.
>
Hi,
I just applied a patch on this in r33464. This patch handles the case
where there is a collision on creating a unique filename. It will now
retry with the next name instead of delaying and retrying with the
same filename.
(The original implementation handled the directory exists condition as
non fatal error after 100 retries like your test showed).
Bert
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@subversion.tigris.org
For additional commands, e-mail: dev-help@subversion.tigris.org
RE: explaining inexplicable delay in svn diff
Posted by Bert Huijben <b....@competence.biz>.
> -----Original Message-----
> From: Dirck Blaskey [mailto:listtarget2@danbala.com]
> Sent: donderdag 25 september 2008 23:31
> To: dev@subversion.tigris.org
> Subject: explaining inexplicable delay in svn diff
>
> Recently upgraded to svn client 1.5.2, and all of a sudden simple diff
> commands take 12+ seconds.
> Using sysinternals processmonitor, it looks like svn is trying to
> create
> a file "tmp" in the TEMP folder;
> in my case (for some reason) there was already a folder called "tmp" in
> the TEMP folder, so
> svn burns about 12 seconds trying again repeatedly, until it moves on
> and tries tmp.2.
>
> If there is a file called "tmp" instead of a folder, it gets a name
> collision and moves on to tmp.2.
>
> Maybe you could check for the "IS DIRECTORY" result from CreateFile and
> not sit and spin.
>
> Here's some of the log from procmon:
>
> starts playing in the temp folder
>
> "41095","2:07:55.3374974
> PM","svn.exe","3716","CreateFile","D:\temp","SUCCESS","Desired Access:
> Read Attributes, Synchronize, Disposition: Open, Options: Synchronous
> IO
> Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete,
> AllocationSize: n/a, OpenResult: Opened"
> "41096","2:07:55.3375524
> PM","svn.exe","3716","QueryInformationVolume","D:\temp","BUFFER
> OVERFLOW","VolumeCreationTime: 4/29/2006 12:22:33 PM,
> VolumeSerialNumber: BC46-4855, SupportsObjects: True, VolumeLabel:
> dat?"
> "41097","2:07:55.3375894
> PM","svn.exe","3716","QueryAllInformationFile","D:\temp","BUFFER
> OVERFLOW","CreationTime: 4/30/2006 1:58:17 PM, LastAccessTime:
> 9/25/2008
> 2:07:21 PM, LastWriteTime: 9/25/2008 2:07:21 PM, ChangeTime: 9/25/2008
> 2:07:21 PM, FileAttributes: D, AllocationSize: 0, EndOfFile: 0,
> NumberOfLinks: 1, DeletePending: False, Directory: True, IndexNumber:
> 0x500000000497d, EaSize: 0, Access: Read Attributes, Synchronize,
> Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement:
> Word"
> "41098","2:07:55.3376282
> PM","svn.exe","3716","CloseFile","D:\temp","SUCCESS",""
> "41100","2:07:55.3377366
> PM","svn.exe","3716","CreateFile","D:\temp\apr-
> tmp.bQ1jpe","SUCCESS","Desired
> Access: Generic Read/Write, Delete, Disposition: Create, Options:
> Synchronous IO Non-Alert, Non-Directory File, Delete On Close,
> Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: 0,
> OpenResult: Created"
> "41101","2:07:55.3379078
> PM","svn.exe","3716","WriteFile","D:\temp\apr-
> tmp.bQ1jpe","SUCCESS","Offset:
> 0, Length: 1"
> "41102","2:07:55.3380203
> PM","svn.exe","3716","CloseFile","D:\temp\apr-tmp.bQ1jpe","SUCCESS",""
> "41103","2:07:55.3381749
> PM","svn.exe","3716","CreateFile","D:\temp\tmp","IS DIRECTORY","Desired
> Access: Generic Read/Write, Disposition: Create, Options: Synchronous
> IO
> Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write,
> Delete, AllocationSize: 0"
>
> last entry repeats 100 or so times, then it tries again read only:
My guess is that it repeats 101 times; the actual action (1) and 100 WIN32
specific retries.
This is what the WIN32_RETRY_LOOP() in subversion/libsvn_subr/io.c does.
This code is used to work around issues caused by open files of other
applications (In my tests mostly Virus Scanners and tsvncache. That last one
sometimes keeps a file monitor open on workingcopies previously opened in
the windows explorer).
Just retrying failed actions might help in some cases, but is severely
broken in others, like this.
(I just remembered
http://blogs.msdn.com/oldnewthing/archive/2005/11/07/489807.aspx )
I think there was some talking on introducing a few new retry loops this
week. (The '[PATCH] Working copy on Samba share' thread).
In my opinion just retrying when you think it might perhaps fix a few user
issues is not the right thing to do. Especially if you don't check for
specific errors, like our current WIN32_RETRY_LOOP() that uses the same
check on all places where it is used.
For this specific case: To get a unique temp file, I think we shouldn't
retry at all. It's better to retry with a different tempname.
Bert
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@subversion.tigris.org
For additional commands, e-mail: dev-help@subversion.tigris.org