Originally posted by: SystemAdmin

Hi,

I'm trying to measure the time consumed by CPLEX using the following code:

// model is already loaded in object 'cplex'
cplex.setParam(IloCplex::TiLim, TIME_LIMIT);
IloTimer timer(env);
timer.start();
cplex.solve();
timer.stop();
cout << "Time: " << timer.getTime() << endl;
CPLEX manual states that method getTime() returns:

public IloNum getTime() const
This member function returns the accumulated time, in seconds, since one of these conditions:
- the first call of the member function start after construction of the invoking timer;
- the most recent call to the member function restart;
- a call to reset.
http://pic.dhe.ibm.com/infocenter/cosinfoc/v12r2/topic/ilog.odms.cplex.help/html/refcppcplex/html/classes/IloTimer.html
Surprisingly, for a very small model, which solves in less than a second, I get a very high integer value (e.g. 900).

I guess that this value cannot be in seconds, since the solution was printed out almost instantly.

Am I getting something wrong?

By the way, is there any better way to get the total user (process) CPU time in CPLEX aside from IloTimer?

Thanks in advance.

My system is:

• MacBook Pro, 2.3 GHz Intel Core i5
• CPLEX 12.4 for x86-64_darwin9_gcc4.0
• Apple LLVM compiler 4.1 (clang++)

#CPLEXOptimizers
#DecisionOptimization

Originally posted by: SystemAdmin

This is indeed weird. Did you change the ClockType parameter?
What happens if you comment out the cplex.solve() call, i.e., just have timer.start() and timer.stop() directly after each other?

Tobias
#CPLEXOptimizers
#DecisionOptimization

Originally posted by: SystemAdmin

Hi Tobias,

Thanks a lot for the hint. Actually, when I comment out the "cplex.solve()" line, the timer returns 0 (obviously).

On the other hand, I added the ClockType parameter, but it remains returning the same result...

However, now I'm trying to compare the time returned by CPLEX with a usual time function as "clock_t":

// model is already loaded in object 'cplex'
cplex.setParam(IloCplex::TiLim, TIME_LIMIT);
cplex.setParam(IloCplex::ClockType, 0);

// clock_t and clock reference: http://www.cplusplus.com/reference/clibrary/ctime/clock/
clock_t clockStart = clock();

IloTimer timer(env);
timer.start();
cplex.solve();
timer.stop();

clock_t clockEnd = clock();

cout << "clock_t: " << (double)(clockEnd - clockStart) / CLOCKS_PER_SEC << " seconds" << endl;
cout << "IloTimer: " << timer.getTime() << " seconds (?)" << endl;
For a particular small problem, I get:
clock_t: 0.23832 seconds
IloTimer: 1300 seconds (?)

Is this normal?

I'll try to make a specific example using the sources that came with CPLEX 12.4, and I'll post the results...

Best regards

> Tobias Achterberg wrote:
> This is indeed weird. Did you change the ClockType parameter?
> What happens if you comment out the cplex.solve() call, i.e., just have timer.start() and timer.stop() directly after each other?
>
> Tobias
#CPLEXOptimizers
#DecisionOptimization

Originally posted by: SystemAdmin

I think what you observe is a known issue with IloTimer on MacOS.
The value returned by IloTimer::getTime() is bogus.
The issue should be fixed in version 12.4.0.1. Can you try to upgrade to this version (or use clock() as you indicated).
#CPLEXOptimizers
#DecisionOptimization

Originally posted by: SystemAdmin

Thanks for the help. Fortunately, I've managed to modify a C++ example to reproduce the problem.

I've edited the file named "ilogoalex2.cpp" which is located in the path:
<YourPathToCPLEX>/CPLEX_Studio124/cplex/examples/src/cpp

I added the following lines, before and after the "cplex.solve(CutGoal(...))" instruction:
...
IloTimer timer(env);
timer.start();
cplex.solve(CutGoal(env, lhs, rhs, cplex.getParam(IloCplex::EpRHS)));
timer.stop();
cout << endl << "IloTimer: " << timer.getTime() << endl;
cout << "IloTimer / 10000: " << timer.getTime() / 10000.0 << endl << endl;
...
Then, I went to:
<YourPathToCPLEX>/CPLEX_Studio124/cplex/examples/x86-64_darwin9_gcc4.0/static_pic

and typed:
$ make ilogoalex2

This particular example reads and solves a model contained in a file named "noswot.mps".

So, when I run it:
$./ilogoalex2
I get the following output:

reading ../../../examples/data/noswot.mps

Selected objective sense: MINIMIZE
Selected objective name: 1
Selected RHS name: RHS
Selected bound name: LINDOBND
extracting model ...
initializing cuts ...
solving model ...
...
blah...
blah...
blah...
...
Root node processing (before b&c):
Real time = 0.02
Sequential b&c:
Real time = 1.29
-------
+Total (root+branch&cut) = 1.31 sec.+

IloTimer: 13200
IloTimer / 10000: 1.32

solution status is Optimal
solution value is -41
As you see Total time is 1.31 sec., and IloTimer returns 13200, that divided by 10000 it yields 1.32.

So it seems that the IloTimer::getTime() method returns tenths of milliseconds, and not seconds as stated in the reference manual.

Best regards
#CPLEXOptimizers
#DecisionOptimization

Originally posted by: SystemAdmin

Yes, the bug I mentioned (and that should be fixed in 12.4.0.1) is that it returns "wallclock time * 10000", which is quite different from what is documented.
#CPLEXOptimizers
#DecisionOptimization