Finding the Cause

The update_net.log log file contains one line for each CRM.pad request, including the service name (in the following example "mobileService"):

2012.10.29 ;10:32:58 ; 0;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Authenticate,user=USER, configid=1015

[…]

2012.10.29 ;10:32:59 ; 938;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

If multiple session IDs exist in the log file, Aurea recommends extracting the lines belonging to the same session. The timestamps on the left give information on how long each synchronization step took:

2012.10.29 ;10:33:39 ; 172;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

2012.10.29 ;10:33:48 ; 500;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

2012.10.29 ;10:33:54 ; 156;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

2012.10.29 ;10:34:04 ; 172;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

The time between two requests is measured, i.e. the time span to execute the request on the server, to transfer the data and to process the data on the client. As client-side processing is quite quick, the difference gives a good estimation on how long processing the request takes in the network environment.

If synchronization problems occur, it is important to identify the request that causes the problem. In most cases this is the last request for the session in the log file. (Sometimes, additional requests from the same session are submitted afterwards, the runtime of the request can then be identified using the time stamps.)

You can find a semantic description of the submitted request (corresponding to the definition of the dataset and starting with ReadByFilterMD) under the line that corresponds to the request's start.

2012.10.29 ;10:34:05 ; 140;mobileService ;Debug ;SID[41jep21jekzingzdalwtmlxi];Service-Name: Synchronization,user=USER, configid=10000004

2012.10.29;10:34:05; 63;mmObjects.Database ;Info ;SID[41jep21jekzingzdalwtmlxi]; ReadByFilterMD (C011='', HavingOptional(C011C011)[C011='F7028 >= "20100101"', HavingOptional(C011C011FI)[FI='', HavingOptional(C011C011FIFI)[FI='', Having:0(C011C011FIFIFI)[FI='', Having:0(C011C011FIFIFIMA)[MA='(F0 >= "20121028" AND F0 <= "20121105")']]], HavingOptional(C011C011FIFI1)[FI='', Having:0(C011C011FIFI1FI)[FI='', With:0(C011C011FIFI1FIFV)[FV='F0 = "$curRep"']]]]])

Reformat this entry to identify what occurred:

ReadByFilterMD (C011='', HavingOptional(C011C011)[C011='F7028 >= "20100101"', HavingOptional(C011C011FI)[FI='', HavingOptional(C011C011FIFI)[FI='', Having:0(C011C011FIFIFI)[FI='', Having:0(C011C011FIFIFIMA)[MA='(F0 >= "20121028" AND F0 <= "20121105")']]], HavingOptional(C011C011FIFI1)[FI='', Having:0(C011C011FIFI1FI)[FI='', With:0(C011C011FIFI1FIFV)[FV='F0 = "$curRep"']]]]])

In this example, entries in the C011 info area that are linked to the FI info area are synchronized using a filter (defined in the C011 dataset). The FI records are determined according to the FI dataset definition based on the existence of MA records or Favorites.

However, the request's complexity and runtime are not immediately apparent from this information as it depends on the number of records in the corresponding tables, the defined access rights, and the size of any additional tables the access rights are applied to.

This is then followed by the SQL statement, which can be even more complicated because this statement needs to depict the access rights applied to the affected info areas (C011, FI, MA, FV) which are defined in the Rights module (mmri.exe).

2012.10.29 ;10:34:05 ; 0;update.net.core.Sql ;Info ;SID[41jep21jekzingzdalwtmlxi];<RPACK=C011; Cur=1; SID=13A63FF0;

2012.10.29 ;10:34:05 ; 15;update.net.core.Sql ;Info ;SID[41jep21jekzingzdalwtmlxi]; SELECT [...]