Numpy, Scipy: очень большая разница для np.dot, работающего с nans на двух машинах

У меня две машины - моя и серверная. Задача состоит в том, чтобы вычислить косинусные расстояния между многими векторами и одним заданным вектором. После нормализации косинус эквивалентен просто скалярному произведению:

cosine(u,v) = 1.0 - np.dot(u, v) / (norm(u) * norm(v))

Поэтому я решил нормализовать свои векторы и получить ускорение в 3 раза. НО есть одно маленькое отличие. Некоторые из векторов могут быть равны векторам np.nans:

nullvect = [np.nan]*300

Это основная часть моей модели. Предположим, следующий эксперимент сравнивает scipy.spatial.distance.cosine, np.dot и скалярное произведение из библиотеки blas:

import numpy as np

from scipy.spatial.distance import cdist

#import blas version
import scipy
gemv = scipy.linalg.get_blas_funcs("gemv") # Numpy somehow does not want to use optimized version. Let's call BLAS directly
dot = lambda x,y: gemv(1,x,y)

# generate data
vectors = np.random.randn(1000,300)
# normalize and write contiguously
vectors = np.ascontiguousarray([v/np.linalg.norm(v) for v in vectors])
# set some of them to nans
nullvect = [np.nan]*300
# place a lot of nan vectors
vecs = []
for vector in vectors:
    if np.random.randint(2) == 1:
        vecs += [nullvect]
    else:
        vecs += [vector]        
vecs = np.ascontiguousarray(vecs)
# normalize traget vector as well
vec = np.random.randn(300)
vec = vec/np.linalg.norm(vec)

import time

def eval_func():
    # cosine distances
    start = time.time()
    dists = cdist([vec], vecs, metric='cosine').ravel()
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")
    # np.dot distances
    start = time.time()
    dists = 1-vecs.dot(vec.T)
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")
    # blas distances
    start = time.time()
    dists = 1-dot(vecs, vec.T)
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")

eval_func()

На моей локальной машине все в порядке - скалярное произведение работает более чем в 3 раза быстрее:

Overall computation took 5.55992126465 ms
Overall computation took 0.340938568115 ms
Overall computation took 11.9209289551 ms

Но на сервере что-то не так - np.dot полный треш!

Overall computation took 5.462169647216797 ms
Overall computation took 81.59875869750977 ms
Overall computation took 15.769004821777344 ms

На обоих компьютерах под управлением Ubuntu 16.04 numpy 1.14 был установлен через pip после того, как OpenBlas был установлен через apt-get.

На обоих компах картина одинаковая:

>>> np.__config__.show()
lapack_mkl_info:
  NOT AVAILABLE
blas_opt_info:                                                                                                                                                        
    library_dirs = ['/usr/local/lib']                                                                                                                                 
    define_macros = [('HAVE_CBLAS', None)]                                                                                                                            
    language = c                                                                                                                                                      
    libraries = ['openblas', 'openblas']                                                                                                                              
lapack_opt_info:                                                                                                                                                      
    library_dirs = ['/usr/local/lib']                                                                                                                                 
    define_macros = [('HAVE_CBLAS', None)]                                                                                                                            
    language = c                                                                                                                                                      
    libraries = ['openblas', 'openblas']                                                                                                                              
blis_info:                                                                                                                                                            
  NOT AVAILABLE                                                                                                                                                       
openblas_lapack_info:                                                                                                                                                 
    library_dirs = ['/usr/local/lib']                                                                                                                                 
    define_macros = [('HAVE_CBLAS', None)]                                                                                                                            
    language = c
    libraries = ['openblas', 'openblas']
blas_mkl_info:
  NOT AVAILABLE
openblas_info:
    library_dirs = ['/usr/local/lib']
    define_macros = [('HAVE_CBLAS', None)]
    language = c
    libraries = ['openblas', 'openblas']

-

