lr_start_timer，lr_get_transaction_duration，lr_get_transaction_wasted_time函数使用总结

lr_start_timer：

函数的功能：

为了计算时间更加精确，可以用这个函数去掉LR自身的检查点所浪费的时间。如text check and image time

 

Action()
{
double time_elapsed;
merc_timer_handle_t timer;

web_url("487989.html",
   "URL=http://www.cnblogs.com/tester2test/archive/2006/08/28/487989.html",
   "Resource=0",
   "RecContentType=text/html",
   "Referer=",
   "Snapshot=t2.inf",
   "Mode=HTML",
   LAST);

lr_start_transaction("download");

timer = lr_start_timer();

Download("http://files.cnblogs.com/tester2test/xncssj.pdf", "http://www.cnblogs.com/tester2test/archive/2006/08/28/487989.html", "c:\test.pdf", "wb");

time_elapsed = lr_end_timer(timer);

lr_wasted_time(time_elapsed * 1000);

lr_end_transaction("download", LR_AUTO);

return 0;
}

double time_elapsed, duration, waste;

merc_timer_handle_t timer;

        lr_start_transaction("sampleTrans");

        web_url("index.htm",

               "URL=http://localhost/index.htm",

               "TargetFrame=",

               "Resource=0",

               "RecContentType=text/html",

               "Referer=",

               "Snapshot=t1.inf",

               "Mode=HTML",

               LAST);

        timer = lr_start_timer();

/* Do some checks the duration of which

is not to be included in the transaction. */

        web_image_check("ImgCheck1",

               "src=index_files/image002.jpg",

               LAST);

        web_image_check("ImgCheck2",

               "src=index_files/planets.gif",

               LAST);

// How long did the tests take in seconds.

        time_elapsed = lr_end_timer(timer);

// Convert to millisecond.s

        waste = time_elapsed * 1000;

/* Remove the time the checks took from

        the transaction. */

        lr_wasted_time(waste);

         lr_end_transaction("sampleTrans", LR_AUTO);

lr_get_transaction_duration：返回事件执行到此处所用的时间

C 语言:

double lr_get_transaction_duration(const char *transaction);

   
Example:

Action()

{

      double Connect_trans_time;  // 接收函数返回值

      double Move_trans_time;

   

      lr_start_transaction("Connect_trans");

      lr_create_socket("socket0","TCP","RemoteHost = localhost:1111",LrsLastArg);  // IP和端口仅供参考

      //......(others)

   

      // 调用 lr_get_transaction_duration() 函数

      Connect_trans_time = lr_get_transaction_duration("Connect_trans");

      lr_end_transaction("Connect_trans",LR_AUTO);

   

      lr_start_transaction("Move_trans");

      //......(others)

      Move_trans_time = lr_get_transaction_duration("Move"); // 获取 Move_trans 事件执行到此处所用时间

      lr_end_transaction("Move_trans",LR_AUTO);

   

      lr_output_message("The duration up to the <Connect_trans_time> is %f seconds",Connect_trans_time);

      lr_output_message("The duration up to the <Move_trans_time> is %f seconds",Move_trans_time);

   

      return 0;

}

    

   

Action.c(1259): Notify: Transaction "Connect_trans" ended with "Pass" status (Duration:1.1164)

Action.c(1717): Notify: Transaction "Move_trans" ended with "Pass" status (Duration: 0.4036)

Action.c(1719): The duration up to the <Connec_trans_time> is 1.116110 seconds

Action.c(1721): The duration up to the <Move_trans_time> is 0.403350 seconds

    

根据业务操作分离出脚本中的两个事件，Connect（连接DB）操作和Move（拖屏）操作，Contro中运行结果显示“拖屏”消耗时间远大于“连接”消耗时间，这同程序设计与实现的实际情况不符。

所以调用了【lr_get_transaction_duration();】函数来验证事件的运行时间，进一步分析性能问题原因所在。

验证结果已证明拖屏操作消耗时间的确小于连接操作消耗时间。

 

lr_get_transaction_wasted_time：函数用于返回指定事物当前的损耗时间(wasted time)。

