locking_experiment.py

# Try to copy "a" value to "c" while simultaneously adding vector of 1's to a.
# If the copy is started before the first assign_add, the copied value will be inconsistent.
#
# Running it on macbook my "c" ends up with a mix of values between 1 and 6
#
#
# 16.017478 copy 1 (0) starting
# 17.006894 write 1 (0) starting
# 28.431654 write 1 ending (11.4247 sec)
# 29.436692 write 1 (1) starting
# 39.684998 write 1 ending (10.2483 sec)
# 40.689955 write 1 (2) starting
# 52.772026 write 1 ending (12.0821 sec)
# 53.775126 write 1 (3) starting
# 64.904223 write 1 ending (11.1291 sec)
# 65.906340 write 1 (4) starting
# 76.779444 write 1 ending (10.8731 sec)
# 76.846212 copy 1 ending (60.8287 sec) 1.00 6.00

import os
os.environ["CUDA_VISIBLE_DEVICES"]=""

import tensorflow as tf
import numpy as np
import threading
import time

use_locking = True

n = 1000*10**6
dtype = tf.float64
a = tf.Variable(tf.ones(shape=(n,), dtype=dtype))
b = tf.Variable(tf.ones(shape=(n,), dtype=dtype))
c = tf.Variable(tf.ones(shape=(n,), dtype=dtype))
sess = tf.Session()
a_add_b = a.assign_add(b, use_locking=use_locking)
a_copy_c = c.assign(a, use_locking=use_locking)
#a_op = a[0]
a_op = a[-1]-a[0]
c_probes = (c[1], c[-1])
num_iters = 100

def increment_body(name):
  elapsed = 1
  for i in range(num_iters):
    time.sleep(1.)
    start = time.time()
    print("%10.6f write %s (%d) starting" %(time.time()-starting_time, name, i))
    sess.run(a_add_b.op)
    elapsed = time.time()-start
    print("%10.6f write %s ending (%.4f sec)" %(time.time()-starting_time, name, elapsed))

def read_body(name):
  elapsed = 1
  for i in range(1000):
    time.sleep(0.01)
    start = time.time()
    print("%10.6f read %s (%d) starting"%(time.time()-starting_time, name, i))
    val = sess.run(a_op)
    elapsed = time.time()-start
    print("%10.6f read %s ending with %.2f (%.4f sec)"%(time.time()-starting_time, name, val, elapsed))

def copy_body(name):
  elapsed = 1
  for i in range(num_iters):
    time.sleep(0.01)
    start = time.time()
    print("%10.6f copy %s (%d) starting"%(time.time()-starting_time, name, i))
    val = sess.run(a_copy_c.op)
    val1, val2 = sess.run(c_probes)
    elapsed = time.time()-start
    print("%10.6f copy %s ending (%.4f sec) %.2f %.2f"%(time.time()-starting_time, name, elapsed, val1, val2))
  minval = sess.run(tf.reduce_max(c))
  maxval = sess.run(tf.reduce_max(c))
  print("%10.6f copy %s (%d) ended (%.4f sec), min %.2f, max %.2f"%(time.time()-starting_time, name, i, elapsed, minval, maxval))

    
starting_time = time.time()
increment_thread1 = threading.Thread(target=increment_body, args=("1"))
read_thread1 = threading.Thread(target=copy_body, args=("1"))
#read_thread1 = threading.Thread(target=read_body, args=("1"))

sess.run(tf.initialize_all_variables())
increment_thread1.start()
read_thread1.start()

for t in [increment_thread1, read_thread1]:
  t.join()