locked
major difference in time running consecutive synchronizations RRS feed

  • General discussion

  • i've been trying out the sync framework in detail in order to use it in a production environment. Globally, it seems to be working fine. However, there seems to be a major difference in time when running sync for the first time and rerunning the sync a second time. The problem seems to be related to setting up connections to the database. It seems as if connection pooling is not working correctly. (i've tried both integrated security and non-integrated security which gives the same result)

    The difference in time running the sync (the environment is set up so that no data needs to be synced) for the first time and for the second time is about 1 second. The first sync is done in 1.0764069 seconds, the second sync is done in 0.1560010. Digging deeper into the cause of the difference learned me that the time needed to connect to the databases is the big 'spender'.

    The first time, the connection part (see below) takes 780 ms; the second time, it takes only 62 ms.

    Setting the sync tracer level to 4 (= verbose) gives me this output for the first sync :

    (partial) OUTPUT WHEN RUNNING SYNC FOR THE FIRST TIME :

    INFO   , SyncApplication, 1, 10/07/2011 06:43:05:274,    BeginSession() called on Provider SqlSyncProvider, Microsoft.Synchronization.Data.SqlServer, Version=3.1.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:306, Connecting using string: Data Source=(local)\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:430, Reading Schema Version Info
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:430,    Executing Command: SELECT [schema_major_version], [schema_minor_version], [schema_extended_info] FROM [schema_info]
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:430, Connecting using string: Data Source=(local)\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True
    INFO   , SyncApplication, 1, 10/07/2011 06:43:05:852,    BeginSession() called on Provider SqlSyncProvider, Microsoft.Synchronization.Data.SqlServer, Version=3.1.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:852, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Password=****;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:867, Reading Schema Version Info
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:867,    Executing Command: SELECT [schema_major_version], [schema_minor_version], [schema_extended_info] FROM [schema_info]
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:05:867, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:06:039, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:43:06:054, Reading Schema Version Info

    (partial) OUTPUT WHEN RUNNING SYNC FOR THE SECOND TIME :

    INFO   , SyncApplication, 1, 10/07/2011 06:44:30:446,    BeginSession() called on Provider SqlSyncProvider, Microsoft.Synchronization.Data.SqlServer, Version=3.1.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:446, Connecting using string: Data Source=(local)\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:446, Reading Schema Version Info
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:446,    Executing Command: SELECT [schema_major_version], [schema_minor_version], [schema_extended_info] FROM [schema_info]
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:461, Connecting using string: Data Source=(local)\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True
    INFO   , SyncApplication, 1, 10/07/2011 06:44:30:477,    BeginSession() called on Provider SqlSyncProvider, Microsoft.Synchronization.Data.SqlServer, Version=3.1.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:477, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Password=****;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:477, Reading Schema Version Info
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:477,    Executing Command: SELECT [schema_major_version], [schema_minor_version], [schema_extended_info] FROM [schema_info]
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:477, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:508, Connecting using string: Data Source=PCCEBIR126;Initial Catalog=SyncSource;User ID=sa;Min Pool Size=20
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:508, Reading Schema Version Info
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:508,    Executing Command: SELECT [schema_major_version], [schema_minor_version], [schema_extended_info] FROM [schema_info]
    VERBOSE, SyncApplication, 1, 10/07/2011 06:44:30:508,    Executing Command: SELECT [scope_id], [scope_local_id], [scope_sync_knowledge], [scope_tombstone_cleanup_knowledge], [scope_timestamp], [scope_config_id], [scope_restore_count] FROM [scope_info] WHERE

    THE CODE USED TO TEST THE PROBLEM

     

    private void btnSimpleStart_Click(object sender, EventArgs e)

     

    string.Empty;

     

    SqlSyncProvider destinationProvider = new SqlSyncProvider(SyncUtils.ScopeName + "_" + SyncUtils.CustomerID + "_" + "1", new SqlConnection("Data Source=(local)\\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True"

     

    SqlSyncProvider sourceProvider = new SqlSyncProvider(SyncUtils.ScopeName + "_" + SyncUtils.CustomerID + "_" + "1", new SqlConnection("Server=PCCEBIR126;initial catalog=SyncSource;User ID=sa;Password=C3bir@2007;Min Pool Size=20"

     

    SyncOrchestrator orchestrator = new SyncOrchestrator

     

    SyncDirectionOrder

     

    SyncOperationStatistics

     

    TimeSpan

     

    this.syncStats.Text = syncStats.Text + "-----Sync completed in " + diff.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Sync Start Time :" + stats.SyncStartTime.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Sync End Time :" + stats.SyncEndTime.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Upload Changes Applied :" + stats.UploadChangesApplied.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Upload Changes Failed :" + stats.UploadChangesFailed.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Upload Changes Total :" + stats.UploadChangesTotal.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Download Changes Applied :" + stats.DownloadChangesApplied.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Download Changes Failed :" + stats.DownloadChangesFailed.ToString() + "\r\n"

     

    this.syncStats.Text = this.syncStats.Text + "Download Changes Total :" + stats.DownloadChangesTotal.ToString() + "\r\n"

     

     

    Who has an idea about the cause of this and, even better, who has a solution to this problem?

     




    ; ;

     

    }

    ;

     

     

    ;

     

     

    ;

     

     

    ;

     

     

    ;

     

     

    ;

     

     

    ;

     

     

    ;

     

     

    diff = stats.SyncEndTime.Subtract(stats.SyncStartTime);

     

     

    stats = orchestrator.Synchronize();

     

     

    .UploadAndDownload;

     

     

    ();

     

    orchestrator.LocalProvider = destinationProvider;

    orchestrator.RemoteProvider = sourceProvider;

    orchestrator.Direction =

    ));

     

     

    ));

     

     

    InitializeBackgoundWorkers();

     

     

    {

    syncStats.Text =

     

    Friday, October 7, 2011 7:17 AM

All replies

  • can you repost your code, somehow some parts of it got mixed up.
    Monday, October 10, 2011 8:28 AM
  • Here is the non-mixed up code:

             private void btnSimpleStart_Click(object sender, EventArgs e)
            {
                syncStats.Text = string.Empty;
                InitializeBackgoundWorkers();
                SqlSyncProvider destinationProvider = new SqlSyncProvider(SyncUtils.ScopeName + "_" + SyncUtils.CustomerID + "_" + "1", new SqlConnection("Data Source=(local)\\sqlexpress;Initial Catalog=SyncDestination1;Integrated Security=True"));
                SqlSyncProvider sourceProvider = new SqlSyncProvider(SyncUtils.ScopeName + "_" + SyncUtils.CustomerID + "_" + "1", new SqlConnection("Server=PCCEBIR126;initial catalog=SyncSource;User ID=sa;Password=C3bir@2007;Min Pool Size=20"));

                SyncOrchestrator orchestrator = new SyncOrchestrator();
                orchestrator.LocalProvider = destinationProvider;
                orchestrator.RemoteProvider = sourceProvider;
                orchestrator.Direction = SyncDirectionOrder.UploadAndDownload;
                SyncOperationStatistics stats = orchestrator.Synchronize();
                TimeSpan diff = stats.SyncEndTime.Subtract(stats.SyncStartTime);
                this.syncStats.Text = syncStats.Text + "-----Sync completed in " + diff.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Sync Start Time :" + stats.SyncStartTime.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Sync End Time   :" + stats.SyncEndTime.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Upload Changes Applied :" + stats.UploadChangesApplied.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Upload Changes Failed  :" + stats.UploadChangesFailed.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Upload Changes Total   :" + stats.UploadChangesTotal.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Download Changes Applied :" + stats.DownloadChangesApplied.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Download Changes Failed  :" + stats.DownloadChangesFailed.ToString() + "\r\n";
                this.syncStats.Text = this.syncStats.Text + "Download Changes Total   :" + stats.DownloadChangesTotal.ToString() + "\r\n"; ;           
            }
        }

    Thx in advance
     

    Monday, October 10, 2011 9:36 AM