"Searching for directory" ta...

[redhan]

Hi!

I have been using FreeFileSync for some time. I use it everyday for syncing my
desktop at work and my laptop at home through an USB stick. Thanks a lot for
this piece of software!

I have a problem however: when FreeFileSync is in the very first step of
"Compare", i.e., when is locating the directories to synchronise, it takes (in
my case about 4 minutes), showing messages of "Searching for directory X"...

The latest version that worked fine for me was 3.8... 3.9 was slower and 3.10
was definitively having this problem. I have recently tested 5.0 and the
problem is still there. I would like to move to a recent version!

My desktop is a Windows XP Professional SP3, FFS is installed as a portable
application in my USB stick. My laptop has the same OS but I do not experience
the problem there...

Any idea about what could I investigate to solve the problem?

Thank you very much in advance

[Zenju]

It seems FFS is blocking doing some file I/O. You can use the free tool
Process Monitor to find out what FFS is doing while it is blocking in
"Searching...":
http://technet.microsoft.com/de-de/sysinternals/bb896645
In order to get a small log, exclude all processes manually (right-click in
Proc Mon) that you know have nothing to do with FFS. I wouldn't use an include
filter on FreeFileSync.exe, since the blocking may be in a sub-process, which
would then be excluded from the log.
Then save the log as a PML file and send it via mail, or load it onto some
online file hoster and link here.

[redhan]

Thanks a lot for your interest.