函数统计的是事物开始到此函数位置，lr自身的浪费时间（如：执行关联、检查点等函数的时间）。
 
损耗时间通常是指脚本消耗在为了支持测试分析而做的操作时间。这些操作不会被实际用户所执行。
 
例如一些循环赋值操作或插入检查点操作。消耗的时间有lr_wasted_time函数在

 
lr_get_transaction_wasted_time函数之前移除了，移除后才得到对应的结果。

函数语法结果

double lr_get_transaction_wasted_time （const char * transaction);

参数 transaction 为事物名称

 
使用lr_get_transaction_wansted_time
函数必须注意，

一它只能对当前运行状态的事物才能返回大于等于0的结果，否则返回小于0的结果。

二是他使用之前应调用lr_wansted_time 函数移除过损耗时间
wasted time，否则lr_get_transaction_wansted_time将返回0。

附代码如下：
        timer=lr_start_timer();
         web_find("web_find",
         "what=9000000022",
         LAST);
         time_elapsed=lr_end_timer(timer);

         lr_output_message("find时间为：%f",time_elapsed);
         lr_output_message("事务当前的损耗时间为：%f",lr_get_transaction_wasted_time("登陆"));  //先算出从事务开始到现在lr自身的浪费时间。因为无损耗,所以，lr_get_transaction_wasted_time= 0s 。

        //使用lr_wasted_time（）函数为事物添加浪费时间
        lr_wasted_time(time_elapsed*1000);     //Wasted Time=lr自身的浪费时间（0s）+第三方时间的开销（time_elapsed*1000s)）
        lr_output_message("find时间为：%f,事务当前的损耗时间为：%f",time_elapsed,lr_get_transaction_wasted_time("登陆"));

Action()
{
    int i, baseIter = 1000; 


    char dude[1000]; 


    double wasteTime, actualElapsedTime; 


    merc_timer_handle_t MasterT, timer; 


    // Examine the total elapsed time of the action 


    MasterT = lr_start_timer(); 


    //Start transaction 


    lr_start_transaction("Demo"); 


    // Create some elapsed time for the transaction 


    for (i=0; i< (10 * baseIter); ++i) 
        sprintf(dude, "This is the way we create elapsed time artificially = %d", i); 
    


    // Add some think time 


    lr_think_time(0.5); 


    // Create some wasted time and record it with timer 


    timer = lr_start_timer(); 


    for (i=0; i< (5 * baseIter); ++i) 


  sprintf(dude, "This is the way we waste time in a script = %d", i); 


    wasteTime = lr_end_timer(timer); 


    lr_output_message("User created waste time = %lf", wasteTime); 


    lr_output_message("Before lr_waste_time: Duration = %lf - Waste = %lf",         


        lr_get_transaction_duration("Demo"), 


        lr_get_transaction_wasted_time("Demo")); 


    /* Convert Timer in seconds to wasted time in milliseconds 


     and add to internally generated waste time */ 


    wasteTime *= 1000; 


    lr_wasted_time(wasteTime); 


    lr_output_message("After lr_waste_time: Duration = %lf - Waste = %lf", 


            lr_get_transaction_duration("Demo"), 


            lr_get_transaction_wasted_time("Demo")); 


    lr_output_message("Think time = %lf", lr_get_transaction_think_time("Demo")); 


    lr_end_transaction("Demo", LR_AUTO); 


    actualElapsedTime = lr_end_timer(MasterT); 


    lr_output_message("Total Elapsed time for Action = %lf", actualElapsedTime);




 return 0;
}


