00010000:00010000:3.0F:1776194618.560898:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0F:1776194619.584615:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:3.0:1776194620.516212:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194620.516276:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194620.516707:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192448
00000100:00100000:2.0:1776194620.516784:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 89
00000100:00100000:2.0:1776194620.516792:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000002976a03a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091192448:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:2.0:1776194620.516888:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000002976a03a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091192448:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 96us (687us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194620.516896:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 89
00000100:00100000:1.0F:1776194620.519534:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192512
00000100:00100000:1.0:1776194620.519627:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 57
00000100:00100000:1.0:1776194620.519635:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000a23e463d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091192512:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:1.0:1776194620.519750:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000a23e463d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091192512:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 114us (3473us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194620.519758:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 57
00010000:00010000:0.0F:1776194620.615226:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:1.0:1776194621.379183:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088885888:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194621.379259:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194621.379303:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:1.0:1776194621.379335:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3019:1862468088885824:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.379380:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194621.379416:0:3020:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000a44ef877 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-lwp-MDT0000_UUID:3020:1862468088886144:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.379417:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886080:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.379473:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194621.379516:0:3020:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194621.379533:0:127860:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088885888
00000100:00100000:1.0:1776194621.379598:0:127860:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 369
00000100:00100000:1.0:1776194621.379610:0:127860:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000cd66c0eb pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088885888:12345-0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194621.379627:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000fc9659b0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088885952:0@lo:400:kworker/u8:2.0
00002000:00000024:1.0:1776194621.379654:0:127860:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194621.379664:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194621.379713:0:3021:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [3->2]
00000100:00100000:0.0:1776194621.379723:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0001_UUID:3021:1862468088886016:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.379739:0:127860:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000cd66c0eb pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088885888:12345-0@lo:13:osp-pre-1-0.0 Request processed in 130us (481us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194621.379749:0:127860:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 369
00000100:00100000:0.0:1776194621.379769:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194621.379799:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088885824
00000100:00100000:0.0:1776194621.379836:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886144
00000100:00100000:1.0:1776194621.379845:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 90
00000100:00100000:1.0:1776194621.379851:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000009cb32bd9 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3019:x1862468088885824:12345-0@lo:400:kworker/u8:2.0
00000100:00100000:0.0:1776194621.379894:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088885952
00000100:00100000:1.0:1776194621.379895:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000009cb32bd9 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3019:x1862468088885824:12345-0@lo:400:kworker/u8:2.0 Request processed in 43us (516us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194621.379910:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 90
00000100:00100000:0.0:1776194621.379918:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886016
00000100:00100000:0.0:1776194621.379933:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 58
00000100:00100000:0.0:1776194621.379938:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000003b937609 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3020:x1862468088886144:12345-0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.379970:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886080
00000100:00100000:0.0:1776194621.379996:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000003b937609 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3020:x1862468088886144:12345-0@lo:400:kworker/u8:2.0 Request processed in 54us (481us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194621.380003:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 58
00000100:00100000:1.0:1776194621.380022:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 585
00000100:00100000:0.0:1776194621.380027:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 59
00000100:00100000:0.0:1776194621.380032:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000072acfe22 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088885952:12345-0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.380042:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000a12c277a pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886080:12345-0@lo:400:kworker/u8:2.0
00000100:00100000:0.0:1776194621.380069:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000072acfe22 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088885952:12345-0@lo:400:kworker/u8:2.0 Request processed in 35us (404us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194621.380093:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000a12c277a pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886080:12345-0@lo:400:kworker/u8:2.0 Request processed in 60us (619us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194621.380100:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 585
00000100:00100000:1.0:1776194621.380143:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886080:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.380150:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3019:1862468088885824:0@lo:400:kworker/u8:2.0
00000100:00100000:1.0:1776194621.380162:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088885888:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194621.380428:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 59
00000100:00100000:0.0:1776194621.380452:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 60
00000100:00100000:0.0:1776194621.380458:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000000616497d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0001_UUID+5:3021:x1862468088886016:12345-0@lo:400:kworker/u8:2.0
00000100:00100000:0.0:1776194621.380517:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000000616497d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0001_UUID+5:3021:x1862468088886016:12345-0@lo:400:kworker/u8:2.0 Request processed in 59us (753us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194621.380523:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 60
00000100:00100000:0.0:1776194621.380610:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0001_UUID:3021:1862468088886016:0@lo:400:kworker/u8:2.0
00000100:00100000:0.0:1776194621.380648:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000fc9659b0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088885952:0@lo:400:kworker/u8:2.0
00000100:00100000:0.0:1776194621.380881:0:3020:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000a44ef877 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-lwp-MDT0000_UUID:3020:1862468088886144:0@lo:400:kworker/u8:2.0
00010000:00010000:2.0:1776194621.632651:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194622.658516:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0:1776194623.680460:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194624.706676:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:3.0:1776194625.638387:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194625.638453:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:1.0:1776194625.638492:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192640
00000100:00100000:3.0:1776194625.638499:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192576
00000100:00100000:3.0:1776194625.638568:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 91
00000100:00100000:3.0:1776194625.638584:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000000df07c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2227:x1862468091192576:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:1.0:1776194625.638585:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 61
00000100:00100000:1.0:1776194625.638595:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000846ad533 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091192640:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:1.0:1776194625.638673:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000846ad533 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091192640:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 78us (296us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194625.638681:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 61
00000100:00100000:3.0:1776194625.640238:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000000df07c pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2227:x1862468091192576:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 1650us (1780us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194625.640254:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 91
00010000:00010000:1.0:1776194625.728589:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:1.0:1776194626.496703:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000bbbf7aab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088886336:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.496815:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194626.496880:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000028dfe281 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088886592:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.496908:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194626.496928:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:1.0:1776194626.496934:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000036983974 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886400:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.496987:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194626.497041:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886336
00000100:00100000:1.0:1776194626.497109:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886592
00000100:00100000:3.0:1776194626.497117:0:140245:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 62
00000100:00100000:3.0:1776194626.497129:0:140245:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000004bc9702 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088886336:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.497136:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 63
00000100:00100000:1.0:1776194626.497141:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000060595934 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088886592:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.497202:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000060595934 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088886592:12345-0@lo:400:kworker/u8:3.0 Request processed in 60us (294us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194626.497210:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 63
00000100:00100000:1.0:1776194626.497244:0:127858:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886400
00000100:00100000:1.0:1776194626.497271:0:127858:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 586
00000100:00100000:1.0:1776194626.497275:0:127858:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000001dfb922c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886400:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.497306:0:127858:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000001dfb922c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886400:12345-0@lo:400:kworker/u8:3.0 Request processed in 30us (320us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194626.497344:0:127858:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 586
00000100:00100000:1.0:1776194626.497391:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000036983974 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886400:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.497403:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000028dfe281 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088886592:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194626.497646:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000000361037 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088886208:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194626.497693:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194626.497720:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088886464:0@lo:13:osp-pre-1-0.0
00000100:00100000:2.0:1776194626.499562:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000fc0e5854 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-OST0000_UUID:3022:1862468088886272:0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194626.499691:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:2.0:1776194626.499736:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000eaa09dbd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-mdtlov_UUID:3022:1862468088886528:0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194626.499769:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:2.0:1776194626.499835:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886528
00000100:00100000:2.0:1776194626.499898:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 587
00000100:00100000:2.0:1776194626.499905:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000628f82d2 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3022:x1862468088886528:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194626.499969:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000628f82d2 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3022:x1862468088886528:12345-0@lo:400:kworker/u8:3.0 Request processed in 64us (200us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194626.499977:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 587
00000100:00100000:2.0:1776194626.500009:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886272
00000100:00100000:2.0:1776194626.500039:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 64
00000100:00100000:2.0:1776194626.500044:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000053a4289a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0000_UUID+5:3022:x1862468088886272:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194626.500076:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000053a4289a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0000_UUID+5:3022:x1862468088886272:12345-0@lo:400:kworker/u8:3.0 Request processed in 31us (388us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194626.500082:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 64
00000100:00100000:2.0:1776194626.500124:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000fc0e5854 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-OST0000_UUID:3022:1862468088886272:0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194626.500149:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000eaa09dbd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-mdtlov_UUID:3022:1862468088886528:0@lo:400:kworker/u8:3.0
00000100:00100000:3.0:1776194626.500366:0:140245:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000004bc9702 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088886336:12345-0@lo:400:kworker/u8:3.0 Request processed in 3236us (3550us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194626.500376:0:140245:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 62
00000100:00100000:0.0:1776194626.500554:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194626.500660:0:127859:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886464
00000100:00100000:0.0:1776194626.501454:0:127859:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 370
00000100:00100000:0.0:1776194626.501465:0:127859:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000a44ef877 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088886464:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:0.0:1776194626.501513:0:127859:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194626.501599:0:127859:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000a44ef877 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088886464:12345-0@lo:13:osp-pre-1-0.0 Request processed in 136us (1054us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194626.501607:0:127859:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 370
00000100:00100000:0.0:1776194626.501676:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088886464:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194626.501985:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000bbbf7aab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088886336:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.504423:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886208
00000100:00100000:1.0:1776194626.504523:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 92
00000100:00100000:1.0:1776194626.504536:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000007b6ea45b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088886208:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194626.504772:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000007b6ea45b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088886208:12345-0@lo:400:kworker/u8:3.0 Request processed in 240us (7078us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194626.504782:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 92
00000100:00100000:0.0:1776194626.504901:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000000361037 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088886208:0@lo:400:kworker/u8:3.0
00010000:00010000:1.0:1776194626.755672:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194627.776590:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194628.803179:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194629.824579:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:2.0:1776194630.756805:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194630.756851:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194630.757088:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192704
00000100:00100000:3.0:1776194630.757149:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 93
00000100:00100000:3.0:1776194630.757155:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000b94763fe pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091192704:12345-192.168.204.22@tcp:400:kworker/u8:0.0
00000100:00100000:3.0:1776194630.757230:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000b94763fe pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091192704:12345-192.168.204.22@tcp:400:kworker/u8:0.0 Request processed in 74us (434us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194630.757238:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 93
00000100:00100000:1.0:1776194630.761935:0:140245:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192768
00000100:00100000:1.0:1776194630.762879:0:140245:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 65
00000100:00100000:1.0:1776194630.762889:0:140245:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000210906e6 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091192768:12345-192.168.204.22@tcp:400:kworker/u8:0.0
00000100:00100000:1.0:1776194630.762983:0:140245:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000210906e6 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091192768:12345-192.168.204.22@tcp:400:kworker/u8:0.0 Request processed in 95us (6133us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194630.762991:0:140245:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 65
00010000:00010000:1.0:1776194630.848575:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:0.0:1776194631.616633:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:0.0:1776194631.616662:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000c0b8412c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886656:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194631.616746:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194631.616935:0:127860:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886656
00000100:00100000:1.0:1776194631.616983:0:127860:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 371
00000100:00100000:1.0:1776194631.616989:0:127860:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000fc9659b0 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886656:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:1.0:1776194631.617025:0:127860:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:1.0:1776194631.617076:0:127860:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000fc9659b0 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088886656:12345-0@lo:13:osp-pre-1-0.0 Request processed in 86us (332us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194631.617083:0:127860:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 371
00000100:00100000:2.0:1776194631.617150:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000c0b8412c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088886656:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194631.617704:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088886720:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194631.617743:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:2.0:1776194631.617827:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886720
00000100:00100000:2.0:1776194631.617859:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 94
00000100:00100000:2.0:1776194631.617863:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000e1df051a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088886720:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624399:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000ed441bd0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-OST0000_UUID:3022:1862468088886784:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624499:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194631.624540:0:3022:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [2->3]
00000100:00100000:0.0:1776194631.624559:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000000f2bb907 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-MDT0000_UUID:3022:1862468088886976:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624584:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194631.624696:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886784
00000100:00100000:0.0:1776194631.624745:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886976
00000100:00100000:0.0:1776194631.624767:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 66
00000100:00100000:0.0:1776194631.624773:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000001072fe25 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0000_UUID+5:3022:x1862468088886784:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624824:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000001072fe25 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0000_UUID+5:3022:x1862468088886784:12345-0@lo:400:kworker/u8:3.0 Request processed in 51us (327us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194631.624832:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 66
00000100:00100000:0.0:1776194631.624853:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 67
00000100:00100000:0.0:1776194631.624857:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000f85c6270 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3022:x1862468088886976:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624883:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000f85c6270 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3022:x1862468088886976:12345-0@lo:400:kworker/u8:3.0 Request processed in 25us (299us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194631.624888:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 67
00000100:00100000:0.0:1776194631.624923:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000000f2bb907 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-MDT0000_UUID:3022:1862468088886976:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624933:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000ed441bd0 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-lwp-OST0000_UUID:3022:1862468088886784:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624957:0:3020:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-mdtlov_UUID:3020:1862468088886912:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.624984:0:3020:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194631.625010:0:3020:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [0->1]
00000100:00100000:0.0:1776194631.625015:0:3020:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-lwp-OST0001_UUID:3020:1862468088886848:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.625036:0:3020:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194631.625056:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886848
00000100:00100000:0.0:1776194631.625077:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 68
00000100:00100000:0.0:1776194631.625082:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000000f2bb907 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0001_UUID+5:3020:x1862468088886848:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194631.625115:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000000f2bb907 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-OST0001_UUID+5:3020:x1862468088886848:12345-0@lo:400:kworker/u8:3.0 Request processed in 33us (79us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194631.625128:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 68
00000100:00100000:0.0:1776194631.625155:0:3020:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-lwp-OST0001_UUID:3020:1862468088886848:0@lo:400:kworker/u8:3.0
00000100:00100000:3.0:1776194631.627353:0:127858:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088886912
00000100:00100000:3.0:1776194631.627415:0:127858:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 588
00000100:00100000:3.0:1776194631.627528:0:127858:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000ed441bd0 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3020:x1862468088886912:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:3.0:1776194631.627619:0:127858:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000ed441bd0 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3020:x1862468088886912:12345-0@lo:400:kworker/u8:3.0 Request processed in 94us (2635us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194631.627635:0:127858:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 588
00000100:00100000:3.0:1776194631.627694:0:3020:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-mdtlov_UUID:3020:1862468088886912:0@lo:400:kworker/u8:3.0
00000100:00100000:2.0:1776194631.637720:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000e1df051a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088886720:12345-0@lo:400:kworker/u8:3.0 Request processed in 19846us (19968us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194631.637738:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 94
00000100:00100000:0.0:1776194631.637880:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088886720:0@lo:400:kworker/u8:3.0
00010000:00010000:2.0:1776194631.877707:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000400:00000080:0.0:1776194632.163304:0:141057:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648
00000001:02000400:0.0:1776194632.163419:0:141057:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: == sanity test 823: Setting create_count > OST_MAX_PRECREATE is lowered to maximum ========================================================== 15:23:50 (1776194630)
00010000:00010000:1.0:1776194632.896610:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194633.923224:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194634.944712:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:3.0:1776194635.875790:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194635.875838:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:0.0:1776194635.875907:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192896
00000100:00100000:0.0:1776194635.875969:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 69
00000100:00100000:0.0:1776194635.875977:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000000361037 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2229:x1862468091192896:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:0.0:1776194635.876049:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000000361037 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2229:x1862468091192896:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 72us (266us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194635.876057:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 69
00000100:00100000:1.0:1776194635.876215:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192832
00000100:00100000:1.0:1776194635.876253:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 95
00000100:00100000:1.0:1776194635.876257:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000465004a6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2229:x1862468091192832:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:1.0:1776194635.876284:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000465004a6 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2229:x1862468091192832:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 26us (447us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194635.876290:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 95
00010000:00010000:1.0:1776194635.969624:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:1.0:1776194636.736683:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3022:1862468088887040:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.736695:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0000_UUID:3019:1862468088887104:0@lo:400:kworker/u8:1.0
00000100:00100000:2.0:1776194636.736795:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000cb69ac06 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887232:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.736963:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194636.737001:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088887360:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737021:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194636.737044:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 2 async RPCs [1->0]
00000100:00100000:0.0:1776194636.737049:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000005956ad3a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088887168:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737067:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194636.737079:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000bbbf7aab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088887424:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194636.737100:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194636.737139:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887104
00000100:00100000:0.0:1776194636.737181:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887360
00000100:00100000:0.0:1776194636.737209:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887168
00000100:00100000:0.0:1776194636.737227:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 70
00000100:00100000:0.0:1776194636.737232:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000ce5a5ae0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0000_UUID+5:3019:x1862468088887104:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737280:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000ce5a5ae0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0000_UUID+5:3019:x1862468088887104:12345-0@lo:400:kworker/u8:1.0 Request processed in 47us (320us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194636.737287:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 70
00000100:00100000:0.0:1776194636.737304:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 71
00000100:00100000:0.0:1776194636.737307:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000006021830d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088887360:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737358:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000006021830d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088887360:12345-0@lo:400:kworker/u8:1.0 Request processed in 50us (337us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194636.737377:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 71
00000100:00100000:0.0:1776194636.737400:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 72
00000100:00100000:0.0:1776194636.737403:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000eca24868 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088887168:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737430:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000eca24868 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088887168:12345-0@lo:400:kworker/u8:1.0 Request processed in 26us (362us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194636.737436:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 72
00000100:00100000:0.0:1776194636.737457:0:127859:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887424
00000100:00100000:0.0:1776194636.737481:0:127859:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 372
00000100:00100000:0.0:1776194636.737485:0:127859:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000e20fb0c3 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088887424:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:0.0:1776194636.737513:0:127859:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194636.737643:0:127859:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000e20fb0c3 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088887424:12345-0@lo:13:osp-pre-1-0.0 Request processed in 156us (541us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194636.737649:0:127859:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 372
00000100:00100000:0.0:1776194636.737695:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000005956ad3a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088887168:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737709:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000bbbf7aab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088887424:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194636.737731:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0000_UUID:3019:1862468088887104:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194636.737741:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000007a543ce1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088887360:0@lo:400:kworker/u8:1.0
00000100:00100000:2.0:1776194636.738015:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:3.0:1776194636.738112:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887232
00000100:00100000:3.0:1776194636.738150:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 589
00000100:00100000:3.0:1776194636.738155:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000038129958 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887232:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:3.0:1776194636.738199:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000038129958 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887232:12345-0@lo:400:kworker/u8:1.0 Request processed in 43us (185us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194636.738206:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 589
00000100:00100000:3.0:1776194636.738234:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000cb69ac06 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887232:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194636.739185:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194636.739224:0:3022:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-mdtlov_UUID:3022:1862468088887296:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194636.739259:0:3022:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:3.0:1776194636.741062:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887040
00000100:00100000:2.0:1776194636.741479:0:127858:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887296
00000100:00100000:2.0:1776194636.741531:0:127858:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 590
00000100:00100000:2.0:1776194636.741536:0:127858:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000078a2a06c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3022:x1862468088887296:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:2.0:1776194636.741702:0:127858:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000078a2a06c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3022:x1862468088887296:12345-0@lo:400:kworker/u8:1.0 Request processed in 164us (2442us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194636.741710:0:127858:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 590
00000100:00100000:2.0:1776194636.741755:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:lustre-MDT0000-mdtlov_UUID:3022:1862468088887296:0@lo:400:kworker/u8:1.0
00000100:00100000:3.0:1776194636.744514:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 96
00000100:00100000:3.0:1776194636.744533:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000007b747a92 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3022:x1862468088887040:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:3.0:1776194636.744646:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000007b747a92 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3022:x1862468088887040:12345-0@lo:400:kworker/u8:1.0 Request processed in 115us (5465us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194636.744654:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 96
00000100:00100000:2.0:1776194636.744715:0:3022:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000034fc040c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_03:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3022:1862468088887040:0@lo:400:kworker/u8:1.0
00010000:00010000:0.0:1776194636.992527:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194638.018521:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194639.040671:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000400:00000080:0.0:1776194639.316873:0:141398:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648
00000001:02000400:0.0:1776194639.316881:0:141398:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: setting create_count to 100200:
00010000:00010000:1.0:1776194640.064774:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000400:00000080:2.0:1776194640.782500:0:141446:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648
00000001:02000400:2.0:1776194640.782508:0:141446:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: -result- count: 9984 with max: 20000, expecting: 9984
00000100:00100000:2.0:1776194641.013180:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194641.013294:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:0.0:1776194641.013499:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091192960
00000100:00100000:0.0:1776194641.013670:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 97
00000100:00100000:0.0:1776194641.013678:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000048e88a2 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2228:x1862468091192960:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:0.0:1776194641.013760:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000048e88a2 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2228:x1862468091192960:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 82us (465us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194641.013768:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 97
00000100:00100000:3.0:1776194641.016407:0:139504:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193024
00000100:00100000:2.0:1776194641.018033:0:139504:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 73
00000100:00100000:2.0:1776194641.018046:0:139504:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000000e49a455 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:9c577acc-8068-4558-bc36-a4a67c56c094+14:2229:x1862468091193024:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:2.0:1776194641.018151:0:139504:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000000e49a455 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:9c577acc-8068-4558-bc36-a4a67c56c094+14:2229:x1862468091193024:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 106us (4981us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194641.018159:0:139504:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 73
00010000:00010000:0.0:1776194641.088612:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:0.0:1776194641.859674:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000beae35d4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887488:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194641.859755:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194641.859821:0:127860:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887488
00000100:00100000:0.0:1776194641.859876:0:127860:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 373
00000100:00100000:0.0:1776194641.859881:0:127860:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000034fc040c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887488:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:0.0:1776194641.859917:0:127860:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194641.859959:0:127860:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000034fc040c pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887488:12345-0@lo:13:osp-pre-1-0.0 Request processed in 77us (204us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194641.859967:0:127860:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 373
00000100:00100000:0.0:1776194641.860023:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000beae35d4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887488:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194641.860352:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000d423863e pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0000_UUID:3019:1862468088887616:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860388:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194641.860408:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:1.0:1776194641.860413:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000c0b8412c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088887680:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860434:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194641.860467:0:139504:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887616
00000100:00100000:1.0:1776194641.860501:0:139504:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887680
00000100:00100000:1.0:1776194641.860519:0:139504:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 74
00000100:00100000:1.0:1776194641.860523:0:139504:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000062cb5d70 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0000_UUID+5:3019:x1862468088887616:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860562:0:139504:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000062cb5d70 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0000_UUID+5:3019:x1862468088887616:12345-0@lo:400:kworker/u8:1.0 Request processed in 38us (174us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194641.860568:0:139504:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 74
00000100:00100000:1.0:1776194641.860583:0:139504:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 75
00000100:00100000:1.0:1776194641.860587:0:139504:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000001dc7b19b pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088887680:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860609:0:139504:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000001dc7b19b pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088887680:12345-0@lo:400:kworker/u8:1.0 Request processed in 21us (174us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194641.860614:0:139504:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 75
00000100:00100000:1.0:1776194641.860652:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000c0b8412c pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088887680:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860660:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000d423863e pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0000_UUID:3019:1862468088887616:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860712:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887744:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860737:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194641.860752:0:3021:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 2 async RPCs [3->2]
00000100:00100000:1.0:1776194641.860756:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000002f73f42a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088887552:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860779:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194641.860790:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000636a4145 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088887808:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860807:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194641.860828:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887744
00000100:00100000:1.0:1776194641.860869:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 591
00000100:00100000:1.0:1776194641.860873:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000d423863e pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887744:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860905:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000d423863e pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088887744:12345-0@lo:400:kworker/u8:1.0 Request processed in 31us (167us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194641.860910:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 591
00000100:00100000:1.0:1776194641.860927:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887552
00000100:00100000:1.0:1776194641.860948:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 98
00000100:00100000:1.0:1776194641.860951:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000e689bc26 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088887552:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.860975:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000e689bc26 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088887552:12345-0@lo:400:kworker/u8:1.0 Request processed in 24us (197us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194641.860980:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 98
00000100:00100000:1.0:1776194641.861011:0:140245:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887808
00000100:00100000:1.0:1776194641.861028:0:140245:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 76
00000100:00100000:1.0:1776194641.861031:0:140245:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000c0b8412c pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088887808:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.861055:0:140245:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000c0b8412c pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088887808:12345-0@lo:400:kworker/u8:1.0 Request processed in 23us (248us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194641.861061:0:140245:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 76
00000100:00100000:1.0:1776194641.861092:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000002f73f42a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088887552:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.861101:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000636a4145 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088887808:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194641.861108:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000083450211 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088887744:0@lo:400:kworker/u8:1.0
00010000:00010000:1.0:1776194642.114624:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194643.136603:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:2.0:1776194644.170578:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194645.184638:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:2.0:1776194646.119716:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194646.119834:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193152
00000100:00100000:2.0:1776194646.119893:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194646.119939:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 77
00000100:00100000:3.0:1776194646.119949:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000073ba692d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091193152:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:2.0:1776194646.119953:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193088
00000100:00100000:2.0:1776194646.120012:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 99
00000100:00100000:2.0:1776194646.120019:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000008f1f5c68 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2227:x1862468091193088:12345-192.168.204.22@tcp:400:kworker/u8:3.0
00000100:00100000:3.0:1776194646.122976:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000073ba692d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091193152:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 3014us (3254us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194646.123000:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 77
00000100:00100000:2.0:1776194646.126572:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000008f1f5c68 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2227:x1862468091193088:12345-192.168.204.22@tcp:400:kworker/u8:3.0 Request processed in 6545us (6676us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194646.126592:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 99
00010000:00010000:1.0:1776194646.209528:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:1.0:1776194646.976644:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088887872:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194646.976718:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194646.976817:0:127859:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887872
00000100:00100000:0.0:1776194646.976875:0:127859:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 374
00000100:00100000:0.0:1776194646.976882:0:127859:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000083450211 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088887872:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:0.0:1776194646.976926:0:127859:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194646.976969:0:127859:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000083450211 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088887872:12345-0@lo:13:osp-pre-1-0.0 Request processed in 87us (252us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194646.976976:0:127859:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 374
00000100:00100000:1.0:1776194646.977281:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000036983974 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888128:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977339:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194646.977378:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088887872:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194646.977401:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 2 async RPCs [1->0]
00000100:00100000:1.0:1776194646.977406:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000eaa09dbd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3019:1862468088887936:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977438:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194646.977457:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000d5dd24af pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088888192:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977482:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194646.977511:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088887936
00000100:00100000:1.0:1776194646.977546:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 100
00000100:00100000:1.0:1776194646.977550:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000e55d5a2e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3019:x1862468088887936:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977595:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000e55d5a2e pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3019:x1862468088887936:12345-0@lo:400:kworker/u8:3.0 Request processed in 44us (157us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194646.977602:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 100
00000100:00100000:1.0:1776194646.977629:0:138592:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888192
00000100:00100000:1.0:1776194646.977652:0:138592:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 78
00000100:00100000:1.0:1776194646.977656:0:138592:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000002f73f42a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088888192:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977699:0:138592:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000002f73f42a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_002:lustre-MDT0000-lwp-MDT0000_UUID+5:3019:x1862468088888192:12345-0@lo:400:kworker/u8:3.0 Request processed in 42us (216us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194646.977705:0:138592:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 78
00000100:00100000:1.0:1776194646.977736:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000eaa09dbd pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3019:1862468088887936:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.977746:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000d5dd24af pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-MDT0000_UUID:3019:1862468088888192:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194646.977894:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000fc0e5854 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888000:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194646.977922:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194646.977947:0:3021:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [3->2]
00000100:00100000:0.0:1776194646.977952:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000028dfe281 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0001_UUID:3021:1862468088888064:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194646.977972:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:3.0:1776194646.978045:0:127858:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888128
00000100:00100000:3.0:1776194646.978084:0:127858:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 592
00000100:00100000:3.0:1776194646.978088:0:127858:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000636a4145 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888128:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:3.0:1776194646.978126:0:127858:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000636a4145 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888128:12345-0@lo:400:kworker/u8:3.0 Request processed in 37us (816us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194646.978132:0:127858:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 592
00000100:00100000:1.0:1776194646.978488:0:140245:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888000
00000100:00100000:1.0:1776194646.978520:0:140245:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888064
00000100:00100000:1.0:1776194646.978544:0:140245:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 79
00000100:00100000:1.0:1776194646.978549:0:140245:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000cb69ac06 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888000:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.978598:0:140245:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000cb69ac06 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888000:12345-0@lo:400:kworker/u8:3.0 Request processed in 48us (676us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194646.978604:0:140245:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 79
00000100:00100000:1.0:1776194646.978616:0:140245:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 80
00000100:00100000:1.0:1776194646.978620:0:140245:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000007a543ce1 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0001_UUID+5:3021:x1862468088888064:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194646.978644:0:140245:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000007a543ce1 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_004:lustre-MDT0000-lwp-OST0001_UUID+5:3021:x1862468088888064:12345-0@lo:400:kworker/u8:3.0 Request processed in 23us (672us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194646.978650:0:140245:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 80
00000100:00100000:1.0:1776194646.978682:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000036983974 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888128:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194646.978826:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000028dfe281 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0001_UUID:3021:1862468088888064:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194646.978836:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000fc0e5854 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888000:0@lo:400:kworker/u8:3.0
00010000:00010000:0.0:1776194647.232502:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194648.258090:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:0.0:1776194649.281614:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194650.304702:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000400:00000080:2.0:1776194650.940937:0:141737:0:(module.c:221:libcfs_ioctl()) libcfs ioctl cmd 3221775648
00000001:02000400:2.0:1776194650.940945:0:141737:0:(debug.c:702:libcfs_debug_mark_buffer()) DEBUG MARKER: == sanity test 831: throttling unlink/setattr queuing on OSP ========================================================== 15:24:09 (1776194649)
00000100:00100000:2.0:1776194651.246978:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194651.247172:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194651.247269:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193216
00000100:00100000:3.0:1776194651.247374:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 101
00000100:00100000:3.0:1776194651.247382:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000986027d4 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091193216:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:3.0:1776194651.247628:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000986027d4 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091193216:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 244us (454us total) trans 0 rc 0/0
00000100:00100000:3.0:1776194651.247637:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 101
00000100:00100000:1.0:1776194651.248188:0:139504:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193280
00000100:00100000:1.0:1776194651.248271:0:139504:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 81
00000100:00100000:1.0:1776194651.248276:0:139504:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000004a5d9c17 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091193280:12345-192.168.204.22@tcp:400:kworker/u8:2.0
00000100:00100000:1.0:1776194651.248359:0:139504:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000004a5d9c17 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:9c577acc-8068-4558-bc36-a4a67c56c094+14:2227:x1862468091193280:12345-192.168.204.22@tcp:400:kworker/u8:2.0 Request processed in 81us (1396us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194651.248387:0:139504:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 81
00010000:00010000:0.0:1776194651.332664:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:0.0:1776194652.097798:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088888256:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.097876:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194652.097918:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000b96314ce pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088888512:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.097945:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194652.097970:0:3021:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 2 async RPCs [3->2]
00000100:00100000:0.0:1776194652.097975:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000005956ad3a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888320:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098000:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194652.098025:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000045a48e72 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088888576:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098046:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194652.098084:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888256
00000100:00100000:0.0:1776194652.098141:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 102
00000100:00100000:0.0:1776194652.098147:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000222f2ad0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088888256:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098191:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000222f2ad0 pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088888256:12345-0@lo:400:kworker/u8:3.0 Request processed in 44us (316us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194652.098197:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 102
00000100:00100000:0.0:1776194652.098233:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888512
00000100:00100000:0.0:1776194652.098255:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 593
00000100:00100000:0.0:1776194652.098259:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000c936d949 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088888512:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098288:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000c936d949 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3021:x1862468088888512:12345-0@lo:400:kworker/u8:3.0 Request processed in 29us (344us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194652.098294:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 593
00000100:00100000:0.0:1776194652.098333:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888320
00000100:00100000:0.0:1776194652.098354:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888576
00000100:00100000:0.0:1776194652.098368:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 82
00000100:00100000:0.0:1776194652.098372:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000049f6643a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888320:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098399:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000049f6643a pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888320:12345-0@lo:400:kworker/u8:3.0 Request processed in 26us (399us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194652.098405:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 82
00000100:00100000:0.0:1776194652.098416:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 83
00000100:00100000:0.0:1776194652.098419:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000a22f5456 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088888576:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098441:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000a22f5456 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088888576:12345-0@lo:400:kworker/u8:3.0 Request processed in 22us (395us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194652.098446:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 83
00000100:00100000:0.0:1776194652.098493:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000005956ad3a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888320:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098504:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000045a48e72 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088888576:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098511:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000157fce9a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088888256:0@lo:400:kworker/u8:3.0
00000100:00100000:0.0:1776194652.098518:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000b96314ce pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-mdtlov_UUID:3021:1862468088888512:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.098753:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088888384:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.098787:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194652.098807:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:1.0:1776194652.098812:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000beae35d4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888448:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.098833:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194652.098861:0:139504:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888384
00000100:00100000:1.0:1776194652.098886:0:139504:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 84
00000100:00100000:1.0:1776194652.098890:0:139504:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000996941e2 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088888384:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.098934:0:139504:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000996941e2 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_003:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088888384:12345-0@lo:400:kworker/u8:3.0 Request processed in 43us (147us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194652.098939:0:139504:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 84
00000100:00100000:1.0:1776194652.098973:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000f60b96e9 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088888384:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.098992:0:127858:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888448
00000100:00100000:1.0:1776194652.099014:0:127858:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 594
00000100:00100000:1.0:1776194652.099017:0:127858:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000abab2000 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888448:12345-0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.099048:0:127858:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000abab2000 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_002:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888448:12345-0@lo:400:kworker/u8:3.0 Request processed in 29us (215us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194652.099054:0:127858:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 594
00000100:00100000:1.0:1776194652.099076:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000beae35d4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888448:0@lo:400:kworker/u8:3.0
00000100:00100000:1.0:1776194652.099408:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000b96314ce pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888640:0@lo:13:osp-pre-1-0.0
00000100:00100000:1.0:1776194652.099438:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194652.099506:0:127860:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888640
00000100:00100000:0.0:1776194652.099539:0:127860:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 375
00000100:00100000:0.0:1776194652.099544:0:127860:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000beae35d4 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888640:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:0.0:1776194652.099575:0:127860:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:0.0:1776194652.099608:0:127860:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000beae35d4 pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888640:12345-0@lo:13:osp-pre-1-0.0 Request processed in 64us (171us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194652.099614:0:127860:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 375
00000100:00100000:1.0:1776194652.099680:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000b96314ce pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888640:0@lo:13:osp-pre-1-0.0
00000100:00100000:3.0:1776194652.109130:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:0.0:1776194652.109338:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193344
00000100:00100000:0.0:1776194652.109398:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 28
00000100:00100000:0.0:1776194652.109405:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000de58c5f0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+14:185666:x1862468091193344:12345-192.168.204.22@tcp:101:lfs.0
00010000:00010000:0.0:1776194652.109427:0:138590:0:(ldlm_lockd.c:1248:ldlm_handle_enqueue0()) ### server-side enqueue handler START
00010000:00010000:0.0:1776194652.109450:0:138590:0:(ldlm_lockd.c:1318:ldlm_handle_enqueue0()) ### server-side enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f02ed lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0xf969c8b2a0475bf5 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109572:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 4 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109587:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109599:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109627:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109634:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109640:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109714:0:138590:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109721:0:138590:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 2/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109727:0:138590:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109734:0:138590:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 0000000009a48f37 already unused, calling callback (0000000065d8aabd)
00010000:00010000:0.0:1776194652.109737:0:138590:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109743:0:138590:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 4/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109755:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:0.0:1776194652.109758:0:138590:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:0.0:1776194652.109762:0:138590:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109779:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f02f4 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109790:0:138590:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109796:0:138590:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109801:0:138590:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109805:0:138590:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000cb6bdac0 already unused, calling callback (0000000065d8aabd)
00010000:00010000:0.0:1776194652.109807:0:138590:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109812:0:138590:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 4/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109818:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x7a6a6e09 (000000008b3c0a4d)
00010000:00010000:0.0:1776194652.109820:0:138590:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:0.0:1776194652.109823:0:138590:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 2/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109828:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f02fb lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109874:0:138590:0:(ldlm_lockd.c:1484:ldlm_handle_enqueue0()) ### server-side enqueue handler, sending reply (err=301, rc=0) ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f02ed lrc: 1/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475bf5 expref: 15 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109892:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f02ed lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475bf5 expref: 15 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.109901:0:138590:0:(ldlm_lockd.c:1565:ldlm_handle_enqueue0()) ### server-side enqueue handler END (lock 000000001af9523a, rc 0)
00000100:00100000:0.0:1776194652.109976:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000de58c5f0 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+14:185666:x1862468091193344:12345-192.168.204.22@tcp:101:lfs.0 Request processed in 570us (854us total) trans 0 rc 301/301
00000100:00100000:0.0:1776194652.109984:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 28
00000100:00100000:2.0:1776194652.124166:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:1.0:1776194652.125455:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193408
00000100:00100000:1.0:1776194652.125521:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 29
00000100:00100000:1.0:1776194652.125528:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000c0f0ea26 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:185666:x1862468091193408:12345-192.168.204.22@tcp:101:lfs.0
00010000:00010000:1.0:1776194652.125549:0:138591:0:(ldlm_lockd.c:1248:ldlm_handle_enqueue0()) ### server-side enqueue handler START
00010000:00010000:1.0:1776194652.125569:0:138591:0:(ldlm_lockd.c:1318:ldlm_handle_enqueue0()) ### server-side enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f0302 lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0xf969c8b2a0475bfc expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125629:0:138591:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 4 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125646:0:138591:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125657:0:138591:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125670:0:138591:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125676:0:138591:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125682:0:138591:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125756:0:138591:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125764:0:138591:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 2/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125781:0:138591:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125786:0:138591:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000d5fdbfa9 already unused, calling callback (0000000065d8aabd)
00010000:00010000:1.0:1776194652.125790:0:138591:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125797:0:138591:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 4/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125807:0:138591:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:1.0:1776194652.125810:0:138591:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:1.0:1776194652.125814:0:138591:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125819:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000d5fdbfa9/0xe96d6de1471f0309 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125829:0:138591:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125834:0:138591:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125840:0:138591:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125844:0:138591:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000b5387c40 already unused, calling callback (0000000065d8aabd)
00010000:00010000:1.0:1776194652.125845:0:138591:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125858:0:138591:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 4/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125866:0:138591:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x7a6a6e09 (00000000549c4e45)
00010000:00010000:1.0:1776194652.125868:0:138591:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:1.0:1776194652.125869:0:138591:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 2/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125874:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0310 lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125905:0:138591:0:(ldlm_lockd.c:1484:ldlm_handle_enqueue0()) ### server-side enqueue handler, sending reply (err=301, rc=0) ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f0302 lrc: 1/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475bfc expref: 15 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125912:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f0302 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475bfc expref: 15 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.125920:0:138591:0:(ldlm_lockd.c:1565:ldlm_handle_enqueue0()) ### server-side enqueue handler END (lock 00000000f0c1ca7b, rc 0)
00000100:00100000:1.0:1776194652.125994:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000c0f0ea26 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:185666:x1862468091193408:12345-192.168.204.22@tcp:101:lfs.0 Request processed in 465us (1837us total) trans 0 rc 301/301
00000100:00100000:1.0:1776194652.126002:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 29
00000100:00100000:0.0:1776194652.133129:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:1.0:1776194652.133244:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193472
00000100:00100000:1.0:1776194652.133327:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 30
00000100:00100000:1.0:1776194652.133334:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000045a48e72 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:185666:x1862468091193472:12345-192.168.204.22@tcp:101:lfs.0
00010000:00010000:1.0:1776194652.133357:0:138591:0:(ldlm_lockd.c:1248:ldlm_handle_enqueue0()) ### server-side enqueue handler START
00010000:00010000:1.0:1776194652.133379:0:138591:0:(ldlm_lockd.c:1318:ldlm_handle_enqueue0()) ### server-side enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000f6a27eb1/0xe96d6de1471f0317 lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0xf969c8b2a0475c03 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133467:0:138591:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 3/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 4 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133482:0:138591:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133493:0:138591:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00000004:00200000:1.0:1776194652.133552:0:138591:0:(mdt_handler.c:912:mdt_pack_attr2body()) [0x200000007:0x1:0x0]: returning size 25088
00000004:00200000:1.0:1776194652.133556:0:138591:0:(mdt_handler.c:1523:mdt_getattr_internal()) dirent count 112 stripe count 1 MDT count 1
00000004:00010000:1.0:1776194652.133586:0:138591:0:(mdt_handler.c:2353:mdt_getattr_name_lock()) ### Returning lock to client ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133614:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000f6a27eb1/0xe96d6de1471f0317 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c03 expref: 16 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133627:0:138591:0:(ldlm_lockd.c:1484:ldlm_handle_enqueue0()) ### server-side enqueue handler, sending reply (err=0, rc=0) ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 3 type: IBT gid 0 flags: 0x40200000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c03 expref: 15 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.133635:0:138591:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:1.0:1776194652.133638:0:138591:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 13
00010000:00010000:1.0:1776194652.133642:0:138591:0:(ldlm_lockd.c:1565:ldlm_handle_enqueue0()) ### server-side enqueue handler END (lock 00000000bb86b83b, rc 0)
00000100:00100000:1.0:1776194652.133704:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000045a48e72 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+15:185666:x1862468091193472:12345-192.168.204.22@tcp:101:lfs.0 Request processed in 370us (586us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194652.133712:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 30
00000100:00100000:2.0:1776194652.145032:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194652.145139:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193600
00000100:00100000:3.0:1776194652.145201:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 31
00000100:00100000:3.0:1776194652.145208:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000009296635d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+15:185666:x1862468091193600:12345-192.168.204.22@tcp:36:lfs.0
00010000:00010000:3.0:1776194652.145263:0:138590:0:(ldlm_lockd.c:1720:ldlm_request_cancel()) ### server-side cancel handler START: 1 locks, starting at 0
00010000:00010000:3.0:1776194652.145292:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000bb86b83b/0xe96d6de1471f031e lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a01000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c03 expref: 15 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.145342:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:3.0:1776194652.145348:0:138590:0:(ldlm_lockd.c:1782:ldlm_request_cancel()) ### server-side cancel handler END
00010000:00010000:3.0:1776194652.145447:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CW) ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,1 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.145462:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,1 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.145488:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,1 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.145575:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PW) ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,1 mode: --/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.145584:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,1 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.145603:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,1 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000004:00200000:2.0:1776194652.148979:0:138590:0:(mdt_handler.c:912:mdt_pack_attr2body()) [0x200002b11:0xec2:0x0]: returning size 512
00010000:00010000:2.0:1776194652.148996:0:138590:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CW) ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,1 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149010:0:138590:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 2/0,0 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149017:0:138590:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,0 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149024:0:138590:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000f2a8a59d already unused, calling callback (0000000065d8aabd)
00010000:00010000:2.0:1776194652.149028:0:138590:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 3/0,0 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149036:0:138590:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 4/0,0 mode: CW/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149053:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:2.0:1776194652.149056:0:138590:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:2.0:1776194652.149060:0:138590:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 2/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.149065:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000f2a8a59d/0xe96d6de1471f0325 lrc: 0/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 3 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000004:00010000:2.0:1776194652.149078:0:138590:0:(mdt_handler.c:3992:mdt_save_lock()) ### save lock request 000000009296635d reply state 0000000009d63816 transno 34359738375
 ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,1 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000100:00100000:2.0:1776194652.149208:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000009296635d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+16:185666:x1862468091193600:12345-192.168.204.22@tcp:36:lfs.0 Request processed in 3997us (4182us total) trans 34359738375 rc 0/0
00000100:00100000:2.0:1776194652.149219:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 31
00010000:00010000:3.0:1776194652.153807:0:3005:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PW) ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,1 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153840:0:3005:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 2/0,0 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153847:0:3005:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,0 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153853:0:3005:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 0000000028768a10 already unused, calling callback (0000000065d8aabd)
00010000:00010000:3.0:1776194652.153857:0:3005:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 3/0,0 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153864:0:3005:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 4/0,0 mode: PW/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153880:0:3005:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x7a6a6e09 (000000002a6b0a8e)
00010000:00010000:3.0:1776194652.153882:0:3005:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:3.0:1776194652.153885:0:3005:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 2/0,0 mode: --/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:3.0:1776194652.153891:0:3005:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 0000000028768a10/0xe96d6de1471f032c lrc: 0/0,0 mode: --/PW res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000100:00100000:1.0:1776194652.196586:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:0.0:1776194652.197102:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193728
00000100:00100000:0.0:1776194652.197164:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 32
00000100:00100000:0.0:1776194652.197171:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000e4b831da pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+15:185667:x1862468091193728:12345-192.168.204.22@tcp:101:lfs.0
00010000:00010000:0.0:1776194652.197200:0:138590:0:(ldlm_lockd.c:1248:ldlm_handle_enqueue0()) ### server-side enqueue handler START
00010000:00010000:0.0:1776194652.197221:0:138590:0:(ldlm_lockd.c:1318:ldlm_handle_enqueue0()) ### server-side enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f0333 lrc: 2/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0xf969c8b2a0475c0a expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197406:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 4 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197420:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197431:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197445:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197472:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197479:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000004:00200000:0.0:1776194652.197560:0:138590:0:(mdt_handler.c:912:mdt_pack_attr2body()) [0x200002b11:0xec2:0x0]: returning size 512
00010000:00010000:0.0:1776194652.197575:0:138590:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197582:0:138590:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 2/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197589:0:138590:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197595:0:138590:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000cb6bdac0 already unused, calling callback (0000000065d8aabd)
00010000:00010000:0.0:1776194652.197599:0:138590:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197606:0:138590:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 4/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197619:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:0.0:1776194652.197622:0:138590:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:0.0:1776194652.197626:0:138590:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197631:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000cb6bdac0/0xe96d6de1471f033a lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197665:0:138590:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197671:0:138590:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197676:0:138590:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197682:0:138590:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 0000000009a48f37 already unused, calling callback (0000000065d8aabd)
00010000:00010000:0.0:1776194652.197684:0:138590:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197690:0:138590:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 4/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197699:0:138590:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x7a6a6e09 (000000008b3c0a4d)
00010000:00010000:0.0:1776194652.197701:0:138590:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:0.0:1776194652.197703:0:138590:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 2/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197709:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 0000000009a48f37/0xe96d6de1471f0341 lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197742:0:138590:0:(ldlm_lockd.c:1484:ldlm_handle_enqueue0()) ### server-side enqueue handler, sending reply (err=301, rc=0) ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f0333 lrc: 1/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c0a expref: 16 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197749:0:138590:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 000000001af9523a/0xe96d6de1471f0333 lrc: 0/0,0 mode: --/CW res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c0a expref: 16 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:0.0:1776194652.197770:0:138590:0:(ldlm_lockd.c:1565:ldlm_handle_enqueue0()) ### server-side enqueue handler END (lock 000000001af9523a, rc 0)
00000100:00100000:0.0:1776194652.197833:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000e4b831da pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+15:185667:x1862468091193728:12345-192.168.204.22@tcp:101:lfs.0 Request processed in 661us (1255us total) trans 0 rc 301/301
00000100:00100000:0.0:1776194652.197841:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 32
00000100:00100000:3.0:1776194652.211377:0:3012:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:1.0:1776194652.211483:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193856
00000100:00100000:1.0:1776194652.211556:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 33
00000100:00100000:1.0:1776194652.211563:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000a4bf3125 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+15:185667:x1862468091193856:12345-192.168.204.22@tcp:101:lfs.0
00010000:00010000:1.0:1776194652.211585:0:138591:0:(ldlm_lockd.c:1248:ldlm_handle_enqueue0()) ### server-side enqueue handler START
00010000:00010000:1.0:1776194652.211604:0:138591:0:(ldlm_lockd.c:1318:ldlm_handle_enqueue0()) ### server-side enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000f6a27eb1/0xe96d6de1471f0348 lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 3 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0xf969c8b2a0475c11 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211674:0:138591:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/1,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x0/0x0 rrc: 4 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211688:0:138591:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211698:0:138591:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211712:0:138591:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/1,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211718:0:138591:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211724:0:138591:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00000004:00200000:1.0:1776194652.211865:0:138591:0:(mdt_handler.c:912:mdt_pack_attr2body()) [0x200002b11:0xec2:0x0]: returning size 512
00010000:00010000:1.0:1776194652.211984:0:138591:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(CR) ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/1,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.211993:0:138591:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 2/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212010:0:138591:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212018:0:138591:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000f0c1ca7b already unused, calling callback (0000000065d8aabd)
00010000:00010000:1.0:1776194652.212021:0:138591:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 3/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212027:0:138591:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 4/0,0 mode: CR/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212038:0:138591:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x0 (00000000203f6435)
00010000:00010000:1.0:1776194652.212041:0:138591:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:1.0:1776194652.212044:0:138591:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 2/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212050:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000f0c1ca7b/0xe96d6de1471f034f lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x2/0x0 rrc: 4 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212060:0:138591:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PR) ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/1,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212064:0:138591:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 2/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212069:0:138591:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212073:0:138591:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 00000000b5387c40 already unused, calling callback (0000000065d8aabd)
00010000:00010000:1.0:1776194652.212075:0:138591:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 3/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212085:0:138591:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 4/0,0 mode: PR/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212102:0:138591:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200000007:0x1:0x0].0x7a6a6e09 (00000000549c4e45)
00010000:00010000:1.0:1776194652.212104:0:138591:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 2
00010000:00010000:1.0:1776194652.212106:0:138591:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 2/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212112:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000b5387c40/0xe96d6de1471f0356 lrc: 0/0,0 mode: --/PR res: [0x200000007:0x1:0x0].0x7a6a6e09 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212145:0:138591:0:(ldlm_lockd.c:1484:ldlm_handle_enqueue0()) ### server-side enqueue handler, sending reply (err=301, rc=0) ns: mdt-lustre-MDT0000_UUID lock: 00000000f6a27eb1/0xe96d6de1471f0348 lrc: 1/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c11 expref: 17 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212153:0:138591:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 00000000f6a27eb1/0xe96d6de1471f0348 lrc: 0/0,0 mode: --/CR res: [0x200000007:0x1:0x0].0x0 bits 0x1/0x0 rrc: 3 type: IBT gid 0 flags: 0x44000000000000 nid: 192.168.204.22@tcp remote: 0xf969c8b2a0475c11 expref: 17 pid: 138591 timeout: 0 lvb_type: 0
00010000:00010000:1.0:1776194652.212161:0:138591:0:(ldlm_lockd.c:1565:ldlm_handle_enqueue0()) ### server-side enqueue handler END (lock 00000000f6a27eb1, rc 0)
00000100:00100000:1.0:1776194652.212231:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000a4bf3125 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+16:185667:x1862468091193856:12345-192.168.204.22@tcp:101:lfs.0 Request processed in 667us (862us total) trans 34359738376 rc 301/301
00000100:00100000:1.0:1776194652.212240:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 33
00000100:00100000:3.0:1776194652.215487:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194652.215578:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091193984
00000100:00100000:2.0:1776194652.215634:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 34
00000100:00100000:2.0:1776194652.215640:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000fc0e5854 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+16:185667:x1862468091193984:12345-192.168.204.22@tcp:36:lfs.0
00010000:00010000:2.0:1776194652.215720:0:138590:0:(ldlm_lock.c:766:ldlm_lock_addref_internal_nolock()) ### ldlm_lock_addref(PW) ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,1 mode: --/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x0/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.215738:0:138590:0:(ldlm_lock.c:1064:ldlm_granted_list_add_lock()) ### About to add lock: ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,1 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.215749:0:138590:0:(ldlm_request.c:528:ldlm_cli_enqueue_local()) ### client-side local enqueue handler, new lock created ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,1 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000004:00010000:2.0:1776194652.215989:0:138590:0:(mdt_handler.c:3992:mdt_save_lock()) ### save lock request 00000000fc0e5854 reply state 00000000758e29bc transno 34359738377
 ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,1 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000004:00200000:2.0:1776194652.216010:0:138590:0:(mdt_handler.c:912:mdt_pack_attr2body()) [0x200002b11:0xec2:0x0]: returning size 512
00000100:00100000:2.0:1776194652.216100:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000fc0e5854 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:9c577acc-8068-4558-bc36-a4a67c56c094+18:185667:x1862468091193984:12345-192.168.204.22@tcp:36:lfs.0 Request processed in 449us (612us total) trans 34359738377 rc 0/0
00000100:00100000:2.0:1776194652.216108:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 34
00010000:00010000:2.0:1776194652.220057:0:3006:0:(ldlm_lock.c:820:ldlm_lock_decref_internal_nolock()) ### ldlm_lock_decref(PW) ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,1 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210000000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220076:0:3006:0:(ldlm_lock.c:879:ldlm_lock_decref_internal()) ### final decref done on CBPENDING lock ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 2/0,0 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x50210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220106:0:3006:0:(ldlm_lockd.c:1879:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,0 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220113:0:3006:0:(ldlm_lockd.c:1893:ldlm_handle_bl_callback()) Lock 000000007db8f1c2 already unused, calling callback (0000000065d8aabd)
00010000:00010000:2.0:1776194652.220117:0:3006:0:(ldlm_request.c:364:ldlm_blocking_ast_nocheck()) ### already unused, calling ldlm_cli_cancel ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 3/0,0 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x40210400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220124:0:3006:0:(ldlm_request.c:1257:ldlm_cli_cancel_local()) ### server-side local cancel ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 4/0,0 mode: PW/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x40218400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220139:0:3006:0:(ldlm_inodebits.c:94:ldlm_reprocess_inodebits_queue()) --- Reprocess resource [0x200002b11:0xec2:0x0].0x0 (00000000a670e66c)
00010000:00010000:2.0:1776194652.220142:0:3006:0:(ldlm_inodebits.c:96:ldlm_reprocess_inodebits_queue()) Hint 20
00010000:00010000:2.0:1776194652.220146:0:3006:0:(ldlm_lockd.c:1903:ldlm_handle_bl_callback()) ### client blocking callback handler END ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 2/0,0 mode: --/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00010000:00010000:2.0:1776194652.220152:0:3006:0:(ldlm_lock.c:216:ldlm_lock_put()) ### final lock_put on destroyed lock, freeing it. ns: mdt-lustre-MDT0000_UUID lock: 000000007db8f1c2/0xe96d6de1471f0364 lrc: 0/0,0 mode: --/PW res: [0x200002b11:0xec2:0x0].0x0 bits 0x20/0x0 rrc: 2 type: IBT gid 0 flags: 0x44a19400000000 nid: local remote: 0x0 expref: -99 pid: 138590 timeout: 0 lvb_type: 0
00000100:00100000:1.0:1776194652.220607:0:3014:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194652.221235:0:138593:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091194112
00000100:00100000:3.0:1776194652.221289:0:138593:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 3
00000100:00100000:3.0:1776194652.221297:0:138593:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000c2d6c51e pname:cluuid+ref:pid:xid:nid:opc:job mdt_rdpg00_000:9c577acc-8068-4558-bc36-a4a67c56c094+17:185667:x1862468091194112:12345-192.168.204.22@tcp:35:lfs.0
00000100:00100000:3.0:1776194652.221592:0:138593:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000c2d6c51e pname:cluuid+ref:pid:xid:nid:opc:job mdt_rdpg00_000:9c577acc-8068-4558-bc36-a4a67c56c094+18:185667:x1862468091194112:12345-192.168.204.22@tcp:35:lfs.0 Request processed in 295us (987us total) trans 34359738378 rc 0/0
00000100:00100000:3.0:1776194652.221600:0:138593:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 3
00010000:00010000:1.0:1776194652.354297:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000001:00080000:2.0:1776194653.213608:0:138618:0:(tgt_lastrcvd.c:913:tgt_cb_last_committed()) lustre-MDT0000: transno 34359738376 is committed
00000001:00080000:2.0:1776194653.213627:0:138618:0:(tgt_lastrcvd.c:913:tgt_cb_last_committed()) lustre-MDT0000: transno 34359738377 is committed
00000001:00080000:2.0:1776194653.213636:0:138618:0:(tgt_lastrcvd.c:913:tgt_cb_last_committed()) lustre-MDT0000: transno 34359738378 is committed
00010000:00010000:1.0:1776194653.377471:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:3.0:1776194654.400785:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00010000:00010000:1.0:1776194655.425488:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:3.0:1776194656.356384:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:3.0:1776194656.356441:0:3013:0:(events.c:361:request_in_callback()) peer: 12345-192.168.204.22@tcp (source: 12345-192.168.204.22@tcp)
00000100:00100000:2.0:1776194656.356546:0:138582:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091194176
00000100:00100000:2.0:1776194656.356606:0:138582:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 103
00000100:00100000:2.0:1776194656.356612:0:138582:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000c8cc9b6b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091194176:12345-192.168.204.22@tcp:400:kworker/u8:0.0
00000100:00100000:2.0:1776194656.356686:0:138582:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000c8cc9b6b pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0001:5f5c1c40-b1db-4d76-936f-e7582a955e7e+9:2226:x1862468091194176:12345-192.168.204.22@tcp:400:kworker/u8:0.0 Request processed in 73us (310us total) trans 0 rc 0/0
00000100:00100000:2.0:1776194656.356692:0:138582:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 103
00000100:00100000:1.0:1776194656.359758:0:138591:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468091194240
00000100:00100000:1.0:1776194656.359891:0:138591:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-192.168.204.22@tcp, seq: 85
00000100:00100000:1.0:1776194656.359899:0:138591:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@0000000028dfe281 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091194240:12345-192.168.204.22@tcp:400:kworker/u8:0.0
00000100:00100000:1.0:1776194656.360031:0:138591:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@0000000028dfe281 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_001:9c577acc-8068-4558-bc36-a4a67c56c094+14:2226:x1862468091194240:12345-192.168.204.22@tcp:400:kworker/u8:0.0 Request processed in 131us (3589us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194656.360039:0:138591:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-192.168.204.22@tcp, seq: 85
00010000:00010000:3.0:1776194656.448754:0:127091:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
00000100:00100000:1.0:1776194657.216516:0:3020:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@000000001c1f2f5d pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-mdtlov_UUID:3020:1862468088888704:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194657.216619:0:3020:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:1.0:1776194657.216715:0:127859:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888704
00000100:00100000:1.0:1776194657.216772:0:127859:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 376
00000100:00100000:1.0:1776194657.216779:0:127859:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000f4951c4d pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3020:x1862468088888704:12345-0@lo:13:osp-pre-1-0.0
00002000:00000024:1.0:1776194657.216812:0:127859:0:(ofd_obd.c:740:ofd_statfs()) blocks cached 0 granted 40566784 pending 0 free 3841982464 avail 3839885312
00000100:00100000:1.0:1776194657.216851:0:127859:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000f4951c4d pname:cluuid+ref:pid:xid:nid:opc:job ll_ost_create00:lustre-MDT0000-mdtlov_UUID+5:3020:x1862468088888704:12345-0@lo:13:osp-pre-1-0.0 Request processed in 73us (235us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194657.216858:0:127859:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 376
00000100:00100000:0.0:1776194657.217043:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000044233bab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088888768:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217078:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194657.217104:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000033f05e5f pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088889024:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217128:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194657.217157:0:3021:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [3->2]
00000100:00100000:0.0:1776194657.217163:0:3021:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@00000000fe0b63f1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888832:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217186:0:3021:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194657.217220:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088889024
00000100:00100000:0.0:1776194657.217246:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888832
00000100:00100000:0.0:1776194657.217266:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 86
00000100:00100000:0.0:1776194657.217271:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000b32ba37d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088889024:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217308:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000b32ba37d pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-MDT0000_UUID+5:3021:x1862468088889024:12345-0@lo:400:kworker/u8:1.0 Request processed in 37us (179us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194657.217335:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 86
00000100:00100000:0.0:1776194657.217350:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 87
00000100:00100000:0.0:1776194657.217354:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000b96314ce pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888832:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217380:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000b96314ce pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0000_UUID+5:3021:x1862468088888832:12345-0@lo:400:kworker/u8:1.0 Request processed in 26us (194us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194657.217385:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 87
00000100:00100000:0.0:1776194657.217411:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000018a3830a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088888896:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217434:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194657.217449:0:3019:0:(ptlrpcd.c:415:ptlrpcd_check()) transfer 1 async RPCs [1->0]
00000100:00100000:0.0:1776194657.217454:0:3019:0:(client.c:1733:ptlrpc_send_new_req()) Sending RPC req@0000000068711ba4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888960:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217482:0:3019:0:(events.c:361:request_in_callback()) peer: 12345-0@lo (source: 12345-0@lo)
00000100:00100000:0.0:1776194657.217529:0:3020:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@000000001c1f2f5d pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_01:lustre-MDT0000-mdtlov_UUID:3020:1862468088888704:0@lo:13:osp-pre-1-0.0
00000100:00100000:0.0:1776194657.217558:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@00000000fe0b63f1 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-OST0000_UUID:3021:1862468088888832:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217567:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000033f05e5f pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:lustre-MDT0000-lwp-MDT0000_UUID:3021:1862468088889024:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217584:0:138590:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888896
00000100:00100000:0.0:1776194657.217619:0:138590:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 88
00000100:00100000:0.0:1776194657.217622:0:138590:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000f60b96e9 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088888896:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.217653:0:138590:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000f60b96e9 pname:cluuid+ref:pid:xid:nid:opc:job mdt00_000:lustre-MDT0000-lwp-OST0001_UUID+5:3019:x1862468088888896:12345-0@lo:400:kworker/u8:1.0 Request processed in 29us (218us total) trans 0 rc 0/0
00000100:00100000:0.0:1776194657.217659:0:138590:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 88
00000100:00100000:0.0:1776194657.217681:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000018a3830a pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-lwp-OST0001_UUID:3019:1862468088888896:0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194657.218282:0:138583:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888768
00000100:00100000:1.0:1776194657.218381:0:138583:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 104
00000100:00100000:1.0:1776194657.218386:0:138583:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@000000002bd3850a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088888768:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194657.218430:0:138583:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@000000002bd3850a pname:cluuid+ref:pid:xid:nid:opc:job ll_mgs_0002:d652416a-7c3e-44ba-a9b7-5f75948a75ab+18:3021:x1862468088888768:12345-0@lo:400:kworker/u8:1.0 Request processed in 43us (1352us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194657.218436:0:138583:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 104
00000100:00100000:1.0:1776194657.218476:0:127855:0:(service.c:2152:ptlrpc_server_handle_req_in()) got req x1862468088888960
00000100:00100000:1.0:1776194657.218501:0:127855:0:(nrs_fifo.c:179:nrs_fifo_req_get()) NRS start fifo request from 12345-0@lo, seq: 595
00000100:00100000:1.0:1776194657.218505:0:127855:0:(service.c:2324:ptlrpc_server_handle_request()) Handling RPC req@00000000157fce9a pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888960:12345-0@lo:400:kworker/u8:1.0
00000100:00100000:1.0:1776194657.218541:0:127855:0:(service.c:2372:ptlrpc_server_handle_request()) Handled RPC req@00000000157fce9a pname:cluuid+ref:pid:xid:nid:opc:job ll_ost00_000:lustre-MDT0000-mdtlov_UUID+5:3019:x1862468088888960:12345-0@lo:400:kworker/u8:1.0 Request processed in 34us (1058us total) trans 0 rc 0/0
00000100:00100000:1.0:1776194657.218546:0:127855:0:(nrs_fifo.c:241:nrs_fifo_req_stop()) NRS stop fifo request from 12345-0@lo, seq: 595
00000100:00100000:1.0:1776194657.218583:0:3019:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000068711ba4 pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_00:lustre-MDT0000-mdtlov_UUID:3019:1862468088888960:0@lo:400:kworker/u8:1.0
00000100:00100000:0.0:1776194657.219200:0:3021:0:(client.c:2215:ptlrpc_check_set()) Completed RPC req@0000000044233bab pname:cluuid:pid:xid:nid:opc:job ptlrpcd_00_02:d652416a-7c3e-44ba-a9b7-5f75948a75ab:3021:1862468088888768:0@lo:400:kworker/u8:1.0
00010000:00010000:1.0:1776194657.472675:0:127090:0:(ldlm_lockd.c:2792:ldlm_bl_get_work()) No blwi found in queue (no bl locks in queue)
Debug log: 811 lines, 811 kept, 0 dropped, 0 bad.