How does the GIL affect my python program when threads are used

This is in relation to the previous post: "What does the GIL lock means when I use threads in Python" .

I have been reading more about the GIL problem in Python and found out that this limitation only exists for CPython. It is not present in the Java base implementation of the python interpreter [1].

Still not convinced how much it affects the execution time I run couple of tests.

A test program

Cloud server provisioning

I have provisioned a 32GB cloud server for the tests. These are some of the server details.

$ cat /proc/cpuinfo  | egrep 'proc|model name' | sort | uniq 
model name : Quad-Core AMD Opteron(tm) Processor 2374 HE
processor : 0
...
processor : 7

$ free -m
            total       used       free     shared    buffers     cached
Mem:         30041       8364      21676          0         34        580
-/+ buffers/cache:       7749      22291
Swap:        61436          0      61436

$ python -V
Python 2.7.3

$ jython -V
Jython 2.5.1+

$ ls -al /etc/alternatives/java
lrwxrwxrwx 1 root root 46 Jul 31 19:36 /etc/alternatives/java -> /usr/lib/jvm/java-6-openjdk-amd64/jre/bin/java

$ /usr/bin/java -version
java version "1.6.0_24"
OpenJDK Runtime Environment (IcedTea6 1.11.3) (6b24-1.11.3-1ubuntu0.12.04.1)
OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

Test results

I run 4 tests. Two with the python and two with the jython interpreter. To start the tests i used:

$ /usr/bin/time -v jython gil_threads_test.py | tee log 
$ /usr/bin/time -v python gil_threads_test.py | tee log

The results for the python after filtering out the unnecessary lines ( results | grep -v ': 0' )

Test1 
  Command being timed: "python gil_threads_test.py"
  User time (seconds): 759.93
  System time (seconds): 516.46
  Percent of CPU this job got: 170%
  Elapsed (wall clock) time (h:mm:ss or m:ss): 12:27.25
  Maximum resident set size (kbytes): 76240000
  Minor (reclaiming a frame) page faults: 5806046
  Voluntary context switches: 44574718 
  Involuntary context switches: 3311991
 
Test2
  Command being timed: "python gil_threads_test.py"
  User time (seconds): 760.37
  System time (seconds): 515.21
  Percent of CPU this job got: 170%
  Elapsed (wall clock) time (h:mm:ss or m:ss): 12:30.16
  Maximum resident set size (kbytes): 76066992
  Minor (reclaiming a frame) page faults: 5817319
  Voluntary context switches: 44574153
  Involuntary context switches: 3318754
  Page size (bytes): 4096

The results for the jython after filtering out the unnecessary lines ( results | grep -v ': 0' )

Test3
  Command being timed: "jython gil_threads_test.py"
  User time (seconds): 955.74
  System time (seconds): 16.31
  Percent of CPU this job got: 397%
  Elapsed (wall clock) time (h:mm:ss or m:ss): 4:04.75
  Maximum resident set size (kbytes): 30018032
  Minor (reclaiming a frame) page faults: 2034262
  Voluntary context switches: 83887
  Involuntary context switches: 110640
  File system outputs: 328
  Page size (bytes): 4096
  
Test4
  Command being timed: "jython gil_threads_test.py"
  User time (seconds): 984.16
  System time (seconds): 16.22
  Percent of CPU this job got: 385%
  Elapsed (wall clock) time (h:mm:ss or m:ss): 4:19.69
  Maximum resident set size (kbytes): 30718496
  Minor (reclaiming a frame) page faults: 2070011
  Voluntary context switches: 97457
  Involuntary context switches: 109420
  File system outputs: 344
  Page size (bytes): 4096

Analisis and results description

• The execution of the test{1,2} was a lot longer than for test{3,4}. The CPython interpreter needed 12:27.25/12:30.16 versus 4:04.75/4:19.69 for the Jython.

• The gil_threads_test.py script CPU utilization in user space is about 20% higher for Jython and there is a big difference how much time the interpreters spent in kernel mode.
  
  Looking at the output from top during the tests we saw that java was able to use 100% all 7 CPUs where python managed only to use have utilization of 13-20%.
  
  The increaded number of context swithces for python has a direct impact on performance what the execution time results show clearly.

• One interesting thing. The memory usage is about 100% higher when python is used. Looks like java is able to better manged the memory allocation and memory management. But I'm not sure as well as how much we can trust the output from the utime -v command for this.

References

1. http://www.jython.org/jythonbook/en/1.0/Concurrency.html