# update-alternatives --config libblas.so.3
There are 2 choices for the alternative libblas.so.3 (providing /usr/lib/libblas.so.3).

  Selection    Path                                 Priority   Status
------------------------------------------------------------
* 0            /usr/lib/openblas-base/libblas.so.3   40        auto mode
  1            /usr/lib/libblas/libblas.so.3         10        manual mode
  2            /usr/lib/openblas-base/libblas.so.3   40        manual mode

Сервер работает под управлением Python 3.6.2, моя локальная машина - 3.5.2. Без нанса в данных все Ок.

Сервер - Xeon с 8 процессорами, мой компьютер - ноутбук i7 с 4 ядрами (так что сервер определенно должен побить меня параллелизмом).

РЕДАКТИРОВАТЬ: Если я использую vectors вместо vecs (без нанов), результат также очень стохастический и может быть больше или меньше косинуса - может быть 1 мс или 7 мс и наоборот. Результаты для двух других алгоритмов постоянны.

Некоторые прогоны без нанов (векторов):

Overall computation took5.519390106201172 ms
Overall computation took1.5783309936523438 ms
Overall computation took8.22305679321289 ms
>>> eval_func()
Overall computation took5.586147308349609 ms
Overall computation took2.3889541625976562 ms
Overall computation took8.22305679321289 ms
>>> eval_func()
Overall computation took5.342960357666016 ms
Overall computation took8.533000946044922 ms
Overall computation took8.122920989990234 ms
>>> eval_func()
Overall computation took5.633831024169922 ms
Overall computation took1.8835067749023438 ms
Overall computation took8.115768432617188 ms
>>> eval_func()
Overall computation took5.548000335693359 ms
Overall computation took1.7952919006347656 ms
Overall computation took8.14199447631836 ms
>>> eval_func()
Overall computation took5.550384521484375 ms
Overall computation took2.02178955078125 ms
Overall computation took8.759498596191406 ms
>>> eval_func()
Overall computation took5.5217742919921875 ms
Overall computation took13.997554779052734 ms
Overall computation took8.320808410644531 ms
>>> eval_func()
Overall computation took5.490779876708984 ms
Overall computation took2.6559829711914062 ms
Overall computation took9.52005386352539 ms
>>> eval_func()
Overall computation took5.395412445068359 ms
Overall computation took2.0003318786621094 ms
Overall computation took8.37564468383789 ms
>>> eval_func()
Overall computation took5.440711975097656 ms
Overall computation took2.224445343017578 ms
Overall computation took8.237361907958984 ms

Некоторые прогоны с nans (vecs):

>>> eval_func()
Overall computation took5.4454803466796875 ms
Overall computation took26.26657485961914 ms
Overall computation took7.8868865966796875 ms
>>> eval_func()
Overall computation took5.366802215576172 ms
Overall computation took19.97232437133789 ms
Overall computation took7.729530334472656 ms
>>> eval_func()
Overall computation took5.433559417724609 ms
Overall computation took19.736289978027344 ms
Overall computation took7.9345703125 ms
>>> eval_func()
Overall computation took5.447864532470703 ms
Overall computation took18.61095428466797 ms
Overall computation took8.14676284790039 ms
>>> eval_func()
Overall computation took5.567073822021484 ms
Overall computation took1.926422119140625 ms
Overall computation took7.729530334472656 ms
>>> eval_func()
Overall computation took5.640983581542969 ms
Overall computation took20.401477813720703 ms
Overall computation took7.8868865966796875 ms

РЕДАКТИРОВАТЬ 2:

Параметр

import os
os.environ['OMP_NUM_THREADS']='1'

не помогло

Может быть, я могу переключиться на какую-то другую библиотеку?

РЕДАКТИРОВАТЬ3:

На обеих машинах

>>> import inspect
>>> inspect.getmodule(np.dot)
<module 'numpy.core.multiarray' from '/usr/local/lib/python3.6/site-packages/numpy/core/multiarray.cpython-36m-x86_64-linux-gnu.so'>

