Investigate Behavior of AIMMS PRO Job

An AIMMS PRO job may spend more time than the corresponding procedure on the client side. In this article we set out to answer the following questions:

  1. How to reduce the execution time of an AIMMS PRO job?
  2. How to find out what went wrong with an AIMMS PRO job?

Tip

A first check is to search for : duration and for transmitted in the session log files; this may provide a clue quickly of where a bottleneck might be.

To provide a structural answer for your application, we need to dive into the workings of the procedure PRO::DelegateToServer.

As the AIMMS PRO job realizing the delegated procedure runs in a different process, potentially on a different host, the necessary actions taken by PRO::DelegateToServer are illustrated in the picture below:

../../_images/actions-delegate.png

Actions taken by PRO::DelegateToServer:

  1. Client side: Create a case file to be used as input
  2. Copy the case file to the AIMMS PRO server
  3. On the AIMMS PRO server, wait for a server license
  4. On the AIMMS PRO server, compile and initialize the AIMMS Project
  5. On the AIMMS PRO server, read the input case file
  6. On the AIMMS PRO server, execute the procedure that is invoked by pro::DelegateToServer
  7. On the AIMMS PRO server, create a case file with the results
  8. Client side: read the case file with results

In this article, we will detail for each of the above actions, how to investigate behavior.

Client side: Create a case file to be used as input

The more information that is shared between the client session and the solver session, the longer it takes (creating, transmitting, reading). The information is shared in the form of a case file. The amount of information in this case file is determined by the set of identifiers and their cardinalities.

The identifiers of the input case created by pro::DelegateToServer is defined by pro::ManagedSessionInputCaseIdentifierSet, minus the identifiers in pro::ManagedSessionRemoveFromCaseIdentifierSet. However, the delegated job may only require the data of a subset of the identifiers in pro::ManagedSessionInputCaseIdentifierSet. To measure how long it takes to create an input case, please execute the procedure SaveInputCase, coded below, with the AIMMS profiler on:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
Procedure SaveInputCase {
    Body: {
        s_InputCaseIdentifierSet :=
            pro::ManagedSessionInputCaseIdentifierSet -
            pro::ManagedSessionRemoveFromCaseIdentifierSet ;
        CaseFileSave(
            url      :  "testcase.data",
            contents :  s_InputCaseIdentifierSet);
    }
    Set s_InputCaseIdentifierSet {
        SubsetOf: AllIdentifiers;
    }
}

Remarks about the above code:

  1. pro::ManagedSessionInputCaseIdentifierSet is initialized to AllIdentifiers

  2. pro::ManagedSessionRemoveFromCaseIdentifierSet is initialized to AllDefinedParameters

  3. Thus, by default defined parameters are not transferred, but defined sets are. Evaluating the definitions of these sets may still take significant time. If so, the AIMMS profiler will identify the sets that take significant time. Some of these sets can be safely added to pro::ManagedSessionRemoveFromCaseIdentifierSet. For instance, those with dimension 2 or higher, as illustrated by adding the following assignment to PostMainInitialization:

    1
    2
    3
    pro::ManagedSessionRemoveFromCaseIdentifierSet := AllDefinedParameters +
                { indexIdentifiers | indexIdentifiers in AllDefinedSets and
                    IdentifierDimension(indexIdentifiers) >= 2 };
    
  4. Please see reduce client server exchange on tips for assigning pro::ManagedSessionInputCaseIdentifierSet to just those that are relevant for the job at hand.

Note

Software evolution: pro::ManagedSessionRemoveFromCaseIdentifierSet is applied to reduce the set of identifiers transferred since AIMMS 4.59.2.

Copy the case file to the AIMMS PRO server

To transfer items, transfer speed and item size do matter. To reduce the item size is discussed in the previous section. The transfer speed depends on the connection and distance. Obviously, when the client and server sessions are executed on the same host or the hosts are in the same domain, the transfer speed is high. On the other hand, when these hosts are in different continents, then the transfer speed may very well be low.

To investigate how much time is spent for the case transfer, we have to look in the session log file of the solver session. This file can be found in the AIMMS PRO data folder, by default C:\ProgramData\AimmsPRO, subfolder Log\Sessions. The name of this log file is a GUID with extension .log. On a test server, the file was named D:\ProgramData\AimmsPRO\Log\Sessions\f9706ac8-841f-4b35-bc74-57863e82e630-1.log

To determine the time, obtain the session log file for the solver session and search for “CaseLoad : duration”:

2019-09-25 09:39:57,835 0x0000c2d0 [INFO] {AIMMS.DataManagement.DataManager} CaseLoad : duration 38093 ms

and a few lines above that:

2019-09-25 09:39:19,744 0x0000c2d0 [INFO] {PRO.Common.GenericFileRetriever} GenericReceiveFile( ..., fullPath = 'D:/ProgramData/AimmsPRO/Data/Publishing/MODELS/6cfce02e-9d7a-439f-b1ce-19f936247e77/PROTemp-058DBE41/cases.data', ... ) Transmitted 889248 KB in 1.93 seconds ( 460750 KB/s)

Because of the superfluous identifier, we’re transmitting a case of 800+ Mb which takes 38 seconds here.

Anyway, now that we have this log file open, we may want to search for other occurrences of the word “duration”, to see if anything interesting pops up.

On the AIMMS PRO server, wait for a server license

