Multiprocessing slows down matrix multiplication (strange interaction with MKL)

[lzlarryli]

Summary: Multiprocessing slows down completely independent matrix multiplication.

It seems multiprocessing makes completely independent numpy computation processes slower, even with the number of OpenMP threads controlled.

Test code example:

import time
import multiprocessing as mp

import numpy as np
import mkl

def work(n=5000, tries=5):
    """Compute the product of two random nxn matrices. Return the average timing of [tries] runs."""
    np.random.seed()
    timings = []
    for i in range(tries):
        start = time.time()
        a = np.random.rand(n, n)
        b = np.random.rand(n, n)
        res = np.sum(a.dot(b))
        stop = time.time()
        timings.append(stop - start)
    return np.mean(timings)


num_cores = mp.cpu_count()
print("# Cores: {}".format(num_cores))

# Print table header by hand
tab = "\t\t"
print("procs", end=tab)
for i in range(1, num_cores + 1):
    print("{}".format(i), end=tab)
print("")
print("threads")

# Try all combinations of threads/processes
for threads in range(1, num_cores + 1):
    mkl.set_num_threads(threads)
    print("set {} get {}".format(threads, mkl.get_max_threads()), end=tab)

    for procs in range(1, num_cores + 1):
        pool = mp.Pool()
        jobs = [() for _ in range(procs)]
        print("{:0.4f}".format(np.mean(pool.starmap(work, jobs))), end=tab)
    print("")

Expectation: when thread is set to 1, running 4 processes on 4 cores should take roughly the same time as running 1 processes on 1 core.

Result on a laptop with 4 processors (Intel i7-6600U, 2 physical cores) and 16GB memory:

# Cores: 4
procs           1               2               3               4
threads
set 1 get 1     6.4352          7.9569          11.3162         18.4924
set 2 get 2     4.3469          9.6891          14.3225         18.6104
set 3 get 2     4.6828          8.5717          13.1268         16.9085
set 4 get 2     4.1497          8.6765          13.4662         17.2045

The observed number of processes and cores used (from htop) agrees with the reported numbers. For example, for 2 procs and 2 threads, htop reports 2 processes using ~200% of CPU and all 4 cores have ~100% load. Yet even with 1 thread, adding independent processes slows down the code substantially. The computation here is not memory bound and there is no communication between processes.

System info:

$ uname -a
Linux xxx 4.13.12-1-ARCH #1 SMP PREEMPT Wed Nov 8 11:54:06 CET 2017 x86_64 GNU/Linux

$ python --version
Python 3.6.2 :: Anaconda, Inc.



In[9]: numpy.distutils.system_info.get_info("mkl")
Out[9]: 
{'define_macros': [('SCIPY_MKL_H', None), ('HAVE_CBLAS', None)],
 'include_dirs': ['/home/larry/programs/anaconda3/include'],
 'libraries': ['mkl_rt', 'pthread'],
 'library_dirs': ['/home/larry/programs/anaconda3/lib']}
In [10]: numpy.version.full_version
Out[10]: '1.13.1'

Related reports:

https://stackoverflow.com/questions/15639779/why-does-multiprocessing-use-only-a-single-core-after-i-import-numpy
https://stackoverflow.com/questions/15414027/multiprocessing-pool-makes-numpy-matrix-multiplication-slower
https://stackoverflow.com/questions/26258728/parallel-processing-with-multiprocessing-is-slower-than-sequential
https://stackoverflow.com/questions/47380366/dramatic-slow-down-using-multiprocess-and-numpy-in-python

I tried all the "solutions" mentioned above. None seems to be relevant. I can confirm that the affinity is correct and all cores are utilized.

[seberg]

Isn't this probably expected, since matrix multiplication is only fast by utilizing the cache very efficiently and likely maxing out memory bandwidth? So doing two at the same time kills both cache usage and uses memory bandwidth more (when compared to two mkl threads).

I kinda thought linear algebra is additionally one of those things that are actually much faster non-naivly threaded, which MKL does.

[lzlarryli]

@seberg Thanks. I did some further testing and can confirm your suspicion.

For future reference, I included the profiling result below. It is clear that with 1 process the DRAM bandwidth is almost maxed out. With 4 processes, I get 3 times L1 misses, half IPC and FPU utilization.

