Benchmark性能测试4并发失败后,再次测试之前测试成功的并发用例失败
[2025-05-21 14:30:37.558+08:00] [426266] [281461462266272] [client] [ERROR] [utils.py:47] Request failed and the reason is abnormal value: Expecting value: line 1 column 2 (char 1), response from se
er is: Engine callback timeout: server e2eTimeout
[2025-05-21 14:30:37.559+08:00] [426266] [281461462266272] [benchmark】 [ERROR] [base api.py:297] [MIEQ1E000008] Request e7409a5f33d1473c88673cf98f218de9 occurs error with message . Invalid response
rmat, please check the message in mindie-client.
[2025-05-21 14:30:37.559+08:00] [426266] [281473072278336] [benchmark] [INFO] [base_api.py:316] Handling 1 requests, failed 1
[2025-05-21 14:30:37.560+08:00] [426266] [281473072278336] [benchmark】 【ERROR] (base api.py:255] [MIEQ1E000005] All requests failed, please check dataset path or other settings.
[2025-05-21 14:30:37.598+08:00] [425973] [281473072278336] [benchmark] [INFO] [benchmarker.py:197] Finish mindie-client inference
Merging data from different processes: 100% 1/1 [00:00<00:00, 2281.99item/
[2025-05-21 14:30:37.641+08:00] [425973] [281473072278336] [benchmark] LINFO] loutput.py:287] calc_common metrics start time: 1747808404.3719962 !
[2025-05-21 14:30:37.641+08:00] [425973] [281473072278336] [benchmark] [wARN] loutput.py:289] [MIEO1W000005] Empty response numbers: 0 !
[2025-05-21 14:30:37.646+08:00] [425973] [281473072278336] [benchmark] [iNFo] [output.py:115]
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC_communicator.cpp:638] : [model_backend] Backend rank 1, start processing the recv message
[==
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:710] : [model backend] Backend rank 1, after calling executor InstanceExecute
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:638] : [model backend] Backend rank 0, start processing the recv message
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:739] : [model backend] Backend rank 1, finish sending infer response message
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave_IPC_communicator.cpp:710] : [model_backend] [ Backend rank 0, after calling executor InstanceExecute
[2025-05-21 14:30:37,732] [416630] [281464114311520] [LLm] [DEBUG] [generator.py-263] : Rank-1 is clearing the cache of [135].
[2025-05-21 14:30:37.733] [416648] [281463889260896] [ULm] [DEBUG] [post processing_manager.cpp:293] Delete conf for 135
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [model agent.cpp:77]: [model backend] [TEST LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:714] : [model backend] [- Backend rank 0, before SerializeInferResponsesMessage
a
[2025-05-21 14:30:37.021+0800] [416628][281473357640032] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave_IPC_communicator.cpp:723] : [model_backend] [= Backend rank 0, after SerializeInferResponsesMessage
[2025-05-21 14:30:37.733+08:00] [416648] [417533] [batchscheduler] (DEBUG] [slave IPC_communicator.cpp:638] : [model_backend] [ Backend rank 3, start processing the recv message
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [master IPC communicator.cpp:539] : [model backend] [ Backend main process: before DeSerializeExecuteResponse
[2025-05-21 14:30:37.733] [416424] [281467608035296] [LLm] [DEBUG] [Llm infer engine ibis api.cpp:455] The model instance executed requests successfully.
[2025-05-21 14:30:37.733408:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis request.cDp:418] : [batch scheduler] IBIS get EndFlag ATTR Tensor, shape: [1.2] tokenNum:1
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:734] : [model backend] [= ====== Backend rank 0, finish sending infer response message, mess
e len:214 =
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [master_IPC_communicator.cpp:226] : [model_backend] BatchSize from sub-process is 1
[2025-05-21 14:30:37.733+08:00][416648] [417533] [batchscheduler] [DEBUG] [slave_TPC_communicator.cpp:710] : [model_backend] [ Backend rank 3, after calling executor InstanceExecute
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [gmis agent base plugin.cpp:88] : [batch scheduler] ContinueBatching, batch id [1032] batch sequence number [1033], worker
read tid [281467608035296]
[2025-05-21 14:30:37.021+0800] [416630] [281473315631456] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00][416424] [420070] [batchscheduler] [DEBUG] [master_IPC_communicator.cpp:583] : [model_backend] [==== Backend main process: after DeSerializeExecuteResponse, ir
r success
[2025-05-21 14:30:37,732] [416648] [281463889260896] [LLm] [DEBUG] [generator.py-263] : Rank-3 is clearing the cache of [135].
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [model agent.cpp:77]: [model backend] [TEST_LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
] [pueypeq 1эpow] : [6£/:ddo JoqepTunwwOO OdI axels] [ON830] [Jalnpayosyogeq] [EES/TV] [8799TV] [00:80+£E/'/8:08:VI T7-SO-SZOZ] Backend rank 3, finish sending infer response message
[2025-05-21 14:30:37.734+08:00] [416424] [420072] [server] [DEBUG] [common_wrapper.cpp:36] : [endpoint] Delete CommonWrapper #36
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis response.cpp:20] : [batch scheduler] success to get IBIS_EOS_ATTR
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [model_backend.cpp:811] : [model_backend] Decode Counts: 1032 workId: O requests size: 1 token to token time: 4 ms; end to
time: 3 ms
[2025-05-21 14:30:37.733+08:00] [4166481 [417533] [batchscheduler] [DEBUG] [model_agent.cpp:77] : [model backend] [TEST_LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get IBIS_SEQS_ID
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get PARENT_SEQS_ID
[2025-05-21 14:30:37.733+08:00] [416424】 [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get OUTPUT_IDS
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis model instance block manager v2.cpp:354] : [batch scheduler] KVCacheLog Request:135 Free. Released Block: blockTabl
reaTd=135. tye=DEVICE 1685. 686. 687. 688. 689.690.691.692.693.694.695.696.697. 698.699. 700.701. 702. 703. 704. 705. 706. 707. 708. 709. 710. 711. 712. 713. 714. 715. 716. 717. 718. 719
20, 721, 722, 723, 724, 725, 726, 727, 728, 729, 730, 731, 732, 733, 734, 735, 736, 737, 738, 739, 740, 741, 742, 743, 744, 745, 746, 747, 748, 749, 750, 751, 752, 753, 754, 755, 756, 757, 758, 759,
60, 761, 762, 763, 764, 765, 766, 767, 768, 769, 770, 771, 772, 773, 774, 775, 776, 777, 778, 779, 780, 781, 782, 783, 784, 785, 786, 787, 788, 789, 790, 791, 792, 793, 794, 795, 796, 797, 798, 799,
00, 801, 802, 803, 804, 805, 806, 807, 808, 809, 810, 811, 812, 813, 814, 815}
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [ibis request.h:37] : [batch scheduler] Update AsyncRequest 35 to SECOND END
[2025-05-21 14:30:37.021+0800] [416648] [281473223422304] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [gmis_agent base_plugin.cpp:155] : [batch_scheduler] Request end, reqId: 35, endState: 2
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [gmis agent local worker.cpp:112] : [batch scheduler] Finish Batch Execute, batch id [1032] batch sequence number [1033],
Benchmark性能测试4并发失败后,再次测试之前测试成功的并发用例失败
[2025-05-21 14:30:37.558+08:00] [426266] [281461462266272] [client] [ERROR] [utils.py:47] Request failed and the reason is abnormal value: Expecting value: line 1 column 2 (char 1), response from se
er is: Engine callback timeout: server e2eTimeout
[2025-05-21 14:30:37.559+08:00] [426266] [281461462266272] [benchmark】 [ERROR] [base api.py:297] [MIEQ1E000008] Request e7409a5f33d1473c88673cf98f218de9 occurs error with message . Invalid response
rmat, please check the message in mindie-client.
[2025-05-21 14:30:37.559+08:00] [426266] [281473072278336] [benchmark] [INFO] [base_api.py:316] Handling 1 requests, failed 1
[2025-05-21 14:30:37.560+08:00] [426266] [281473072278336] [benchmark】 【ERROR] (base api.py:255] [MIEQ1E000005] All requests failed, please check dataset path or other settings.
[2025-05-21 14:30:37.598+08:00] [425973] [281473072278336] [benchmark] [INFO] [benchmarker.py:197] Finish mindie-client inference
Merging data from different processes: 100% 1/1 [00:00<00:00, 2281.99item/
[2025-05-21 14:30:37.641+08:00] [425973] [281473072278336] [benchmark] LINFO] loutput.py:287] calc_common metrics start time: 1747808404.3719962 !
[2025-05-21 14:30:37.641+08:00] [425973] [281473072278336] [benchmark] [wARN] loutput.py:289] [MIEO1W000005] Empty response numbers: 0 !
[2025-05-21 14:30:37.646+08:00] [425973] [281473072278336] [benchmark] [iNFo] [output.py:115]
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC_communicator.cpp:638] : [model_backend] Backend rank 1, start processing the recv message
[==
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:710] : [model backend] Backend rank 1, after calling executor InstanceExecute
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:638] : [model backend] Backend rank 0, start processing the recv message
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:739] : [model backend] Backend rank 1, finish sending infer response message
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave_IPC_communicator.cpp:710] : [model_backend] [ Backend rank 0, after calling executor InstanceExecute
[2025-05-21 14:30:37,732] [416630] [281464114311520] [LLm] [DEBUG] [generator.py-263] : Rank-1 is clearing the cache of [135].
[2025-05-21 14:30:37.733] [416648] [281463889260896] [ULm] [DEBUG] [post processing_manager.cpp:293] Delete conf for 135
[2025-05-21 14:30:37.733+08:00] [416630] [417522] [batchscheduler] [DEBUG] [model agent.cpp:77]: [model backend] [TEST LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:714] : [model backend] [- Backend rank 0, before SerializeInferResponsesMessage
a
[2025-05-21 14:30:37.021+0800] [416628][281473357640032] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave_IPC_communicator.cpp:723] : [model_backend] [= Backend rank 0, after SerializeInferResponsesMessage
[2025-05-21 14:30:37.733+08:00] [416648] [417533] [batchscheduler] (DEBUG] [slave IPC_communicator.cpp:638] : [model_backend] [ Backend rank 3, start processing the recv message
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [master IPC communicator.cpp:539] : [model backend] [ Backend main process: before DeSerializeExecuteResponse
[2025-05-21 14:30:37.733] [416424] [281467608035296] [LLm] [DEBUG] [Llm infer engine ibis api.cpp:455] The model instance executed requests successfully.
[2025-05-21 14:30:37.733408:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis request.cDp:418] : [batch scheduler] IBIS get EndFlag ATTR Tensor, shape: [1.2] tokenNum:1
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [slave IPC communicator.cpp:734] : [model backend] [= ====== Backend rank 0, finish sending infer response message, mess
e len:214 =
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [master_IPC_communicator.cpp:226] : [model_backend] BatchSize from sub-process is 1
[2025-05-21 14:30:37.733+08:00][416648] [417533] [batchscheduler] [DEBUG] [slave_TPC_communicator.cpp:710] : [model_backend] [ Backend rank 3, after calling executor InstanceExecute
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [gmis agent base plugin.cpp:88] : [batch scheduler] ContinueBatching, batch id [1032] batch sequence number [1033], worker
read tid [281467608035296]
[2025-05-21 14:30:37.021+0800] [416630] [281473315631456] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00][416424] [420070] [batchscheduler] [DEBUG] [master_IPC_communicator.cpp:583] : [model_backend] [==== Backend main process: after DeSerializeExecuteResponse, ir
r success
[2025-05-21 14:30:37,732] [416648] [281463889260896] [LLm] [DEBUG] [generator.py-263] : Rank-3 is clearing the cache of [135].
[2025-05-21 14:30:37.733+08:00] [416628] [417532] [batchscheduler] [DEBUG] [model agent.cpp:77]: [model backend] [TEST_LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
] [pueypeq 1эpow] : [6£/:ddo JoqepTunwwOO OdI axels] [ON830] [Jalnpayosyogeq] [EES/TV] [8799TV] [00:80+£E/'/8:08:VI T7-SO-SZOZ] Backend rank 3, finish sending infer response message
[2025-05-21 14:30:37.734+08:00] [416424] [420072] [server] [DEBUG] [common_wrapper.cpp:36] : [endpoint] Delete CommonWrapper #36
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis response.cpp:20] : [batch scheduler] success to get IBIS_EOS_ATTR
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [model_backend.cpp:811] : [model_backend] Decode Counts: 1032 workId: O requests size: 1 token to token time: 4 ms; end to
time: 3 ms
[2025-05-21 14:30:37.733+08:00] [4166481 [417533] [batchscheduler] [DEBUG] [model_agent.cpp:77] : [model backend] [TEST_LOG] ModelAgent::ProcessRecvPythonMessage using channel: 1
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get IBIS_SEQS_ID
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get PARENT_SEQS_ID
[2025-05-21 14:30:37.733+08:00] [416424】 [420070] [batchscheduler] [DEBUG] [ibis_response.cpp:20] : [batch_scheduler] success to get OUTPUT_IDS
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [ibis model instance block manager v2.cpp:354] : [batch scheduler] KVCacheLog Request:135 Free. Released Block: blockTabl
reaTd=135. tye=DEVICE 1685. 686. 687. 688. 689.690.691.692.693.694.695.696.697. 698.699. 700.701. 702. 703. 704. 705. 706. 707. 708. 709. 710. 711. 712. 713. 714. 715. 716. 717. 718. 719
20, 721, 722, 723, 724, 725, 726, 727, 728, 729, 730, 731, 732, 733, 734, 735, 736, 737, 738, 739, 740, 741, 742, 743, 744, 745, 746, 747, 748, 749, 750, 751, 752, 753, 754, 755, 756, 757, 758, 759,
60, 761, 762, 763, 764, 765, 766, 767, 768, 769, 770, 771, 772, 773, 774, 775, 776, 777, 778, 779, 780, 781, 782, 783, 784, 785, 786, 787, 788, 789, 790, 791, 792, 793, 794, 795, 796, 797, 798, 799,
00, 801, 802, 803, 804, 805, 806, 807, 808, 809, 810, 811, 812, 813, 814, 815}
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [ibis request.h:37] : [batch scheduler] Update AsyncRequest 35 to SECOND END
[2025-05-21 14:30:37.021+0800] [416648] [281473223422304] [batchscheduler] [DEBUG] [model.py:107] : [python thread: infer] block waiting for a inference task
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [INFO] [gmis_agent base_plugin.cpp:155] : [batch_scheduler] Request end, reqId: 35, endState: 2
[2025-05-21 14:30:37.733+08:00] [416424] [420070] [batchscheduler] [DEBUG] [gmis agent local worker.cpp:112] : [batch scheduler] Finish Batch Execute, batch id [1032] batch sequence number [1033],