This is also known as wait time or queueing time. This can be obtained from the Jobs tab in the AIMMS PRO Portal as illustrated in the image below:

../../_images/JobsTabForQueueing.png

In the example above, the job didn’t have to wait for other jobs. Clearly, the queueing time depends on the load of the AIMMS PRO server, but that falls outside the scope of this article.

On the AIMMS PRO server, compile and initialize the AIMMS Project

A solver session starts with opening the project, including running initialization procedures of the Main model and running the initialization procedures of each of its libraries.

By adding the code ProfilerStart() at the top of your MainInitialization procedure, you can measure how long do these initialization procedures take for your project. After adding this line, close and reopen your AIMMS project. Profiler -> Results Overview will give you the numbers on client side.

../../_images/ProfiledClientSideInitialization.png

Once you are satisfied with the initialization times of your project on client side, you might want to check this on the server side as well. How to check the timings server side is discussed below: see On the AIMMS PRO server, execute the delegated procedure.

On the AIMMS PRO server, read the input case file

This action, and subsequently the time it takes, is closely linked to the size of the case file as discussed above.

On the AIMMS PRO server, execute the delegated procedure

We will use the attached AIMMS project as an example for this section.

We assume here that your MainInitialization procedure, still starts with ProfilerStart(); In addition, we assume here that delegation is done as follows:

1
2
3
4
5
6
7
8
if pro::GetPROEndPoint() then
    if pro::DelegateToServer( waitForCompletion  :  1,
                  completionCallback :  'pro::session::LoadResultsCallBack' ) then
        return 1;
    endif ;
endif ;

pr_WorkSolve();

We change this to:

1
2
3
4
5
6
7
8
if pro::GetPROEndPoint() then
    if pro::DelegateToServer( waitForCompletion  :  1,
                  completionCallback :  'pro::session::LoadResultsCallBack' ) then
        return 1;
    endif ;
endif ;

gss::pr_GuardAndProfileServerJob( 'pr_WorkSolve' );

gss::pr_GuardAndProfileServerJob(); is defined as:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
Procedure pr_GuardAndProfileServerJob {
    Arguments: (ep_Work);
    Body: {
        block
            empty s_JobErrorMessageNumbers ;

            ! Ensure that the error recorded and profiler data are transmitted via the output case:
            pro::ManagedSessionOutputCaseIdentifierSet += ServerSessionProfilerErrorData ;

            ! Actual work.
            apply( ep_Work);

            ! Ensure that the definitions of all defined sets and defined parameters in
            ! output case identifier set are profiled.
            update pro::ManagedSessionOutputCaseIdentifierSet;

        onerror ep_err do

            ! Increase the number of recorded error messages.
            s_JobErrorMessageNumbers += card(s_JobErrorMessageNumbers) + 1;
            ep_JobErrorMessageNumber := last(s_JobErrorMessageNumbers);

            ! Record the message and severity.
            sp_JobErrorMessages(ep_JobErrorMessageNumber) := errh::Message( ep_err);
            sp_JobErrorMoments( ep_JobErrorMessageNumber) := CurrentToString("%c%y-%m-%d %H:%M:%S:%T%TZ('UTC')");
            ep_JobErrorSeverity(ep_JobErrorMessageNumber) := errh::Severity(ep_err);

            ! Record the entire stack of error positions
            p_errStackHeight := errh::NumberOfLocations(ep_err);
            p_errStackPos := 1 ;
            while p_errStackPos <= p_errStackHeight do
                ep_StackPosition := p_errStackPos;
                ep_JobErrorNodes(ep_JobErrorMessageNumber,ep_StackPosition) := errh::Node(ep_err,ep_StackPosition);
                p_JobErrorLines( ep_JobErrorMessageNumber,ep_StackPosition) := errh::Line(ep_err,ep_StackPosition);
                p_errStackPos += 1 ;
            endwhile ;

            ! Don't let the server job be halted by this error;
            ! we still want the result case including the profiled data.
            errh::MarkAsHandled(ep_err);

        endblock ;
        ProfilerCollectAllData(
            ProfilerData       :  p_JobProfilerData,
            GrossTimeThreshold :  0,
            NetTimeThreshold   :  0);
    }
    ElementParameter ep_err {
        Range: errh::PendingErrors;
    }
    Parameter p_errStackHeight;
    Parameter p_errStackPos;
    ElementParameter ep_StackPosition {
        Range: s_StackPositions;
    }
    ElementParameter ep_JobErrorMessageNumber {
        Range: s_JobErrorMessageNumbers;
    }
    ElementParameter ep_Work {
        Range: AllProcedures;
        Default: 'gss::pr_SampleProc';
        Property: Input;
    }
}

Note

ProfilerCollectAllData is available since AIMMS 4.68

In addition, we also set the option communicate_warnings_to_end_users to on.

Run the optimization via the widget action of the Gantt Chart:

../../_images/StartOptimization.png

Switch to the profile and error page of the app:

../../_images/ErrorProfilerDataServerJob.png

The flow shop project contains a custom library GuardServerSession, which you can download and add to your project. See add libraries to your project.

On the AIMMS PRO server, create a case file with the results

This is the same as section Client side: Create a case file to be used as input, except the other way around and the identifier pro::ManagedSessionOutputCaseIdentifierSet

Client side: read the case file with results

This is the same as section On the AIMMS PRO server, read the input case file.

Last Updated: March, 2020