结果：
Starting iteration 1.
Starting action Action.
Action.c(17): Notify: Transaction "Demo" started.
Action.c(45): User created waste time = 15.768059
Action.c(47): Before lr_waste_time: Duration = 65.147478 - Waste = 0.000000
Action.c(61): After lr_waste_time: Duration = 65.153110 - Waste = 15.768000
Action.c(67): Think time = 0.000000
Action.c(71): Notify: Transaction "Demo" ended with "Pass" status (Duration: 65.1589 Wasted Time: 15.7680).
Action.c(75): Total Elapsed time for Action = 65.170579
Ending action Action.
Ending iteration 1.

 lr_get_transaction_wasted_time函数用于返回指定事物当前的损耗时间(wasted time)。     损耗时间通常是指脚本消耗在为了支持测试分析而做的操作时间。这些操作不会被实际用户所执行。     例如一些循环赋值操作或插入检查点操作。消耗的时间有lr_wasted_time函数在
  lr_get_transaction_wasted_time函数之前移除了，移除后才得到对应的结果。
  函数语法结果
  double lr_get_transaction_wasted_time （const char * transaction);
  参数 transaction 为事物名称
  使用lr_get_transaction_wansted_time 函数必须注意，一它只能对当前运行状态的事物才能返回大于等于0的结果，否则返回小于0的结果。二是他使用之前应调用lr_wansted_time 函数移除过损耗时间 wasted time，否则lr_get_transaction_wansted_time将返回0。

帮助例子程序：

WasteTime()

{

       int i, baseIter = 1000;

       char dude[1000];

       double wasteTime, actualElapsedTime;

       merc_timer_handle_t MasterT, timer;

       // Examine the total elapsed time of the action

       MasterT = lr_start_timer();

       //Start transaction

       lr_start_transaction("Demo");

       // Create some elapsed time for the transaction

       for (i=0; i< (10 * baseIter); ++i)

      sprintf(dude,

        "This is the way we create elapsed  time artificially = %d", i);                 

       // Add some think time

       lr_think_time(0.5);

       // Create some wasted time and record it with timer

       timer =lr_start_timer();

       for (i=0; i< (5 * baseIter); ++i)

                     sprintf(dude,

                            "This is the way we waste time in  a script. = %d", i);

       wasteTime =lr_end_timer(timer);

       lr_output_message("User created waste time = %lf",  wasteTime);

       lr_output_message("Before lr_waste_time: Duration = %lf  - Waste = %lf",              

         lr_get_transaction_duration("Demo"),

        lr_get_transaction_wasted_time("Demo"));

       /* Convert Timer in seconds to wasted time in  milliseconds

        and add to internally generated waste time */

       wasteTime *= 1000;

       lr_wasted_time(wasteTime);

       lr_output_message("After lr_waste_time: Duration = %lf  - Waste = %lf",

        lr_get_transaction_duration("Demo"),

       lr_get_transaction_wasted_time("Demo"));

       lr_output_message("Think time = %lf",

              lr_get_transaction_think_time("Demo"));

       lr_end_transaction("Demo", LR_AUTO);

       actualElapsedTime = lr_end_timer(MasterT);

       lr_output_message("Total Elapsed time for Action =  %lf",

              actualElapsedTime);

       return 0;

}

Vuser Output log file 输出日志

Note there is no difference between the transaction duration  before and after the call to lr_waste_time

WasteTime.c(28): User created waste time = 0.031250       

WasteTime.c(32): Before lr_waste_time: Duration = 0.609375 -  Waste = 0.000000       

WasteTime.c(40): After lr_waste_time: Duration = 0.625000 -  Waste = 0.031000       

WasteTime.c(44): Think time = 0.500000       

WasteTime.c(47): Notify: Transaction Demo ended with Pass  status (Duration: 0.6406 Think Time: 0.5000 Wasted Time: 0.0310).       

WasteTime.c(50): Total Elapsed time for Action = 0.640625        

Analysis: Average Response Time Raw Data

Note that the Transaction Response Time for "Demo" is 0.61.  This is the Duration from the Vuser log (0.6406) minus the Wasted Time (  0.0310).

Transaction End Status	Transaction Father Tree path	Scenario Elapsed Time	Transaction Response Time	Transaction Name
Pass	NONE	4.843	0	vuser_init_Transaction
Pass	WasteTime_Transaction	5.514	0.61	Demo
Pass	NONE	5.53	0.625	WasteTime_Transaction
Pass	NONE	5.53	0	vuser_end_Transaction