none
SyncOrchestrator.Synchronize Waits Indefinitely

    Question

  • I have a scenario that has stumped me concerning the Microsoft Sync Framework 2.1 SyncOrchestrator.Synchronize method.

    I have three different sets of databases (Sql CE for the local and Sql Server for the remote) using this at once, each in a separate thread.  Each database has its own set of sync providers.  I provision each database the exact same way (no filtering).  Two out of the three databases synchronize flawlessly.

    The third database gets through the initial synchronization fine (before I insert any data or if there are no new rows that need to be synchronized).  As soon as I start to add or change data (around 60 inserts per second and about as many deletes, although on different rows), any call to SyncOrchestrator.Synchronize waits until I no longer make changes to the database before the server actually gets these updates.  This is also a problem because my memory usage seems to continue to grow as long as the method waits.

    I have tried setting a timeout for the remote sync provider, and I have tried many different settings for MemoryDataCacheSize for the local and remote sync providers and ApplicationTransactionSize for the remote sync provider, none of which have made a difference.  Also, there are generally no conflicts or errors in these inserts and deletes.  When an error or conflict does occur I give it the action: ApplyAction.RetryWithForceWrite.

    Any ideas on what might be causing this?

    Thanks,

    Stuart


    Stuart Summers

    Monday, March 12, 2012 10:46 PM

