libnvmf icon indicating copy to clipboard operation
libnvmf copied to clipboard
verified publisher icon bytedance

nvmf-fio can connect SPDK nvmf target, but failed to start up with libnvmf malloc error

Open gaowayne opened this issue 2 years ago • 2 comments

reproduce steps:

  1. configure rxe for rdma
rdma link add rxe_eth0 type rxe netdev eth0
  1. configure SPDK nvmf target
run build/bin/nvmf_tgt under spdk
root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py bdev_null_create null0 4096 4096
null0
root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_create_transport -t RDMA -u 8192 -i 131072 -c 8192
root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_create_subsystem nqn.2022-06.io.spdk:cnode1 -a -s SPDK00000000000001 -d SPDK_Controller1
root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_subsystem_add_ns nqn.2022-06.io.spdk:cnode1 null0
#root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_sussystem_add_listener nqn.2022-06.io.spdk:cnode1 -t rdma -a 192.168.1.10 -s 4420
root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_subsystem_add_listener nqn.2022-06.io.spdk:cnode1 -t rdma -a 192.168.1.10 -s 4420

root@wayne-VirtualBox:~/wayne/spdk# scripts/rpc.py nvmf_get_subsystems
[
  {
    "nqn": "nqn.2014-08.org.nvmexpress.discovery",
    "subtype": "Discovery",
    "listen_addresses": [],
    "allow_any_host": true,
    "hosts": []
  },
  {
    "nqn": "nqn.2022-06.io.spdk:cnode1",
    "subtype": "NVMe",
    "listen_addresses": [
      {
        "transport": "RDMA",
        "trtype": "RDMA",
        "adrfam": "IPv4",
        "traddr": "192.168.1.10",
        "trsvcid": "4420"
      }
    ],
    "allow_any_host": true,
    "hosts": [],
    "serial_number": "SPDK00000000000001",
    "model_number": "SPDK_Controller1",
    "max_namespaces": 32,
    "min_cntlid": 1,
    "max_cntlid": 65519,
    "namespaces": [
      {
        "nsid": 1,
        "bdev_name": "null0",
        "name": "null0",
        "nguid": "A33CE19995A845C399EF9C266D477EBF",
        "uuid": "a33ce199-95a8-45c3-99ef-9c266d477ebf"
      }
    ]
  }
]
  1. then run nvmf-fio over spdk nvmf target, you can see the buddy create error log at last part