I have generated the PML file and posted it to Mediafire, you can download it
from [404, Invalid URL: http://www.mediafire.com/?chdf869ehjfyity]

I hope there is useful info inside... it is the first time I use FileMonitor.


Please let me know if there is anything else I can do!

[Zenju]

From a rough overview this run looks pretty much normal. Did you experience
the lag you described above?
In order to get a better analysis it would be a good idea to simplify your
configuration. If possible, try to create a minimal testcase that still
exhibits the lag, and then create a new log. It may also be a good idea to
create a second log, that only captures the lag (i.e. start while FFS hangs
and log, say 10 seconds).

[redhan]

Thanks for the analysis!

Yes, the lag was present. I will perform tomorrow when I have access to the
desktop, a simplified test following your suggestion and post the results.

Would it be helpful to post a video showing the behaviour?

[redhan]

I have simplified the test case, there is only one directory to be
synchronised, C:\testFFS (in my desktop) and L:\testFFS (in my USB stick). The
directories contain only an empty text file that has not changed.

I have created two log files, one with the complete cycle of "Compare" and
"Synchronise" (Logfile_testFFS.PML.zip), and another one capturing only the
lags experience during "Compare" for both directories
(Logfile_testFFS_lag.PML.zip). Both files can be downloaded from [404, Invalid URL: http://www.mediafire.com/?li04p2vfixybx4e%2C98a5opnim1wbp4p]

There is also a small video showing the lag (testFFS_lag.zip) you can download
from [404, Invalid URL: http://www.mediafire.com/?ozpg265hg9qndge] Just unzip and double click on the htm file (video created with
Wink at 8 fps). You can notice how each "Searching" takes around 15 seconds.

Thanks!

[redhan]

Hi again.

I have noticed that following exactly your second suggestion, that is, to
capture events while FFS is in the lag, the data in the log file is different.
Please have a look at the PML file in [404, Invalid URL: http://www.mediafire.com/?1mcj4lltcu8mb69] (Logfile_testFFS_lag2.PML.zip)
where (I think) the lag is shown between 11:09:37 and 11:09:49 (12 seconds,
which is more or less the time lag experienced).

However, I have no clue about who is producing the lag. Should I unfilter
something?

Thanks

[Zenju]

> two log files and video
Wow, now that's something I can work with! A video is an excellent way to
become familiar with the scenario.

There's just one problem, I can't access any of the files:

quote: "This file is currently set to private.
When a file is set to private by its owner only the owner of the file can
access it. If you are the owner of the file please log into your account to
access this file."

[redhan]

My sincere apologies!

Somehow I messed it up. Should work now.

[Zenju]

After analyizing the video and the data there are at least two problems:
1. from the video it is obvious that FFS is not responsive while "searching for dir". This may need to be fixed, but it is also a hint to:
2. The lag is related to writing the lock file. The process monitor shows two conspicuous entries next to each other: "createfile "L:\dev\urandom" and "Createfile sync.ffs.lock". The first entry is very odd, a quick research showed that \dev\urandom is poorly chosen as a random number generator seed by a boost library, irrespective that this volume is existent on Linux only and it doesn't make sense to query for it on Windows at all.
From your video I saw that your working directory is "L:". This explains why
"\dev\urandom" is resolved as "L:\dev\urandom" in both cases when creating
locks for "C:" and "L:". Further assuming that access to "L:" is slow (is it
some network drive?), we have writing a lockfile + useless checks on a non-
exitsing directory.
At this point I cannot say which of the two accesses (or both) is responsible
for the lag. So I assembled a testversion which hacks away the check for the
non-existing directory urandom:

[404, Invalid URL: http://www.2shared.com/file/3_79SM1Q/FreeFileSync_Win32_no_urandom.html]

Do you see any change in lag-behavior with this version?

Advanced test: Although I am pretty sure the lag is related to the lock file
you can verify this assumption: Use the current v5.0 FFS version and make both
test directories read-only (set folder permissions accordingly). FFS won't
complain against failure to create the lock files, but since the lag is
expected to be in the write phase (proc mon), comparison should not block this
time.

[redhan]

Hi

L: is the usb stick

I am afraid the lag is still there using the no_urandom version. I have also
made both test directories read-only and v5.0 also presens the lag...

[Zenju]

> both test directories read-only and v5.0 also presens the lag...
This is very strange, do you have a log for this?

[redhan]

Sure!

Here you are: [404, Invalid URL: http://www.mediafire.com/?j3clrnpemh5c9lm]

I have used the following approach:
1. Start ProcMon
2. Start FFS
3. Filter all that is not FFS
4. Disconnect from events
5. Filter all events before
6. Launch "Compare"
7. Connect ProcMon to Events

This was the same approach used in Logfile_testFFS_lag2.PML.zip

BTW, I have to check but I think the lag can be reproduced in my laptop if it
is disconnected from the ethernet cable (?). On one hand this is good because
I could keep providing you feedback next week (I will be far from my desktop
then). But on the other hand this makes me think: both the desktop and the
laptop were configured by the systems department of my company. Could FFS be
being disturbed by any sw both machines have in common?

In the meanwhile I will try and reproduce this on my laptop, to see if the
network connection has any influence. I have a second laptop I have configured
myself (also Windows XP, but no sw installed by the company) I can use to test
in a "company-sw-free" environment.

Thank you very much!

[Zenju]

> This was the same approach used in Logfile_testFFS_lag2.PML.zip
FFS still successfully writes to "L:\testFFS\sync.ffs_lock" (At relative time
06:23:1659170). So the "L:\testFFS" folder is writeable. If it were read-only,
there should be no lag anymore.

So the assumption that the lag is happening on first write access to L: is
still strong. The big question is why it is lagging at all. USB sticks are
generally FAT-formatted with caching disabled, which explains part of why the
access is slow. But over 10 seconds seems excessive for the first write
access.

> laptop if it is disconnected from the ethernet cable (?).
It's a good idea to do various tests changing even seemingly unrelated
elements (like LAN cable software). A disconnected LAN easily creates worst
lags if software tries to access it. At this point almost anything can be the
culprit. But it is necessary to identify a single element that is stable in
all these tests (e.g. the lag occurs using the same usb stick irrespective of
tests on different PCs / operating systems / LAN connectivity, etc.) for
further diagnosis.

[Zenju]

Possibly related problem:
viewtopic.php?t=1919

[redhan]

> So the "L:\testFFS" folder is writeable.

You are right. Both C:\testFFS and L:\testFFS are writeable. Funny enough, it
seems that the read-only attribute for the folders is not kept: I use the
right-click "properties" menu to make the folders read-only; when I press
"Apply" and "OK" and again on "Properties", the read-only flag is gone!

From what I am finding in Google the read-only flag in Windows does not work
as it is supposed to do. I will try and find a way to make the folder truly
read-only and come back with the result.

> Possibly related problem:
My USB stick is a 8GB Patriot Rage, normally it is quick. I had before a Sony
TinyVault and if I remember well the problem was there also.

I have checked another scenario without the USB stick: FFS is launched from my
C: drive to synchronise a folder in my desktop PC and a network share, the lag
is there also... I have gone again to version 3.8 and it is done in an
instant. 3.10 onwards the lag is there...

[Zenju]

> I will try and find a way to make the folder truly read-only and come back
with the result.
Originally I proposed to set "folder permissions" (not the folder attributes),
but your FAT obviously doesn't have NTFS permissions. Perhaps your USB stick
has some hard-ware read-only button?

Anyway I may be a bit too fast with considering the USB stick responsible.
Carefully reanalyzing your first logs, it becomes evident that *both* first
lock file writes on C:\ and L:\ have a 10 second lag. A slow USB stick doesn't
explain why writing to C:\ would lag. So an interesting next test would be to
exclude the USB stick from the testcase and sync C:\ <-> C:\ and see if it
still lags.

> FFS is launched from my C: drive to synchronise a folder in my desktop PC
and a network share, the lag is there also
Great, it seems the USB stick is not the cause!
The next culprit would be network. Can you send me two logs, one for a
testcase C:\ <-> C:\
and one for C:\ <-> network that show the lag? Best start capturing the log
before clicking the compare button (the last two logfiles trimmed the first
lag, so I missed it).

[Zenju]

PS: In order to "fully" exclude the USB stick from the test case, run FFS from
C:\ (not from L:\)
Else we have a access to ""L:\dev\urandom" which may confuse our conclusions.

[Zenju]

Another test comes to my mind: The question is whether the lag is caused
1. by the special way FFS writes the lock file or
2. whether *any* write access causes the lag.

You can test this by using FFS's batch mode and have a log file written into
one of the two drives that are synced. The log is written before the lock
file. If the lag now occurs when writing the log, we're in case 2., else were
in 1. This distinction is important, because I may be able to fix 1 but not 2.
(In any case, please share the procmon log)

[redhan]

Sorry for the delay, I have been away for a while.

I have run the tests you suggested. I downloaded FFS v5.2 and installed it
locally on my C: drive. Now the events are captured before pressing the
"Compare" button. The USB is not used at all.

The first test is a C:\ <-> C:\ case (actually C:\testFFS\source\ <->
C:\testFFS\target\). The lag is shown and the PML file can be found here: [404, Invalid URL: http://www.mediafire.com/?o67tuwckocuc9ck]

The second test is a C:\<-> network. The lag is also shown, and the PML file
can be found here: [404, Invalid URL: http://www.mediafire.com/?0uo4sh2zglw1um2]

The third test is a C:\<->C:\, identical to the first test but in batch mode.
According to my observations the log file is created without lag so
(hopefully) we would be in case 1. I have shared the following:
- batch file (probably you do not need it): [404, Invalid URL: http://www.mediafire.com/?vzui9h2z29ywd3u]
- PML file: [404, Invalid URL: http://www.mediafire.com/?5shczseaolpwpvo]
- video: [404, Invalid URL: http://www.mediafire.com/?4gz48q31pz40smb]
- log file: [404, Invalid URL: http://www.mediafire.com/?bh2bls9tx53bnke]

Hope this helps!

[Zenju]

Very interesting, in your new testcases, the lag happens consistently, no
matter what drives you are operating on, even C: <-> C:. What strikes me as
odd, is that on first creation of the logfile, directly after the bogus
"urandom" log entry, a lot of internet/network staff is called (wsock). This
is essentially boost random number generation, but what this does interally is
redirect to Windows random number generation, which obviously uses some
network data as seed. This would be a very good explanation for a lag!
I *had thought* I had already exlcuded this as a culprit in testcase
"FreeFileSync_Win32_no_urandom.html" above. But carefully re-analyzing the log
you sent above I find a "urandom" entry, which should not be there and I
didn't notice when I first reviewed it. It seems you have tested with another
version instead, therefore urandom is back as a candidate! Could you please
redo the tests with "FreeFileSync_Win32_no_urandom.html"?

[Zenju]

I have gained further insights by debugging on my machine and trying to
reproduce your log file. Although it's true that boost random number
generation is back as a culprit (we haven't yet excluded the urandom
scenario), my assumption the network/internet log entries would be related to
random number seeding were wrong. In fact they are produced by wxWidgets full
host name determination. Looking at its code, it is my top candiate right now,
with full potential to create all the lag of the world.

Therefore I have assembled a new candidate for testing, which hacks out host
name determination:

[404, Invalid URL: http://www.2shared.com/file/_gk1J2IO/FreeFileSync_v53_beta_setup.html]

Is there any change to lag behavior?

[redhan]

> It seems you have tested with another version instead
You are right, the last tests were done with v5.2. Since the no_urandom
version also presented the lag I thought it better to use the standard
version.

> Is there any change to lag behavior?
My dear Zenju... with v5.3 beta the lag is gone!!!!!! Awesome! You can see
in the video below the lightning speed for the C:\<->C:\ test case. The same
happens for USB, network share... unbelievable!

Just for your record:
- video showing the absence of lag: [404, Invalid URL: http://www.mediafire.com/?pz1lvcfbpgmgaqd]
- PML file: [404, Invalid URL: http://www.mediafire.com/?2sgsh6y01wgsfsh]

Thanks a lot for this fantastic fix!

There are bad news... but most probably they are due to the "beta" nature of
the code. When performing actually the synchronisation there is an error:



Error copying file:
"C:\testFFS\source\test.txt" ->
"C:\testFFS\target\test.txt.ffs_tmp"

Windows Error Code 87: The parameter is incorrect.



I have made myself sure the directories/files are not read-only. I have
shared:
- video: [404, Invalid URL: http://www.mediafire.com/?bhvl79bga43fx9b]
- PML: [404, Invalid URL: http://www.mediafire.com/?bhvl79bga43fx9b]

[Zenju]

> with v5.3 beta the lag is gone
Incredible! :) All this little sub-routine was supposed to do is to give a
network-unique id for the current computer. It seems it checks the whole
internet for uniquness considering the time it wastes.
Now this host name determination is probably the only part of FFS's complete
sync logic that relies on wxWidgets still.
Relying on third-party libraries for critical code proves to be painful each
and every time, I should have learned this lession long ago! I'll get rid of
it and come up with a better solution with controlled performance.

> When performing actually the synchronisation there is an error:
Yes this is due to the beta, there is some new code for testing purposes which
requires Windows Vista upwards. I'll remove it for the next test.

Stay tuned for the final fixed version!

[redhan]

> Stay tuned for the final fixed version!

I will certainly be!

Thank you very much for your support!

[Zenju]

It is done! I have reworked big parts of the locking algorithm, so that it
should be not only without a lag, but also better at detecting and resolving
abandoned locks automatically.

Here is the new version. I'll do another code review and if you don't find any
problems this should be it.

[404, Invalid URL: http://www.2shared.com/file/W8zwI8Ai/FreeFileSync_v53_beta_setup.html]

Thanks a lot for your help, Zenju

[redhan]

Dear Zenju,

Works perfectly!!! Incredibly fast! No more lags, and the Synchronisation
works as fine as ever!

Thank you so much for finding the problem!