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:

  • How can I reduce the execution time of my AIMMS PRO job?
  • How can I find out what went wrong with my AIMMS PRO job?

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 server 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. Clearly when the client and server session are executed on the same host, or the hosts are in the same domain, then transfer speed is high. On the other hand, when those hosts are on 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 server 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 server 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 AIMMS PRO portal, tab jobs 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 server 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 line

1
ProfilerStart();

Restarting AIMMS on your project, opening the profiler, results overview, you’ll get an impression how long initialization, client side, took for your project.

../../_images/ProfiledClientSideInitialization.png

Once you’re ok with the initialization time of your project, you may want to check this server side as well. How to check the timings server side is discussed below: see On the AIMMS PRO server, execute the procedure that is invoked by pro::DelegateToServer.

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 procedure that is invoked by pro::DelegateToServer

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 ;

pr_GuardAndProfileServerJob();

whereby the procedure 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
block
    empty s_JobErrorMessageNumbers ;

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

    ! Actual work.
    pr_WorkSolve();

    ! 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);
    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);

Remarks:

  1. ProfilerCollectAllData is available since AIMMS 4.68

In addition, we 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

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.

Project download

The AIMMS project used to create the screenshots of this article can be downloaded below:

Last Updated: October, 2019