LAST_DOWNLOAD_TIME is not changing after successful sync

[Former Member]

Hello, I am using SQLAnyWhere 12.0.1.3152 and am connecting an Oracle 10g database to an UltraLite db on a handscanner that runs Windows CE. I have had no issues with my synchronization until recently. I was setting up a new scanner, and after running my initial synchronization I noticed that the number of records being downloaded where not changing. I am using timestamp based downloads that is utilizing shadow tables. I noticed that in the ML_SUBSCRIPTION the LAST_DOWNLOAD_TIME is not being updated for the user. However the LAST_UPLOAD_TIME is being updated correctly. I have no custom coding that would keep setting the ml s.last_download_time to a fixed value.

I have tried looking through the forums but have not found anything that resembled my current issue. If anybody has any suggestions as to what I can try, I would appreciate it very much. Thank you in advance.

[Breck_Carter]

Is the download failing? It runs after the upload. Check the MobiLink server -o log file.

[Former Member]

We saw something very similar to this a few days ago (SA 10.0.1.x though), and still don't know exactly what happened. The consolidated db was also Oracle 10g. However, a restart of the MobiLink server corrected the problem.

Since it is an older version of the product, we are ok with that resolution, but of course we are curious why so we can prevent it in future. In case either of these resonate with your situation, here are a couple things we've considered.

• Coincidentally the customer had cancelled a synchronization in the middle of a long session, and then reset that database as if it had never synchronized. That has never been a problem before, but it's unusual.
  

• Also coincidentally, the server appears to have had a long uptime without restart (multiple months anyway). Again, we've never noticed a problem with that before.

[jeff_albion]

In addition to the MobiLink server log, do you have access to the synchronization return codes in the API from the UltraLite synchronization for this remote (from an application log)? Breck is likely correct in that the download was failing to apply for this particular remote.

Restarting the MobiLink server should not 'change' such an issue - the data selected to be exchanged with the remote should be the same in all instances.

[Former Member]

The download is not failing, at least from what I can see in the mlsrv.log file with verbose logging on. The download is applying changes to the UltraLite DB, because I am picking up new values in tables as they change on the consolidated DB.

I have restarted the MobiLink synch server, but not the server that I am running the process from.

Jeff, how would I go about trying to get that information from the UltraLite API?

Here are a few lines from the log file, about my last sync try. Again I searched for any errors and there were none reported by the process. Let me know if there is anything else I can get that could help in this situation.

  365                          UPDATE ml_database SET sync_key = :p1 WHERE rid = :p2
  366: I. 2013-01-28 14:37:25. <1> Publication #1: Warehouse Scan System, subscription id: 2, last download time: 2013-01-28 09:41:39.000000
  367  I. 2013-01-28 14:37:25. <1> System event on synchronization connection:
  368                          SELECT progress FROM ml_subscription WHERE rid = ? AND subscription_id = ?
1561: I. 2013-01-28 14:37:26. <1> modify_last_download_timestamp <connection> (no script)
 1562: I. 2013-01-28 14:37:26. <1> prepare_for_download <connection> (no script)
 1563: I. 2013-01-28 14:37:26. <1> COMMIT Transaction: prepare_for_download
 1564: I. 2013-01-28 14:37:26. <1> Next last download timestamp fetched from the consolidated database is "2013-01-28 09:41:39.000000"
1135778: I. 2013-01-28 14:37:39. <1> COMMIT Transaction: end_download
 1135779  I. 2013-01-28 14:37:39. <1> end_publication <connection> (no script)
 1135780  I. 2013-01-28 14:37:39. <1> end_synchronization BC_ERROR (no script)
 .....
 1135844  I. 2013-01-28 14:37:39. <1> Translated SQL:
 1135845                          UPDATE ml_database SET sync_key = :p1 WHERE rid = :p2
 1135846: I. 2013-01-28 14:37:39. <1> Sending the download to the remote database
 1135847  I. 2013-01-28 14:38:00. <main> System event on shared administrative connection:
 1135848                          SELECT count(*) FROM ml_passthrough_script
 .....
 1135871  I. 2013-01-28 14:39:41. <1> PHASE: begin_sync: 77
 1135872  I. 2013-01-28 14:39:41. <1> PHASE: apply_upload: 4
 1135873: I. 2013-01-28 14:39:41. <1> PHASE: prepare_for_download: 2
 1135874: I. 2013-01-28 14:39:41. <1> PHASE: fetch_download: 13642
 1135875  I. 2013-01-28 14:39:41. <1> PHASE: end_sync: 3
 1135876: I. 2013-01-28 14:39:41. <1> PHASE: send_download: 121987
 1135877: I. 2013-01-28 14:39:41. <1> PHASE: wait_for_download_ack: 0
 1135878: I. 2013-01-28 14:39:41. <1> PHASE: get_db_worker_for_download_ack: 0
 1135879: I. 2013-01-28 14:39:41. <1> PHASE: connect_for_download_ack: 0
 1135880: I. 2013-01-28 14:39:41. <1> PHASE: nonblocking_download_ack: 0 

