You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@subversion.apache.org by Tobias Bading <tb...@web.de> on 2013/05/23 11:05:39 UTC
subversion-1.8.0-rc2: diff_test 60 fails
Hello everyone,
I'm having a bit of trouble with subversion-1.8.0-rc2 on my Ubuntu Lucid
(x86_64) machine. "make check" or "./diff_tests.py 60" (in directory
subversion/tests/cmdline) fails with:
---
W: =============================================================
Expected '3449_spurious' and actual '3449_spurious' in status tree are
different!
=============================================================
EXPECTED NODE TO BE:
=============================================================
* Node name: 3449_spurious
Path: svn-test-work/working_copies/diff_tests-60/3449_spurious
Contents: None
Properties: {}
Attributes: {'status': 'M ', 'wc_rev': '2'}
Children: None (node is probably a file)
=============================================================
ACTUAL NODE FOUND:
=============================================================
* Node name: 3449_spurious
Path: svn-test-work/working_copies/diff_tests-60/3449_spurious
Contents: None
Properties: {}
Attributes: {'status': ' ', 'wc_rev': '2'}
Children: None (node is probably a file)
W: ACTUAL STATUS TREE:
svntest.wc.State(wc_dir, {
'' : Item(status=' M', wc_rev='2'),
'A' : Item(status=' ', wc_rev='2'),
'A/B' : Item(status=' ', wc_rev='2'),
'A/B/F' : Item(status=' ', wc_rev='2'),
'A/B/E' : Item(status=' ', wc_rev='2'),
'A/B/E/alpha' : Item(status=' ', wc_rev='2'),
'A/B/E/beta' : Item(status=' ', wc_rev='2'),
'A/B/lambda' : Item(status=' ', wc_rev='2'),
'A/D' : Item(status=' ', wc_rev='2'),
'A/D/H' : Item(status=' ', wc_rev='2'),
'A/D/H/omega' : Item(status=' ', wc_rev='2'),
'A/D/H/psi' : Item(status=' ', wc_rev='2'),
'A/D/H/chi' : Item(status=' ', wc_rev='2'),
'A/D/gamma' : Item(status=' ', wc_rev='2'),
'A/D/G' : Item(status=' ', wc_rev='2'),
'A/D/G/tau' : Item(status=' ', wc_rev='2'),
'A/D/G/pi' : Item(status=' ', wc_rev='2'),
'A/D/G/rho' : Item(status=' ', wc_rev='2'),
'A/C' : Item(status=' ', wc_rev='2'),
'A/mu' : Item(status=' ', wc_rev='2'),
'3449_spurious' : Item(status=' ', wc_rev='2'),
'iota' : Item(status=' ', wc_rev='2'),
})
W: CWD: [...]/subversion-1.8.0-rc2/subversion/tests/cmdline
W: EXCEPTION: SVNTreeUnequal
Traceback (most recent call last):
File
"[...]/subversion-1.8.0-rc2/subversion/tests/cmdline/svntest/main.py",
line 1550, in run
rc = self.pred.run(sandbox)
File
"[...]/subversion-1.8.0-rc2/subversion/tests/cmdline/svntest/testcase.py",
line 176, in run
return self.func(sandbox)
File "./diff_tests.py", line 3878, in no_spurious_conflict
svntest.actions.run_and_verify_status(wc_dir, expected_status)
File
"[...]/subversion-1.8.0-rc2/subversion/tests/cmdline/svntest/actions.py", line
1479, in run_and_verify_status
status_tree.compare_and_display('status', actual_status)
File
"[...]/subversion-1.8.0-rc2/subversion/tests/cmdline/svntest/wc.py",
line 344, in compare_and_display
raise svntest.tree.SVNTreeUnequal
SVNTreeUnequal
FAIL: diff_tests.py 60: no spurious conflict on update
---
It seems that the test fails to prepare the working copy for the actual
test. The "merge -c4 ^/" does not work as expected. Instead of merging
the changes of file 3449_spurious into the working copy, only a
svn:mergeinfo property is added to the working copy root.
Revision 4 itself seems fine in the repository.
"[...]/subversion/svn/svn diff -c4 ^/" appears to show the correct
changes in 3449_spurious.
Once the test fails, the incomplete merge is repeatable in directory
subversion/tests/cmdline/svn-test-work/working_copies/diff_tests-60 by
executing "[...]/subversion/svn/svn revert -R ." and then the merge
again. The merge fails to update file 3449_spurious every time, no
matter whether the last argument of the merge is "^/",
"^/3449_spurious",
"file://[...]/repositories/diff_tests-60/3449_spurious", or
"file://[...]/repositories/diff_tests-60/3449_spurious". If the last
argument refers to 3449_spurious, then a svn:mergeinfo property is added
to file 3449_spurious in the working copy, otherwise the property is
added to the root directory of the working copy. But the contents of
file 3449_spurious are never changed :-(. (The file's timestamp doesn't
change either.)
However, once I execute "[...]/svn revert -R .", "[...]/svn update", and
"[...]/svn update -r2" in the working copy, the merge works just fine
afterwards. And that "update -r2" is exactly what no_spurious_conflict
in diff_tests.py does before the faulty merge, if I'm reading the code
correctly.
Anyone else having this problem?
Ideas are welcome... :-)
Kind regards,
Tobias
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 28.05.2013 15:24, Tobias Bading wrote:
> On 28.05.2013 15:15, Philip Martin wrote:
>> Are you running some non-standard kernel?
>
> Depends on your definition of 'standard'. ;-)
> I'm using the default kernel linux-image-2.6.32-46-generic from the
Ubuntu Lucid repositories.
Harmless little joke... and that's when the real fun started...
I checked a few older build directories. One had these 16 timestamps:
2012-03-27 11:00:38.000594290 +0200
2012-03-27 11:00:38.020593756 +0200
2012-03-27 11:00:38.170593413 +0200
[...]
2012-03-27 11:00:38.780593824 +0200
2012-03-27 11:00:38.790594918 +0200
2012-03-27 11:00:38.830594476 +0200
I guess on March 27th last year, the world was still spinning at the
proper speed ;-). Next I checked my installation history in Synaptic
Package Manager to see what Ubuntu kernel I was running back then:
linux-image-2.6.32-39-generic. After installing and booting into this
kernel, I ran the '{ while true; do echo >t; ls --full-time t; rm t;
done; } | uniq' test again... take a guess... now I'm getting exactly
100 unique timestamps per second. WTF?!?? 'diff_tests.py 60' works just
fine now without patching svn_io_sleep_for_timestamps.
sysconf(_SC_CLK_TCK) returns 100 in both kernel versions, so the HZ
value shouldn't be the cause. I'll try to find the proper channels to
ask the Ubuntu kernel gurus for a comment. If anyone knows the proper
channels, please let me know.
Summary (or "What have I learned so far?"):
The "if (finfo.mtime % APR_USEC_PER_SEC)" block in
svn_io_sleep_for_timestamps seems a bit too simplistic. Even with the
100 timestamps per second I get now, sleeping just 1 millisecond might
not be enough if the following action is fast enough to use the same
timestamp as the last action prior to the short nap. Brane and Philip
already mentioned possible ways to implement this differently. Maybe you
could discuss this in the dev mailing list?
Kind regards & thanks for all the help,
Tobias
PS: I'll keep you updated regarding the kernel problem.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 28.05.2013 15:15, Philip Martin wrote:
> Are you running some non-standard kernel?
Depends on your definition of 'standard'. ;-)
I'm using the default kernel linux-image-2.6.32-46-generic from the
Ubuntu Lucid repositories.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Tobias Bading <tb...@web.de> writes:
> Did you run the tests on Ubuntu 10.04 on an ext3 or ext4 filesystem?
> On ext3 you might not encounter this problem because ext3 only has a
> timestamp resolution of a second, thus you don't enter the
> "if(finfo.mtime % APR_USEC_PER_SEC)" block in
> svn_io_sleep_for_timestamps.
I probably used the default install, which I think is ext4, but I no
longer have the installation to check.
> Good idea :-). The tmpfs filesystem shows the same behaviour. So it's
> nothing ext4 specific.
Are you running some non-standard kernel?
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 28.05.2013 14:31, Philip Martin wrote:
> Tobias Bading<tb...@web.de> writes:
>> b) '{ while true; do echo "">t; ls -l --full-time t; rm t; done; } |
>> uniq' prints exactly *two* lines per second, one every 0.5 seconds,
>> exact down to the millisecond.
> I have an Ubuntu 12.04 machine and I see the expected behaviour: lots of
> different timestamps. I have run the Subversion tests on Ubuntu 10.04 in
> the past without a problem.
Did you run the tests on Ubuntu 10.04 on an ext3 or ext4 filesystem? On
ext3 you might not encounter this problem because ext3 only has a
timestamp resolution of a second, thus you don't enter the
"if(finfo.mtime % APR_USEC_PER_SEC)" block in svn_io_sleep_for_timestamps.
> If you do a Subversion checkout of something like
> http://svn.apache.org/repos/asf/subversion/trunk/subversion/libsvn_wc do
> you see all the working files with different timestamps? If you then
> remove the working files and run 'svn revert -R' all the files should be
> restored in a fraction of a second. Do they all have different
> timestamps?
I've already checked a few build directories. The
two-timestamps-per-second effect is consistent, e.g. in
subversion/svn/.libs I have unique timestamps like these (from a 'make
-j 3'):
2013-05-27 11:27:17.279848045 +0200
2013-05-27 11:27:17.779847483 +0200
2013-05-27 11:27:18.279848246 +0200
2013-05-27 11:27:18.779846845 +0200
2013-05-27 11:27:19.279848307 +0200
2013-05-27 11:27:19.779848160 +0200
Multiple files have the exact same timestamp, but there are no
timestamps in between. It clearly seems that some code in the
kernel/ext4-driver/somewhere uses a cached timestamp that is updated
exactly every 0.5 seconds.
> You could also try mounting a tmpfs filesystem:
>
> sudo mount -t tmpfs tmpfs /mnt
>
> Do you get the same timestamp behaviour on that filesystem?
Good idea :-). The tmpfs filesystem shows the same behaviour. So it's
nothing ext4 specific.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Tobias Bading <tb...@web.de> writes:
> b) '{ while true; do echo "" >t; ls -l --full-time t; rm t; done; } |
> uniq' prints exactly *two* lines per second, one every 0.5 seconds,
> exact down to the millisecond.
I have an Ubuntu 12.04 machine and I see the expected behaviour: lots of
different timestamps. I have run the Subversion tests on Ubuntu 10.04 in
the past without a problem.
If you do a Subversion checkout of something like
http://svn.apache.org/repos/asf/subversion/trunk/subversion/libsvn_wc do
you see all the working files with different timestamps? If you then
remove the working files and run 'svn revert -R' all the files should be
restored in a fraction of a second. Do they all have different
timestamps?
You could also try mounting a tmpfs filesystem:
sudo mount -t tmpfs tmpfs /mnt
Do you get the same timestamp behaviour on that filesystem?
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 28.05.2013 12:54, Philip Martin wrote:
> Tobias Bading<tb...@web.de> writes:
>> On 27.05.2013 16:12, Tobias Bading wrote:
>>> On 27.05.2013 16:01, Branko Čibej wrote:
>>>> Can you try this: run the following command for a couple of seconds, it
>>>> should give you an idea about the system clock precision.
>>>>
>>>> { while true; do date '+%M:%S.%N'; done; } | uniq
>>> Redirected to a file, I get about 1250 unique timestamps per second, nicely distributed it seems.
>> Hmm... a modified version of your command paints a completely different picture:
>>
>> { while true; do touch t; ls -l --full-time t; done; } | uniq
>>
>> prints exactly *two* lines per second, one every 0.5 second, exact down to the millisecond.
>> No idea why yet, but this explaines everything I guess. Asking Google...
> An earlier mail showed us that you are using ext4 on OSX -- does OSX
> have native support for ext4 now or are you using a 3rd party driver?
Sounds like a misunderstanding. On Saturday, I compiled Subversion 1.8
RC2 at home on my MacBook to check whether I could reproduce the problem
on a different platform. I couldn't, "make check" worked fine on Snow
Leopard (on a HFS+ disk).
On my Ubuntu Lucid machine at work, the problem persists on an ext4
partition.
> Subversion assumes that a sub-second timestamp implies at least a
> millisecond resolution but that is not the case on your ext4 filesystem.
I'm not sure where exactly the source of the problem is. So far I know:
a) 'touch -d "2013-05-27 14:27:35.069850993" t ; ls --full-time t' works
fine and shows the file's timestamp 100% correct to the nanosecond.
b) '{ while true; do echo "" >t; ls -l --full-time t; rm t; done; } |
uniq' prints exactly *two* lines per second, one every 0.5 seconds,
exact down to the millisecond.
No matter whether the test under b) uses touch or creates a new file
every time, I only get two different timestamps each second. I didn't
find an explanation via Google yet. Someone suggested that the ext4
implementation might use a cached kernel time and that time is only
updated at certain timer intervals.
> We would need to modify the sleep algorithm if we are to support this
> filesystem.
>
> We could modify the sleep calculation to something like:
>
> if timestamp has sub 1ms component
> sleep for 1ms
> else if timestamp has sub 10ms component
> sleep for 10ms
> else if timestamp has sub 100ms component
> sleep for 100ms
> else
> sleep for 1s
>
> or perhaps do it in base 2 rather than base 10?
From what I googled so far there doesn't seem to be a reliable way to
determine the timestamp resolution of a filesystem. And as my kind of
spooky case shows, there seem to be other dark forces at work as well... ;-)
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Branko Čibej <br...@wandisco.com> writes:
> What we /should/ do is create a tempfile and keep changing and stat'ing
> it until its mtime changes. We could do this with an exponential backoff
> sleep, too. Then there would be no guesswork about the timestamp
> resolution of the WC file system.
>
> The problem is that we don't always get a path into
> sleep_for_timestamps; but we already have a fallback for that.
There are other things we could try. When we do get a path we could
identify the wc root and then run a SQLite query to get the most recent
last_mod_time. We could use that to reduce the sleep.
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Branko Čibej <br...@wandisco.com>.
On 28.05.2013 12:54, Philip Martin wrote:
> Tobias Bading <tb...@web.de> writes:
>
>> On 27.05.2013 16:12, Tobias Bading wrote:
>>> On 27.05.2013 16:01, Branko Čibej wrote:
>>>> Can you try this: run the following command for a couple of seconds, it
>>>> should give you an idea about the system clock precision.
>>>>
>>>> { while true; do date '+%M:%S.%N'; done; } | uniq
>>> Redirected to a file, I get about 1250 unique timestamps per second, nicely distributed it seems.
>> Hmm... a modified version of your command paints a completely different picture:
>>
>> { while true; do touch t; ls -l --full-time t; done; } | uniq
>>
>> prints exactly *two* lines per second, one every 0.5 second, exact down to the millisecond.
>> No idea why yet, but this explaines everything I guess. Asking Google...
> An earlier mail showed us that you are using ext4 on OSX -- does OSX
> have native support for ext4 now or are you using a 3rd party driver?
>
> Subversion assumes that a sub-second timestamp implies at least a
> millisecond resolution but that is not the case on your ext4 filesystem.
> We would need to modify the sleep algorithm if we are to support this
> filesystem.
>
> We could modify the sleep calculation to something like:
>
> if timestamp has sub 1ms component
> sleep for 1ms
> else if timestamp has sub 10ms component
> sleep for 10ms
> else if timestamp has sub 100ms component
> sleep for 100ms
> else
> sleep for 1s
What we /should/ do is create a tempfile and keep changing and stat'ing
it until its mtime changes. We could do this with an exponential backoff
sleep, too. Then there would be no guesswork about the timestamp
resolution of the WC file system.
The problem is that we don't always get a path into
sleep_for_timestamps; but we already have a fallback for that.
-- Brane
--
Branko Čibej
Director of Subversion | WANdisco | www.wandisco.com
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Tobias Bading <tb...@web.de> writes:
> On 27.05.2013 16:12, Tobias Bading wrote:
>> On 27.05.2013 16:01, Branko Čibej wrote:
>>> Can you try this: run the following command for a couple of seconds, it
>>> should give you an idea about the system clock precision.
>>>
>>> { while true; do date '+%M:%S.%N'; done; } | uniq
>>
>> Redirected to a file, I get about 1250 unique timestamps per second, nicely distributed it seems.
>
> Hmm... a modified version of your command paints a completely different picture:
>
> { while true; do touch t; ls -l --full-time t; done; } | uniq
>
> prints exactly *two* lines per second, one every 0.5 second, exact down to the millisecond.
> No idea why yet, but this explaines everything I guess. Asking Google...
An earlier mail showed us that you are using ext4 on OSX -- does OSX
have native support for ext4 now or are you using a 3rd party driver?
Subversion assumes that a sub-second timestamp implies at least a
millisecond resolution but that is not the case on your ext4 filesystem.
We would need to modify the sleep algorithm if we are to support this
filesystem.
We could modify the sleep calculation to something like:
if timestamp has sub 1ms component
sleep for 1ms
else if timestamp has sub 10ms component
sleep for 10ms
else if timestamp has sub 100ms component
sleep for 100ms
else
sleep for 1s
or perhaps do it in base 2 rather than base 10?
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 27.05.2013 16:12, Tobias Bading wrote:
> On 27.05.2013 16:01, Branko Čibej wrote:
>> Can you try this: run the following command for a couple of seconds, it
>> should give you an idea about the system clock precision.
>>
>> { while true; do date '+%M:%S.%N'; done; } | uniq
>
> Redirected to a file, I get about 1250 unique timestamps per second,
> nicely distributed it seems.
Hmm... a modified version of your command paints a completely different
picture:
{ while true; do touch t; ls -l --full-time t; done; } | uniq
prints exactly *two* lines per second, one every 0.5 second, exact down
to the millisecond.
No idea why yet, but this explaines everything I guess. Asking Google...
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 27.05.2013 16:01, Branko Čibej wrote:
> Can you try this: run the following command for a couple of seconds, it
> should give you an idea about the system clock precision.
>
> { while true; do date '+%M:%S.%N'; done; } | uniq
Redirected to a file, I get about 1250 unique timestamps per second,
nicely distributed it seems.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Branko Čibej <br...@wandisco.com>.
On 27.05.2013 15:40, Tobias Bading wrote:
> On 27.05.2013 12:43, Branko Čibej wrote:
>> On 27.05.2013 09:59, Tobias Bading wrote:
>>> Quick update:
>>> The problem is definitely timestamp related. "touch 3449_spurious"
>>> fixes a "corrupt" working copy, i.e. "svn status" and "svn diff" work
>>> properly afterwards. I'll try to figure out why my machine is living
>>> in its own timeline. All I can say after reading just a few lines of
>>> python code is that I don't have
>>> SVN_I_LOVE_CORRUPTED_WORKING_COPIES_SO_DISABLE_SLEEP_FOR_TIMESTAMPS
>>> hard-wired to 'yes' :-).
>> Well, that's a relief, at least.
>>
>> Can you please get two pieces of information:
>>
>> 1) run the "mount" command and past the line representing the ext4
>> filesystem where your working copy lives
>
> /dev/sdb1 on / type ext4 (rw,relatime,errors=remount-ro)
>
>> 2) Get the ext4 superblock info, using "sudo tune2fs -l /dev/something";
>> the mount output will tell you which /dev/something
>
> tune2fs 1.41.11 (14-Mar-2010)
> Filesystem volume name: <none>
> Last mounted on: /
> Filesystem UUID: dcabb217-5e67-45ee-bbd1-bc78b9755514
> Filesystem magic number: 0xEF53
> Filesystem revision #: 1 (dynamic)
> Filesystem features: has_journal ext_attr resize_inode dir_index
> filetype needs_recovery extent flex_bg sparse_super large_file
> huge_file uninit_bg dir_nlink extra_isize
> Filesystem flags: signed_directory_hash
> Default mount options: (none)
> Filesystem state: clean
> Errors behavior: Continue
> Filesystem OS type: Linux
> Inode count: 15269888
> Block count: 61049088
> Reserved block count: 3052452
> Free blocks: 26233604
> Free inodes: 13780922
> First block: 0
> Block size: 4096
> Fragment size: 4096
> Reserved GDT blocks: 1009
> Blocks per group: 32768
> Fragments per group: 32768
> Inodes per group: 8192
> Inode blocks per group: 512
> RAID stride: 32730
> Flex block group size: 16
> Filesystem created: Tue Jul 5 15:41:05 2011
> Last mount time: Mon May 27 09:14:16 2013
> Last write time: Mon Apr 29 09:44:35 2013
> Mount count: 18
> Maximum mount count: 27
> Last checked: Mon Apr 29 09:44:35 2013
> Check interval: 15552000 (6 months)
> Next check after: Sat Oct 26 09:44:35 2013
> Lifetime writes: 1283 GB
> Reserved blocks uid: 0 (user root)
> Reserved blocks gid: 0 (group root)
> First inode: 11
> Inode size: 256
> Required extra isize: 28
> Desired extra isize: 28
> Journal inode: 8
> First orphan inode: 4072404
> Default directory hash: half_md4
> Directory Hash Seed: 3cc06f24-54d0-4435-94d0-d8ce07f75445
> Journal backup: inode blocks
>
>
>
> Further tests:
> After the failed test, 'ls -l --full-time 3449_spurious' prints the
> timestamp '2013-05-27 14:27:35.069850993 +0200'.
> At this point, 'svn status 3449_spurious' claims that 3449_spurious is
> unmodified. (This is what caused the test failure).
>
> After a 'touch -d "2013-05-27 14:27:35.069850" 3449_spurious', 'ls -l
> --full-time 3449_spurious' prints the timestamp '2013-05-27
> 14:27:35.069850000 +0200' and 'svn status 3449_spurious' still claims
> that the file is unmodified.
>
> After a 'touch -d "2013-05-27 14:27:35.069851" 3449_spurious', 'svn
> status 3449_spurious' admits that the file has been modified.
>
> This makes sense I guess, because apr_finfo_t has microsecond
> resolution, whereas stat(2) (and ext4 obviously) have nanosecond
> resolution. What doesn't make sense to me is why I have to patch
> svn_io_sleep_for_timestamps to sleep a whole second. Waiting e.g. 0.1
> seconds is not sufficient.
>
> I tested a 'touch t1 ; touch t2 ; ... ; touch t50' and then 'ls -l
> --full-time', which shows identical timestamps for all 50 files. Isn't
> that a bit... odd?
Hmmmm .... there's a difference between the /resolution/ of the
timestamp (in the filesystem) and the /precision/ of either the
timestamp or the system clock.
In this case, judging from your "touch" test, it would appear that the
system clock has a much lower precision than one would expect.
Can you try this: run the following command for a couple of seconds, it
should give you an idea about the system clock precision.
{ while true; do date '+%M:%S.%N'; done; } | uniq
--
Branko Čibej
Director of Subversion | WANdisco | www.wandisco.com
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
On 27.05.2013 12:43, Branko Čibej wrote:
> On 27.05.2013 09:59, Tobias Bading wrote:
>> Quick update:
>> The problem is definitely timestamp related. "touch 3449_spurious"
>> fixes a "corrupt" working copy, i.e. "svn status" and "svn diff" work
>> properly afterwards. I'll try to figure out why my machine is living
>> in its own timeline. All I can say after reading just a few lines of
>> python code is that I don't have
>> SVN_I_LOVE_CORRUPTED_WORKING_COPIES_SO_DISABLE_SLEEP_FOR_TIMESTAMPS
>> hard-wired to 'yes' :-).
> Well, that's a relief, at least.
>
> Can you please get two pieces of information:
>
> 1) run the "mount" command and past the line representing the ext4
> filesystem where your working copy lives
/dev/sdb1 on / type ext4 (rw,relatime,errors=remount-ro)
> 2) Get the ext4 superblock info, using "sudo tune2fs -l /dev/something";
> the mount output will tell you which /dev/something
tune2fs 1.41.11 (14-Mar-2010)
Filesystem volume name: <none>
Last mounted on: /
Filesystem UUID: dcabb217-5e67-45ee-bbd1-bc78b9755514
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index
filetype needs_recovery extent flex_bg sparse_super large_file huge_file
uninit_bg dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: (none)
Filesystem state: clean
Errors behavior: Continue
Filesystem OS type: Linux
Inode count: 15269888
Block count: 61049088
Reserved block count: 3052452
Free blocks: 26233604
Free inodes: 13780922
First block: 0
Block size: 4096
Fragment size: 4096
Reserved GDT blocks: 1009
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
RAID stride: 32730
Flex block group size: 16
Filesystem created: Tue Jul 5 15:41:05 2011
Last mount time: Mon May 27 09:14:16 2013
Last write time: Mon Apr 29 09:44:35 2013
Mount count: 18
Maximum mount count: 27
Last checked: Mon Apr 29 09:44:35 2013
Check interval: 15552000 (6 months)
Next check after: Sat Oct 26 09:44:35 2013
Lifetime writes: 1283 GB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
First orphan inode: 4072404
Default directory hash: half_md4
Directory Hash Seed: 3cc06f24-54d0-4435-94d0-d8ce07f75445
Journal backup: inode blocks
Further tests:
After the failed test, 'ls -l --full-time 3449_spurious' prints the
timestamp '2013-05-27 14:27:35.069850993 +0200'.
At this point, 'svn status 3449_spurious' claims that 3449_spurious is
unmodified. (This is what caused the test failure).
After a 'touch -d "2013-05-27 14:27:35.069850" 3449_spurious', 'ls -l
--full-time 3449_spurious' prints the timestamp '2013-05-27
14:27:35.069850000 +0200' and 'svn status 3449_spurious' still claims
that the file is unmodified.
After a 'touch -d "2013-05-27 14:27:35.069851" 3449_spurious', 'svn
status 3449_spurious' admits that the file has been modified.
This makes sense I guess, because apr_finfo_t has microsecond
resolution, whereas stat(2) (and ext4 obviously) have nanosecond
resolution. What doesn't make sense to me is why I have to patch
svn_io_sleep_for_timestamps to sleep a whole second. Waiting e.g. 0.1
seconds is not sufficient.
I tested a 'touch t1 ; touch t2 ; ... ; touch t50' and then 'ls -l
--full-time', which shows identical timestamps for all 50 files. Isn't
that a bit... odd?
Kind regards,
Tobias
PS: Please put me on CC when replying, I'm not subscribed to the mailing
list.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Branko Čibej <br...@wandisco.com>.
On 27.05.2013 09:59, Tobias Bading wrote:
> Quick update:
> The problem is definitely timestamp related. "touch 3449_spurious"
> fixes a "corrupt" working copy, i.e. "svn status" and "svn diff" work
> properly afterwards. I'll try to figure out why my machine is living
> in its own timeline. All I can say after reading just a few lines of
> python code is that I don't have
> SVN_I_LOVE_CORRUPTED_WORKING_COPIES_SO_DISABLE_SLEEP_FOR_TIMESTAMPS
> hard-wired to 'yes' :-).
Well, that's a relief, at least.
Can you please get two pieces of information:
1) run the "mount" command and past the line representing the ext4
filesystem where your working copy lives
2) Get the ext4 superblock info, using "sudo tune2fs -l /dev/something";
the mount output will tell you which /dev/something
-- Brane
--
Branko Čibej
Director of Subversion | WANdisco | www.wandisco.com
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
Quick update:
The problem is definitely timestamp related. "touch 3449_spurious" fixes
a "corrupt" working copy, i.e. "svn status" and "svn diff" work properly
afterwards. I'll try to figure out why my machine is living in its own
timeline. All I can say after reading just a few lines of python code is
that I don't have
SVN_I_LOVE_CORRUPTED_WORKING_COPIES_SO_DISABLE_SLEEP_FOR_TIMESTAMPS
hard-wired to 'yes' :-).
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
Next update:
With a plain & simple
void
svn_io_sleep_for_timestamps(const char *path, apr_pool_t *pool)
{
apr_sleep(1010000);
}
in libsvn_subr/io.c the test is running slower, but works every time.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
Another update:
Tried to build against latest apr-1.4.6.tar.bz2 & apr-util-1.5.2.tar.bz2
instead of the older versions from the Ubuntu Lucid repositories. No
change :-(, i.e. the test fails with the original
svn_io_sleep_for_timestamps implementation.
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
Hi Branko & Philip,
thanks a lot for your hints. I've seen your mails only now on http://mail-archives.apache.org/ and won't have access to my GNU/Linux machine till Monday. Meanwhile I'm giving 1.8 RC2 a try on Mac OS Snow Leopard.
What do you mean by "sleep for timestamps disabled"? I didn't do anything special, just running "make check" or "./diff_tests.py [-v] 60" (on an ext4 filesystem).
You've probably hit the mark with timestamps. While performing more tests yesterday, I experienced another problem, but that one was nondeterministic. Every once in a while, I'd say in about 1 out of 5-10 attempts, "./diff_tests.py -v 60" failed to create revision 4. The output claimed that the "svn ci" command was executed, but the repository only contained 3 revisions. I inserted debug outputs into the svn shell script, right before the exec, to make sure that everything is in order and file 3449_spurious has the proper contents. Everything looked perfectly fine and yet the commit did nothing at all sometimes. No "Sending..." output, no output to stdout at all. The reason for this problem could be very similar. Maybe Subversion thinks that there's nothing to commit at all, if the timestamp of file 3449_spurious didn't change? (Maybe svn could print something like "(No changes need to be committed)" in such a case, like GNU Emacs when there's nothing to save ;-)
On Monday, I'll check if a "touch 3449_spurious" fixes the broken working copy.
Kind regards,
Tobias
PS: All tests in the green on Snow Leopard now :-).
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Branko Čibej <br...@wandisco.com> writes:
> On 24.05.2013 09:32, Tobias Bading wrote:
>> So, the update claims to have updated 3449_spurious to r2 and the
>> merge claims to have merged c4 into that file. As it turns out, both
>> claims seem correct. The contents of 3449_spurious look correct.
>> However, "svn status" and "svn diff" run afterwards both swear that
>> the only local modification of the working copy is a property change
>> at the wc root, the addition of the svn:mergeinfo property.
>>
>> Any idea what's going on here? What could affect the python script in
>> a way that its merge is messed up, although the same merge run by hand
>> works fine?
>
> Are you by any chance running the tests with the sleep for timestamps
> disabled? That could cause the effects you're seeing, especially
> combined with running on a FAT filesystem (which has 2-second timestamp
> granularity).
It does sound like a sleep/timestamp problem. If you take a "broken"
working copy where the merge has changed 3449_spurious but status/diff
don't show it then running 'touch 3449_spurious' will change the
timestamp and should make status/diff work.
If the text change made by merge is not showing up in status it implies
that the preceeding update didn't sleep properly so we should be able to
confirm with this patch:
Index: subversion/tests/cmdline/diff_tests.py
===================================================================
--- subversion/tests/cmdline/diff_tests.py (revision 1485754)
+++ subversion/tests/cmdline/diff_tests.py (working copy)
@@ -3853,6 +3853,7 @@
svntest.actions.run_and_verify_svn(None, None, [],
'update', '-r2', wc_dir)
+ from time import sleep;sleep(2)
svntest.actions.run_and_verify_svn(None, None, [],
'merge', '-c4', '^/', wc_dir)
However this test explictly re-enables sleeping so the test should work
without that explicit sleep. What filesystem are you using?
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Branko Čibej <br...@wandisco.com>.
On 24.05.2013 09:32, Tobias Bading wrote:
> Hi Philip,
>
> thanks for your suggestions. I tried to dig a little deeper... and now
> things are getting even more strange.
>
> First, I tried to delete everything after the "update -r2" from
> no_spurious_conflict so I could make a copy of the wc before the
> merge. Guess what? Executing the "merge -c4 ^/" in a shell after
> running the test worked perfectly fine. So I removed the "update -r2"
> from no_spurious_conflict as well. Running "update -r2" and "merge -c4
> ^/" in a shell after the test worked perfectly fine again.
>
> Obviously, the test script does something differently than me in a
> shell. My python ain't that good, but I managed to come up with these
> lines:
>
> exit_code, out, err = svntest.actions.run_and_verify_svn(None, None,
> [], 'update', '-r2', wc_dir)
> print "update exit_code: ", exit_code
> print "update out: ", out
> print "update err: ", err
> exit_code, out, err = svntest.actions.run_and_verify_svn(None, None,
> [], 'merge', '-c4', '^/', wc_dir)
> print "merge exit_code: ", exit_code
> print "merge out: ", out
> print "merge err: ", err
>
> Now the test prints:
>
> update exit_code: 0
> update out: ["Updating
> 'svn-test-work/working_copies/diff_tests-60':\n", 'U
> svn-test-work/working_copies/diff_tests-60/3449_spurious\n', 'Updated
> to revision 2.\n']
> update err: []
> merge exit_code: 0
> merge out: ["--- Merging r4 into
> 'svn-test-work/working_copies/diff_tests-60':\n", 'U
> svn-test-work/working_copies/diff_tests-60/3449_spurious\n', "---
> Recording mergeinfo for merge of r4 into
> 'svn-test-work/working_copies/diff_tests-60':\n", ' U
> svn-test-work/working_copies/diff_tests-60\n']
> merge err: []
>
> So, the update claims to have updated 3449_spurious to r2 and the
> merge claims to have merged c4 into that file. As it turns out, both
> claims seem correct. The contents of 3449_spurious look correct.
> However, "svn status" and "svn diff" run afterwards both swear that
> the only local modification of the working copy is a property change
> at the wc root, the addition of the svn:mergeinfo property.
>
> Any idea what's going on here? What could affect the python script in
> a way that its merge is messed up, although the same merge run by hand
> works fine?
Are you by any chance running the tests with the sleep for timestamps
disabled? That could cause the effects you're seeing, especially
combined with running on a FAT filesystem (which has 2-second timestamp
granularity).
-- Brane
--
Branko Čibej
Director of Subversion | WANdisco | www.wandisco.com
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Tobias Bading <tb...@web.de>.
Hi Philip,
thanks for your suggestions. I tried to dig a little deeper... and now
things are getting even more strange.
First, I tried to delete everything after the "update -r2" from
no_spurious_conflict so I could make a copy of the wc before the merge.
Guess what? Executing the "merge -c4 ^/" in a shell after running the
test worked perfectly fine. So I removed the "update -r2" from
no_spurious_conflict as well. Running "update -r2" and "merge -c4 ^/" in
a shell after the test worked perfectly fine again.
Obviously, the test script does something differently than me in a
shell. My python ain't that good, but I managed to come up with these lines:
exit_code, out, err = svntest.actions.run_and_verify_svn(None, None,
[], 'update', '-r2', wc_dir)
print "update exit_code: ", exit_code
print "update out: ", out
print "update err: ", err
exit_code, out, err = svntest.actions.run_and_verify_svn(None, None,
[], 'merge', '-c4', '^/', wc_dir)
print "merge exit_code: ", exit_code
print "merge out: ", out
print "merge err: ", err
Now the test prints:
update exit_code: 0
update out: ["Updating
'svn-test-work/working_copies/diff_tests-60':\n", 'U
svn-test-work/working_copies/diff_tests-60/3449_spurious\n', 'Updated to
revision 2.\n']
update err: []
merge exit_code: 0
merge out: ["--- Merging r4 into
'svn-test-work/working_copies/diff_tests-60':\n", 'U
svn-test-work/working_copies/diff_tests-60/3449_spurious\n', "---
Recording mergeinfo for merge of r4 into
'svn-test-work/working_copies/diff_tests-60':\n", ' U
svn-test-work/working_copies/diff_tests-60\n']
merge err: []
So, the update claims to have updated 3449_spurious to r2 and the merge
claims to have merged c4 into that file. As it turns out, both claims
seem correct. The contents of 3449_spurious look correct. However, "svn
status" and "svn diff" run afterwards both swear that the only local
modification of the working copy is a property change at the wc root,
the addition of the svn:mergeinfo property.
Any idea what's going on here? What could affect the python script in a
way that its merge is messed up, although the same merge run by hand
works fine?
I can provide a tarball containing the messed up working copy and the
repository if you like.
Kind regards,
Tobias
Re: subversion-1.8.0-rc2: diff_test 60 fails
Posted by Philip Martin <ph...@wandisco.com>.
Tobias Bading <tb...@web.de> writes:
> However, once I execute "[...]/svn revert -R .", "[...]/svn update",
> and "[...]/svn update -r2" in the working copy, the merge works just
> fine afterwards. And that "update -r2" is exactly what
> no_spurious_conflict in diff_tests.py does before the faulty merge, if
> I'm reading the code correctly.
Yes, the test is doing an update to r2.
The double update should be an overall no-op, but it is making a
difference. You have to compare the working copy before and after the
double update and determine what has changed. One would expect the
timestamp of 3449_spurious to get changed by the double update, does
anything else change? Does the text of 3449_spurious change? Does the
output of
svn info 3449_spurious
change? Does the output of
svn pl -v
change? Try running
sqlite3 .svn/wc.db "select * from nodes order by local_relpath"
sqlite3 .svn/wc.db "select * from actual_node order by local_relpath"
does anything there change?
If you cannot identify what has changed perhaps you could provide a
tarball containing the repository and the broken working copy.
--
Certified & Supported Apache Subversion Downloads:
http://www.wandisco.com/subversion/download