Unit test on shared memory fails nondeterministically

[BarclayII]

🐛 Bug

test_shared_mem_store may occasionally fail on CI:

test_shared_mem_store.test_init ... /var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: Initializer is not set. Use zero initializer instead. To suppress this warning, use `set_initializer` to explicitly specify which initializer to use.
  warnings.warn(msg, warn_type)
/var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: It may not be safe to access node data of all nodes.It's recommended to node data of a subset of nodes directly.
  warnings.warn(msg, warn_type)
/var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: It may not be safe to access edge data of all edges.It's recommended to edge data of a subset of edges directly.
  warnings.warn(msg, warn_type)
[06:09:05] /var/jenkins_home/workspace/DGL_PR-752@2/src/runtime/shared_mem.cc:32: remove /test_graph1_node_feat for shared memory
[06:09:05] /var/jenkins_home/workspace/DGL_PR-752@2/src/runtime/shared_mem.cc:32: remove /test_graph1_node_test4 for shared memory
[06:09:05] /var/jenkins_home/workspace/DGL_PR-752@2/src/runtime/shared_mem.cc:32: remove /test_graph1_in for shared memory
[06:09:05] /var/jenkins_home/workspace/DGL_PR-752@2/src/runtime/shared_mem.cc:32: remove /test_graph1_edge_feat for shared memory
[06:09:05] /var/jenkins_home/workspace/DGL_PR-752@2/src/runtime/shared_mem.cc:32: remove /test_graph1_edge_test4 for shared memory
/var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: Initializer is not set. Use zero initializer instead. To suppress this warning, use `set_initializer` to explicitly specify which initializer to use.
  warnings.warn(msg, warn_type)
/var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: It may not be safe to access node data of all nodes.It's recommended to node data of a subset of nodes directly.
  warnings.warn(msg, warn_type)
/var/jenkins_home/workspace/DGL_PR-752@2/python/dgl/base.py:18: UserWarning: It may not be safe to access edge data of all edges.It's recommended to edge data of a subset of edges directly.
  warnings.warn(msg, warn_type)

Arrays are not almost equal to 7 decimals

(mismatch 100.0%)
 x: array([20., 20., 20., 20., 20., 20., 20., 20., 20., 20.], dtype=float32)
 y: array(11)
Traceback (most recent call last):
  File "/var/jenkins_home/workspace/DGL_PR-752@2/tests/distributed/test_shared_mem_store.py", line 65, in check_init_func
    check_array_shared_memory(g, worker_id, [g.nodes[:].data['test4'], g.edges[:].data['test4']])
  File "/var/jenkins_home/workspace/DGL_PR-752@2/tests/distributed/test_shared_mem_store.py", line 28, in check_array_shared_memory
    assert_almost_equal(F.asnumpy(arr[0]), i + 10)
  File "/usr/local/lib/python3.5/dist-packages/numpy/testing/nose_tools/utils.py", line 567, in assert_almost_equal
    return assert_array_almost_equal(actual, desired, decimal, err_msg)
  File "/usr/local/lib/python3.5/dist-packages/numpy/testing/nose_tools/utils.py", line 965, in assert_array_almost_equal
    precision=decimal)
  File "/usr/local/lib/python3.5/dist-packages/numpy/testing/nose_tools/utils.py", line 781, in assert_array_compare
    raise AssertionError(msg)
AssertionError: 
Arrays are not almost equal to 7 decimals

(mismatch 100.0%)
 x: array([20., 20., 20., 20., 20., 20., 20., 20., 20., 20.], dtype=float32)
 y: array(11)
FAIL

Also confirmed by @yzh119

[jermainewang]

@aksnzhy would you please have a look?

[aksnzhy]

Sure, I will check this error.

[jermainewang]

@aksnzhy any progress? We might need to temporarily disable the test case since it's too much a nuisance.

[aksnzhy]

@jermainewang It's very strange that I cannot reproduce this bug on my dev-machine. @zheng-da Could you give some advice? I'm not very familiar with the graph_store code.

[jermainewang]

Try directly use the docker image. It should reliably reproduce the problem.

[classicsong]

Just go through the tests/distributed/test_shared_mem_store.py. In the buggy test_init():

dgl/tests/distributed/test_shared_mem_store.py

Lines 105 to 116 in c4989b4

	def test_init():
	manager = Manager()
	return_dict = manager.dict()
	serv_p = Process(target=server_func, args=(2, 'test_graph1'))
	work_p1 = Process(target=check_init_func, args=(0, 'test_graph1', return_dict))
	work_p2 = Process(target=check_init_func, args=(1, 'test_graph1', return_dict))
	serv_p.start()
	work_p1.start()
	work_p2.start()
	serv_p.join()
	work_p1.join()
	work_p2.join()

The execution order of work_p1 and work_p2 is undetermined even in a single core machine. Before

dgl/tests/distributed/test_shared_mem_store.py

Lines 68 to 70 in c4989b4

	g.init_ndata('test4', (g.number_of_nodes(), 10), 'float32')
	g.init_edata('test4', (g.number_of_edges(), 10), 'float32')
	g._sync_barrier(60)

the workers are synced at g._sync_barrier(60). But the latter execution are not synced. It is possible that:

dgl/tests/distributed/test_shared_mem_store.py

Lines 31 to 34 in c4989b4

	else:
	g._sync_barrier(60)
	for i, arr in enumerate(arrays):
	assert_almost_equal(F.asnumpy(arr[0]), i + 10)

execute latter than

dgl/tests/distributed/test_shared_mem_store.py

Lines 77 to 79 in c4989b4

	data = g.edges[:].data['test4']
	g.set_e_repr({'test4': F.ones((1, 10)) * 20}, edges=[0])
	assert_almost_equal(F.asnumpy(data[0]), np.squeeze(F.asnumpy(g.edges[0].data['test4'])))

which may cause the problem.

To reproduce the bug deterministically, add time.sleep(3) to L27 as follows:

def check_array_shared_memory(g, worker_id, arrays):
    if worker_id == 0:
        for i, arr in enumerate(arrays):
            arr[0] = i + 10
        g._sync_barrier(60)
    else:
        g._sync_barrier(60)
        time.sleep(3)
        for i, arr in enumerate(arrays):
            assert_almost_equal(F.asnumpy(arr[0]), i + 10)

@zheng-da @jermainewang