Metadata load is too slow

Actually, I think apport hasn't attached anything useful to debug the applet crash....

2009-09-25 14:23:30,810 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2009-09-25 14:30:17,435 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 3191, idx_node_id: 3191, shares: 7

^ Why is that a 7 minute difference?!

Reassigning to Guillermo to take a look at why there is a 7 minute gap to load the metadata.

Hi,

I talked with Martin via IRC, and he can't reproduce this.

I think the problem with the 7 minutes might be related to a very slow creation of the filesystem manager index.

Facundo, any ideas on what might be causing such delay?

Thanks.

Hi All,

This bug is quite prevalent to me after I tried to backup my entire home folder to ubuntuone (with the help of Roman we could see that it was around 380000 files). Took about 3 hours to copy the data to the ubuntuone folder (don't know why local disc copies was so slow, ran at about 700KBs, disk is never that slow), seems to have taken about 8 hours to index and then takes another 8 hours each time the pc starts up to read the data. During that time the PC is practically unusable. CPU is fine (Intel(R) Core(TM)2 Duo CPU T7700 @ 2.40GHz) but the disk access is the problem. Firefox greys out, nautilus greys out, everything is just horribly slow. Iotop shows that that the disk is continuously running at about 400K/s read

Total DISK READ: 382.60 K/s | Total DISK WRITE: 0.00 B/s
  TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
11118 be/4 ruald 382.60 K/s 0.00 B/s 0.00 % 0.00 % python /usr/lib/ubuntuone-client/ubuntuone-syncdaemon

I have been trying to backup my entire home folder to u1 since i purchased 50GB of space bout 3 months so to get this working properly is quite a priority for me. Please let me know if you require any other info.

I logged a bug this morning re the client applet crashing while the syncd is still running, not knowing that reading the data is what it was still doing (https://bugs.launchpad.net/ubuntu/+source/ubuntuone-client/+bug/537138)

Might be some useful info in there as well.

Thanks

Here's the info about syncdaemon startup from psypher:

2010-03-12 07:15:59,194 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2010-03-12 07:54:56,636 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 195799, idx_node_id: 14082, shares: 1
2010-03-12 07:54:56,642 - ubuntuone.SyncDaemon.HQ - INFO - HashQueue: _hasher started
2010-03-12 07:54:57,239 - ubuntuone.SyncDaemon.DBus - INFO - DBusInterface initialized.
...
2010-03-12 07:54:57,241 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan starting...
2010-03-12 07:54:57,241 - ubuntuone.SyncDaemon.local_rescan - INFO - start scan all shares
2010-03-12 08:05:48,303 - ubuntuone.SyncDaemon.Main - NOTE - ---- MARK (state: READING; queues: metadata: 0; content: 0; hash: 0, fsm-cache: hit=8 miss=587391) ----
...
2010-03-12 08:10:24,726 - ubuntuone.SyncDaemon.Main - NOTE - Local rescan finished!
2010-03-12 08:10:24,727 - ubuntuone.SyncDaemon.Main - INFO - hash queue empty. We are ready!

So it takes 39 minutes to load metadata and 15 minutes to rescan all local files.

Metadata loading _is_ slow.

Another thing with metadata being stored as enormous amount of files is that we will be unable to use readahead(2) facility - too many files to cache, too small files and the gain of readahead in this case is close to zero. Having it all in one file might speed-up the syncdaemon startup, since ureadahead profiling might find out that we are loading such file on startup and cache it e.g. during/before gdm login.

Discussed it, and this is what we will do:

- create benchmarks for this
- design a new structure that...
    - be really faster to build the index from it (that is what actually takes too long at the start)
    - don't be seriously slower than it is now when writing or reading a separate node

This structure will be a big file in the fileshelf path that will replace the actual dir with lot of small files.

please could some more attention be given to this issue, it is are making this commercial product completely unusable in real world situations. I know as I have been trying to use it for 3 months now and it just doesn't work as expected. Considering canceling my account :(

Some info from my current system in my laptop:

nessita@miro:~$ u1sdtool --list-folders | grep subscribed=True
4: id=2db262f5-a151-4c19-969c-bb5ced753c61 subscribed=True path=/home/nessita/Documents/tesis
5: id=0e0a3c0d-ddb8-4926-ad71-c33fd6079e6a subscribed=True path=/home/nessita/.purple/logs
8: id=9ea892f8-15fa-4201-bdbf-8de99fa5f588 subscribed=True path=/home/nessita/Public

nessita@miro:~$ find Ubuntu\ One/ Documents/tesis/ Public/ .purple/logs | wc -l
27074

* Every first time I start syncdaemon (in each boot), the metadata load doesn't finish and SD apparently crashes without leaving any trace. This means that the log file has nothing but:

2010-11-11 08:54:50,330 - ubuntuone.SyncDaemon.VM.MD - DEBUG - metadata version: 6
2010-11-11 08:54:50,385 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata

and syncdaemon is not working. So I run u1sdtool -s again, and the log file is rotates and the load metadata process restart, and I get something like this:

2010-11-11 09:04:12,049 - ubuntuone.SyncDaemon.VM.MD - DEBUG - metadata version: 6
2010-11-11 09:04:12,050 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2010-11-11 09:06:05,100 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 19704, idx_node_id: 15127, shares: 12

So the second metadata load process finish because the first attempt cached most of the files in the disk cache. So the second attempt takes 2 minutes when most of the files are already in the disk cache! So this amount of time is extremely large.

Starting syncdaemon with:

/usr/lib/ubuntuone-client/ubuntuone-syncdaemon --logging-level=DEBUG

will complete the metadata load in the first attempt. In this case, it took:

2010-11-11 13:07:56,933 - ubuntuone.SyncDaemon.VM.MD - DEBUG - metadata version: 6
2010-11-11 13:07:57,021 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2010-11-11 13:12:45,864 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 19704, idx_node_id: 16948, shares: 12

Almost 5 minutes of intensive disk usage (which makes the rest of the desktop pretty unusable due to IO starvation).

I separated from this bug the problem of sycdaemon silently crashing on bug #683116

This is now fixed in trunk,

according to Martin logs:

2011-01-10 12:17:48,642 - ubuntuone.SyncDaemon.tritcask - INFO - Initializing Tritcask on: /home/beuno/.local/share/ubuntuone/syncdaemon/tritcask
2011-01-10 12:17:48,644 - ubuntuone.SyncDaemon.tritcask - DEBUG - lookingup data files
2011-01-10 12:17:48,645 - ubuntuone.SyncDaemon.tritcask - INFO - found 1 data files and 0 dead files
2011-01-10 12:17:48,645 - ubuntuone.SyncDaemon.tritcask - DEBUG - building the keydir, using: ['129450510717705']
2011-01-10 12:17:48,646 - ubuntuone.SyncDaemon.tritcask - DEBUG - loading entries from (build_hint=False): /home/beuno/.local/share/ubuntuone/syncdaemon/tritcask/129450510717705.live.tritcask-v1.data
2011-01-10 12:17:48,720 - ubuntuone.SyncDaemon.tritcask - INFO - keydir ready! (keys: 2264)
2011-01-10 12:17:48,721 - ubuntuone.SyncDaemon.VM.MD - DEBUG - metadata version: 7
2011-01-10 12:17:48,725 - ubuntuone.SyncDaemon.fsm - INFO - loading updated metadata
2011-01-10 12:17:48,854 - ubuntuone.SyncDaemon.fsm - INFO - initialized: idx_path: 2247, idx_node_id: 2247, shares: 15

I takes less than a second to load the metadata and build the indexes.

This bug was fixed in the package ubuntuone-client - 1.5.3-0ubuntu1

---------------
ubuntuone-client (1.5.3-0ubuntu1) natty; urgency=low

  * New upstream release.
    - Metadata load is too slow (LP: #436612)
    - Out of space dialog is broken (LP: #650671)
    - Should not autoconnect when there are no credentials (LP: #701588)
    - gsd extension should not ask for sso credentials (LP: #702171)
 -- Rodney Dawes <email address hidden> Tue, 25 Jan 2011 16:42:52 -0500