putting a larger file in synced folder generates large amount of Watcher events

Bug #805210 reported by Bjorge Dijkstra
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Syncany
Confirmed
Undecided
Philipp C. Heckel

Bug Description

When I copy a somewhat larger file (e.g. a couple of megabytes) into the synchronized folder then this generates a very large amount of file watcher events and corresponding indexer updates.

11-07-03 20:39:24 | vulcan | BufferedWatcher | BufWatchTimer | INFO : ENTRY_CREATE /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | Indexer | Indexer | INFO : Processing request org.syncany.index.requests.CheckIndexRequest@746ac18c
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | CheckIndexRequest | Indexer | INFO : Indexer: Checking file /home/bjd/Public/CIMG2015.JPG ...
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:24 | vulcan | LocalWatcher | BufWatchTimer | INFO : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
... <repeated lots of times> ...

11-07-03 20:39:25 | vulcan | Indexer | Indexer | INFO : Processing request org.syncany.index.requests.CheckIndexRequest@51d7aa64
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : Indexer: Checking file /home/bjd/Public/CIMG2015.JPG ...
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : File found in DB. Same modified date, same size. Nothing to do!
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : Checking file DONE: /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:25 | vulcan | Indexer | Indexer | INFO : Processing request org.syncany.index.requests.CheckIndexRequest@6d172f8f
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : Indexer: Checking file /home/bjd/Public/CIMG2015.JPG ...
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : File found in DB. Same modified date, same size. Nothing to do!
11-07-03 20:39:25 | vulcan | CheckIndexRequest | Indexer | INFO : Checking file DONE: /home/bjd/Public/CIMG2015.JPG
11-07-03 20:39:25 | vulcan | Indexer | Indexer | INFO : Processing request org.syncany.index.requests.CheckIndexRequest@34ae19a
... <repeated lots of times> ...

Moving parentKey.reset() from the BufferedWatcher worker thread to the end of processEvent() to hold of any new events until after processing seems to solve this (see attached patch).

Revision history for this message
Bjorge Dijkstra (bjd) wrote :
Revision history for this message
Philipp C. Heckel (binwiederhier) wrote :

Great thanks, I'll merge this in the newsync branch tomorrow.

Changed in syncany:
milestone: none → 0.1-alpha
assignee: nobody → Philipp C. Heckel (binwiederhier)
status: New → Fix Committed
Revision history for this message
Philipp C. Heckel (binwiederhier) wrote :

Even though the fix seems to solve the problem, it does create another one: if more than one event are fired in one batch (in one parentKey), the other events are purged.

I'll look into this a little more.

Changed in syncany:
status: Fix Committed → Confirmed
Revision history for this message
Bjorge Dijkstra (bjd) wrote :

I agree. The problem actually appears to be that, while processing of an event is held off when the associated file is still changing, these changes still generate new events that are also queued. So when a file finally stops changing suddenly a whole bunch of queued events for that file become ready for processing.

Revision history for this message
Philipp C. Heckel (binwiederhier) wrote : Re: [Bug 805210] Re: putting a larger file in synced folder generates large amount of Watcher events

I fixed it in my newsync branch; It now removes all outdated MODIFY
events for the same file. Check it out here:
http://bazaar.launchpad.net/~binwiederhier/syncany/newsync/revision/67#syncany/syncany-core/src/main/java/name/pachler/nio/file/contrib/BufferedWatcher.java

What do you think? It's probably not perfect since the event queue is
(once again) walked through, but it's better than passing every single
event to the indexer.

Revision history for this message
Bjorge Dijkstra (bjd) wrote :

I don't think it will be much of a problem that you walk again through the list. Since you now prevent the queue from filling up with a lot of duplicates the queue will in general be quite short (unless a lot different files change at the same time).

In its current form it will probably hang though, since the while loop will only terminate if you remove all events from the queue which is not very likely to happen.

Revision history for this message
Philipp C. Heckel (binwiederhier) wrote :
Download full text (4.1 KiB)

I figured that out already -- I forgot the increment i++
Are you by any change related to Edsger Dijkstra?

On Wed, Jul 6, 2011 at 10:53 PM, Bjorge Dijkstra <email address hidden> wrote:
> I don't think it will be much of a problem that you walk again through
> the list. Since you now prevent the queue from filling up with a lot of
> duplicates the queue will in general be quite short (unless a lot
> different files change at the same time).
>
> In its current form it will probably hang though, since the while loop
> will only terminate if you remove all events from the queue which is not
> very likely to happen.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/805210
>
> Title:
>  putting a larger file in synced folder generates large amount of
>  Watcher events
>
> Status in Syncany:
>  Confirmed
>
> Bug description:
>  When I copy a somewhat larger file (e.g. a couple of megabytes) into
>  the synchronized folder then this generates a very large amount of
>  file watcher events and corresponding indexer updates.
>
>  11-07-03 20:39:24 | vulcan     | BufferedWatcher      | BufWatchTimer      | INFO     : ENTRY_CREATE /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | Indexer              | Indexer            | INFO     : Processing request org.syncany.index.requests.CheckIndexRequest@746ac18c
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | CheckIndexRequest    | Indexer            | INFO     : Indexer: Checking file /home/bjd/Public/CIMG2015.JPG ...
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:24 | vulcan     | LocalWatcher         | BufWatchTimer      | INFO     : Watcher: Checking new/modified file /home/bjd/Public/CIMG2015.JPG
>  ... <repeated lots of times> ...
>
>  11-07-03 20:39:25 | vulcan     | Indexer              | Indexer            | INFO     : Processing request org.syncany.index.requests.CheckIndexRequest@51d7aa64
>  11-07-03 20:39:25 | vulcan     | CheckIndexRequest    | Indexer            | INFO     : Indexer: Checking file /home/bjd/Public/CIMG2015.JPG ...
>  11-07-03 20:39:25 | vulcan     | CheckIndexRequest    | Indexer            | INFO     : File found in DB. Same modified date, same size. Nothing to do!
>  11-07-03 20:39:25 | vulcan     | CheckIndexRequest    | Indexer            | INFO     : Checking file DONE: /home/bjd/Public/CIMG2015.JPG
>  11-07-03 20:39:25 | vulcan     | Indexer              | Indexer            ...

Read more...

Revision history for this message
Bjorge Dijkstra (bjd) wrote :

No, I'm not related to him. The last name Dijkstra is actually very common here in the north of the Netherlands.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.