[VolkerBarth]

Just a sidenote: 12.0.1.3152 is the GA version from summer 2011 and as that a rather old release. I'd generally try to use a current EBF to see if this issue might have been fixed (though Jeff, Russ and Graham will know that en detail...).

[Former Member]

All of what you are seeing is expected when the LDT doesn't advance. No errors are expected, but rows will get downloaded again and again until the LDT advances.

• Russ

[Former Member · Accepted solution]

The issue is a long-running transaction against the consolidated database. In order for sync to download the rows that have changed, it can only look at completed transactions. If there is a long-running transaction, the last-download time (LDT) cannot advance until it completes. Why? Because that transaction may have last_modified (or equivalent) logic that has dates set to the starting time of the transaction. To maintain robust sync, there is no choice but to defer the advancement of the LDT.

I suspect the reason why it worked when you shut down ML server is that a long-running sync was in progress, or hung. Or at the same time the long-running transaction finished.

When the LDT fails to advance, please use your Oracle (or RDBMS-specific) admin tools to look for long-running (eg. batch) transactions. Even if the transactions do not affect sync tables, by default they will defer the advancement of the LDT.

• Russ

[Former Member · Accepted solution]

Russ will you please look at my comment that I posted shortly after you put your answer up. Thank you

[Former Member · Accepted solution]

For more background on why long-running transactions in Oracle can cause the same rows to be downloaded again, see this old tech note. Note that since version 9.0.2.3021, MobiLink defaults to using the earliest start time of open Oracle transactions to set the LDT. So as long as an Oracle transaction is uncommitted, the LDT cannot advance.

You could check by running the following query against your Oracle consolidated to see if it matched the unchanging LDT value:

SELECT MIN( TO_DATE( START_TIME, 'mm/dd/rr hh24:mi:ss' ) ) FROM GV$TRANSACTION;

[Former Member · Accepted solution]

Graham, I ran that query and it returned a null result. I ran it as a SELECT * and I had a record come back, but it was for today at 8:31 AM, not the 1/28/13 9:41:39 AM that I consistently getting from sync process. Thank you for the suggestion

[Former Member · Accepted solution]

Did you connect as the same Oracle user as MobiLink server?

[Former Member · Accepted solution]

Initially I did not connect as the MobiLink Oracle user. I just did and re-ran the query. I did not get a null answer this time, but the time I did get is 1/29/13 8:46:43 AM which is still greater than the 1/28/13 9:41:39 AM I get when I sync.

I really do appreciate your help Russ. Is there anyway to force the LDT to a different value?

[Former Member · Accepted solution]

That query would return null if there were no transactions with uncommitted changes, so your long running transaction must have committed or rolled back.

FYI, this is the query that the MobiLink server runs (for Oracle 9 and above) to determine the next LDT:

SELECT TO_CHAR(NVL( MIN( TO_TIMESTAMP( START_TIME, 'mm/dd/rr hh24:mi:ss' ) ), SYSTIMESTAMP ),'YYYY-MM-DD HH24:MI:SS.FF' ) FROM GV$TRANSACTION"

The result of that query is given in this line of your log output, proving that at 2013-01-28 14:37:26 there was a still an open transaction started at 2013-01-28 09:41:39:

 1564: I. 2013-01-28 14:37:26. <1> Next last download timestamp fetched from the consolidated database is "2013-01-28 09:41:39.000000"

[Former Member · Accepted solution]

Just to update, my sync process is now working correctly. I believe everyone was right about there being an outstanding transaction. Thank you so much for your quick and helpful responses. You have helped me get past a sticking point in my project.

[Former Member · Accepted solution]

You should determine what is causing the long transactions, since apparently you've got another (that started at 08:46:43 today).

[Former Member]

i had exactly the same issue. Once the 'killed' Oracle session was gone, my 'last downloaded' was updating correctly again.

Thanx a lot only because of these posts i could figure out what was going on.

martin