Consolidated: SQL Server 2008 R2
Moblink: Version 12.0.1.3873
Ultralite iOS: Version 12.0.1.4006

Initial sync's for my users are prohibitively long. Using -vm verbosity (see below) I've narrowed the issue down to the "fetch_download" phase (anywhere from 5 - 10 minutes). Subsequent sync's work fine (typically within seconds), this only happens on initial sync's.

Initial sync sends down about 3500 rows. With a total size when sent of around 300KB.

I suspect there is some issue or conflict happening in the "fetch_download" phase. I've tried verbosity level v+ and couldn't find any obvious issues.

What other additional steps could I take to track down the issue? Any ideas on what could be causing the issue? The status quo isn't working as you can imagine clients are abandoning with such a long initial sync.

Thanks in advance!

Jason

I. 2014-06-13 15:23:02. <3> PHASE: start_time: 2014-06-13 15:12:40.949
I. 2014-06-13 15:23:02. <3> PHASE: duration: 621278
I. 2014-06-13 15:23:02. <3> PHASE: sync_request: 0
I. 2014-06-13 15:23:02. <3> PHASE: receive_upload: 0
I. 2014-06-13 15:23:02. <3> PHASE: get_db_worker: 0
I. 2014-06-13 15:23:02. <3> PHASE: connect: 63
I. 2014-06-13 15:23:02. <3> PHASE: authenticate_user: 3463
I. 2014-06-13 15:23:02. <3> PHASE: begin_sync: 639
I. 2014-06-13 15:23:02. <3> PHASE: apply_upload: 1155
I. 2014-06-13 15:23:02. <3> PHASE: prepare_for_download: 1154
I. 2014-06-13 15:23:02. <3> PHASE: fetch_download: 611076
I. 2014-06-13 15:23:02. <3> PHASE: end_sync: 31
I. 2014-06-13 15:23:02. <3> PHASE: send_download: 3697
I. 2014-06-13 15:23:02. <3> PHASE: wait_for_download_ack: 0
I. 2014-06-13 15:23:02. <3> PHASE: get_db_worker_for_download_ack: 0
I. 2014-06-13 15:23:02. <3> PHASE: connect_for_download_ack: 0
I. 2014-06-13 15:23:02. <3> PHASE: nonblocking_download_ack: 0

asked 13 Jun '14, 11:52

Jason's gravatar image

Jason
121459
accept rate: 0%

2

Hi Jason,

So to recap, the 'fetch_download' is essentially the time to run all of your download and download delete cursors.

Consolidated: SQL Server 2008 R2 I've tried verbosity level v+ and couldn't find any obvious issues.

I'd start investigating breaking out each table and deciding how much time each download cursor takes to run against SQL Server. In the log above for <3>, have you taken a look for any long-running events and if they can be optimized inside SQL Server?

The status quo isn't working as you can imagine clients are abandoning with such a long initial sync.

Is there any way you can perhaps lessen the data load for the initial sync by pre-populating the remote database or removing data from the initial sync that isn't required immediately?

Or perhaps you can run the synchronization in a background thread so that users don't feel they have to wait for the initial synchronization to finish before they can use the application?

