core/Profiler.cc

   1 /******************************************************************************
   2  * Copyright (c) 2000-2016 Ericsson Telecom AB
   3  * All rights reserved. This program and the accompanying materials
   4  * are made available under the terms of the Eclipse Public License v1.0
   5  * which accompanies this distribution, and is available at
   6  * http://www.eclipse.org/legal/epl-v10.html
   7  *
   8  * Contributors:
   9  *   Balasko, Jeno
  10  *   Baranyi, Botond
  11  *
  12  ******************************************************************************/
  13
  14 #include "Profiler.hh"
  15 #include <stdio.h>
  16 #include <stdlib.h>
  17 #include <string.h>
  18 #include <unistd.h>
  19 #include <pwd.h>
  20 #include <sys/wait.h>
  21 #include "memory.h"
  22 #include "Runtime.hh"
  23 #include "Logger.hh"
  24
  25 ////////////////////////////////////
  26 ////////// TTCN3_Profiler //////////
  27 ////////////////////////////////////
  28
  29 TTCN3_Profiler ttcn3_prof;
  30
  31 TTCN3_Profiler::TTCN3_Profiler()
  32 : stopped(FALSE), disable_profiler(FALSE), disable_coverage(FALSE)
  33 , aggregate_data(FALSE), disable_stats(FALSE), stats_flags(Profiler_Tools::STATS_ALL)
  34 {
  35   database_filename = mcopystr("profiler.db");
  36   stats_filename = mcopystr("profiler.stats");
  37   reset();
  38 }
  39
  40 TTCN3_Profiler::~TTCN3_Profiler()
  41 {
  42   if (!profiler_db.empty() && !TTCN_Runtime::is_undefined() &&
  43       (!disable_profiler || !disable_coverage)) {
  44     if (aggregate_data && (TTCN_Runtime::is_single() || TTCN_Runtime::is_hc())) {
  45       // import the data from the previous run
  46       import_data();
  47     }
  48     if (TTCN_Runtime::is_hc()) {
  49       // import the data gathered by the other processes (the import function
  50       // waits for them to finish exporting)
  51       for (size_t i = 0; i < pid_list.size(); ++i) {
  52         import_data(pid_list[i]);
  53       }
  54     }
  55     export_data();
  56     if (!disable_stats && (TTCN_Runtime::is_single() || TTCN_Runtime::is_hc())) {
  57       print_stats();
  58     }
  59   }
  60   for (size_t i = 0; i < profiler_db.size(); ++i) {
  61     Free(profiler_db[i].filename);
  62     for (size_t j = 0; j < profiler_db[i].functions.size(); ++j) {
  63       Free(profiler_db[i].functions[j].name);
  64     }
  65   }
  66   Free(database_filename);
  67   Free(stats_filename);
  68 }
  69
  70 void TTCN3_Profiler::start()
  71 {
  72   if (stopped) {
  73     set_prev(disable_profiler ? -1 : TTCN3_Stack_Depth::depth(), NULL, -1);
  74     stopped = FALSE;
  75   }
  76 }
  77
  78 void TTCN3_Profiler::stop()
  79 {
  80   if (!stopped) {
  81     if (NULL != prev_file) {
  82       // update the previous line's time
  83       timeval elapsed = Profiler_Tools::subtract_timeval(get_time(), prev_time);
  84       add_line_time(elapsed, get_element(prev_file), prev_line);
  85       TTCN3_Stack_Depth::update_stack_elapsed(elapsed);
  86     }
  87     stopped = TRUE;
  88   }
  89 }
  90
  91 void TTCN3_Profiler::set_disable_profiler(boolean p_disable_profiler)
  92 {
  93   disable_profiler = p_disable_profiler;
  94 }
  95
  96 void TTCN3_Profiler::set_disable_coverage(boolean p_disable_coverage)
  97 {
  98   disable_coverage = p_disable_coverage;
  99 }
 100
 101 // handles metacharacters in the database or statistics file name
 102 static char* finalize_filename(const char* p_filename_skeleton)
 103 {
 104   size_t len = strlen(p_filename_skeleton);
 105   size_t next_idx = 0;
 106   char* ret_val = NULL;
 107   for (size_t i = 0; i < len - 1; ++i) {
 108     if ('%' == p_filename_skeleton[i]) {
 109       ret_val = mputstrn(ret_val, p_filename_skeleton + next_idx, i - next_idx);
 110       switch (p_filename_skeleton[i + 1]) {
 111       case 'e': // %e -> executable name
 112         ret_val = mputstr(ret_val, TTCN_Logger::get_executable_name());
 113         break;
 114       case 'h': // %h -> host name
 115         ret_val = mputstr(ret_val, TTCN_Runtime::get_host_name());
 116         break;
 117       case 'p': // %p -> process ID
 118         ret_val = mputprintf(ret_val, "%ld", (long)getpid());
 119         break;
 120       case 'l': { // %l -> login name
 121         setpwent();
 122         struct passwd *p = getpwuid(getuid());
 123         if (NULL != p) {
 124           ret_val = mputstr(ret_val, p->pw_name);
 125         }
 126         endpwent();
 127         break; }
 128       case '%': // %% -> single %
 129         ret_val = mputc(ret_val, '%');
 130         break;
 131       default: // unknown sequence -> leave it as it is
 132         ret_val = mputstrn(ret_val, p_filename_skeleton + i, 2);
 133         break;
 134       }
 135       next_idx = i + 2;
 136       ++i;
 137     }
 138   }
 139   if (next_idx < len) {
 140     ret_val = mputstr(ret_val, p_filename_skeleton + next_idx);
 141   }
 142   return ret_val;
 143 }
 144
 145 void TTCN3_Profiler::set_database_filename(const char* p_database_filename)
 146 {
 147   Free(database_filename);
 148   database_filename = finalize_filename(p_database_filename);
 149 }
 150
 151 void TTCN3_Profiler::set_aggregate_data(boolean p_aggregate_data)
 152 {
 153   aggregate_data = p_aggregate_data;
 154 }
 155
 156 void TTCN3_Profiler::set_stats_filename(const char* p_stats_filename)
 157 {
 158   Free(stats_filename);
 159   stats_filename = finalize_filename(p_stats_filename);
 160 }
 161
 162 void TTCN3_Profiler::set_disable_stats(boolean p_disable_stats)
 163 {
 164   disable_stats = p_disable_stats;
 165 }
 166
 167 void TTCN3_Profiler::reset_stats_flags()
 168 {
 169   stats_flags = 0;
 170 }
 171
 172 void TTCN3_Profiler::add_stats_flags(unsigned int p_flags)
 173 {
 174   stats_flags |= p_flags;
 175 }
 176
 177 boolean TTCN3_Profiler::is_profiler_disabled() const
 178 {
 179   return disable_profiler;
 180 }
 181
 182 boolean TTCN3_Profiler::is_running() const
 183 {
 184   return !stopped;
 185 }
 186
 187 void TTCN3_Profiler::add_child_process(pid_t p_pid)
 188 {
 189   pid_list.push_back(p_pid);
 190 }
 191
 192 void TTCN3_Profiler::import_data(pid_t p_pid /* = 0 */)
 193 {
 194   char* file_name = NULL;
 195   if (0 == p_pid) {
 196     // this is the main database file (from the previous run), no suffix needed
 197     file_name = database_filename;
 198   }
 199   else {
 200     // this is the database for one of the PTCs or the MTC,
 201     // suffix the file name with the component's PID
 202     file_name = mprintf("%s.%d", database_filename, p_pid);
 203
 204     // wait for the process to finish
 205     int status = 0;
 206     waitpid(p_pid, &status, 0);
 207   }
 208
 209   Profiler_Tools::import_data(profiler_db, file_name, TTCN_warning);
 210
 211   if (0 != p_pid) {
 212     // the process-specific database file is no longer needed
 213     remove(file_name);
 214     Free(file_name);
 215   }
 216 }
 217
 218 void TTCN3_Profiler::export_data()
 219 {
 220   char* file_name = NULL;
 221   if (TTCN_Runtime::is_single() || TTCN_Runtime::is_hc()) {
 222     // this is the main database file, no suffix needed
 223     file_name = database_filename;
 224   }
 225   else {
 226     // this is the database for one of the PTCs or the MTC,
 227     // suffix the file name with the component's PID
 228     file_name = mprintf("%s.%d", database_filename, (int)getpid());
 229   }
 230
 231   Profiler_Tools::export_data(profiler_db, file_name, disable_profiler,
 232     disable_coverage, TTCN_warning);
 233
 234   if (file_name != database_filename) {
 235     Free(file_name);
 236   }
 237 }
 238
 239 void TTCN3_Profiler::print_stats()
 240 {
 241   if (profiler_db.empty()) {
 242     return;
 243   }
 244
 245   Profiler_Tools::print_stats(profiler_db, stats_filename, disable_profiler,
 246     disable_coverage, stats_flags, TTCN_warning);
 247 }
 248
 249 void TTCN3_Profiler::reset()
 250 {
 251   prev_time.tv_sec = 0;
 252   prev_time.tv_usec = 0;
 253   prev_file = NULL;
 254   prev_line = -1;
 255   prev_stack_len = -1;
 256 }
 257
 258 timeval TTCN3_Profiler::get_time()
 259 {
 260   timeval tv;
 261   gettimeofday(&tv, NULL);
 262   return tv;
 263 }
 264
 265 void TTCN3_Profiler::enter_function(const char* filename, int lineno)
 266 {
 267   if (disable_profiler && disable_coverage) {
 268     return;
 269   }
 270
 271   // Note that the execution time of the last line in a function
 272   // is measured by using the stack depth.
 273   execute_line(filename, lineno);
 274
 275   if (!stopped) {
 276     int element = get_element(filename);
 277
 278     // store function data
 279     if (!disable_coverage) {
 280       ++profiler_db[element].functions[get_function(element, lineno)].exec_count;
 281     }
 282   }
 283 }
 284
 285 void TTCN3_Profiler::execute_line(const char* filename, int lineno)
 286 {
 287   if (disable_profiler && disable_coverage) {
 288     return;
 289   }
 290
 291   if (!disable_profiler && TTCN3_Stack_Depth::depth() > prev_stack_len) {
 292     // this line is in a different function than the last one, don't measure anything
 293     TTCN3_Stack_Depth::add_stack(prev_stack_len, prev_file, filename, prev_line, lineno);
 294   }
 295
 296   if (!stopped) {
 297     if (!disable_profiler && NULL != prev_file) {
 298       // this line is in the same function as the previous one, measure the time difference
 299       timeval elapsed = Profiler_Tools::subtract_timeval(get_time(), prev_time);
 300
 301       // add the elapsed time to the total time of the previous line
 302       add_line_time(elapsed, get_element(prev_file), prev_line);
 303
 304       TTCN3_Stack_Depth::update_stack_elapsed(elapsed);
 305     }
 306
 307     // functions starting at line 0 are: pre_init_module and post_init_module,
 308     // don't include them in the database (as they don't appear in the TTCN-3 code),
 309     // but include any actual code lines they may contain
 310     // also, several instructions could be in the same line, only count the line once
 311     if (0 != lineno && !disable_coverage && (lineno != prev_line || NULL == prev_file ||
 312                                              0 != strcmp(prev_file, filename))) {
 313       int element = get_element(filename);
 314
 315       // increase line execution count
 316       ++profiler_db[element].lines[get_line(element, lineno)].exec_count;
 317     }
 318   }
 319
 320   // store the current location as previous for the next call
 321   set_prev(disable_profiler ? -1 : TTCN3_Stack_Depth::depth(), filename, lineno);
 322 }
 323
 324 int TTCN3_Profiler::get_element(const char* filename)
 325 {
 326   for (size_t i = 0; i < profiler_db.size(); ++i) {
 327     if (0 == strcmp(profiler_db[i].filename, filename)) {
 328       return i;
 329     }
 330   }
 331
 332   Profiler_Tools::profiler_db_item_t item;
 333   item.filename = mcopystr(filename);
 334   profiler_db.push_back(item);
 335   return profiler_db.size() - 1;
 336 }
 337
 338 int TTCN3_Profiler::get_function(int element, int lineno)
 339 {
 340   return Profiler_Tools::get_function(profiler_db, element, lineno);
 341 }
 342
 343 void TTCN3_Profiler::create_function(int element, int lineno, const char* function_name)
 344 {
 345   Profiler_Tools::create_function(profiler_db, element, lineno, function_name);
 346 }
 347
 348 int TTCN3_Profiler::get_line(int element, int lineno)
 349 {
 350   return Profiler_Tools::get_line(profiler_db, element, lineno);
 351 }
 352
 353 void TTCN3_Profiler::create_line(int element, int lineno)
 354 {
 355   Profiler_Tools::create_line(profiler_db, element, lineno);
 356 }
 357
 358 void TTCN3_Profiler::add_line_time(timeval elapsed, int element, int lineno)
 359 {
 360   if (0 == lineno) {
 361     return;
 362   }
 363   profiler_db[element].lines[get_line(element, lineno)].total_time = Profiler_Tools::add_timeval(
 364     profiler_db[element].lines[get_line(element, lineno)].total_time, elapsed);
 365 }
 366
 367 void TTCN3_Profiler::add_function_time(timeval elapsed, int element, int lineno)
 368 {
 369   int func = get_function(element, lineno);
 370   if (-1 == func) {
 371     return;
 372   }
 373   profiler_db[element].functions[func].total_time = Profiler_Tools::add_timeval(
 374     profiler_db[element].functions[func].total_time, elapsed);
 375 }
 376
 377 void TTCN3_Profiler::update_last()
 378 {
 379   if (stopped || (0 == prev_time.tv_sec && 0 == prev_time.tv_usec) || NULL == prev_file) {
 380     return;
 381   }
 382
 383   timeval elapsed = Profiler_Tools::subtract_timeval(get_time(), prev_time);
 384
 385   int element = get_element(prev_file);
 386
 387   // add the elapsed time to the total time of the previous line
 388   add_line_time(elapsed, element, prev_line);
 389   TTCN3_Stack_Depth::update_stack_elapsed(elapsed);
 390
 391   // reset measurement
 392   prev_time.tv_sec = 0;
 393   prev_time.tv_usec = 0;
 394 }
 395
 396 void TTCN3_Profiler::set_prev(int stack_len, const char* filename, int lineno)
 397 {
 398   prev_file = filename;
 399   prev_line = lineno;
 400   if (!disable_profiler) {
 401     prev_time = get_time();
 402     prev_stack_len = stack_len;
 403   }
 404 }
 405
 406 /////////////////////////////////////
 407 ///////// TTCN3_Stack_Depth /////////
 408 /////////////////////////////////////
 409
 410 int TTCN3_Stack_Depth::current_depth = -1;
 411 Vector<TTCN3_Stack_Depth::call_stack_timer_item_t> TTCN3_Stack_Depth::call_stack_timer_db;
 412 boolean TTCN3_Stack_Depth::net_line_times = FALSE;
 413 boolean TTCN3_Stack_Depth::net_func_times = FALSE;
 414
 415 TTCN3_Stack_Depth::TTCN3_Stack_Depth()
 416 {
 417   if (ttcn3_prof.is_profiler_disabled()) {
 418     return;
 419   }
 420   ++current_depth;
 421 }
 422
 423 TTCN3_Stack_Depth::~TTCN3_Stack_Depth()
 424 {
 425   if (ttcn3_prof.is_profiler_disabled()) {
 426     return;
 427   }
 428   ttcn3_prof.update_last();
 429   remove_stack();
 430   if (0 == current_depth) {
 431     ttcn3_prof.reset();
 432   }
 433   --current_depth;
 434 }
 435
 436 void TTCN3_Stack_Depth::set_net_line_times(boolean p_net_line_times)
 437 {
 438   net_line_times = p_net_line_times;
 439 }
 440
 441 void TTCN3_Stack_Depth::set_net_func_times(boolean p_net_func_times)
 442 {
 443   net_func_times = p_net_func_times;
 444 }
 445
 446 void TTCN3_Stack_Depth::add_stack(int stack_len, const char* caller_file, const char* func_file,
 447                                   int caller_line, int start_line)
 448 {
 449   call_stack_timer_item_t item;
 450   item.stack_len = stack_len;
 451   item.caller_file = caller_file;
 452   item.func_file = func_file;
 453   item.caller_line = caller_line;
 454   item.start_line = start_line;
 455   item.elapsed.tv_sec = 0;
 456   item.elapsed.tv_usec = 0;
 457   item.first_call = true;
 458   item.recursive_call = false;
 459
 460   if (!net_line_times || !net_func_times) {
 461     // check if it's a recursive function
 462     for (int i = current_depth - 1; i >= 0 ; --i) {
 463       if (call_stack_timer_db[i].start_line == start_line &&
 464           0 == strcmp(call_stack_timer_db[i].func_file, func_file)) {
 465         item.recursive_call = true;
 466
 467         // check if the caller is new
 468         if (call_stack_timer_db[i].caller_line == caller_line &&
 469             ((NULL == call_stack_timer_db[i].caller_file && NULL == caller_file) ||
 470              (NULL != call_stack_timer_db[i].caller_file && NULL != caller_file &&
 471              0 == strcmp(call_stack_timer_db[i].caller_file, caller_file)))) {
 472           item.first_call = false;
 473           break;
 474         }
 475       }
 476     }
 477   }
 478
 479   call_stack_timer_db.push_back(item);
 480 }
 481
 482 void TTCN3_Stack_Depth::remove_stack()
 483 {
 484   // add the time gathered for this stack level to the appropriate line and function
 485   // except for functions starting at line 0 (pre_init_module and post_init_module)
 486   if (0 != call_stack_timer_db[current_depth].start_line) {
 487     timeval elapsed = call_stack_timer_db[current_depth].elapsed;
 488     if (!net_line_times && NULL != call_stack_timer_db[current_depth].caller_file &&
 489         call_stack_timer_db[current_depth].first_call) {
 490       // add the elapsed time to the caller line, if it exists
 491       // (only add it once for recursive functions, at the first call)
 492       ttcn3_prof.add_line_time(elapsed,
 493         ttcn3_prof.get_element(call_stack_timer_db[current_depth].caller_file),
 494         call_stack_timer_db[current_depth].caller_line);
 495     }
 496     if (!net_func_times && !call_stack_timer_db[current_depth].recursive_call) {
 497       // add the elapsed time to the called function, if it's not recursive
 498       // (in case of net function times this has already been done in update_stack_elapsed)
 499       ttcn3_prof.add_function_time(elapsed,
 500         ttcn3_prof.get_element(call_stack_timer_db[current_depth].func_file),
 501         call_stack_timer_db[current_depth].start_line);
 502     }
 503   }
 504
 505   ttcn3_prof.set_prev(call_stack_timer_db[current_depth].stack_len,
 506     call_stack_timer_db[current_depth].caller_file,
 507     call_stack_timer_db[current_depth].caller_line);
 508
 509   call_stack_timer_db.erase_at(current_depth);
 510 }
 511
 512 void TTCN3_Stack_Depth::update_stack_elapsed(timeval elapsed)
 513 {
 514   // if function times are net times, only add the elapsed time to the current function
 515   if (net_func_times) {
 516     ttcn3_prof.add_function_time(elapsed,
 517       ttcn3_prof.get_element(call_stack_timer_db[current_depth].func_file),
 518       call_stack_timer_db[current_depth].start_line);
 519   }
 520   if (!net_line_times || !net_func_times) {
 521     // cycle through the stack and add the elapsed time to the entries where
 522     // the function/caller pair appears for the first time (marked by 'first_call')
 523     for(int i = 0; i <= current_depth; ++i) {
 524       if (call_stack_timer_db[i].first_call) {
 525         call_stack_timer_db[i].elapsed = Profiler_Tools::add_timeval(
 526           call_stack_timer_db[i].elapsed, elapsed);
 527       }
 528     }
 529   }
 530 }