How to evaluate execution time when using scipy.optimize?

Question

I am working on a python script that utilizes the minimize() function from scipy.optimize. The script works fine, but it is relatively slow, and I am trying to figure out how to (a) figure out where the time is being spent) so I can (b) speed it up.

My current benchmark for "slow" I have a dataset of entities where each entity contains ~5000 samples (i.e., I need to minimize() 5000 times/entity. I have roughly 2000 entities. My current run times vary between 35-45 seconds per entity so I am looking at a total run time of 80k seconds (or 22.2 hours). This would be fine if it was just a one-off, but this is something that requires testing multiple models, etc. So I need to get run times way down.

The main part of the script is as follows:

###Initializing Export Arrays
Vmin1 = np.array([])
Vmin2 = np.array([])
Vmin3 = np.array([])
Vmin4 = np.array([])
Vmin5 = np.array([])
Vmin6 = np.array([])
Vclay = np.array([])
Vker = np.array([])


###Initial Estimate
x0 = np.array([0.5, 0.1, 0.1, 0.0, 0.01, 0.07, 0.2, 0.02,])
bounds = ((0,1), (0,1), (0,1), (0,1), (0,1), (0,1), (0,1), (0,1)) 

C =np.array([[rhob_Vmin1, rhob_Vmin2, rhob_Vmin3, rhob_Vmin4, rhob_Vmin5, rhob_Vmin6, rhob_Vclay, rhob_Vker],
              [nphi_Vmin1, nphi_Vmin2, nphi_Vmin3, nphi_Vmin4, nphi_Vmin5, nphi_Vmin6, nphi_Vclay, nphi_Vker],
              [pe_Vmin1, pe_Vmin2, pe_Vmin3, pe_Vmin4, pe_Vmin5, pe_Vmin6, pe_Vclay, pe_Vker],
              [dt_Vmin1, dt_Vmin2, dt_Vmin3, dt_Vmin4, dt_Vmin5, dt_Vmin6, dt_Vclay, dt_Vker],
              [0,0,0,0,0,0,1,0],
              [0,0,0,0,0,0,0,1],
              [1,1,1,1,1,1,1,1]])


def mineral_inversion(x, L, C):
    L_pred = np.matmul(C, x)
    if not np.isnan(L[0][0]):
        I1 = (np.subtract(L[0][0], L_pred[0])/unc_rhob)**2
    else:
        I1=0
    if not np.isnan(L[0][1]):
        I2 = (np.subtract(L[0][1], L_pred[1])/unc_nphi)**2
    else:
        I2 = 0
    if not np.isnan(L[0][2]):
        I3 = (np.subtract(L[0][2], L_pred[2])/unc_pe)**2
    else:
        I3 = 0
    if not np.isnan(L[0][3]):
        I4 = (np.subtract(L[0][3], L_pred[3])/unc_dt)**2
    else:
        I4 = 0
    if not np.isnan(L[0][4]):
        I5 = (np.subtract(L[0][4], L_pred[4])/unc_vwcl)**2
    else:
        I5 = 0
    if not np.isnan(L[0][5]):
        I6 = (np.subtract(L[0][5], L_pred[5])/unc_vker)**2    
    else:
        I6 = 0
    I7 = ((1-x.sum())/unc_unity)**2

    incoherence = I1+I2+I3+I4+I5+I6+I7
    return incoherence   

from datetime import datetime
t0 = datetime.now()
vpor_init = np.float(0.1)

for dd in range(len(depth)):

    ###Log values used in mineral inversion + unity value
    L = np.array([[rhob[dd], nphi[dd], pe[dd], dt[dd], vwcl[dd], vkero[dd], 1]])

    res = minimize(fun = mineral_inversion, x0 = x0, args = (L, C), bounds=bounds, method='SLSQP')
    Vmin1 = np.append(Vmin1, res.x[0])
    Vmin2 = np.append(Vmin2, res.x[1])
    Vmin3 = np.append(Vmin3, res.x[2])
    Vmin4 = np.append(Vmin4, res.x[3])
    Vmin5 = np.append(Vmin5, res.x[4])
    Vmin6 = np.append(Vmin6, res.x[5])    
    Vclay = np.append(Vclay, res.x[6])
    Vker = np.append(Vker,   res.x[7])

t1 = datetime.now()
time = t1-t0
print('Run Time: ', time)

At present I am logging the run time at the for loop level. However, this doesn't tell me much with respect to where my bottleneck might be. Is it at the level of the mineral_inversion() function, is it in the minimize() function itself, etc.

Questions: (1) How can I smartly log the execution time to figure out if speeding this up is even possible? (2) What would be a fair way to state if this is actually 'slow' or if I am just being unreasonable and it is a lot of samples to iterate over? (3) Are there any obvious bad practices/speed traps that I have thrown in?

Answer 1

trying to figure out how to (a) figure out where the time is being spent

Use pstats module from the standard library for the function-level profiling, and kernprof for line-level profiling.

In a jupyter notebook, it's %prun and %lprun magics.