root@wayne-VirtualBox:~/wayne/libnvmf/examples# ./nvmf-fio --filename=nvmf-rdma://192.168.1.10:4420/nqn.2022-06.io.spdk:cnode1/1 --randwrite --iodepth=32 --ioqueues=4 --runtime=5
        nvmf-fio Sat Feb 25 16:06:53 2023[debug]nvmf_default_options 167 nvmf_parse_uri rdma 192.168.1.10 4420 nqn.2022-06.io.spdk:cnode1 1
        nvmf-fio Sat Feb 25 16:06:53 2023[trace]nvmf_queue_timer_new 126 
        nvmf-fio Sat Feb 25 16:06:53 2023[trace]nvmf_ctrl_setup 217 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_thread 518 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_setup_admin_queue 172 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_create_queue 515 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_create_queue 534 queue[0] qsize 32, pages 2
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_wait_state 495 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cma_handler 317 queue[0] handle cma event 0 (RDMA_CM_EVENT_ADDR_RESOLVED), status 0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cma_handler 317 queue[0] handle cma event 2 (RDMA_CM_EVENT_ROUTE_RESOLVED), status 0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_route_handler 257 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cma_handler 317 queue[0] handle cma event 9 (RDMA_CM_EVENT_ESTABLISHED), status 0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_buffer_setup 464 queue[0]cmd mr LKEY[1013], RKEY[1013], base 0x7f7048001af0, size 3328
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_buffer_setup 476 queue[0]data mr LKEY[118d], RKEY[118d], base 0x7f7048002830, size 8192(size 4096 * nmemb 2)
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_buffer_setup 492 queue[0]cqe mr LKEY[12e6], RKEY[12e6], base 0x7f7048010ca0, size 512
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_connect_admin_queue 76 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_host_data 802 cmd = 0x7f, length = 1024, addr = 0x7f7048002830, key = 0x118d
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x1, tag[0x0] sq_head: 1, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_connect_admin_queue_cb 29 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_connect_admin_queue_cb 38 queue[0]connect admin queue, cntlid: 1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_ctrl_enable 69 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read32 269 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_null 748 cmd = 0x7f, addr = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x10300, tag[0x0] sq_head: 2, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read32_cb 226 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_reg_read32_cb 234 reg read64 succeed, offset 0x8, res: 0x10300
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_ctrl_enable 77 read cap NVME_REG_VS: 0x10300
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read64 350 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_null 748 cmd = 0x7f, addr = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x201e01007f, tag[0x0] sq_head: 3, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read64_cb 308 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_reg_read64_cb 316 reg read64 succeed, offset 0x0, res: 0x201e01007f
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_ctrl_enable 86 read cap NVME_REG_CAP: 0x201e01007f
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[warn]nvmf_ctrl_enable 103 cap mqes 127 < opt queue entries 128, set entries to 127
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_write32 416 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_null 748 cmd = 0x7f, addr = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x0, tag[0x0] sq_head: 4, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_write32_cb 380 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_reg_write32_cb 386 reg write32 succeed
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read32 269 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_null 748 cmd = 0x7f, addr = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x1, tag[0x0] sq_head: 5, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_reg_read32_cb 226 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_reg_read32_cb 234 reg read64 succeed, offset 0x1c, res: 0x1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_ctrl_wait_ready 399 read cap NVME_REG_CSTS: 0x1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify 662 nvmf identify cns 1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_host_data 802 cmd = 0x6, length = 4096, addr = 0x7f7048002830, key = 0x118d
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x0, tag[0x0] sq_head: 6, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_identify_cb 614 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify_cb 624 cmd identify succeed
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_cmd_identify_to_ctrl 530 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_cmd_identify_to_ctrl 571 sn: SPDK00000000000001  , mn: SPDK_Controller1                        , nn: 32, mdts: 5, vwc: 5, ioccsz: 516, iorcsz: 1, icdoff: 0, maxcmd: 128, oncs: 0x29
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify 662 nvmf identify cns 2
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_host_data 802 cmd = 0x6, length = 4096, addr = 0x7f7048002830, key = 0x118d
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x0, tag[0x0] sq_head: 7, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_identify_cb 614 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify_cb 624 cmd identify succeed
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_cmd_identify_to_ctrl 530 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_cmd_identify_to_ctrl 594 ns active list: 1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_ns_find_by_id 470 find nsid 1
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify 662 nvmf identify cns 0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_host_data 802 cmd = 0x6, length = 4096, addr = 0x7f7048002830, key = 0x118d
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x0, tag[0x0] sq_head: 8, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_identify_cb 614 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_identify_cb 624 cmd identify succeed
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_cmd_identify_to_ctrl 530 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_cmd_identify_to_ctrl 544 nsid: 1, nsze: 1048576, ncap: 0x100000, lbads = 12
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_set_features 479 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_queue_request 831 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_do_req 468 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_ctrl_process_queue 912 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_queue_send 862 queue[0] sending req 0x7f7048000c80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvme_rdma_set_sg_null 748 cmd = 0x9, addr = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 144 send completion
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cm_event 363 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event 169 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_cq_event_handler 130 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_event_handler 132 queue[0] status = 0x0, opcode = 0x80
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_cq_handle_recv 93 queue[0] handle rsp, result: 0x7e007e, tag[0x0] sq_head: 9, sq_id: 0, command_id: 0x0, status: 0x0
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_set_features_cb 445 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[debug]nvmf_set_features_cb 451 set features succeed
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_free_request 719 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_timer 151 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_thread 527 
  nvmf-:cnode1-0 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_thread 518 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_event 97 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_rdma_create_queue 515 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[debug]nvmf_rdma_create_queue 534 queue[1] qsize 127, pages 127
  _

> nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[error]nvmf_rdma_create_queue 554 queue[1] buddy_create for data failed, Success
> create src ctrl failed

_
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_handle_timer 151 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_thread 527 
  nvmf-:cnode1-1 Sat Feb 25 16:06:53 2023[trace]nvmf_queue_pollfds 403

gaowayne avatar Feb 25 '23 08:02 gaowayne

TCP has been tested a lot, RDMA was tested by RXE and kernel target only. Recently I have no enough time to fix this(I hope that I can fix this in 2023 Q2), could you please use TCP? Frankly, libiscsi(iSER) also reaches the 200K+ IOPS, libnvmf(RDMA) has no obvious improvement. However, libiscsi(TCP) has only 60K IOPS, libnvmf(TCP, 4 queues) has 200K+ IOPS.

I prefer to keep this issue open until I have time to fix this ...

pizhenwei avatar Feb 25 '23 08:02 pizhenwei

TCP has been tested a lot, RDMA was tested by RXE and kernel target only. Recently I have no enough time to fix this(I hope that I can fix this in 2023 Q2), could you please use TCP? Frankly, libiscsi(iSER) also reaches the 200K+ IOPS, libnvmf(RDMA) has no obvious improvement. However, libiscsi(TCP) has only 60K IOPS, libnvmf(TCP, 4 queues) has 200K+ IOPS.

I prefer to keep this issue open until I have time to fix this ...

Thank you so much. :)

gaowayne avatar Feb 27 '23 02:02 gaowayne