Repository navigation
Issues with RoCE support #9926
Description
Activity
@ChenChuang , can you be more specific which function were you referring to? I do not see RecvLocalAsync is defined in rdma_rendezvous_mgr.cc.
The error handling part of contrib/verbs is weak, partially because I do not know what to do when verbs fails, except restarting the whole process. Your suggestions, comments and contributions (pull-request) are welcome.
I feel I'm facing similar situation. When trying to run two-node set up, I see following errors.
On first (chief) worker:
... 2017-05-17 22:43:09.680866: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:1 2017-05-17 22:43:30.237809: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:30.237851: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:1 2017-05-17 22:43:30.239249: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:0 2017-05-17 22:43:30.239955: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:31.592456: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected ... 2017-05-17 22:44:30.982164: F tensorflow/contrib/verbs/rdma.cc:679] Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:0/cpu:0;5e9e196185e311cc;/job:ps/replica:0/task:0/cpu:0;edge_15063_Mul_145;0:0;141115178875244276 error message: Step 141115178875244276On first parameter server:
2017-05-17 22:42:51.775275: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:0 2017-05-17 22:43:13.055682: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:1 2017-05-17 22:43:30.239808: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:35.198098: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:35.198150: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:1 2017-05-17 22:43:35.198926: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:44:29.948398: F tensorflow/contrib/verbs/rdma.cc:130] Check failed: wc_[i].status == IBV_WC_SUCCESS Failed status transport retry counter exceeded 12 738900624 129On second worker:
... 2017-05-17 22:43:29.731111: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:0 2017-05-17 22:43:29.733157: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:1 2017-05-17 22:43:29.734459: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:0 2017-05-17 22:43:30.234363: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:31.588210: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:35.194635: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected ... 2017-05-17 22:44:30.979018: F tensorflow/contrib/verbs/rdma.cc:679] Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:1/cpu:0;47caf76f804b2108;/job:ps/replica:0/task:1/cpu:0;edge_16166_Mul_85;0:0;117997835881656439 error message: Step 117997835881656439On second parameter server:
2017-05-17 22:43:26.510171: I tensorflow/core/distributed_runtime/rpc/grpc_server_lib.cc:331] Started server with target: grpc://localhost:31254 2017-05-17 22:43:26.510230: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:1 2017-05-17 22:43:31.588367: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:31.588410: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:worker/replica:0/task:0 2017-05-17 22:43:31.589394: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:43:31.589446: I tensorflow/contrib/verbs/rdma_mgr.cc:56] connecting to remote node /job:ps/replica:0/task:0 2017-05-17 22:43:35.195517: I tensorflow/contrib/verbs/rdma.cc:519] channel already connected 2017-05-17 22:44:29.981975: F tensorflow/contrib/verbs/rdma.cc:679] Check failed: status.ok() RecvLocalAsync was not ok, key/job:ps/replica:0/task:1/cpu:0;e73d8038df027221;/job:worker/replica:0/task:0/gpu:0;edge_17945_group_deps_2/NoOp_1;0:0;141115178875244276 error message: Dequeue operation was cancelled [[Node: fifo_queue_DequeueMany = QueueDequeueManyV2[component_types=[DT_BOOL], timeout_ms=-1, _device="/job:ps/replica:0/task:1/cpu:0"](fifo_queue, fifo_queue_DequeueMany/n)]]ibv_devinfoon first machine:hca_id: mlx5_1 transport: InfiniBand (0) fw_ver: 14.14.2320 node_guid: 248a:0703:004c:2719 sys_image_guid: 248a:0703:004c:2718 vendor_id: 0x02c9 vendor_part_id: 4117 hw_ver: 0x0 board_id: DEL2420110034 phys_port_cnt: 1 Device ports: port: 1 state: PORT_DOWN (1) max_mtu: 4096 (5) active_mtu: 1024 (3) sm_lid: 0 port_lid: 0 port_lmc: 0x00 link_layer: Ethernet hca_id: mlx5_0 transport: InfiniBand (0) fw_ver: 14.14.2320 node_guid: 248a:0703:004c:2718 sys_image_guid: 248a:0703:004c:2718 vendor_id: 0x02c9 vendor_part_id: 4117 hw_ver: 0x0 board_id: DEL2420110034 phys_port_cnt: 1 Device ports: port: 1 state: PORT_ACTIVE (4) max_mtu: 4096 (5) active_mtu: 1024 (3) sm_lid: 0 port_lid: 0 port_lmc: 0x00 link_layer: Ethernetibv_devinfoon second machine:hca_id: mlx5_1 transport: InfiniBand (0) fw_ver: 14.14.2320 node_guid: 248a:0703:004c:25f9 sys_image_guid: 248a:0703:004c:25f8 vendor_id: 0x02c9 vendor_part_id: 4117 hw_ver: 0x0 board_id: DEL2420110034 phys_port_cnt: 1 Device ports: port: 1 state: PORT_DOWN (1) max_mtu: 4096 (5) active_mtu: 1024 (3) sm_lid: 0 port_lid: 0 port_lmc: 0x00 link_layer: Ethernet hca_id: mlx5_0 transport: InfiniBand (0) fw_ver: 14.14.2320 node_guid: 248a:0703:004c:25f8 sys_image_guid: 248a:0703:004c:25f8 vendor_id: 0x02c9 vendor_part_id: 4117 hw_ver: 0x0 board_id: DEL2420110034 phys_port_cnt: 1 Device ports: port: 1 state: PORT_ACTIVE (4) max_mtu: 4096 (5) active_mtu: 1024 (3) sm_lid: 0 port_lid: 0 port_lmc: 0x00 link_layer: EthernetAs you may notice, first port in the list is DOWN. To work around that, I made modification suggested by @bkovalev in the
verbsto open device like this:ibv_context* open_default_device() { ibv_device** dev_list; ibv_device* ib_dev; int num_devices; dev_list = ibv_get_device_list(&num_devices); CHECK(dev_list) << "No InfiniBand device found"; ib_dev = dev_list[num_devices - 1]; /// THIS IS MODIFICATION CHECK(ib_dev) << "No InfiniBand device found"; ibv_context* context = ibv_open_device(ib_dev); CHECK(context) << "Open context failed for " << ibv_get_device_name(ib_dev); return context; }Any suggestions?
@alsrgv The error mostly likely is due to rdma connection failures.I don't have any experience in multiple IB devices in a single box. But from your ib_devinfo log, it seems the first device "mlx5_0" was active and the second device "mlx5_1" was down. @bkovalev had a similar issue here: YahooArchive#5. Maybe he can clarify this.
@bkovalev when I execute
mst start
Starting MST (Mellanox Software Tools) driver set
Loading MST PCI module - Success
Loading MST PCI configuration module - Success
Create devices
Unloading MST PCI module (unused) - Success
mst status
MST modules:MST PCI module is not loaded MST PCI configuration module loadedMST devices:
/dev/mst/mt4115_pciconf0 - PCI configuration cycles access.
domain:bus:dev.fn=0000:84:00.0 addr.reg=88 data.reg=92
Chip revision is: 00
echo 0000:05:00.0 > /sys/bus/pci/drivers/mlx5_core/unbind
I got the following error
bash: echo: write error: No such deviceI am referring to
RdmaTensorBuffer::SendNextItem()，wherecbinchannel_->adapter_->worker_env_>rendezvous_mgr->RecvLocalAsync(step_id, parsed, cb)will get status ofRecvLocalAsync，ifRecvLocalAsyncfailed, I think the receiver is expecting to be notified ? @junshi15Similar situation occurs with the following message:
2017-06-16 20:24:35.483589: F tensorflow/contrib/verbs/rdma.cc:678] Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:0/gpu:0;27319926cf0b2d4c;/job:ps/replica:0/task:0/cpu:0;edge_103_report_uninitialized_variables/boolean_mask/Squeeze;0:0;97320812532467277 error message: Step 97320812532467277We are training a VGG16 net using Google's official benchmark script.
Moreover, different nodes fail for different Ops and/or different devices (CPU/GPU).
Node 1:
Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:0/cpu:0;64747ef5beaa3090;/job:ps/replica:0/task:1/cpu:0;edge_177_v/tower_0/gradients/AddN_4;0:0;94094948734439551 error message: Step 94094948734439551Node 2:
Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:1/cpu:0;9c15404106788d80;/job:ps/replica:0/task:2/cpu:0;edge_126_v/tower_0/gradients/AddN;0:0;79207857884824133 error message: Step 79207857884824133Node 3:
Check failed: status.ok() RecvLocalAsync was not ok, key/job:worker/replica:0/task:2/cpu:0;058e67ed7fd0680e;/job:ps/replica:0/task:0/cpu:0;edge_207_group_deps_3/NoOp_1;0:0;79431287967600536 error message: Step 79431287967600536The same problem goes away changing server protocol back to
grpc.This has not been our case. We are using only 1 rNIC with two ports, and two ports connect to two different switches in parallel. So both ports are UP.
13 remaining items
Thanks @byronyi , please ignore the log.
The GlobalStepWatcher fooled me (https://github.com/tensorflow/benchmarks/blob/master/scripts/tf_cnn_benchmarks/tf_cnn_benchmarks.py#L229) by reading the global_step 4 times a second (while the training step was stuck).
I removed it and now I have a cleaner log where things are actually stuck without traffic at all (:
This bug is driving me crazy, a lot because it only happens when working with "real" data (ImageNet).
Can happen after 90 steps or after 1.
I'm starting to think maybe we should use UCX instead of native verbs implementation, since it abstract much of the low level verbs issues and implements already Rendezvous, etc..@AEGQ, no problem. I think we will go for the environment variables.
Anyway I must find the bug before.That patch is an effort we've been working on for over a year, and it's been tested on our RoCE environment extensively. Moreover, the whole design is considered carefully to integrate well with existing TF bits (and even the un-open sourced part; see here), with a memory allocator that re-use pre-pinned tensor buffer. Since the buffers are pre-pinned, we only need a single READ to retrieve the tensor buffer from remote, and this greatly simplifies my design (no need for a state machine; just read and then invalidate).
@shamoya , I am wondering if your hang is caused by a corrupted message due to a multi-thread race condition. Let's say an Ack is corrupted, hence not parsed properly, then the remote buffer is not released. as a result, no more message can be sent. I describe the messaging system in detail here in case you did not know already.
If you see multiple lines like
remote_status_ is not idle, there is a good chance the messaging system is screwed up.Hi @junshi15
This is not the case I'm seeing in my case.
I get ACKs to all REQUEST/RESPONSES, and everything looks good from the verbs protocol side.
I even checked hash collision in the buffer table - and it's not it as well.After serious debug, it looks like something wrong with the step_id handling.
I'm not sure it's related to the verbs code directly, but something in Distributed TF, with the timing happens only with: RDMA && large number of GPUS && loading ImageNet from storage.@shamoya I have tried with the latest (1.4-dev0) and the same issue, i.e. edge_4_global_step being repeatedly requested, showed up even without any verbs nor GDR code (i.e. the default build options with gRPC). I suspect it is a bug in gRPC runtime side (perhaps not being able to handle higher request rates with the latest upgrade), and I am filing a bug report regarding to this.
Hi @byronyi,
I found out that the repeated edge_4_global request is actually coming from here.
It's a python thread that reads the global counter for counting and timing process.
Once something is stuck, this thread endlessly continues to read the global counter (4 times in a second).
It didn't related to the stuck issue - once I disabled this thread we indeed saw the runtime was stuck without further log messages (the stuck bug was fixed in #12361).
Sorry for not updating this.Automatically closing due to lack of recent activity. Please update the issue when new information becomes available, and we will reopen the issue. Thanks!
When rendezvous_mgr->RecvLocalAsync fails, grpc responds with the Status, while grpc+verbs does not. Should we consider this situation ? @junshi15