title: Multi-processing in Python: Numpy + Vector Summation -> Huge Slowdown
body: <p>Please don't be discouraged by the long post. I try to present as much data as I can, and I really need help with the problem :S. I'll update daily if there are new tips or ideas</p>
  
  <h1>Problem:</h1>
  
  <p>I try to run a Python code on a two core machine in parallel with the help of parallel processes (to avoid GIL), but have the problem that the code significantly slows down. For example, a run on a one core machine takes 600sec per workload, but a run on a two core machine takes 1600sec (800sec per workload). </p>
  
  <h1>What I already tried:</h1>
  
  <ul>
  <li><p>I measured the memory, and there appears to be no memory problem. 
  [just using 20% at the high point]. </p></li>
  <li><p>I used “htop” to check whether I am really running the program on different cores, or if my core affinity is messed up. But no luck either, my program is running on all of my cores. </p></li>
  <li><p>The problem is a CPU-bounded problem, and so I checked and confirmed that my code is running at 100% CPU on all cores, most of the time.</p></li>
  <li><p>I checked the process ID’s and I am, indeed, spawning  two different processes.</p></li>
  <li><p>I changed my function which I’m submitting into the executor [ e.submit(function,[…]) ]  to a calculate-pie function and observed a huge speedup. So the problem is probable in my process_function(…) which I am submitting into the executor and not in the code before.</p></li>
  <li><p>Currently I'm using "futures" from "concurrent" to parallize the task. But I also tried the "pool" class from "multiprocessing". However, the result remained the same.</p></li>
  </ul>
  
  <h1>Code:</h1>
  
  <ul>
  <li><p>Spawn processes:</p>
  
  <pre><code>result = [None]*psutil.cpu_count()
  
  e = futures.ProcessPoolExecutor( max_workers=psutil.cpu_count() )
  
  for i in range(psutil.cpu_count()):
      result[i] = e.submit(process_function, ...)
  </code></pre></li>
  <li><p>process_function:</p>
  
  <pre><code>from math import floor
  from math import ceil
  import numpy
  import MySQLdb
  import time
  
  db = MySQLdb.connect(...)
  cursor  = db.cursor()
  query = "SELECT ...."
  cursor.execute(query)
  
  [...]  #save db results into the variable db_matrix (30 columns, 5.000 rows)
  [...]  #save db results into the variable bp_vector (3 columns, 500 rows)
  [...]  #save db results into the variable option_vector( 3 columns, 4000 rows)
  
  cursor.close()
  db.close()
  
  counter = 0 
  
  for i in range(4000):
      for j in range(500):
           helper[:] = (1-bp_vector[j,0]-bp_vector[j,1]-bp_vector[j,2])*db_matrix[:,0] 
                       + db_matrix[:,option_vector[i,0]] * bp_vector[j,0]  
                       + db_matrix[:,option_vector[i,1]] * bp_vector[j,1]   
                       + db_matrix[:,option_vector[i,2]] * bp_vector[j,2]
  
           result[counter,0] = (helper &lt; -7.55).sum()
  
           counter = counter + 1
  
  return result
  </code></pre></li>
  </ul>
  
  <h1>My guess:</h1>
  
  <ul>
  <li><p>My guess is, that for some reason the weigthed vector multiplication which creates the vector "helper" is causing problems. <em>[I believe the Time Measurement section confirms this guess]</em></p></li>
  <li><p>Could it be the case, that numpy creates these problems? Is numpy compatible with multi-processing? If not, what can I do? <em>[Already answered in the comments]</em> </p></li>
  <li><p>Could it be the case because of the cache memory? I read on the forum about it, but to be honest, didn't really understood it. But if the problem is rooted there, I would make myself familar with this topic. </p></li>
  </ul>
  
  <h1>Time Measurement: (edit)</h1>
  
  <ul>
  <li><p>One core: time to get the data from the db: 8 sec.</p></li>
  <li><p>Two core: time to get the data from the db: 12 sec.</p></li>
  <li><p>One core: time to do the double-loop in the process_function: ~ 640 sec.</p></li>
  <li><p>Two core: time to do the double-loop in the process_function: ~ 1600 sec</p></li>
  </ul>
  
  <h1>Update: (edit)</h1>
  
  <p>When I measure the time with two processes for every 100 i's in the loop, I see that it is roughly 220% of the time I observe when I measure the same thing while running on only one process. But what is even more mysterious is that if I quit on process during the run, the other process speeds up! The other process then actually speeds up to the same level it had during the solo run. So, there must be some dependencies between the processes I just don't see at the moment :S</p>
  
  <h1>Update-2: (edit)</h1>
  
  <p>So, I did a few more test runs and measurements. In the test runs, I used as compute-instances either a <strong>one-core linux machine</strong> (n1-standard-1, 1 vCPU, 3.75 GB memory) or a <strong>two-core linux machine</strong> (n1-standard-2, 2 vCPUs, 7.5 GB memory) from Google cloud compute engine. However, I did also tests on my local computer and observed roughly the same results. (-> therefore, the virtualized environment should be fine). Here are the results:</p>
  
  <p>P.S: The time here differs from the measurements above, because I limited the loop a little bit and did the testing on Google Cloud instead of on my home pc.</p>
  
  <blockquote>
    <p><strong>1-core machine, started 1 process:</strong></p>
    
    <p>time: 225sec , CPU utilization: ~100%</p>
    
    <p><strong>1-core machine, started 2 process:</strong> </p>
    
    <p>time: 557sec , CPU utilization: ~100%</p>
    
    <p><strong>1-core machine, started 1 process, limited max. CPU-utilization to 50%:</strong></p>
    
    <p>time: 488sec , CPU utilization: ~50%</p>
  </blockquote>
  
  <p>.</p>
  
  <blockquote>
    <p><strong>2-core machine, started 2 process:</strong></p>
    
    <p>time: 665sec , CPU-1 utilization: ~100% , CPU-2 utilization: ~100%  </p>
    
    <p>the process did not jumped between the cores, each used 1 core</p>
    
    <p>(at least htop displayed these results with the “Process” column)</p>
    
    <p><strong>2-core machine, started 1 process:</strong></p>
    
    <p>time: 222sec , CPU-1 utilization: ~100% (0%) , CPU-2 utilization: ~0%  (100%)</p>
    
    <p>however, the process jumped sometimes  between the cores</p>
    
    <p><strong>2-core machine, started 1 process, limited max. CPU-utilization to 50%:</strong></p>
    
    <p>time: 493sec , CPU-1 utilization: ~50% (0%) , CPU-2 utilization: ~0% (100%)</p>
    
    <p>however, the process jumped extremely often between the cores </p>
  </blockquote>
  
  <p>I used "htop" and the python module "time" to obtain these results.</p>
  
  <h1>Update - 3: (edit)</h1>
  
  <p>I used cProfile for profiling my code:</p>
  
  <pre><code>python -m cProfile -s cumtime fun_name.py
  </code></pre>
  
  <p>The files are too long to post here, but I believe if they contain valuable information at all, this information is probably the one on top of the outcome-text. Therefore, I will post the first lines of the results here:</p>
  
  <p><strong>1-core machine, started 1 process:</strong></p>
  
  <pre><code>623158 function calls (622735 primitive calls) in 229.286 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall   filename:lineno(function)
          1    0.371    0.371  229.287  229.287   20_with_multiprocessing.py:1(&lt;module&gt;)
          3    0.000    0.000  225.082   75.027   threading.py:309(wait)
          1    0.000    0.000  225.082  225.082   _base.py:378(result)
         25  225.082    9.003  225.082    9.003   {method 'acquire' of 'thread.lock' objects}
          1    0.598    0.598    3.081    3.081   get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.877    0.959   cursors.py:164(execute)
          3    0.000    0.000    2.877    0.959   cursors.py:353(_query)
          3    0.000    0.000    1.958    0.653   cursors.py:315(_do_query)
          3    0.000    0.000    1.943    0.648   cursors.py:142(_do_get_result)
          3    0.000    0.000    1.943    0.648   cursors.py:351(_get_result)
          3    1.943    0.648    1.943    0.648   {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    0.919    0.306   cursors.py:358(_post_get_result)
          3    0.000    0.000    0.917    0.306   cursors.py:324(_fetch_row)
          3    0.917    0.306    0.917    0.306   {built-in method fetch_row}
     591314    0.161    0.000    0.161    0.000   {range}
  </code></pre>
  
  <p><strong>1-core machine, started 2 process:</strong></p>
  
  <pre><code>626052 function calls (625616 primitive calls) in 578.086 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall   filename:lineno(function)
          1    0.310    0.310  578.087  578.087   20_with_multiprocessing.py:1(&lt;module&gt;)
         30  574.310   19.144  574.310   19.144   {method 'acquire' of 'thread.lock' objects}
          2    0.000    0.000  574.310  287.155   _base.py:378(result)
          3    0.000    0.000  574.310  191.437   threading.py:309(wait)
          1    0.544    0.544    2.854    2.854   get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.563    0.854   cursors.py:164(execute)
          3    0.000    0.000    2.563    0.854   cursors.py:353(_query)
          3    0.000    0.000    1.715    0.572   cursors.py:315(_do_query)
          3    0.000    0.000    1.701    0.567   cursors.py:142(_do_get_result)
          3    0.000    0.000    1.701    0.567   cursors.py:351(_get_result)
          3    1.701    0.567    1.701    0.567   {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    0.848    0.283   cursors.py:358(_post_get_result)
          3    0.000    0.000    0.847    0.282   cursors.py:324(_fetch_row)
          3    0.847    0.282    0.847    0.282   {built-in method fetch_row}
     591343    0.152    0.000    0.152    0.000   {range}
  </code></pre>
  
  <p>.</p>
  
  <p><strong>2-core machine, started 1 process:</strong></p>
  
  <pre><code>623164 function calls (622741 primitive calls) in 235.954 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall   filename:lineno(function)
          1    0.246    0.246  235.955  235.955   20_with_multiprocessing.py:1(&lt;module&gt;)
          3    0.000    0.000  232.003   77.334   threading.py:309(wait)
         25  232.003    9.280  232.003    9.280   {method 'acquire' of 'thread.lock' objects}
          1    0.000    0.000  232.003  232.003   _base.py:378(result)
          1    0.593    0.593    3.104    3.104   get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.774    0.925   cursors.py:164(execute)
          3    0.000    0.000    2.774    0.925   cursors.py:353(_query)
          3    0.000    0.000    1.981    0.660   cursors.py:315(_do_query)
          3    0.000    0.000    1.970    0.657   cursors.py:142(_do_get_result)
          3    0.000    0.000    1.969    0.656   cursors.py:351(_get_result)
          3    1.969    0.656    1.969    0.656   {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    0.794    0.265 cursors.py:358(_post_get_result)  
          3    0.000    0.000    0.792    0.264   cursors.py:324(_fetch_row)
          3    0.792    0.264    0.792    0.264   {built-in method fetch_row}
     591314    0.144    0.000    0.144    0.000   {range}
  </code></pre>
  
  <p><strong>2-core machine, started 2 process:</strong></p>
  
  <pre><code>626072 function calls (625636 primitive calls) in 682.460 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall   filename:lineno(function)
          1    0.334    0.334  682.461  682.461   20_with_multiprocessing.py:1(&lt;module&gt;)
          4    0.000    0.000  678.231  169.558   threading.py:309(wait)
         33  678.230   20.552  678.230   20.552   {method 'acquire' of 'thread.lock' objects}
          2    0.000    0.000  678.230  339.115   _base.py:378(result)
          1    0.527    0.527    2.974    2.974   get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.723    0.908   cursors.py:164(execute)
          3    0.000    0.000    2.723    0.908   cursors.py:353(_query)
          3    0.000    0.000    1.749    0.583   cursors.py:315(_do_query)
          3    0.000    0.000    1.736    0.579   cursors.py:142(_do_get_result)
          3    0.000    0.000    1.736    0.579   cursors.py:351(_get_result)
          3    1.736    0.579    1.736    0.579   {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    0.975    0.325   cursors.py:358(_post_get_result)
          3    0.000    0.000    0.973    0.324   cursors.py:324(_fetch_row)
          3    0.973    0.324    0.973    0.324   {built-in method fetch_row}
          5    0.093    0.019    0.304    0.061   __init__.py:1(&lt;module&gt;)
          1    0.017    0.017    0.275    0.275   __init__.py:106(&lt;module&gt;)
          1    0.005    0.005    0.198    0.198   add_newdocs.py:10(&lt;module&gt;)
     591343    0.148    0.000    0.148    0.000   {range}
  </code></pre>
  
  <p>I, personally, don't really know what to do with these results. Would be glad to receive tips, hints or any other help - thanks :)</p>
  
  <h1>Reply to Answer-1: (edit)</h1>
  
  <p>Roland Smith looked at the data and suggest, that multiprocessing might hurt the performance more than it does help. Therefore, I did one more measurement without multiprocessing (like the code he suggested):</p>
  
  <p>Am I right in the conclusion, that this is not the case? Because the measured times appear to be similar to the times measured before with multiprocessing?</p>
  
  <p><strong>1-core machine:</strong></p>
  
  <blockquote>
    <p>Database access took 2.53 seconds</p>
    
    <p>Matrix manipulation took 236.71 seconds</p>
  </blockquote>
  
  <pre><code>1842384 function calls (1841974 primitive calls) in 241.114 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall   filename:lineno(function)
          1  219.036  219.036  241.115  241.115   20_with_multiprocessing.py:1(&lt;module&gt;)
     406000    0.873    0.000   18.097    0.000   {method 'sum' of 'numpy.ndarray' objects}
     406000    0.502    0.000   17.224    0.000   _methods.py:31(_sum)
     406001   16.722    0.000   16.722    0.000   {method 'reduce' of 'numpy.ufunc' objects}
          1    0.587    0.587    3.222    3.222   get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.964    0.988   cursors.py:164(execute)
          3    0.000    0.000    2.964    0.988   cursors.py:353(_query)
          3    0.000    0.000    1.958    0.653   cursors.py:315(_do_query)
          3    0.000    0.000    1.944    0.648   cursors.py:142(_do_get_result)
          3    0.000    0.000    1.944    0.648   cursors.py:351(_get_result)
          3    1.944    0.648    1.944    0.648   {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    1.006    0.335   cursors.py:358(_post_get_result)
          3    0.000    0.000    1.005    0.335   cursors.py:324(_fetch_row)
          3    1.005    0.335    1.005    0.335   {built-in method fetch_row}
     591285    0.158    0.000    0.158    0.000   {range}
  </code></pre>
  
  <p><strong>2-core machine:</strong></p>
  
  <blockquote>
    <p>Database access took 2.32 seconds</p>
    
    <p>Matrix manipulation took 242.45 seconds</p>
  </blockquote>
  
  <pre><code>1842390 function calls (1841980 primitive calls) in 246.535 seconds
  
     Ordered by: cumulative time
  
     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
          1  224.705  224.705  246.536  246.536 20_with_multiprocessing.py:1(&lt;module&gt;)
     406000    0.911    0.000   17.971    0.000 {method 'sum' of 'numpy.ndarray' objects}
     406000    0.526    0.000   17.060    0.000 _methods.py:31(_sum)
     406001   16.534    0.000   16.534    0.000 {method 'reduce' of 'numpy.ufunc' objects}
          1    0.617    0.617    3.113    3.113 get_BP_Verteilung_Vektoren.py:1(get_BP_Verteilung_Vektoren)
          3    0.000    0.000    2.789    0.930 cursors.py:164(execute)
          3    0.000    0.000    2.789    0.930 cursors.py:353(_query)
          3    0.000    0.000    1.938    0.646 cursors.py:315(_do_query)
          3    0.000    0.000    1.920    0.640 cursors.py:142(_do_get_result)
          3    0.000    0.000    1.920    0.640 cursors.py:351(_get_result)
          3    1.920    0.640    1.920    0.640 {method 'store_result' of '_mysql.connection' objects}
          3    0.001    0.000    0.851    0.284 cursors.py:358(_post_get_result)
          3    0.000    0.000    0.849    0.283 cursors.py:324(_fetch_row)
          3    0.849    0.283    0.849    0.283 {built-in method fetch_row}
     591285    0.160    0.000    0.160    0.000 {range}
  </code></pre>