Originally posted by: VKV7_Anulark_Naber

I used the following codes in main() of BranchCallback

varCplex.TotBranchTime += getCplexTime() - StartTime; //cumulative CPU time of branchcallback

varCplex.TotBranchTime and TotBranchDetTime are global variables.

I ran the program using 16 threads opportunistic, while solve() is interrupted and resolve() many times, but the TotBranchTime is cumulative. At the end I printed out theses time. While the CPU runtime was 3600 seconds, the TotBranchTime was 32666 seconds.

I went through the cplex documentation under the topic "Determinism and Timing Interfaces", but it was not clear to me what went wrong. Any advice would be appreciated.

I hope you are properly locking around

varCplex.TotBranchTime += getCplexTime() - StartTime; //cumulative CPU time of branchcallback
varCplex.TotBranchDetTime += getDetTime() - StartDetTime;

? Otherwise you will update varCplex concurrently from multiple threads and the results could be random.

When you say the total CPU runtime was 3600 seconds, how did you measure the total CPU runtime?

Is there a reason you need to use CPU time and cannot use wallclock time?

Originally posted by: VKV7_Anulark_Naber

varCplex.TotBranchTime and varCplex.TotBranchDetTime do not appear anywhere else except in BranchCallback::main().

I measured the cpu time by the following codes in main():

loop:

++n;

solve();

TotalCPUTime is correct as 3600 is the time limit I set, and indeed cplex is terminated by this limit.

i do not want to use wallclock time, as there may be some other processes running in parallel or on the background which can also delay the elapsed time.

varCplex.TotBranchTime and varCplex.TotBranchDetTime do not appear anywhere else except in BranchCallback::main().

I don't see how this would avoid race conditions. If you run with 16 threads in opportunistic parallel then callbacks are invoked in parallel as well. So multiple threads may execute

varCplex.TotBranchTime += getCplexTime() - StartTime; //cumulative CPU time of branchcallback
varCplex.TotBranchDetTime += getDetTime() - StartDetTime;

concurrently and the result of that would be sort of random. So you should really lock around this statement to avoid concurrent updates and make sure this is not the reason for seeing those numbers.

When the total CPU time 3600 seconds, what amount of wallclock time does expire in that timespan? Is the wallclock time spent in your code close to 3600 or is it significantly smaller? I am asking because I am trying to see whether the CPU time in your main thread may just not account for CPU times in the other threads.

Finally, what operating system are you using? And what version of CPLEX do you use?

Originally posted by: VKV7_Anulark_Naber

Please excuse my limited knowledge in multi-threading. Now I used mutex to lock and unlock around these two assignment codes. However, when I ran with 16 thread, I still got about the high total branchcallback time, about 76% of the total cpu time, when compared with 12% of running with 1 thread. In addition, when I ran with 1 thread, the total cpu time is about 900 seconds, while with 16 thread, it took more than 2000 seconds (much higher). Despite these time difference, I suppose the percentage of branchcallback time should not be that much off.

Both CPU time and wallclock time are close to 3600 seconds, as I usually do not run any other jobs in parallel, only sometimes. I suppose main() is ran under one thread, while these CPU time and time limit are imposed only in main(). Their figures are not suspicious as the branchcallback time.

I am using Windows 8.1 and cplex 12.5.0.1. 

Thanks in advance.

I think the problem is using getCplexTime() in the callback (sorry for not seeing this earlier). getCplexTime() returns the amount of CPU seconds the whole process (i.e. all threads) consumed. Assume you have 16 threads, all run the callback simultaneously and all spend 1 CPU second in the callback. That makes a total of 16 CPU seconds consumed by the process. However, you are measuring these 16 seconds in each thread and adding them once for each thread. So you are adding 16*16 CPU seconds to TotBranchTime.

In the callbacks you should only measure the CPU time for the current thread. You could get a CPU timestamp for the current thread like this (I am not a Windows expert, so there might be better ways):

double getThreadCpuTime()
{
    FILETIME c, e, k, u;
    GetThreadTimes(GetCurrentThread(), &c, &e, &k, &u);
    return 1e-7 * (((unsigned __int64)k.dwLowDateTime) + (((unsigned __int64)k.dwHighDateTime) << 32) +
        ((unsigned __int64)u.dwLowDateTime) + (((unsigned __int64)u.dwHighDateTime) << 32));

}

Do you get more consistent results if you use that instead of getCplexTime() in the callbacks?

Originally posted by: VKV7_Anulark_Naber

Yes, it did solve the problem. TotBranchTime is now about 12% as expected.

Interestingly, the CPU time of 16 Thread is also reduced and is consistent to that of 1 thread, although I only change the getCplexTime() to getThreadCpuTime() in BranchCallback only.

Thank you very much, Daniel.

Originally posted by: VKV7_Anulark_Naber

Now i am using the same codes for UserCutCallback::main(), but the total cut cpu time looks suspicious (50% of total cpu time). Should it also work in UserCutCallback, or should I do it differently?

The code I posted for getting a thread-local CPU time is completely independent of CPLEX, so it should work in any callback.

Note that by replacing 'Thread' by 'Process' everywhere in my code snippet you can get the CPU time of the whole process. If the CPU times returned by CPLEX look suspicious to you, I would implement a function getProcessCpuTime() and use that instead of CPLEX to measure the process's CPU time. If the timings you get this way are very different from what CPLEX reports then there may be a problem in CPLEX.

Depending on how big the time intervals are that you measure here, you may want to use an integral type (instead of double) for getting and accumulating the CPU time (GetThreadTimes() returns integers) to avoid round-off errors.

Originally posted by: VKV7_Anulark_Naber

Thank you. I did compare getCplexTime() with getProcessCpuTime(); getCplexTime() works fine.

However, for the UserCutCallback time, I need to recheck my codes, why it takes so much time.