sync speed improvements

[s0129]

Has improved the speed of syncing. Now the slowest part is transmission over the network. I am behind your master branch but can't work out how to update so this may conflict. - Sorry I have never used git before, and the eclipse integration is confusing!

[freezy]

Thanks a lot! I'm no git guru either, so I'm not sure if I can integrate your code with proper credits. If you can apply your changes on the current HEAD that would be no problem of course.

[s0129]

I will have a look. It might be easier that way!

[jstemmer]

Github has some excellent help pages that explain how to work with multiple repos.

http://help.github.com/fork-a-repo/

The easiest way to get your repo up to date is to add the original repo as a remote (upstream in the help examples) and merge the upstream master branch into your own branch. You will have to resolve some conflicts, commit them and push the merge commit to your repo. I'm not sure, but that will probably update this pull request automatically.

[s0129]

Thanks! Will have a go at following that guide.

[s0129]

I believe I have updated to the current HEAD. So hopefully this pull request should now apply without conflicts. Speed is defiantly improved when adding to database. May be possible to optimise it a bit further.

[freezy]

Hmm I've just tested this but it doesn't seem to be any faster:

01-08 21:41:43.070: D/MusicPagerActivity(22040): Starting triggerRefresh()...
01-08 21:41:43.110: D/MusicPagerActivity(22040): triggerRefresh() done in 32ms.
01-08 21:41:43.110: D/AudioSyncService(22040): Starting onCreate()...
01-08 21:41:43.120: D/AudioSyncService(22040): onCreate() done in 0ms.
01-08 21:41:43.120: D/AudioSyncService(22040): Starting onHandleIntent(intent=Intent { act=android.intent.action.SYNC cmp=org.xbmc.android.remotesandbox/org.xbmc.android.jsonrpc.service.AudioSyncService (has extras) })...
01-08 21:41:43.151: I/JsonApiRequest(22040): POST request: http://192.168.0.100:8080/jsonrpc
01-08 21:41:43.151: I/JsonApiRequest(22040): POST entity:{"id":1326055303128,"jsonrpc":"2.0","method":"AudioLibrary.GetArtists","params":{"albumartistsonly":false}}
01-08 21:41:43.151: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(22040): Starting onReceiveResult()...
01-08 21:41:43.151: D/MusicPagerActivity(22040): Starting updateRefreshStatus()...
01-08 21:41:43.180: D/MusicPagerActivity(22040): updateRefreshStatus() done in 27ms.
01-08 21:41:43.180: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(22040): onReceiveResult() done in 28ms.
01-08 21:41:44.140: D/dalvikvm(22040): GC_CONCURRENT freed 2356K, 25% free 9809K/12935K, paused 5ms+7ms
01-08 21:41:44.600: D/dalvikvm(22040): GC_CONCURRENT freed 412K, 24% free 9908K/12935K, paused 5ms+28ms
01-08 21:41:45.110: D/dalvikvm(22040): GC_CONCURRENT freed 366K, 23% free 9987K/12935K, paused 5ms+28ms
01-08 21:41:45.130: I/JsonApiRequest(22040): POST response: {   "id": 1326055303128,    "jsonrpc": "2.0",   "result": { ... }
01-08 21:41:45.360: D/dalvikvm(22040): GC_FOR_ALLOC freed <1K, 20% free 10426K/12935K, paused 66ms
01-08 21:41:46.050: D/dalvikvm(22040): GC_CONCURRENT freed 361K, 19% free 10577K/12935K, paused 5ms+32ms
01-08 21:41:46.930: D/dalvikvm(22040): GC_CONCURRENT freed 129K, 16% free 10966K/12935K, paused 5ms+34ms
01-08 21:41:47.140: D/ArtistHandler(22040): Building queries for artist's drop and create.
01-08 21:41:47.520: I/JsonHandler(22040): Starting to execute 1272 batches..
01-08 21:41:47.950: D/dalvikvm(22040): GC_CONCURRENT freed 514K, 15% free 11053K/12935K, paused 4ms+17ms
01-08 21:41:51.160: I/JsonHandler(22040): Execution done in 4017ms.
01-08 21:41:51.280: I/JsonApiRequest(22040): POST request: http://192.168.0.100:8080/jsonrpc
01-08 21:41:51.280: I/JsonApiRequest(22040): POST entity:{"id":1326055311161,"jsonrpc":"2.0","method":"AudioLibrary.GetAlbums","params":{"properties":["title","artistid","year"]}}
01-08 21:41:51.810: D/dalvikvm(22040): GC_CONCURRENT freed 1914K, 25% free 9780K/12935K, paused 5ms+28ms
01-08 21:41:52.190: D/dalvikvm(22040): GC_CONCURRENT freed 383K, 24% free 9844K/12935K, paused 6ms+6ms
01-08 21:41:52.200: I/JsonApiRequest(22040): POST response: {   "id": 1326055311161,    "jsonrpc": "2.0",   "result": { ... }
01-08 21:41:52.890: D/dalvikvm(22040): GC_CONCURRENT freed 191K, 22% free 10158K/12935K, paused 5ms+8ms
01-08 21:41:53.370: D/AlbumHandler(22040): Building queries for album's drop and create.
01-08 21:41:53.690: D/dalvikvm(22040): GC_CONCURRENT freed 337K, 21% free 10332K/12935K, paused 4ms+31ms
01-08 21:41:53.710: I/JsonHandler(22040): Starting to execute 426 batches..
01-08 21:41:55.010: I/JsonHandler(22040): Execution done in 1633ms.
01-08 21:41:55.010: I/AudioSyncService(22040): All done, remote sync took 11884ms.
01-08 21:41:55.010: D/AudioSyncService(22040): Sync finished!
01-08 21:41:55.010: D/AudioSyncService(22040): onHandleIntent() done in 11892ms.
01-08 21:41:55.049: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(22040): Starting onReceiveResult()...
01-08 21:41:55.060: D/AlbumsFragment(22040): Refreshing Albums from database.
01-08 21:41:55.060: D/ArtistsFragment(22040): Refreshing Artists from database.
01-08 21:41:55.080: D/MusicPagerActivity(22040): Starting updateRefreshStatus()...
01-08 21:41:55.100: D/MusicPagerActivity(22040): updateRefreshStatus() done in 23ms.
01-08 21:41:55.100: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(22040): onReceiveResult() done in 56ms.

Still takes 10+ seconds (network ~2 seconds). Can you confirm that this is log from your code?

[s0129]

Are you running it in debug in eclipse as I found this really slows it down?

This is my log when I run normally, not debug. 01-08 21:59:34.692: D/BaseFragmentTabsActivity(5760): Starting onCreate()... 01-08 21:59:34.702: D/BaseFragmentTabsActivity(5760): Starting addTab()... 01-08 21:59:34.702: D/BaseFragmentTabsActivity(5760): addTab() done in 4ms. 01-08 21:59:34.712: D/BaseFragmentTabsActivity(5760): Starting addTab()... 01-08 21:59:34.712: D/BaseFragmentTabsActivity(5760): addTab() done in 4ms. 01-08 21:59:34.712: D/BaseFragmentTabsActivity(5760): Starting addTab()... 01-08 21:59:34.712: D/BaseFragmentTabsActivity(5760): addTab() done in 2ms. 01-08 21:59:34.712: D/BaseFragmentTabsActivity(5760): onCreate() done in 22ms. 01-08 21:59:34.712: D/MusicPagerActivity(5760): Starting triggerRefresh()... 01-08 21:59:34.722: D/MusicPagerActivity(5760): triggerRefresh() done in 6ms. 01-08 21:59:34.722: D/MusicPagerActivity(5760): Starting updateRefreshStatus()... 01-08 21:59:34.722: D/MusicPagerActivity(5760): updateRefreshStatus() done in 0ms. 01-08 21:59:34.722: D/AudioSyncService(5760): Starting onCreate()... 01-08 21:59:34.722: D/AudioSyncService(5760): onCreate() done in 0ms. 01-08 21:59:34.732: D/AudioSyncService(5760): Starting onHandleIntent(intent=Intent { act=android.intent.action.SYNC cmp=org.xbmc.android.remotesandbox/org.xbmc.android.jsonrpc.service.AudioSyncService (has extras) })... 01-08 21:59:34.742: D/BaseFragmentTabsActivity(5760): Registered refresh observer. 01-08 21:59:34.752: I/JsonApiRequest(5760): POST request: http://192.168.1.6:8081/jsonrpc 01-08 21:59:34.752: I/JsonApiRequest(5760): POST entity:{"id":1326059974743,"jsonrpc":"2.0","method":"AudioLibrary.GetArtists","params":{"albumartistsonly":false}} 01-08 21:59:35.292: D/dalvikvm(5760): GC_FOR_MALLOC freed 472K, 54% free 3183K/6855K, external 2167K/2643K, paused 32ms 01-08 21:59:35.332: D/dalvikvm(5760): GC_FOR_MALLOC freed 208K, 55% free 3137K/6855K, external 969K/2141K, paused 26ms 01-08 21:59:35.332: I/dalvikvm-heap(5760): Grow heap (frag case) to 6.563MB for 148674-byte allocation 01-08 21:59:35.372: D/dalvikvm(5760): GC_FOR_MALLOC freed <1K, 54% free 3282K/7047K, external 969K/2141K, paused 31ms 01-08 21:59:35.422: D/dalvikvm(5760): GC_FOR_MALLOC freed 323K, 56% free 3104K/7047K, external 969K/2141K, paused 31ms 01-08 21:59:35.422: I/JsonApiRequest(5760): POST response: {"id":1326059974743,"jsonrpc":"2.0","result":{"artists" 01-08 21:59:35.512: D/dalvikvm(5760): GC_CONCURRENT freed 277K, 53% free 3339K/7047K, external 969K/2141K, paused 2ms+3ms 01-08 21:59:35.512: D/BaseFragmentTabsActivity(5760): Registered refresh observer. 01-08 21:59:35.662: D/dalvikvm(5760): GC_CONCURRENT freed 135K, 47% free 3754K/7047K, external 969K/1481K, paused 2ms+4ms 01-08 21:59:35.692: D/dalvikvm(5760): GC_EXTERNAL_ALLOC freed 6K, 47% free 3748K/7047K, external 969K/1481K, paused 36ms 01-08 21:59:35.702: D/ArtistHandler(5760): Building queries for artist's drop and create. 01-08 21:59:35.743: I/JsonHandler(5760): Starting to execute 1136 batches.. 01-08 21:59:36.283: I/JsonHandler(5760): Execution done in 579ms. 01-08 21:59:36.293: I/JsonApiRequest(5760): POST request: http://192.168.1.6:8081/jsonrpc 01-08 21:59:36.293: I/JsonApiRequest(5760): POST entity:{"id":1326059976290,"jsonrpc":"2.0","method":"AudioLibrary.GetAlbums","params":{"properties":["title","artistid","year"]}} 01-08 21:59:36.453: D/dalvikvm(5760): GC_CONCURRENT freed 1222K, 55% free 3180K/7047K, external 2092K/2610K, paused 2ms+3ms 01-08 21:59:36.483: D/dalvikvm(5760): GC_FOR_MALLOC freed 264K, 55% free 3186K/7047K, external 2092K/2610K, paused 20ms 01-08 21:59:36.503: D/dalvikvm(5760): GC_FOR_MALLOC freed 162K, 54% free 3268K/7047K, external 2092K/2610K, paused 21ms 01-08 21:59:36.533: D/dalvikvm(5760): GC_FOR_MALLOC freed 243K, 55% free 3193K/7047K, external 2092K/2610K, paused 23ms 01-08 21:59:36.553: D/dalvikvm(5760): GC_FOR_MALLOC freed 184K, 55% free 3177K/7047K, external 2092K/2610K, paused 22ms 01-08 21:59:36.553: I/JsonApiRequest(5760): POST response: {"id":1326059976290,"jsonrpc":"2.0","result":{"albums" 01-08 21:59:36.673: D/dalvikvm(5760): GC_CONCURRENT freed 386K, 49% free 3661K/7047K, external 2092K/2610K, paused 2ms+4ms 01-08 21:59:36.703: D/AlbumHandler(5760): Building queries for album's drop and create. 01-08 21:59:36.744: I/JsonHandler(5760): Starting to execute 735 batches.. 01-08 21:59:36.994: I/JsonHandler(5760): Execution done in 290ms. 01-08 21:59:36.994: I/AudioSyncService(5760): All done, remote sync took 2255ms. 01-08 21:59:36.994: D/AudioSyncService(5760): Sync finished! 01-08 21:59:36.994: D/AudioSyncService(5760): onHandleIntent() done in 2257ms.

[freezy]

I've run this on the emulator. Let me check on the device then.

[freezy]

Right, this looks different:

01-08 23:08:13.320: D/MusicPagerActivity(28015): Starting triggerRefresh()...
01-08 23:08:13.335: D/MusicPagerActivity(28015): triggerRefresh() done in 15ms.
01-08 23:08:13.339: D/AudioSyncService(28015): Starting onCreate()...
01-08 23:08:13.339: D/AudioSyncService(28015): onCreate() done in 0ms.
01-08 23:08:13.347: D/AudioSyncService(28015): Starting onHandleIntent(intent=Intent { act=android.intent.action.SYNC cmp=org.xbmc.android.remotesandbox/org.xbmc.android.jsonrpc.service.AudioSyncService (has extras) })...
01-08 23:08:13.351: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(28015): Starting onReceiveResult()...
01-08 23:08:13.351: D/MusicPagerActivity(28015): Starting updateRefreshStatus()...
01-08 23:08:13.359: D/MusicPagerActivity(28015): updateRefreshStatus() done in 9ms.
01-08 23:08:13.359: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(28015): onReceiveResult() done in 10ms.
01-08 23:08:13.363: I/JsonApiRequest(28015): POST request: http://192.168.0.100:8080/jsonrpc
01-08 23:08:13.363: I/JsonApiRequest(28015): POST entity:{"id":1326060493361,"jsonrpc":"2.0","method":"AudioLibrary.GetArtists","params":{"albumartistsonly":false}}
01-08 23:08:14.210: I/JsonApiRequest(28015): POST response: {   "id": 1326060493361,    "jsonrpc": "2.0",   "result": {...}
01-08 23:08:14.499: D/ArtistHandler(28015): Building queries for artist's drop and create.
01-08 23:08:14.589: I/JsonHandler(28015): Starting to execute 1272 batches..
01-08 23:08:15.148: I/JsonHandler(28015): Execution done in 650ms.
01-08 23:08:15.160: I/JsonApiRequest(28015): POST request: http://192.168.0.100:8080/jsonrpc
01-08 23:08:15.160: I/JsonApiRequest(28015): POST entity:{"id":1326060495151,"jsonrpc":"2.0","method":"AudioLibrary.GetAlbums","params":{"properties":["title","artistid","year"]}}
01-08 23:08:15.488: I/JsonApiRequest(28015): POST response: {   "id": 1326060495151,    "jsonrpc": "2.0",   "result": {...}
01-08 23:08:15.664: D/AlbumHandler(28015): Building queries for album's drop and create.
01-08 23:08:15.691: I/JsonHandler(28015): Starting to execute 426 batches..
01-08 23:08:16.078: I/JsonHandler(28015): Execution done in 414ms.
01-08 23:08:16.078: I/AudioSyncService(28015): All done, remote sync took 2721ms.
01-08 23:08:16.082: D/AudioSyncService(28015): Sync finished!
01-08 23:08:16.093: D/AudioSyncService(28015): onHandleIntent() done in 2747ms.
01-08 23:08:16.113: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(28015): Starting onReceiveResult()...
01-08 23:08:16.128: D/AlbumsFragment(28015): Refreshing Albums from database.
01-08 23:08:16.128: D/ArtistsFragment(28015): Refreshing Artists from database.
01-08 23:08:16.128: D/MusicPagerActivity(28015): Starting updateRefreshStatus()...
01-08 23:08:16.140: D/MusicPagerActivity(28015): updateRefreshStatus() done in 9ms.
01-08 23:08:16.140: D/org.xbmc.android.remotesandbox.ui.MusicPagerActivity$SyncStatusUpdaterFragment(28015): onReceiveResult() done in 28ms.

Great work! Will push it upstream now.

[s0129]

Thats more like it! Hopefully I can optimise it a bit more. We will see...

[freezy]

Yes, great stuff. Keep rebasing while you're working so the next pull request will be less painful :)