lr Controller中事务响应时间与日志中的不一致。

manchao

上图是运行场景后的事务响应时间，最大才0.126秒，但是查看运行日志是，却有88多秒的。日志如下：
Virtual User Script started at : 2013-09-04 11:10:53 [MsgId: MMSG-15967]
Starting action vuser_init. [MsgId: MMSG-15919]
Web Services replay version 11.0.0 for Windows 7; Toolkit: "NotDefined"; build 9409 [MsgId: MMSG0]
Run-Time Settings file: "C:\Users\suchenhui\AppData\Local\Temp\lr5tmpdirLz7.322\lrcfg1jC.323\cfgGxT.326" [MsgId: MMSG0]
Vuser directory: "I:\lr\lr_script\mssql_connect" [MsgId: MMSG0]
Vuser output directory: "I:\lr\lr_script\mssql_connect" [MsgId: MMSG0]
LOCAL start date/time:  2013-09-04 11:10:53 [MsgId: MMSG0]
vuser_init.c(3): Warning: The string 'SQL Server' with parameter delimiters is not a parameter. [MsgId: MWAR-13987]
vuser_init.c(3): DB Connection "Connect" started ... Wait .... [MsgId: MMSG-108774]
vuser_init.c(9): 连接数据库成功 [MsgId: MMSG-17999]
Ending action vuser_init. [MsgId: MMSG-15918]
Running Vuser... [MsgId: MMSG-15964]
Starting iteration 1. [MsgId: MMSG-15968]
Starting action Action. [MsgId: MMSG-15919]
Action.c(8): Rendezvous 查询库存 [MsgId: MMSG-17988]
Action.c(9): Notify: Transaction "SQL_Select" started. [MsgId: MMSG-16999]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '1'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C216" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 2 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '2'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "B395" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 3 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '3'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "CP88" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 4 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '4'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BZ29" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 5 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '5'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C510" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 6 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '6'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BW39" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 7 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '7'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "HC42" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 8 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '8'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BM89" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 9 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '9'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BS61" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 10 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '10'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "HF42" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 11 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '11'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "HC63" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 12 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '12'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C603" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 13 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '13'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "CA57" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 14 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '14'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "I557" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 15 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '15'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BS29" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 16 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '16'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C349" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 17 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '17'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C795" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 18 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '18'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "CR12" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 19 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '19'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "HI50" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 20 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '20'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "HD09" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 21 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '21'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "CN70" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 22 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '22'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "BJ89" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 23 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '23'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C401" [MsgId: MMSG-13992]
Action.c(13): Notify: Next row for parameter code = 24 [table  = code]. [MsgId: MMSG-13876]
Action.c(13): Notify: Getting new value for parameter 'code': table = 'code.dat' column = '0' row = '24'. [MsgId: MMSG-13877]
Action.c(13): Notify: Parameter Substitution: parameter "code" =  "C210" [MsgId: MMSG-13992]
Action.c(13): SQL Statement  execution "PerformQuery" started [MsgId: MMSG-108760]
Action.c(13): ================================================ [MsgId: MMSG0]
Action.c(21): The query returned 105 rows. [MsgId: MMSG-17999]
Action.c(24): Notify: Transaction "SQL_Select" ended with "Pass" status (Duration: 88.7412 Wasted Time: 88.7389). [MsgId: MMSG-16871]
Ending action Action. [MsgId: MMSG-15918]
Ending iteration 1. [MsgId: MMSG-15965]
Ending Vuser... [MsgId: MMSG-15966]
Starting action vuser_end. [MsgId: MMSG-15919]
vuser_end.c(3): DB disconnect "Disconnect" started [MsgId: MMSG-108767]
vuser_end.c(3): ================================================ [MsgId: MMSG0]
vuser_end.c(6): 断开连接成功 [MsgId: MMSG-17999]
Ending action vuser_end. [MsgId: MMSG-15918]
Vuser Terminated. [MsgId: MMSG-15963]

补充：在界面上运行与日志中的时间是差不多的。
为什么在Controller的事务响应时间却那么少呢

hlhelei

看清楚Duration: 88.7412 Wasted Time: 88.7389
二者之差 才是事务响应时间
Wasted Time 是代码消耗时间

manchao

看清楚Duration: 88.7412 Wasted Time: 88.7389
二者之差 才是事务响应时间
Wasted Time 是代码消耗时间
hlhelei 发表于 2013-9-4 11:58

谢谢指点。请问，在Controller或者Analysis中，我能获得到这个Wasted Time吗？

manchao

看清楚Duration: 88.7412 Wasted Time: 88.7389
二者之差 才是事务响应时间
Wasted Time 是代码消耗时间
hlhelei 发表于 2013-9-4 11:58

谢谢指点。请问，在Controller或者Analysis中，我能获得到这个Wasted Time吗？

hlhelei

Analysis中 看不到 Wasted Time 这些值的,