src/vm/statistics.c

   1 /* vm/statistics.c - global varables for statistics
   2
   3    Copyright (C) 1996-2005 R. Grafl, A. Krall, C. Kruegel, C. Oates,
   4    R. Obermaisser, M. Platter, M. Probst, S. Ring, E. Steiner,
   5    C. Thalinger, D. Thuernbeck, P. Tomsich, C. Ullrich, J. Wenninger,
   6    Institut f. Computersprachen - TU Wien
   7
   8    This file is part of CACAO.
   9
  10    This program is free software; you can redistribute it and/or
  11    modify it under the terms of the GNU General Public License as
  12    published by the Free Software Foundation; either version 2, or (at
  13    your option) any later version.
  14
  15    This program is distributed in the hope that it will be useful, but
  16    WITHOUT ANY WARRANTY; without even the implied warranty of
  17    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  18    General Public License for more details.
  19
  20    You should have received a copy of the GNU General Public License
  21    along with this program; if not, write to the Free Software
  22    Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA
  23    02111-1307, USA.
  24
  25    Contact: cacao@complang.tuwien.ac.at
  26
  27    Authors: Christian Thalinger
  28
  29    $Id: statistics.c 1954 2005-02-17 19:47:23Z christian $
  30
  31 */
  32
  33
  34 #include <sys/time.h>
  35 #include <sys/resource.h>
  36
  37 #include "toolbox/logging.h"
  38 #include "vm/global.h"
  39 #include "vm/options.h"
  40 #include "vm/statistics.h"
  41
  42
  43 /* global variables */
  44
  45 static s8 loadingtime = 0;              /* accumulated loading time           */
  46 static s8 loadingstarttime = 0;
  47 static s8 loadingstoptime = 0;
  48 static s4 loadingtime_recursion = 0;
  49
  50 static s8 compilingtime = 0;            /* accumulated compile time           */
  51 static s8 compilingstarttime = 0;
  52 static s8 compilingstoptime = 0;
  53 static s4 compilingtime_recursion = 0;
  54
  55 s4 memoryusage = 0;
  56 s4 maxmemusage = 0;
  57 s4 maxdumpsize = 0;
  58
  59 s4 globalallocateddumpsize = 0;
  60 s4 globaluseddumpsize = 0;
  61
  62 int count_class_infos = 0;              /* variables for measurements         */
  63 int count_const_pool_len = 0;
  64 int count_vftbl_len = 0;
  65 int count_all_methods = 0;
  66 int count_methods_marked_used = 0;  /* RTA */
  67
  68 int count_vmcode_len = 0;
  69 int count_extable_len = 0;
  70 int count_class_loads = 0;
  71 int count_class_inits = 0;
  72
  73 int count_utf_len = 0;                  /* size of utf hash                   */
  74 int count_utf_new = 0;                  /* calls of utf_new                   */
  75 int count_utf_new_found  = 0;           /* calls of utf_new with fast return  */
  76
  77 int count_locals_conflicts = 0;         /* register allocator statistics */
  78 int count_locals_spilled = 0;
  79 int count_locals_register = 0;
  80 int count_ss_spilled = 0;
  81 int count_ss_register = 0;
  82 int count_methods_allocated_by_lsra = 0;
  83 int count_mem_move_bb = 0;
  84 int count_interface_size = 0;
  85 int count_argument_mem_ss = 0;
  86 int count_argument_reg_ss = 0;
  87 int count_method_in_register = 0;
  88
  89 int count_jit_calls = 0;
  90 int count_methods = 0;
  91 int count_spills = 0;
  92 int count_spills_read = 0;
  93 int count_pcmd_activ = 0;
  94 int count_pcmd_drop = 0;
  95 int count_pcmd_zero = 0;
  96 int count_pcmd_const_store = 0;
  97 int count_pcmd_const_alu = 0;
  98 int count_pcmd_const_bra = 0;
  99 int count_pcmd_load = 0;
 100 int count_pcmd_move = 0;
 101 int count_load_instruction = 0;
 102 int count_pcmd_store = 0;
 103 int count_pcmd_store_comb = 0;
 104 int count_dup_instruction = 0;
 105 int count_pcmd_op = 0;
 106 int count_pcmd_mem = 0;
 107 int count_pcmd_met = 0;
 108 int count_pcmd_bra = 0;
 109 int count_pcmd_table = 0;
 110 int count_pcmd_return = 0;
 111 int count_pcmd_returnx = 0;
 112 int count_check_null = 0;
 113 int count_check_bound = 0;
 114 int count_max_basic_blocks = 0;
 115 int count_basic_blocks = 0;
 116 int count_javainstr = 0;
 117 int count_max_javainstr = 0;
 118 int count_javacodesize = 0;
 119 int count_javaexcsize = 0;
 120 int count_calls = 0;
 121 int count_tryblocks = 0;
 122 int count_code_len = 0;
 123 int count_data_len = 0;
 124 int count_cstub_len = 0;
 125 int count_nstub_len = 0;
 126 int count_max_new_stack = 0;
 127 int count_upper_bound_new_stack = 0;
 128 static int count_block_stack_init[11] = {
 129         0, 0, 0, 0, 0,
 130         0, 0, 0, 0, 0,
 131         0
 132 };
 133 int *count_block_stack = count_block_stack_init;
 134 static int count_analyse_iterations_init[5] = {
 135         0, 0, 0, 0, 0
 136 };
 137 int *count_analyse_iterations = count_analyse_iterations_init;
 138 static int count_method_bb_distribution_init[9] = {
 139         0, 0, 0, 0, 0,
 140         0, 0, 0, 0
 141 };
 142 int *count_method_bb_distribution = count_method_bb_distribution_init;
 143 static int count_block_size_distribution_init[18] = {
 144         0, 0, 0, 0, 0,
 145         0, 0, 0, 0, 0,
 146         0, 0, 0, 0, 0,
 147         0, 0, 0
 148 };
 149 int *count_block_size_distribution = count_block_size_distribution_init;
 150 static int count_store_length_init[21] = {
 151         0, 0, 0, 0, 0,
 152         0, 0, 0, 0, 0,
 153         0, 0, 0, 0, 0,
 154         0, 0, 0, 0, 0,
 155         0
 156 };
 157 int *count_store_length = count_store_length_init;
 158 static int count_store_depth_init[11] = {
 159         0, 0, 0, 0, 0,
 160         0, 0, 0, 0, 0,
 161         0
 162 };
 163 int *count_store_depth = count_store_depth_init;
 164
 165
 166 /* getcputime *********************************** ******************************
 167
 168    Returns the used CPU time in microseconds
 169
 170 *******************************************************************************/
 171
 172 s8 getcputime()
 173 {
 174         struct rusage ru;
 175         int sec, usec;
 176
 177         getrusage(RUSAGE_SELF, &ru);
 178         sec = ru.ru_utime.tv_sec + ru.ru_stime.tv_sec;
 179         usec = ru.ru_utime.tv_usec + ru.ru_stime.tv_usec;
 180
 181         return sec * 1000000 + usec;
 182 }
 183
 184
 185 /* loadingtime_stop ************************************************************
 186
 187    XXX
 188
 189 *******************************************************************************/
 190
 191 void loadingtime_start()
 192 {
 193         loadingtime_recursion++;
 194
 195         if (loadingtime_recursion == 1)
 196                 loadingstarttime = getcputime();
 197 }
 198
 199
 200 /* loadingtime_stop ************************************************************
 201
 202    XXX
 203
 204 *******************************************************************************/
 205
 206 void loadingtime_stop()
 207 {
 208         if (loadingtime_recursion == 1) {
 209                 loadingstoptime = getcputime();
 210                 loadingtime += (loadingstoptime - loadingstarttime);
 211         }
 212
 213         loadingtime_recursion--;
 214 }
 215
 216
 217 /* compilingtime_stop **********************************************************
 218
 219    XXX
 220
 221 *******************************************************************************/
 222
 223 void compilingtime_start()
 224 {
 225         compilingtime_recursion++;
 226
 227         if (compilingtime_recursion == 1)
 228                 compilingstarttime = getcputime();
 229 }
 230
 231
 232 /* compilingtime_stop **********************************************************
 233
 234    XXX
 235
 236 *******************************************************************************/
 237
 238 void compilingtime_stop()
 239 {
 240         if (compilingtime_recursion == 1) {
 241                 compilingstoptime = getcputime();
 242                 compilingtime += (compilingstoptime - compilingstarttime);
 243         }
 244
 245         compilingtime_recursion--;
 246 }
 247
 248
 249 /* print_times *****************************************************************
 250
 251    Prints a summary of CPU time usage.
 252
 253 *******************************************************************************/
 254
 255 void print_times()
 256 {
 257         s8 totaltime = getcputime();
 258         s8 runtime = totaltime - loadingtime - compilingtime;
 259         char logtext[MAXLOGTEXT];
 260
 261 #if defined(__I386__) || defined(__POWERPC__)
 262         sprintf(logtext, "Time for loading classes: %lld secs, %lld millis",
 263 #else
 264         sprintf(logtext, "Time for loading classes: %ld secs, %ld millis",
 265 #endif
 266                         loadingtime / 1000000, (loadingtime % 1000000) / 1000);
 267         log_text(logtext);
 268
 269 #if defined(__I386__) || defined(__POWERPC__)
 270         sprintf(logtext, "Time for compiling code:  %lld secs, %lld millis",
 271 #else
 272         sprintf(logtext, "Time for compiling code:  %ld secs, %ld millis",
 273 #endif
 274                         compilingtime / 1000000, (compilingtime % 1000000) / 1000);
 275         log_text(logtext);
 276
 277 #if defined(__I386__) || defined(__POWERPC__)
 278         sprintf(logtext, "Time for running program: %lld secs, %lld millis",
 279 #else
 280         sprintf(logtext, "Time for running program: %ld secs, %ld millis",
 281 #endif
 282                         runtime / 1000000, (runtime % 1000000) / 1000);
 283         log_text(logtext);
 284
 285 #if defined(__I386__) || defined(__POWERPC__)
 286         sprintf(logtext, "Total time: %lld secs, %lld millis",
 287 #else
 288         sprintf(logtext, "Total time: %ld secs, %ld millis",
 289 #endif
 290                         totaltime / 1000000, (totaltime % 1000000) / 1000);
 291         log_text(logtext);
 292 }
 293
 294
 295 /* print_stats *****************************************************************
 296
 297    outputs detailed compiler statistics
 298
 299 *******************************************************************************/
 300
 301 void print_stats()
 302 {
 303         char logtext[MAXLOGTEXT];
 304
 305         sprintf(logtext, "Number of JitCompiler Calls: %d", count_jit_calls);
 306         log_text(logtext);
 307         sprintf(logtext, "Number of compiled Methods: %d", count_methods);
 308         log_text(logtext);
 309         if (opt_rt) {
 310           sprintf(logtext, "Number of Methods marked Used: %d", count_methods_marked_used);
 311           log_text(logtext);
 312           }
 313         sprintf(logtext, "Number of max basic blocks per method: %d", count_max_basic_blocks);
 314         log_text(logtext);
 315         sprintf(logtext, "Number of compiled basic blocks: %d", count_basic_blocks);
 316         log_text(logtext);
 317         sprintf(logtext, "Number of max JavaVM-Instructions per method: %d", count_max_javainstr);
 318         log_text(logtext);
 319         sprintf(logtext, "Number of compiled JavaVM-Instructions: %d", count_javainstr);
 320         log_text(logtext);
 321         sprintf(logtext, "Size of compiled JavaVM-Instructions:   %d(%d)", count_javacodesize,
 322                         count_javacodesize - count_methods * 18);
 323         log_text(logtext);
 324         sprintf(logtext, "Size of compiled Exception Tables:      %d", count_javaexcsize);
 325         log_text(logtext);
 326         sprintf(logtext, "Number of Machine-Instructions: %d", count_code_len >> 2);
 327         log_text(logtext);
 328         sprintf(logtext, "Number of Spills (write to memory): %d", count_spills);
 329         log_text(logtext);
 330         sprintf(logtext, "Number of Spills (read from memory): %d", count_spills_read);
 331         log_text(logtext);
 332         sprintf(logtext, "Number of Activ    Pseudocommands: %5d", count_pcmd_activ);
 333         log_text(logtext);
 334         sprintf(logtext, "Number of Drop     Pseudocommands: %5d", count_pcmd_drop);
 335         log_text(logtext);
 336         sprintf(logtext, "Number of Const    Pseudocommands: %5d (zero:%5d)", count_pcmd_load, count_pcmd_zero);
 337         log_text(logtext);
 338         sprintf(logtext, "Number of ConstAlu Pseudocommands: %5d (cmp: %5d, store:%5d)", count_pcmd_const_alu, count_pcmd_const_bra, count_pcmd_const_store);
 339         log_text(logtext);
 340         sprintf(logtext, "Number of Move     Pseudocommands: %5d", count_pcmd_move);
 341         log_text(logtext);
 342         sprintf(logtext, "Number of Load     Pseudocommands: %5d", count_load_instruction);
 343         log_text(logtext);
 344         sprintf(logtext, "Number of Store    Pseudocommands: %5d (combined: %5d)", count_pcmd_store, count_pcmd_store - count_pcmd_store_comb);
 345         log_text(logtext);
 346         sprintf(logtext, "Number of OP       Pseudocommands: %5d", count_pcmd_op);
 347         log_text(logtext);
 348         sprintf(logtext, "Number of DUP      Pseudocommands: %5d", count_dup_instruction);
 349         log_text(logtext);
 350         sprintf(logtext, "Number of Mem      Pseudocommands: %5d", count_pcmd_mem);
 351         log_text(logtext);
 352         sprintf(logtext, "Number of Method   Pseudocommands: %5d", count_pcmd_met);
 353         log_text(logtext);
 354         sprintf(logtext, "Number of Branch   Pseudocommands: %5d (rets:%5d, Xrets: %5d)",
 355                         count_pcmd_bra, count_pcmd_return, count_pcmd_returnx);
 356         log_text(logtext);
 357         sprintf(logtext, "Number of Table    Pseudocommands: %5d", count_pcmd_table);
 358         log_text(logtext);
 359         sprintf(logtext, "Number of Useful   Pseudocommands: %5d", count_pcmd_table +
 360                         count_pcmd_bra + count_pcmd_load + count_pcmd_mem + count_pcmd_op);
 361         log_text(logtext);
 362         sprintf(logtext, "Number of Null Pointer Checks:     %5d", count_check_null);
 363         log_text(logtext);
 364         sprintf(logtext, "Number of Array Bound Checks:      %5d", count_check_bound);
 365         log_text(logtext);
 366         sprintf(logtext, "Number of Try-Blocks: %d", count_tryblocks);
 367         log_text(logtext);
 368         sprintf(logtext, "Maximal count of stack elements:   %d", count_max_new_stack);
 369         log_text(logtext);
 370         sprintf(logtext, "Upper bound of max stack elements: %d", count_upper_bound_new_stack);
 371         log_text(logtext);
 372         sprintf(logtext, "Distribution of stack sizes at block boundary");
 373         log_text(logtext);
 374         sprintf(logtext, "    0    1    2    3    4    5    6    7    8    9    >=10");
 375         log_text(logtext);
 376         sprintf(logtext, "%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d", count_block_stack[0],
 377                         count_block_stack[1], count_block_stack[2], count_block_stack[3], count_block_stack[4],
 378                         count_block_stack[5], count_block_stack[6], count_block_stack[7], count_block_stack[8],
 379                         count_block_stack[9], count_block_stack[10]);
 380         log_text(logtext);
 381         sprintf(logtext, "Distribution of store stack depth");
 382         log_text(logtext);
 383         sprintf(logtext, "    0    1    2    3    4    5    6    7    8    9    >=10");
 384         log_text(logtext);
 385         sprintf(logtext, "%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d", count_store_depth[0],
 386                         count_store_depth[1], count_store_depth[2], count_store_depth[3], count_store_depth[4],
 387                         count_store_depth[5], count_store_depth[6], count_store_depth[7], count_store_depth[8],
 388                         count_store_depth[9], count_store_depth[10]);
 389         log_text(logtext);
 390         sprintf(logtext, "Distribution of store creator chains first part");
 391         log_text(logtext);
 392         sprintf(logtext, "    0    1    2    3    4    5    6    7    8    9  ");
 393         log_text(logtext);
 394         sprintf(logtext, "%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d", count_store_length[0],
 395                         count_store_length[1], count_store_length[2], count_store_length[3], count_store_length[4],
 396                         count_store_length[5], count_store_length[6], count_store_length[7], count_store_length[8],
 397                         count_store_length[9]);
 398         log_text(logtext);
 399         sprintf(logtext, "Distribution of store creator chains second part");
 400         log_text(logtext);
 401         sprintf(logtext, "   10   11   12   13   14   15   16   17   18   19  >=20");
 402         log_text(logtext);
 403         sprintf(logtext, "%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d%5d", count_store_length[10],
 404                         count_store_length[11], count_store_length[12], count_store_length[13], count_store_length[14],
 405                         count_store_length[15], count_store_length[16], count_store_length[17], count_store_length[18],
 406                         count_store_length[19], count_store_length[20]);
 407         log_text(logtext);
 408         sprintf(logtext, "Distribution of analysis iterations");
 409         log_text(logtext);
 410         sprintf(logtext, "    1    2    3    4    >=5");
 411         log_text(logtext);
 412         sprintf(logtext, "%5d%5d%5d%5d%5d", count_analyse_iterations[0], count_analyse_iterations[1],
 413                         count_analyse_iterations[2], count_analyse_iterations[3], count_analyse_iterations[4]);
 414         log_text(logtext);
 415         sprintf(logtext, "Distribution of basic blocks per method");
 416         log_text(logtext);
 417         sprintf(logtext, " <= 5 <=10 <=15 <=20 <=30 <=40 <=50 <=75  >75");
 418         log_text(logtext);
 419         sprintf(logtext, "%5d%5d%5d%5d%5d%5d%5d%5d%5d", count_method_bb_distribution[0],
 420                         count_method_bb_distribution[1], count_method_bb_distribution[2], count_method_bb_distribution[3],
 421                         count_method_bb_distribution[4], count_method_bb_distribution[5], count_method_bb_distribution[6],
 422                         count_method_bb_distribution[7], count_method_bb_distribution[8]);
 423         log_text(logtext);
 424         sprintf(logtext, "Distribution of basic block sizes");
 425         log_text(logtext);
 426         sprintf(logtext,
 427                          "  0    1    2    3    4   5   6   7   8   9 <13 <15 <17 <19 <21 <26 <31 >30");
 428         log_text(logtext);
 429         sprintf(logtext, "%3d%5d%5d%5d%4d%4d%4d%4d%4d%4d%4d%4d%4d%4d%4d%4d%4d%4d",
 430                         count_block_size_distribution[0], count_block_size_distribution[1], count_block_size_distribution[2],
 431                         count_block_size_distribution[3], count_block_size_distribution[4], count_block_size_distribution[5],
 432                         count_block_size_distribution[6], count_block_size_distribution[7], count_block_size_distribution[8],
 433                         count_block_size_distribution[9], count_block_size_distribution[10], count_block_size_distribution[11],
 434                         count_block_size_distribution[12], count_block_size_distribution[13], count_block_size_distribution[14],
 435                         count_block_size_distribution[15], count_block_size_distribution[16], count_block_size_distribution[17]);
 436         log_text(logtext);
 437         sprintf(logtext, "Size of Code Area (Kb):  %10.3f", (float) count_code_len / 1024);
 438         log_text(logtext);
 439         sprintf(logtext, "Size of data Area (Kb):  %10.3f", (float) count_data_len / 1024);
 440         log_text(logtext);
 441         sprintf(logtext, "Size of Class Infos (Kb):%10.3f", (float) (count_class_infos) / 1024);
 442         log_text(logtext);
 443         sprintf(logtext, "Size of Const Pool (Kb): %10.3f", (float) (count_const_pool_len + count_utf_len) / 1024);
 444         log_text(logtext);
 445         sprintf(logtext, "Size of Vftbl (Kb):      %10.3f", (float) count_vftbl_len / 1024);
 446         log_text(logtext);
 447         sprintf(logtext, "Size of comp stub (Kb):  %10.3f", (float) count_cstub_len / 1024);
 448         log_text(logtext);
 449         sprintf(logtext, "Size of native stub (Kb):%10.3f", (float) count_nstub_len / 1024);
 450         log_text(logtext);
 451         sprintf(logtext, "Size of Utf (Kb):        %10.3f", (float) count_utf_len / 1024);
 452         log_text(logtext);
 453         sprintf(logtext, "Size of VMCode (Kb):     %10.3f(%d)", (float) count_vmcode_len / 1024,
 454                         count_vmcode_len - 18 * count_all_methods);
 455         log_text(logtext);
 456         sprintf(logtext, "Size of ExTable (Kb):    %10.3f", (float) count_extable_len / 1024);
 457         log_text(logtext);
 458         sprintf(logtext, "Number of class loads:   %d", count_class_loads);
 459         log_text(logtext);
 460         sprintf(logtext, "Number of class inits:   %d", count_class_inits);
 461         log_text(logtext);
 462         sprintf(logtext, "Number of loaded Methods: %d\n\n", count_all_methods);
 463         log_text(logtext);
 464
 465         sprintf(logtext, "Calls of utf_new: %22d", count_utf_new);
 466         log_text(logtext);
 467         sprintf(logtext, "Calls of utf_new (element found): %6d\n\n", count_utf_new_found);
 468         log_text(logtext);
 469
 470         sprintf(logtext, "Methods allocated by LSRA:         %6d", count_methods_allocated_by_lsra);
 471         log_text(logtext);
 472         sprintf(logtext, "Conflicts between local Variables: %6d", count_locals_conflicts);
 473         log_text(logtext);
 474         sprintf(logtext, "Local Variables held in Memory:    %6d", count_locals_spilled);
 475         log_text(logtext);
 476         sprintf(logtext, "Local Variables held in Registers: %6d", count_locals_register);
 477         log_text(logtext);
 478         sprintf(logtext, "Stackslots held in Memory:         %6d", count_ss_spilled);
 479         log_text(logtext);
 480         sprintf(logtext, "Stackslots held in Registers:      %6d",count_ss_register );
 481         log_text(logtext);
 482         sprintf(logtext, "Memory moves at BB Boundaries:     %6d",count_mem_move_bb );
 483         log_text(logtext);
 484         sprintf(logtext, "Number of interface slots:         %6d\n\n",count_interface_size );
 485         log_text(logtext);
 486         sprintf(logtext, "Number of Argument stack slots in register:  %6d",count_argument_reg_ss );
 487         log_text(logtext);
 488         sprintf(logtext, "Number of Argument stack slots in memory:    %6d\n\n",count_argument_mem_ss );
 489         log_text(logtext);
 490         sprintf(logtext, "Number of Methods kept in registers:         %6d\n\n",count_method_in_register );
 491         log_text(logtext);
 492 }
 493
 494
 495 /* mem_usagelog ****************************************************************
 496
 497    prints some memory related infos
 498
 499 *******************************************************************************/
 500
 501 void mem_usagelog(bool givewarnings)
 502 {
 503         if ((memoryusage != 0) && givewarnings) {
 504                 dolog("Allocated memory not returned: %d", (s4) memoryusage);
 505         }
 506
 507         if ((globalallocateddumpsize != 0) && givewarnings) {
 508                 dolog("Dump memory not returned: %d", (s4) globalallocateddumpsize);
 509         }
 510
 511         dolog("Random/Dump - max. memory usage: %dkB/%dkB",
 512                   (s4) ((maxmemusage + 1023) / 1024),
 513                   (s4) ((maxdumpsize + 1023) / 1024));
 514 }
 515
 516
 517 /*
 518  * These are local overrides for various environment variables in Emacs.
 519  * Please do not remove this and leave it at the end of the file, where
 520  * Emacs will automagically detect them.
 521  * ---------------------------------------------------------------------
 522  * Local variables:
 523  * mode: c
 524  * indent-tabs-mode: t
 525  * c-basic-offset: 4
 526  * tab-width: 4
 527  * End:
 528  */