Log file time stamps and overall duration

[mfreedberg]

Looking over the logs, there is a difference between the overall time reported
and the start and end times recorded in the log file.
A recent log file shows the following summary:
Items processed: 5 (5.56 MB)
Items remaining: 1 (0 Bytes)
Total time: 00:01:28

and the time-stamped entries show a start time of and an end time of - a
duration of only eight seconds to do the actual work - I removed the path
information to help with legibility and all the errors are expected.




[8:06:24 AM] Warning: Recycle Bin is not available for the following paths! Files will be deleted permanently instead:
[8:06:24 AM] Info: Processing folder pair:
[8:06:24 AM] Info: Processing folder pair:
[8:06:24 AM] Info: Processing folder pair:
[8:06:24 AM] Info: Processing folder pair:
[8:06:25 AM] Info: Processing folder pair:
[8:06:25 AM] Info: Processing folder pair:
[8:06:25 AM] Info: Processing folder pair:
[8:06:25 AM] Info: Processing folder pair:
[8:06:26 AM] Info: Processing folder pair:
[8:06:26 AM] Info: Overwriting file ...
[8:06:30 AM] Info: Processing folder pair:
[8:06:30 AM] Info: Deleting file
[8:06:30 AM] Info: Deleting file
[8:06:30 AM] Info: Creating file
[8:06:30 AM] Info: Creating file
[8:06:31 AM] Info: Creating file
[8:06:31 AM] Error: Cannot read file.
[8:06:32 AM] Warning: Synchronization completed with errors



I assume that the difference in the overall time and actual time stamped
entries is the time it takes FFS to discover the various directories, do the
necessary comparisons, build a table of actions, and then, once it really
starts to do stuff, the log reflects those actual actions with the time-
stamped entries. Is this correct?

[mfreedberg]

Sorry, did not realize that the codify tag would be so terrible! Here is the
log data again:

Warning: Recycle Bin is not available for the following paths! Files will be
deleted permanently instead: Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Processing folder pair:
Info: Overwriting file ...
Info: Processing folder pair:
Info: Deleting file
Info: Deleting file
Info: Creating file
Info: Creating file
Info: Creating file
Error: Cannot read file.
Warning: Synchronization completed with errors

[mfreedberg]

Ok, no idea how that worked, but now the code piece looks great! Ignore my
second comment :-)

[Zenju]

The "total time" includes the time it takes to do the comparison while the log
only shows the second step, the synchronization.

[Zenju]

I've updated FFS to show the begin of the comparison phase to avoid this kind
of confusion in the future:

______________________________________
Batch execution - 24.07.2012 - Default

Nothing to synchronize!

Total time: 00:00:08
______________________________________

Info: Start comparison
Info: Synchronize folder pair:
Left: 'c:\'
Right: 'g:\'
Info: Nothing to synchronize!

[mfreedberg]

Ok, good to know. Here is our thinking, which perhaps I will revise based on
the data in the log.

Our plan is: once a day, we will take the last log from a sync event, parse
out the header info for duration, number of items, and amount of data and
report that to our database as a "heartbeat" record - proving that the person
is still running our tools and providing good stats on time, volume, number of
items.

The duration would be sort of wrong in that it did not really take that long
to copy the data, but it would be correct in that the entire process took that
long, so we may well just stick with that.

Thanks for explaining!

[mfreedberg]

Wow, even better, I did not see your second comment in time! What version
would this be in, 5.6?

[Zenju]

Yes, 5.6, we're absolutely "agile" here :)

[Zenju]

You may already check it out: The (production quality) beta representing the
development progress can be found here:
[404, Invalid URL: http://freefilesync.sourceforge.net/FreeFileSync_5.6_beta_setup.exe]

[mfreedberg]

The update is working as expected, thanks very much!

Here is a sample header from a recent sync event, about 40 seconds to do the
directory comparison (I am using complex filters to keep the number of
directories in to compare lower, that seems to be one way to help increase the
speed a bit).

______________________________________________________
Batch execution - 7/24/2012 - SyncEverythingAllTheTime

Synchronization completed with errors!

Items processed: 3 (32.1 MB)
Items remaining: 1 (0 Bytes)
Total time: 00:01:20
______________________________________________________

Info: Start comparison
Warning: Recycle Bin is not available for the following paths! Files will be
deleted permanently instead:
{and so on}

One question about the log...do you only write out the log to disk when FFS
quits? If so, just curious why that might be; if the program crashes or fails
to exit properly, there would be no logging.

[Zenju]

The log file is opened before starting sync in order to get an early error in
case of problems with the log being the only communication channel. But the
log content is assembled and written after sync when all data is available.
This is just a simpler and easier to implement model, and there doesn't seem
to be very useful options to "improve" it anyway.