Однако похоже, что это может отличаться

РЕДАКТИРОВАТЬ 4: Самый большой сюрприз: np.inner(), похоже, работает нормально (это эквивалентно np.dot для умножения матрицы на вектор, но немного медленнее):

def eval_func():
    # cosine distances
    start = time.time()
    dists = cdist([vec], vecs, metric='cosine').ravel()
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")
    # np.dot distances
    start = time.time()
    dists = 1-vecs.dot(vec.T)
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")
    # blas distances
    start = time.time()
    dists = 1-dot(vecs, vec.T)
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")


    start = time.time()
    dists = 1-np.inner(vecs, vec.T)
    end = time.time()
    print("Overall computation took"+ str((end-start)*10000)+" ms")

eval_func()


>>> eval_func()
Overall computation took5.500316619873047 ms
Overall computation took37.69874572753906 ms
Overall computation took8.03232192993164 ms
Overall computation took0.6771087646484375 ms
>>> eval_func()
Overall computation took5.517005920410156 ms
Overall computation took1.811981201171875 ms
Overall computation took7.5435638427734375 ms
Overall computation took0.6580352783203125 ms
>>> eval_func()
Overall computation took5.688667297363281 ms
Overall computation took38.02061080932617 ms
Overall computation took7.672309875488281 ms
Overall computation took0.5245208740234375 ms
>>> eval_func()
Overall computation took5.614757537841797 ms
Overall computation took38.6500358581543 ms
Overall computation took8.053779602050781 ms
Overall computation took0.6699562072753906 ms
>>> eval_func()
Overall computation took5.481243133544922 ms
Overall computation took39.615631103515625 ms
Overall computation took7.724761962890625 ms
Overall computation took0.5125999450683594 ms
>>> eval_func()
Overall computation took5.562305450439453 ms
Overall computation took2.0051002502441406 ms
Overall computation took7.450580596923828 ms
Overall computation took0.5030632019042969 ms
>>> eval_func()
Overall computation took5.252361297607422 ms
Overall computation took3.883838653564453 ms
Overall computation took7.433891296386719 ms
Overall computation took0.705718994140625 ms

EDIT5: Итак, я хотел заменить cdist на np.inner в своей программе и получил замедление! Вот сравнение результатов времени в мс между cdist (первый) и np.inner (второй). Последний кортеж представляет собой форму массива векторов:

