Analyzing the update_net.log Log File

Learn how to analyze the log file.

The below sections describe how to analyze the log file:

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 [...]

"Z Fields" in Linked Info Areas

This problem can be identified by a quite high number of follow-up requests applied to other info areas (with conditions applied to ID) following the initial SQL statement in the synchronization request:

2012.10.30 ;13:50:36 ; 16;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];<RPACK=MA; Cur=1; SID=07AF61D0;

2012.10.30 ;13:50:36 ; 15;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; SELECT [...]

2012.10.30 ;13:50:37 ; 765;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=765; Conn=2; Cur=1; Rec=1024; Ret=0; Res=1024;

2012.10.30;13:50:37; 15;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];<READ=FI; Cur=0; SID=07AF61D0; ' ,0,0';

2012.10.30;13:50:37; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; SELECT [...] WHERE ID=?

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; V1='429496729665';

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=0; Conn=2; Cur=0; Rec=1; Ret=0; Res=1;

;SID [nqgpay55rl3iil45lagq1l45];<READ=KP; Cur=0; SID=07AF61D0; ' ,0,0';

2012.10.30;13:50:37; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; SELECT […] WHERE ID=?

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; V1='429496730029';

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=0; Conn=2; Cur=0; Rec=1; Ret=0; Res=1;

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Notice ;SID[nqgpay55rl3iil45lagq1l45];timer=0; Ok; 0ms; SID=07AF61D0;>

2012.10.30;13:50:37; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];<READ=FI; Cur=0; SID=07AF61D0; ' ,0,0';

2012.10.30;13:50:37; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; SELECT […] WHERE ID=?

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; V1='4294967308';

2012.10.30 ;13:50:37 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=0; Conn=2; Cur=0; Rec=1; Ret=0; Res=1;

You can avoid this problem by using the corresponding link fields in the configuration instead of the Z fields, i.e. the fields for the first name and last name from the KP info area instead of the "Person" Z field. These fields must subsequently be synchronized with the KP dataset.

This issue depends on the number of synchronized records. Reduce the offline dataset in order to execute a smaller number of additional statements.

The Runtime of the Initial Statement is too Long

The problem can be identified by the first statement taking a long time (or because it is the last entry for this session in the log file).

Processing the request on the database server takes a long time. The runtime is determined by the dataset and access rights definition. The runtime depends on the size of the involved tables and how easy it is to depict the conditions applied to these tables. Therefore, this problem can also occur if the synchronized data volume is quite small.

The Statement Returns too Much Data

The problem can be identified by the statement executing successfully but returning a very large amount of data - this is the case if the statement completes executing (i.e. a runtime and results set are specified) and is followed by several RPACK lines for the info area being synchronized.

2012.10.30 ;13:50:36 ; 16;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];< RPACK =MA; Cur=1; SID=07AF61D0;

2012.10.30;13:50:36; 15;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; SELECT [...] FROM BTB70_MA […]

2012.10.30 ;13:50:37 ; 765;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=765; Conn=2; Cur=1; Rec=1024; Ret=0; Res=1024;

2012.10.30 ;13:50:40 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];< RPACK =MA; Cur=1; SID=07AF61D0;

2012.10.30 ;13:50:40 ; 16;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=16; Conn=2; Cmd=FNEXT; Cur=1; Rec=1024; Ret=0; Res=1024;

2012.10.30 ;13:50:40 ; 0;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45];< RPACK =MA; Cur=1; SID=07AF61D0;

2012.10.30 ;13:50:40 ; 16;update.net.core.Sql ;Info ;SID[nqgpay55rl3iil45lagq1l45]; EXEC=16; Conn=2; Cmd=FNEXT; Cur=1; Rec=1024; Ret=0; Res=1024;

[...]

This problem can also cause CRM.pad to "crash" (it is terminated by the iOS operating system because the response cannot be processed due to a lack of memory resources). This occurrence depends on a record's width (the number of fields and their length) and on the number of records (usually more than 50,000 records) in one info area synchronized on the device. Try to reduce the data volume that is synchronized to improve the performance of the client.