perf output for 1 process:

 Performance counter stats for 'python mp.py 1 3000':                           
                                                                                
      35203.647582      task-clock:u (msec)       #    1.918 CPUs utilized      
                 0      context-switches:u        #    0.000 K/sec              
                 0      cpu-migrations:u          #    0.000 K/sec              
            41,618      page-faults:u             #    0.001 M/sec              
    95,675,772,169      cycles:u                  #    2.718 GHz                
   295,095,802,372      instructions:u            #    3.08  insn per cycle     
     9,499,806,824      branches:u                #  269.853 M/sec              
         9,260,261      branch-misses:u           #    0.10% of all branches    
   114,152,441,686      L1-dcache-loads:u         # 3242.631 M/sec              
     7,681,387,929      L1-dcache-load-misses:u   #    6.73% of all L1-dcache hits
       176,927,978      LLC-loads:u               #    5.026 M/sec              
        10,067,166      LLC-load-misses:u         #    5.69% of all LL-cache hits
                                                                                
      18.351525927 seconds time elapsed                                         

perf output for 4 processes:

 Performance counter stats for 'python mp.py 4 3000':                           
                                                                                
     284762.225130      task-clock:u (msec)       #    3.969 CPUs utilized      
                 0      context-switches:u        #    0.000 K/sec              
                 0      cpu-migrations:u          #    0.000 K/sec              
           145,438      page-faults:u             #    0.511 K/sec              
   700,820,186,535      cycles:u                  #    2.461 GHz                
 1,168,783,354,835      instructions:u            #    1.67  insn per cycle     
    33,947,569,741      branches:u                #  119.214 M/sec              
        64,718,944      branch-misses:u           #    0.19% of all branches    
   450,346,738,326      L1-dcache-loads:u         # 1581.483 M/sec              
    87,875,798,897      L1-dcache-load-misses:u   #   19.51% of all L1-dcache hits
       757,222,130      LLC-loads:u               #    2.659 M/sec              
        70,360,552      LLC-load-misses:u         #    9.29% of all LL-cache hits
                                                                                
      71.753016098 seconds time elapsed                                         

Intel APS output for 1 process:

  Elapsed time:               17.34 sec                                         
  SP GFLOPS:                 124.51                                             
  CPI Rate:                    0.33                                             
  CPU Utilization:                               49.30%                         
    Average CPU Usage:                            1.97   Out of    4 logical CPUs
  Memory Stalls:                               6.30% of pipeline slots          
    Cache Stalls:                              2.70% of cycles                  
    DRAM Stalls:                               2.00% of cycles                  
    Average DRAM Bandwidth:                    7.35  GB/s                       
  FPU utilization:                          68.40%                              
       SP FLOPS per cycle:                       21.90   Out of   32            
       Vector capacity:                          99.50%                         
       FP Instruction Mix:                                                      
          % of Packed FP Instr.:                    99.30%                      
             % of 128-bit instructions:              0.00%                      
             % of 256-bit instructions:             99.30%                      
          % of Scalar FP Instr:                      0.70%                      
       FP Arith/Mem Rd Instr. Ratio:              2.42                          
       FP Arith/Mem Wr Instr. Ratio:             47.41                          
 Memory Footprint:                                                              
  Resident:         28.33 MB                                                    
  Virtual:         335.75 MB                                                    

Intel APS for 4 processes:

  Elapsed time:               72.14 sec
  SP GFLOPS:                 120.67
  CPI Rate:                    0.62
  CPU Utilization:                               99.20%
    Average CPU Usage:                            3.97   Out of    4 logical CPUs
  Memory Stalls:                               3.90% of pipeline slots
    Cache Stalls:                             13.60% of cycles
    DRAM Stalls:                               1.50% of cycles
    Average DRAM Bandwidth:                    8.69  GB/s
  FPU utilization:                          37.70%
       SP FLOPS per cycle:                       12.07   Out of   32
       Vector capacity:                          99.60%
       FP Instruction Mix:            
          % of Packed FP Instr.:                    99.40%
             % of 128-bit instructions:              0.00%
             % of 256-bit instructions:             99.40%
          % of Scalar FP Instr:                      0.60%
       FP Arith/Mem Rd Instr. Ratio:              2.43
       FP Arith/Mem Wr Instr. Ratio:             55.92
 Memory Footprint:
  Resident:         28.34 MB
  Virtual:         335.75 MB