Wall clock solve time spikes compared to reported optimizer time

I am using the Drake GurobiSolver interface to solve a high-rate MIQP Model Predictive Control problem on Ubuntu 20.04. Occasionally, I will see large spikes in the amount of time it takes to solve a problem, that are not reflected in the optimizer_time reported by Gurobi:

From the debugging I've been able to do, it seems like a potential reason for this discrepancy is that GRBoptimize() calls GRBgetcpu(), which opens and reads the file /proc/cpuinfo. is there a parameter I can use to disable this check? I am still experiencing this issue even when set ConcurrentMIP and Threads to 1.

Here's a stack trace showing that code path:

#0 0x00007ffff0a5efd4 in __libc_open64 (file=0x7ffff38f8884 "/proc/cpuinfo",
oflag=0) at ../sysdeps/unix/sysv/linux/open64.c:48
#1 0x00007ffff09e1016 in __GI__IO_file_open (fp=fp@entry=0x555558cef570,
filename=<optimized out>, posix_mode=<optimized out>, prot=prot@entry=438,
read_write=8, is32not64=<optimized out>) at fileops.c:189
#2 0x00007ffff09e12da in _IO_new_file_fopen (fp=fp@entry=0x555558cef570,
filename=filename@entry=0x7ffff38f8884 "/proc/cpuinfo",
mode=<optimized out>, mode@entry=0x7ffff38f1030 "r",
is32not64=is32not64@entry=1) at fileops.c:281
#3 0x00007ffff09d398e in __fopen_internal (is32=1, mode=0x7ffff38f1030 "r",
filename=0x7ffff38f8884 "/proc/cpuinfo") at iofopen.c:75
#4 _IO_new_fopen (filename=0x7ffff38f8884 "/proc/cpuinfo",
mode=0x7ffff38f1030 "r") at iofopen.c:86
#5 0x00007ffff190071e in GRBgetcpu ()
from /home/brian/workspace/gurobi/gurobi1003/linux64/lib/libgurobi100.so
#6 0x00007ffff17ab327 in GRBoptimize ()
from /home/brian/workspace/gurobi/gurobi1003/linux64/lib/libgurobi100.so

Jaromił Najman

Gurobi Staff

April 04, 2024 09:06

Hi Brian,

Is it correct that the difference you see is within ~0.02 seconds? It might be possible that some Thread is blocking the access to get the CPU time. Are you running something in parallel or in the background?

Best regards,
Jaromił

Brian Acosta

April 04, 2024 14:23 Edited

That is correct. I investigated a little more and found that when I remove read permissions for the file "/proc/cpuinfo", the discrepancy goes away. This is consistent with the hypothesis that reading that file is the problem. I also confirmed that I don't see this discrepancy on macos, potentially due to a different implementation for retrieving the cpu info.

April 04, 2024 15:29

I investigated a little more and found that when I remove read permissions for the file "/proc/cpuinfo", the discrepancy goes away.

Good that you were able to figure this out. I think this is a good indicator that there were some conflicts when trying to access the file.

Wall clock solve time spikes compared to reported optimizer time

Comments

Didn't find what you were looking for?