(13 Jun '14, 12:46) Jeff Albion

The fetch_download phase time is the time taken to fetch the rows to be downloaded from the consolidated database. Bascially that's time taken to run your download_delete_cursor and download_cursor SQL statements in your SQL Server database. For initial syncs, it's likely the time taken to run your download_cursor SQL statements that is longest. You'll probably have to tune your SQL Server database once you identify what is taking so long.

BTW, the MobiLink Profiler in version 16 records the times for each MobiLink event and table, to more easily narrow down performance bottlenecks. (In earlier versions you can use the MobiLink Monitor to see timings at the phase level, but you have to use a verbose log file for more detailed timings.)

The verbose MobiLink log that you already have should have the information you need, though the timing is indirect: you have to look at the differences between the timestamps of log entries.

FYI the MobiLink plug-in of Sybase Central includes a MobiLink Server Log File Viewer. You might find that helpful, for example to see the log messages of only one synchronization.

In case you aren't already aware, the documentation has a MobiLink Performance section, and there are MobiLink Performance whitepapers.

permanent link

answered 13 Jun '14, 12:53

Graham%20Hurst's gravatar image

Graham Hurst
2.7k11843
accept rate: 29%

I wanted to comment on the correct answer. I was able to track down an offending download query using the -v+ option with -pass option. Thanks!

(13 Jun '14, 16:07) Jason

Thanks for the quick response. The Mobilink Server Log File Viewer was very helpful. I've narrowed down the performance issues to this <Main> section. This happens about halfway through my sync, holds everything up for 5 minutes, then continues on through. Notice the start time of this section is 16:34 and the end time is 16:39 (5 minutes later!). I've run these scripts manually on my consolidated and they come right back with no delay, except for the one with the ? parameter which just errors out for obvious reasons... I assume that "?" gets set and this isn't exactly what it's executing? Any advice on what exactly is going on here and why it's holding up the sync for such a large amount of time? Thanks! (apologies for replying in "Answer" but comment section limits reply)

See log below:

I. 2014-06-13 16:34:36. <Main> System event on shared administrative connection:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:34:36. <Main> Translated SQL:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:35:01. <Main> System event on shared administrative connection:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:35:01. <Main> Translated SQL:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:35:37. <Main> System event on shared administrative connection:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:35:37. <Main> Translated SQL:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:36:02. <Main> System event on shared administrative connection:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:36:02. <Main> Translated SQL:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:36:39. <Main> System event on shared administrative connection:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:36:39. <Main> Translated SQL:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:37:03. <Main> System event on shared administrative connection:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:37:03. <Main> Translated SQL:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:37:41. <Main> System event on shared administrative connection:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:37:41. <Main> Translated SQL:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:38:03. <Main> System event on shared administrative connection:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:38:03. <Main> Translated SQL:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:38:38. <Main> System event on shared administrative connection:
                        select 1, property_name, cast(property_value as char(254)) from ml_property where component_name = 'MLS' AND property_set_name = 'ml_user_log_verbosity' union select 2, property_name, cast(property_value as char(254)) from ml_property where component_name = 'MLS' AND property_set_name = 'ml_remote_id_log_verbosity'
I. 2014-06-13 16:38:38. <Main> Translated SQL:
                        select 1, property_name, cast(property_value as char(254)) from ml_property where component_name = 'MLS' AND property_set_name = 'ml_user_log_verbosity' union select 2, property_name, cast(property_value as char(254)) from ml_property where component_name = 'MLS' AND property_set_name = 'ml_remote_id_log_verbosity'
I. 2014-06-13 16:38:43. <Main> System event on shared administrative connection:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:38:43. <Main> Translated SQL:
                        SELECT property_set_name, property_name, property_value FROM ml_property WHERE component_name = ? ORDER BY property_set_name 
I. 2014-06-13 16:39:04. <Main> System event on shared administrative connection:
                        SELECT count(*) FROM ml_passthrough_script
I. 2014-06-13 16:39:04. <Main> Translated SQL:
                        SELECT count(*) FROM ml_passthrough_script
permanent link

answered 13 Jun '14, 14:14

Jason's gravatar image

Jason
121459
accept rate: 0%

2

Even though there are long times between these log entries, these are not the time consuming SQL statements; those are MobiLink server system events that are invoked once per minute by default. You can use -pass to suppress that.

As Jeff suggested, look at the times for download_cursor events for a slow initial synchronization (such as <3>).

Since you have a significant prepare_for_download time too (when usually that is negligible), my guess is that you've got business logic in stored procedures (or maybe in triggers), instead of simple SQL statements, and something about those is taking a long time for initial syncs.

(13 Jun '14, 14:43) Graham Hurst

I see now. I added the -pass option and was clearly able to see the offending download script. I was able to modify the query and reduce the initial sync from 5 minutes down to 30 seconds. I'll add another question soon to ask why the offending query runs in milliseconds when direct queried but takes 5 minutes when part of fetch_download. Thank you so much!!!

(13 Jun '14, 16:05) Jason
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Question tags:

×371
×162

question asked: 13 Jun '14, 11:52

question was seen: 6,457 times

last updated: 13 Jun '14, 16:07