All replies

  • are you using WCF?

    try enabling Sync Framework Tracing to see what its doing

    Tuesday, March 13, 2012 1:37 AM
    Moderator
  • After enabling the Sync Tracer and rerunning the application, I see maybe 30 lines of 

    CSN upper bound changed. New CSN: 319990

    followed by a transaction commit, followed by an infinite loop of 

    Applied 0 of 75 rows with bulk command BulkDeleteCommand
    Applied -75 of 75 rows with bulk command BulkDeleteCommand
    Applied -150 of 75 rows with bulk command BulkDeleteCommand
    Applied -224 of 75 rows with bulk command BulkDeleteCommand
    Applied -299 of 75 rows with bulk command BulkDeleteCommand
    ...

    This seems to be my problem.  I will look into why these applied rows are decrementing instead of incrementing.

    Thanks in advance for any help!

    Update:

    When doing a verbose trace level, inserting into and deleting from a table in this database seems to cause an infinite loop of either inserts or deletes as below:

    Insert for row with PK: Index = 58e598b2-aae3-4559-83fb-4a40a3a7d62c on c:\database.sdf
    UV: 0,4329 CV: 0,4329
    
    Insert for row with PK: Index = 8d41d142-573d-489a-b3d4-4a4b2b081259 on c:\database.sdf
    UV: 0,1366 CV: 0,1366
    
    Insert for row with PK: Index = 5c47215d-fc10-41e5-98cf-4ae04d227b93 on c:\database.sdf
    UV: 0,1065 CV: 0,1065
    
    ...

    Stuart Summers


    • Edited by J. Stuart Tuesday, March 13, 2012 8:51 PM
    Tuesday, March 13, 2012 4:57 PM
  • is the log big? can you post it with the corresponding events?
    Wednesday, March 14, 2012 12:08 PM
    Moderator
  • just had a quick peek at the sqlcesyncprovider and i noticed that the transaction isolation level is different from sqlsyncprovider.

    in sqlsyncprovider, its set to snapshot isolation, in sqlcesyncprovider, its set to read committed

    try doing the same thing you did here: http://social.msdn.microsoft.com/Forums/en/syncdevdiscussions/thread/d0ad8f07-5d65-4e14-8fca-3c1c1ce9890a on the sqlcesyncprovider and setting the transaciton isolation to serializable (SQL Ce dont have snapshot isolation)

    Wednesday, March 14, 2012 12:31 PM
    Moderator
  • I had run into an infinite loop when I used ApplyAction.RetryWithForceWrite in certain scenarios. ... it would just keep retrying over and over....
    Wednesday, March 14, 2012 2:54 PM
  • June,

    That's actually my post :).  And yes, that does fix the Sql Notification issue I was having, but might be part of the cause of this infinite loop issue.

    Let me run another test this morning and I'll post the trace file.

    and Racing_Prog,

    I actually do use ApplyAction.RetryWithForceWrite.  I'll see if that's the problem.  I want to say it isn't because I'm not seeing any errors, but I'll let you know.

    -Stuart

    Update:

    I re-read your post and realized that I had misread before.  I'll try setting the IsolationLevel to Serializable and see if that fixes the issue.


    Stuart Summers


    • Edited by J. Stuart Wednesday, March 14, 2012 7:21 PM Misread post.
    Wednesday, March 14, 2012 3:29 PM
  • Update:

    After running some tests this morning, the trace looks a bit different, although synchronization still does not complete.

    Racing_Prog,

    I verified that I am not hitting breakpoints set on ApplyChangeFailed for either the local or the remote providers (this is the only place where I am setting the Action = ApplyAction.RetryWithForce).

    June,

    Below is my current trace file (filtered to view just the actions on the table in question: there is one other table, which does not have any data) along with some of my sync provider settings:

    This is the first call to SyncOrchestrator.Synchronize (in the main thread).  It executes with no issues, although no data is being inserted or deleted at this point.  This call is made when the application starts.  When a trace output is repeated, I just put ... in the log to indicate a repeated trace output:

        BatchingDirectory has been set to: c:\directory		
        ApplicationTransactionSize has been set to: 10					
        BatchingDirectory has been set to: c:\directory		
        Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
     ----- Checking for Outdated Peer -----					
        Destination is not outdated					
     --- End Checking for Outdated Peer ---					
     					
     Memory DataCache Batching enabled. DataCache Size: 10 Kb					
           SyncBatchProducer: Starting Background enumeration thread.					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event			
        RelationalSyncProvider.BatchedEnum: --- End Table "MyTable" ---					
     					
           RelationalSyncProvider.BatchedEnum: Finished enumerating all adapters.					
           RelationalSyncProvider.BatchedEnum: Adding non batched rows as the last batch. Last batch data size 0 Bytes					
           SyncBatchProducer: Received 1st and last DataSet. Skip to Non batched mode.					
           RelationalSyncProvider.BatchedEnum: Setting BgdEnumInProcess to false	 BgdEnumCompleted to True and setting Cancellation event.				
           SyncBatchProducer: Queue availablility event fired					
     Committing transaction					
     ----- Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" -----					
             Source Scope Id: 6a5e20074f6a4b8383ad452d468b738f					
        Destination Scope Id: 0054b2dae13a4e69895da16447990f7c					
     					
        ----- Deletes for Table "MyTable" -----					
           0 Deletes Applied					
        --- End Deletes for Table "MyTable" ---									
     					
        ----- Inserts for Table "MyTable" -----					
           0 Inserts Applied					
        --- End Inserts for Table "MyTable" ---										
     					
        ----- Updates for Table "MyTable" -----					
           0 Updates Applied					
        --- End Updates for Table "MyTable" ---					
     					
     --- End Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" ---					
     					
     Committing transaction					
         SyncBatchProducer: Canceling Background enumeration thread. Waiting for cancellation event: False		
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
     ----- Checking for Outdated Peer -----					
        Destination is not outdated					
     --- End Checking for Outdated Peer ---					
     					
     Memory DataCache Batching enabled. DataCache Size: 10 Kb					
           SyncBatchProducer: Starting Background enumeration thread.					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
       					
        RelationalSyncProvider.BatchedEnum: --- End Table "MyTable" ---					
     					
           RelationalSyncProvider.BatchedEnum: Finished enumerating all adapters.					
           RelationalSyncProvider.BatchedEnum: Adding non batched rows as the last batch. Last batch data size 0 Bytes					
           SyncBatchProducer: Received 1st and last DataSet. Skip to Non batched mode.					
           RelationalSyncProvider.BatchedEnum: Setting BgdEnumInProcess to false	 BgdEnumCompleted to True and setting Cancellation event.				
           SyncBatchProducer: Queue availablility event fired					
     Committing transaction					
     ----- Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" -----					
             Source Scope Id: 6a5e20074f6a4b8383ad452d468b738f					
        Destination Scope Id: 0054b2dae13a4e69895da16447990f7c					
     					
        ----- Deletes for Table "MyTable" -----					
           0 Deletes Applied					
        --- End Deletes for Table "MyTable" ---					
     				
        ----- Inserts for Table "MyTable" -----					
           0 Inserts Applied					
        --- End Inserts for Table "MyTable" ---								
     					
        ----- Updates for Table "MyTable" -----					
           0 Updates Applied					
        --- End Updates for Table "MyTable" ---					
     					
     --- End Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" ---					
     					
     Committing transaction		
           SyncBatchProducer: Canceling Background enumeration thread. Waiting for cancellation event: False					
        
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
     ----- Checking for Outdated Peer -----					
        Destination is not outdated					
     --- End Checking for Outdated Peer ---					
     					
     Memory DataCache Batching enabled. DataCache Size: 10 Kb					
           SyncBatchProducer: Destination knowledge read from preexisting batch header file: ReplicaKeyMap: [(0:6a5e20074f6a4b8383ad452d468b738f) (1:0054b2dae13a4e69895da16447990f7c)] ScopeRangeSet: [00:[(0:9223372036854775807) (1:61142)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300032003800340065006100660066002d0062003400320036002d0034006100630035002d0039003500640030002d003600360036006600360039006300630031003600320065:[(0:9223372036854775807) (1:61229)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300032003800340065006100660066002d0062003400320036002d0034006100630035002d0039003500640030002d00360036003600660036003900630063003100360032006500:[(0:9223372036854775807) (1:61142)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300035003300390063006300380031002d0030003100650031002d0034006200380031002d0061003800330033002d006100390035006400300066003000630030003200350036:[(0:9223372036854775807) (1:61241)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300035003300390063006300380031002d0030003100650031002d0034006200380031002d0061003800330033002d00610039003500640030006600300063003000320035003600:[(0:9223372036854775807) (1:61142)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300036006500620066003200350038002d0033003400300036002d0034006500640033002d0038003600380039002d003200660064003400630039003300650039003000300039:[(0:9223372036854775807) (1:61271)]
           SyncBatchProducer: Current Destination knowledge: ReplicaKeyMap: [(0:6a5e20074f6a4b8383ad452d468b738f) (1:0054b2dae13a4e69895da16447990f7c)] ScopeRangeSet: [00:[(0:9223372036854775807) (1:74357)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300033003400650065003700340062002d0064006200650032002d0034003100650063002d0038006200320030002d00300030003100620030006500620030006400370037003200:[(0:9223372036854775807) (1:61142)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300035003300390063006300380031002d0030003100650031002d0034006200380031002d0061003800330033002d006100390035006400300066003000630030003200350036:[(0:9223372036854775807) (1:61241)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300035003300390063006300380031002d0030003100650031002d0034006200380031002d0061003800330033002d00610039003500640030006600300063003000320035003600:[(0:9223372036854775807) (1:61142)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300036006500620066003200350038002d0033003400300036002d0034006500640033002d0038003600380039002d003200660064003400630039003300650039003000300039:[(0:9223372036854775807) (1:61271)]	 007400610062006c0065006d007500640066006c006f007700700075006c007300650073002d00300036006500620066003200350038002d0033003400300036002d0034006500640033002d0038003600380039002d00320066006400340063003900330065003900300030003900:[(0:9223372036854775807) (1:61142)]
           SyncBatchProducer: Knowledge in batch does not contain current destination knowledge.  Batch cannot be reused.					
           SyncBatchProducer: Starting Background enumeration thread.					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
     					
           RelationalSyncProvider.BatchedEnum: Memory data cache size 10313 Bytes greater than specified cache limit of 10240 Bytes					
           RelationalSyncProvider.BatchedEnum: Spooling new batch.					
           SyncBatchProducer: Enqueuing Batch. Total Batches Enqueued: 1. Details: 					
    		
    					
           SyncBatchProducer: Queue availablility event fired					
     RelationalSyncProvider.BatchedReception: Receiving Batched changes. Starting SyncBatchConsumer					
        RelationalSyncProvider.BatchedReception: Enqueueing batch c:\directory\sync_0054b2dae13a4e69895da16447990f7c6a5e20074f6a4b8383ad452d468b738f\75a25a2f-08f9-4220-bf81-00637199e42f.batch to consumer.					
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
           RelationalSyncProvider.BatchedEnum: Memory data cache size 10285 Bytes greater than specified cache limit of 10240 Bytes					
           RelationalSyncProvider.BatchedEnum: Spooling new batch.					
           SyncBatchProducer: Enqueuing Batch. Total Batches Enqueued: 2. Details: 					
    								
    					
           SyncBatchProducer: Queue availablility event fired					
        RelationalSyncProvider.BatchedReception: Enqueueing batch c:\directory\sync_0054b2dae13a4e69895da16447990f7c6a5e20074f6a4b8383ad452d468b738f\c610a15e-073f-47fe-becf-28b67e8cf17f.batch to consumer.					
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
           RelationalSyncProvider.BatchedEnum: Memory data cache size 10323 Bytes greater than specified cache limit of 10240 Bytes					
           RelationalSyncProvider.BatchedEnum: Spooling new batch.					
           SyncBatchProducer: Enqueuing Batch. Total Batches Enqueued: 3. Details: 					
    					
    					
    ...
    ...
    ...					
    									
    					
           SyncBatchProducer: Queue availablility event fired					
        RelationalSyncProvider.BatchedReception: Enqueueing batch c:\directory\sync_0054b2dae13a4e69895da16447990f7c6a5e20074f6a4b8383ad452d468b738f\ec5284de-171e-473d-827a-0e0b74540490.batch to consumer.					
           RelationalSyncProvider.BatchedEnum: Memory data cache size 10305 Bytes greater than specified cache limit of 10240 Bytes					
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
           RelationalSyncProvider.BatchedEnum: Spooling new batch.					
           SyncBatchProducer: Enqueuing Batch. Total Batches Enqueued: 119. Details: 					
    					
    			
           SyncBatchProducer: Queue availablility event fired					
        RelationalSyncProvider.BatchedReception: Enqueueing batch c:\directory\sync_0054b2dae13a4e69895da16447990f7c6a5e20074f6a4b8383ad452d468b738f\9bd6bf10-5a08-4890-849d-a24ef28f0f20.batch to consumer.					
     Remote data cache size requested: 10 Kb	 Local data cache size: 10 Kb				
     Enumeration data cache size selected: 10 Kb					
           SyncBatchProducer: Producer queue empty.  Waiting for queue availablility event					
        RelationalSyncProvider.BatchedEnum: --- End Table "MyTable" ---					
     					
           RelationalSyncProvider.BatchedEnum: Finished enumerating all adapters.					
           RelationalSyncProvider.BatchedEnum: Adding non batched rows as the last batch. Last batch data size 9976 Bytes					
           SyncBatchProducer: Enqueuing Batch. Total Batches Enqueued: 120. Details: 					
    					
    					
           RelationalSyncProvider.BatchedEnum: Setting BgdEnumInProcess to false	 BgdEnumCompleted to True and setting Cancellation event.				
           SyncBatchProducer: Queue availablility event fired					
     Committing transaction					
        RelationalSyncProvider.BatchedReception: Enqueueing batch c:\directory\sync_0054b2dae13a4e69895da16447990f7c6a5e20074f6a4b8383ad452d468b738f\8e9b087a-5cfa-4444-9668-783f19db5e63.batch to consumer.					
        RelationalSyncProvider.BatchedReception: Received Last batch. Applying batched.					
           SyncBatchConsumer: Applying 1 of 120 batches.					
           SyncBatchConsumer: Batch 1 application result - Continue					
           SyncBatchConsumer: Applying 2 of 120 batches.					
           SyncBatchConsumer: Batch 2 application result - Continue					
           SyncBatchConsumer: Applying 3 of 120 batches.					
           SyncBatchConsumer: Batch 3 application result - Continue	
    
    ...
    ...
    ...				
           				
           SyncBatchConsumer: Applying 119 of 120 batches.					
           SyncBatchConsumer: Batch 119 application result - Continue					
           SyncBatchConsumer: Applying 120 of 120 batches.					
           SyncBatchConsumer: Batch 120 application result - Continue					
           SyncBatchConsumer: All batches successfully applied. Deletes retry count: 0					
    Here is the second call to SyncOrchestrator.Synchronize (in a background thread and not accessed outside of that thread).  This is where the loop seems to begin.  I am no longer seeing the repeated negative adds as in the first post, but it still seems to go through these actions indefinitely:
     ----- Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" -----					
             Source Scope Id: 0054b2dae13a4e69895da16447990f7c					
        Destination Scope Id: 6a5e20074f6a4b8383ad452d468b738f					
     					
        ----- Deletes for Table "MyTable" -----					
     Applied 19 of 75 rows with bulk command BulkDeleteCommand					
     Applied -52 of 18 rows with bulk command BulkDeleteCommand					
           93 Deletes Applied					
        --- End Deletes for Table "MyTable" ---					
     					
     					
        ----- Inserts for Table "MyTable" -----					
     Applied 75 of 75 rows with bulk command BulkInsertCommand					
     Applied 29 of 29 rows with bulk command BulkInsertCommand					
           104 Inserts Applied					
        --- End Inserts for Table "MyTable" ---					
     					
       				
        ----- Updates for Table "MyTable" -----					
           0 Updates Applied					
        --- End Updates for Table "MyTable" ---					
     					
     --- End Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" ---					
     					
     Committing transaction					
     ----- Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" -----					
             Source Scope Id: 0054b2dae13a4e69895da16447990f7c					
        Destination Scope Id: 6a5e20074f6a4b8383ad452d468b738f					
     					
        ----- Deletes for Table "MyTable" -----					
     Applied 19 of 75 rows with bulk command BulkDeleteCommand					
     Applied -52 of 11 rows with bulk command BulkDeleteCommand					
           86 Deletes Applied					
        --- End Deletes for Table "MyTable" ---					
     								
     					
        ----- Inserts for Table "MyTable" -----					
     Applied 75 of 75 rows with bulk command BulkInsertCommand					
     Applied 34 of 34 rows with bulk command BulkInsertCommand					
           109 Inserts Applied					
        --- End Inserts for Table "MyTable" ---					
     								
     					
        ----- Updates for Table "MyTable" -----					
           0 Updates Applied					
        --- End Updates for Table "MyTable" ---					
     					
     --- End Applying Changes for Scope "d898a8d9-f2ca-4efa-8f0f-73944a87ad69" ---					
     					
     Committing transaction		
    
    ...
    ...
    ...

    My configuration for the sync providers are setting each transaction type to ReadCommitted as in my previous post, and setting the MemoryDataCacheSize and ApplicationTransactionSize both to 10.


    Stuart Summers


    • Edited by J. Stuart Wednesday, March 14, 2012 4:38 PM
    Wednesday, March 14, 2012 4:36 PM
  • Changing my transaction isolation level to Serializable caused the number of concurrent locks to go way up, causing the application to process much slower.  The issue where values were not being synchronized is still not fixed.  I am able to see a few values on the server after a very long time waiting (maybe 30 minutes), but after those initial values, no more values are synchronized.

    -Stuart


    Stuart Summers

    Thursday, March 15, 2012 9:44 PM
  • did you set Serializable on both  sides of the provider? or just on the Sql Ce provider?

    just to reconfirm, you are doing the inserts/deletes on the SQL Ce side?

    would you mind sending me the full trace log at junetidlethoughts at hotmail dot com? better if this is just a sample app you have, if you can send me the sample app, saves me some time recreating it to reproduce the behaviour :)

    Friday, March 16, 2012 1:26 AM
    Moderator
  • Ok, another update:

    Originally, the table being synchronized had 4 columns: 2 integer type, 1 float type, and 1 datetime type.  The row inserts for this table, as stated above, were done with a frequency of about 1/60th of a second per insert.

    It seems that the problem might have involved the datetime column.  Since I only ever insert to this column with a time resolution of one second, I decided to try changing that column to a float type and insert a DateTime.Ticks value instead of a raw DateTime value.  This seems to have fixed the problem as now the rows are being synchronized to the server, although the application still runs somewhat sluggishly.

    So it seems like the problem was that inserting so many rows with a larger column type caused the synchronization transaction to add rows to the transaction continuously without a break to commit the transaction to the server.

    June: I also have both the sql and the sql ce providers using Serializable Isolation levels.

    Thanks for the help with this.


    Stuart Summers

    Friday, March 16, 2012 6:31 PM
  • i replied to your email.

    seems strange to me that a change in data type would fix the problem though.

    Monday, March 19, 2012 1:58 AM
    Moderator