2018-02-07 23:12:37,609 0.6237030029296875 20.6756591796875 (1381, 300)
2018-02-07 23:12:37,612 0.6270408630371094 0.7233619689941406 (1381, 300)
2018-02-07 23:12:37,614 2.070188522338867 4.981040954589844 (2879, 300)
2018-02-07 23:12:37,630 19.373416900634766 28.1679630279541 (2387, 300)
2018-02-07 23:12:37,641 0.6058216094970703 28.65886688232422 (1007, 300)
2018-02-07 23:12:37,642 1.2252330780029297 12.749433517456055 (2879, 300)
2018-02-07 23:12:37,649 29.929637908935547 76.58910751342773 (9151, 300)
2018-02-07 23:12:37,649 1.0759830474853516 15.654802322387695 (2387, 300)
2018-02-07 23:12:37,653 0.5512237548828125 6.318569183349609 (1007, 300)
2018-02-07 23:12:37,664 0.4935264587402344 6.627321243286133 (1007, 300)
2018-02-07 23:12:37,670 1.275777816772461 11.78598403930664 (2879, 300)
2018-02-07 23:12:37,679 0.47206878662109375 10.010242462158203 (1007, 300)
2018-02-07 23:12:37,679 0.46634674072265625 16.28565788269043 (922, 300)
2018-02-07 23:12:37,683 0.7443428039550781 29.844284057617188 (1381, 300)
2018-02-07 23:12:37,686 26.117801666259766 36.93413734436035 (9929, 300)
2018-02-07 23:12:37,693 1.2125968933105469 13.280630111694336 (2879, 300)
2018-02-07 23:12:37,698 0.4277229309082031 6.974458694458008 (922, 300)
2018-02-07 23:12:37,698 0.5869865417480469 8.502006530761719 (1381, 300)
2018-02-07 23:12:37,708 0.48828125 22.032976150512695 (1007, 300)
2018-02-07 23:12:37,710 0.4360675811767578 6.644725799560547 (922, 300)
2018-02-07 23:12:37,713 0.6110668182373047 8.195638656616211 (1381, 300)
2018-02-07 23:12:37,719 1.1529922485351562 12.442350387573242 (2879, 300)
2018-02-07 23:12:37,720 0.4718303680419922 5.584001541137695 (1007, 300)
2018-02-07 23:12:37,725 0.46443939208984375 13.801336288452148 (922, 300)
2018-02-07 23:12:37,729 0.5846023559570312 2.321958541870117 (1381, 300)
2018-02-07 23:12:37,737 0.4661083221435547 4.40669059753418 (922, 300)
2018-02-07 23:12:37,746 0.09751319885253906 0.033855438232421875 (4, 300)
2018-02-07 23:12:37,749 0.4220008850097656 6.46662712097168 (922, 300)
2018-02-07 23:12:37,750 0.07700920104980469 0.030040740966796875 (4, 300)
2018-02-07 23:12:37,751 0.16117095947265625 26.17502212524414 (62, 300)
2018-02-07 23:12:37,751 0.14591217041015625 19.942522048950195 (37, 300)
2018-02-07 23:12:37,752 0.0743865966796875 0.029325485229492188 (4, 300)
2018-02-07 23:12:37,753 0.1418590545654297 1.1310577392578125 (37, 300)
2018-02-07 23:12:37,753 0.07486343383789062 0.019788742065429688 (4, 300)
2018-02-07 23:12:37,754 0.10466575622558594 0.9295940399169922 (37, 300)
2018-02-07 23:12:37,755 0.07486343383789062 0.029802322387695312 (4, 300)
2018-02-07 23:12:37,755 0.10275840759277344 0.8199214935302734 (37, 300)
2018-02-07 23:12:37,757 0.10943412780761719 0.7965564727783203 (37, 300)
2018-02-07 23:12:37,758 0.11110305786132812 0.8292198181152344 (37, 300)
2018-02-07 23:12:37,758 0.07224082946777344 0.029325485229492188 (4, 300)
2018-02-07 23:12:37,765 8.567333221435547 22.03059196472168 (9929, 300)
2018-02-07 23:12:37,771 0.12874603271484375 17.62080192565918 (62, 300)
2018-02-07 23:12:37,776 0.12159347534179688 2.850055694580078 (62, 300)
2018-02-07 23:12:37,782 4.766225814819336 44.742584228515625 (9151, 300)
2018-02-07 23:12:37,783 0.14066696166992188 4.610538482666016 (62, 300)
2018-02-07 23:12:37,786 0.12326240539550781 0.9648799896240234 (62, 300)
2018-02-07 23:12:37,788 0.12063980102539062 0.9310245513916016 (62, 300)
2018-02-07 23:12:37,814 0.26988983154296875 26.521682739257812 (428, 300)

Я просто не понимаю, что происходит...

EDIT6: переустановлено изображение докера с библиотекой atlas, но недавно установленный numpy по-прежнему говорит в np.__config__.show(), что он использует openblas. Которого даже нет в системе.

EDIT7: перестройте numpy для использования atlas. Теперь результаты для np.dot и np.inner наконец-то стабильны, хотя только в два раза лучше, чем для scipy cdist. Похоже, проблема с openblas на сервере Amazon ec2. Результаты для него полностью стохастические.

Я проверил ситуацию вне докера, она такая же.