src/vm/statistics.c

   1 /* src/vm/statistics.c - global varables for statistics
   2
   3    Copyright (C) 1996-2005, 2006 R. Grafl, A. Krall, C. Kruegel,
   4    C. Oates, R. Obermaisser, M. Platter, M. Probst, S. Ring,
   5    E. Steiner, C. Thalinger, D. Thuernbeck, P. Tomsich, C. Ullrich,
   6    J. Wenninger, 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., 51 Franklin Street, Fifth Floor, Boston, MA
  23    02110-1301, USA.
  24
  25    Contact: cacao@cacaojvm.org
  26
  27    Authors: Christian Thalinger
  28
  29    Changes:
  30
  31    $Id: statistics.c 4397 2006-01-31 23:29:59Z twisti $
  32
  33 */
  34
  35
  36 #include "config.h"
  37
  38 #include <string.h>
  39 #include <sys/time.h>
  40 #include <sys/resource.h>
  41
  42 #include "vm/types.h"
  43
  44 #include "toolbox/logging.h"
  45 #include "vm/global.h"
  46 #include "vm/options.h"
  47 #include "vm/statistics.h"
  48
  49
  50 /* global variables ***********************************************************/
  51
  52 static s8 loadingtime = 0;              /* accumulated loading time           */
  53 static s8 loadingstarttime = 0;
  54 static s8 loadingstoptime = 0;
  55 static s4 loadingtime_recursion = 0;
  56
  57 static s8 compilingtime = 0;            /* accumulated compile time           */
  58 static s8 compilingstarttime = 0;
  59 static s8 compilingstoptime = 0;
  60 static s4 compilingtime_recursion = 0;
  61
  62 s4 codememusage = 0;
  63 s4 maxcodememusage = 0;
  64
  65 s4 memoryusage = 0;
  66 s4 maxmemusage = 0;
  67
  68 s4 maxdumpsize = 0;
  69
  70 s4 globalallocateddumpsize = 0;
  71 s4 globaluseddumpsize = 0;
  72
  73 int count_class_infos = 0;              /* variables for measurements         */
  74 int count_const_pool_len = 0;
  75 int count_classref_len = 0;
  76 int count_parsed_desc_len = 0;
  77 int count_vftbl_len = 0;
  78 int count_all_methods = 0;
  79 int count_methods_marked_used = 0;  /* RTA */
  80
  81 int count_vmcode_len = 0;
  82 int count_extable_len = 0;
  83 int count_class_loads = 0;
  84 int count_class_inits = 0;
  85
  86 int count_utf_len = 0;                  /* size of utf hash                   */
  87 int count_utf_new = 0;                  /* calls of utf_new                   */
  88 int count_utf_new_found  = 0;           /* calls of utf_new with fast return  */
  89
  90 int count_locals_conflicts = 0;         /* register allocator statistics */
  91 int count_locals_spilled = 0;
  92 int count_locals_register = 0;
  93 int count_ss_spilled = 0;
  94 int count_ss_register = 0;
  95 int count_methods_allocated_by_lsra = 0;
  96 int count_mem_move_bb = 0;
  97 int count_interface_size = 0;
  98 int count_argument_mem_ss = 0;
  99 int count_argument_reg_ss = 0;
 100 int count_method_in_register = 0;
 101 int count_mov_reg_reg = 0;
 102 int count_mov_mem_reg = 0;
 103 int count_mov_reg_mem = 0;
 104 int count_mov_mem_mem = 0;
 105
 106 int count_jit_calls = 0;
 107 int count_methods = 0;
 108 int count_spills = 0;
 109 int count_spills_read = 0;
 110 int count_pcmd_activ = 0;
 111 int count_pcmd_drop = 0;
 112 int count_pcmd_zero = 0;
 113 int count_pcmd_const_store = 0;
 114 int count_pcmd_const_alu = 0;
 115 int count_pcmd_const_bra = 0;
 116 int count_pcmd_load = 0;
 117 int count_pcmd_move = 0;
 118 int count_load_instruction = 0;
 119 int count_pcmd_store = 0;
 120 int count_pcmd_store_comb = 0;
 121 int count_dup_instruction = 0;
 122 int count_pcmd_op = 0;
 123 int count_pcmd_mem = 0;
 124 int count_pcmd_met = 0;
 125 int count_pcmd_bra = 0;
 126 int count_pcmd_table = 0;
 127 int count_pcmd_return = 0;
 128 int count_pcmd_returnx = 0;
 129 int count_check_null = 0;
 130 int count_check_bound = 0;
 131 int count_max_basic_blocks = 0;
 132 int count_basic_blocks = 0;
 133 int count_javainstr = 0;
 134 int count_max_javainstr = 0;
 135 int count_javacodesize = 0;
 136 int count_javaexcsize = 0;
 137 int count_calls = 0;
 138 int count_tryblocks = 0;
 139 int count_code_len = 0;
 140 int count_data_len = 0;
 141 int count_cstub_len = 0;
 142 int count_nstub_len = 0;
 143 int count_max_new_stack = 0;
 144 int count_upper_bound_new_stack = 0;
 145
 146 u8 count_native_function_calls=0;
 147 u8 count_jni_callXmethod_calls=0;
 148 u8 count_jni_calls=0;
 149
 150
 151 static int count_block_stack_init[11] = {
 152         0, 0, 0, 0, 0,
 153         0, 0, 0, 0, 0,
 154         0
 155 };
 156 int *count_block_stack = count_block_stack_init;
 157 static int count_analyse_iterations_init[5] = {
 158         0, 0, 0, 0, 0
 159 };
 160 int *count_analyse_iterations = count_analyse_iterations_init;
 161 static int count_method_bb_distribution_init[9] = {
 162         0, 0, 0, 0, 0,
 163         0, 0, 0, 0
 164 };
 165 int *count_method_bb_distribution = count_method_bb_distribution_init;
 166 static int count_block_size_distribution_init[18] = {
 167         0, 0, 0, 0, 0,
 168         0, 0, 0, 0, 0,
 169         0, 0, 0, 0, 0,
 170         0, 0, 0
 171 };
 172 int *count_block_size_distribution = count_block_size_distribution_init;
 173 static int count_store_length_init[21] = {
 174         0, 0, 0, 0, 0,
 175         0, 0, 0, 0, 0,
 176         0, 0, 0, 0, 0,
 177         0, 0, 0, 0, 0,
 178         0
 179 };
 180 int *count_store_length = count_store_length_init;
 181 static int count_store_depth_init[11] = {
 182         0, 0, 0, 0, 0,
 183         0, 0, 0, 0, 0,
 184         0
 185 };
 186 int *count_store_depth = count_store_depth_init;
 187
 188
 189 /* instruction scheduler statistics *******************************************/
 190
 191 s4 count_schedule_basic_blocks = 0;
 192 s4 count_schedule_nodes = 0;
 193 s4 count_schedule_leaders = 0;
 194 s4 count_schedule_max_leaders = 0;
 195 s4 count_schedule_critical_path = 0;
 196
 197
 198 /* nativeinvokation ***********************************************************
 199
 200    increments the native invokation count by one
 201
 202 *******************************************************************************/
 203
 204 void nativeinvokation(void)
 205 {
 206         /* XXX do locking here */
 207         count_native_function_calls++;
 208 }
 209
 210
 211 /* jnicallXmethodinvokation ***************************************************
 212
 213    increments the jni CallXMethod invokation count by one
 214
 215 *******************************************************************************/
 216
 217 void jnicallXmethodnvokation(void)
 218 {
 219         /* XXX do locking here */
 220         count_jni_callXmethod_calls++;
 221 }
 222
 223
 224 /* jniinvokation *************************************************************
 225
 226    increments the jni overall  invokation count by one
 227
 228 *******************************************************************************/
 229
 230 void jniinvokation(void)
 231 {
 232         /* XXX do locking here */
 233         count_jni_calls++;
 234 }
 235
 236
 237 /* getcputime *********************************** ******************************
 238
 239    Returns the used CPU time in microseconds
 240
 241 *******************************************************************************/
 242
 243 s8 getcputime(void)
 244 {
 245         struct rusage ru;
 246         int sec, usec;
 247
 248         getrusage(RUSAGE_SELF, &ru);
 249         sec = ru.ru_utime.tv_sec + ru.ru_stime.tv_sec;
 250         usec = ru.ru_utime.tv_usec + ru.ru_stime.tv_usec;
 251
 252         return sec * 1000000 + usec;
 253 }
 254
 255
 256 /* loadingtime_stop ************************************************************
 257
 258    XXX
 259
 260 *******************************************************************************/
 261
 262 void loadingtime_start(void)
 263 {
 264         loadingtime_recursion++;
 265
 266         if (loadingtime_recursion == 1)
 267                 loadingstarttime = getcputime();
 268 }
 269
 270
 271 /* loadingtime_stop ************************************************************
 272
 273    XXX
 274
 275 *******************************************************************************/
 276
 277 void loadingtime_stop(void)
 278 {
 279         if (loadingtime_recursion == 1) {
 280                 loadingstoptime = getcputime();
 281                 loadingtime += (loadingstoptime - loadingstarttime);
 282         }
 283
 284         loadingtime_recursion--;
 285 }
 286
 287
 288 /* compilingtime_stop **********************************************************
 289
 290    XXX
 291
 292 *******************************************************************************/
 293
 294 void compilingtime_start(void)
 295 {
 296         compilingtime_recursion++;
 297
 298         if (compilingtime_recursion == 1)
 299                 compilingstarttime = getcputime();
 300 }
 301
 302
 303 /* compilingtime_stop **********************************************************
 304
 305    XXX
 306
 307 *******************************************************************************/
 308
 309 void compilingtime_stop(void)
 310 {
 311         if (compilingtime_recursion == 1) {
 312                 compilingstoptime = getcputime();
 313                 compilingtime += (compilingstoptime - compilingstarttime);
 314         }
 315
 316         compilingtime_recursion--;
 317 }
 318
 319
 320 /* print_times *****************************************************************
 321
 322    Prints a summary of CPU time usage.
 323
 324 *******************************************************************************/
 325
 326 void print_times(void)
 327 {
 328         s8 totaltime;
 329         s8 runtime;
 330
 331         totaltime = getcputime();
 332         runtime = totaltime - loadingtime - compilingtime;
 333
 334 #if SIZEOF_VOID_P == 8
 335         dolog("Time for loading classes: %6ld ms", loadingtime / 1000);
 336         dolog("Time for compiling code:  %6ld ms", compilingtime / 1000);
 337         dolog("Time for running program: %6ld ms", runtime / 1000);
 338         dolog("Total time:               %6ld ms", totaltime / 1000);
 339 #else
 340         dolog("Time for loading classes: %6lld ms", loadingtime / 1000);
 341         dolog("Time for compiling code:  %6lld ms", compilingtime / 1000);
 342         dolog("Time for running program: %6lld ms", runtime / 1000);
 343         dolog("Total time:               %6lld ms", totaltime / 1000);
 344 #endif
 345 }
 346
 347
 348 /* print_stats *****************************************************************
 349
 350    outputs detailed compiler statistics
 351
 352 *******************************************************************************/
 353
 354 void print_stats(void)
 355 {
 356         s4    i;
 357         float f;
 358         s4    sum;
 359
 360
 361         dolog("Number of JIT compiler calls: %6d", count_jit_calls);
 362         dolog("Number of compiled methods:   %6d", count_methods);
 363
 364         dolog("Number of compiled basic blocks:               %6d",
 365                   count_basic_blocks);
 366         dolog("Number of max. basic blocks per method:        %6d",
 367                   count_max_basic_blocks);
 368
 369         dolog("Number of compiled JavaVM instructions:        %6d",
 370                   count_javainstr);
 371         dolog("Number of max. JavaVM instructions per method: %6d",
 372                   count_max_javainstr);
 373         dolog("Size of compiled JavaVM instructions:          %6d(%d)",
 374                   count_javacodesize, count_javacodesize - count_methods * 18);
 375
 376         dolog("Size of compiled Exception Tables:      %d", count_javaexcsize);
 377         dolog("Number of Machine-Instructions: %d", count_code_len >> 2);
 378         dolog("Number of Spills (write to memory): %d", count_spills);
 379         dolog("Number of Spills (read from memory): %d", count_spills_read);
 380         dolog("Number of Activ    Pseudocommands: %6d", count_pcmd_activ);
 381         dolog("Number of Drop     Pseudocommands: %6d", count_pcmd_drop);
 382         dolog("Number of Const    Pseudocommands: %6d (zero:%5d)",
 383                   count_pcmd_load, count_pcmd_zero);
 384         dolog("Number of ConstAlu Pseudocommands: %6d (cmp: %5d, store:%5d)",
 385                   count_pcmd_const_alu, count_pcmd_const_bra, count_pcmd_const_store);
 386         dolog("Number of Move     Pseudocommands: %6d", count_pcmd_move);
 387         dolog("Number of Load     Pseudocommands: %6d", count_load_instruction);
 388         dolog("Number of Store    Pseudocommands: %6d (combined: %5d)",
 389                   count_pcmd_store, count_pcmd_store - count_pcmd_store_comb);
 390         dolog("Number of OP       Pseudocommands: %6d", count_pcmd_op);
 391         dolog("Number of DUP      Pseudocommands: %6d", count_dup_instruction);
 392         dolog("Number of Mem      Pseudocommands: %6d", count_pcmd_mem);
 393         dolog("Number of Method   Pseudocommands: %6d", count_pcmd_met);
 394         dolog("Number of Branch   Pseudocommands: %6d (rets:%5d, Xrets: %5d)",
 395                   count_pcmd_bra, count_pcmd_return, count_pcmd_returnx);
 396         dolog("Number of Table    Pseudocommands: %6d", count_pcmd_table);
 397         dolog("Number of Useful   Pseudocommands: %6d", count_pcmd_table +
 398                   count_pcmd_bra + count_pcmd_load + count_pcmd_mem + count_pcmd_op);
 399         dolog("Number of Null Pointer Checks:     %6d", count_check_null);
 400         dolog("Number of Array Bound Checks:      %6d", count_check_bound);
 401         dolog("Number of Try-Blocks: %d", count_tryblocks);
 402         dolog("Maximal count of stack elements:   %d", count_max_new_stack);
 403         dolog("Upper bound of max stack elements: %d", count_upper_bound_new_stack);
 404         dolog("Distribution of stack sizes at block boundary");
 405         dolog("     0     1     2     3     4     5     6     7     8     9  >=10");
 406         dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
 407                   count_block_stack[0], count_block_stack[1], count_block_stack[2],
 408                   count_block_stack[3], count_block_stack[4], count_block_stack[5],
 409                   count_block_stack[6], count_block_stack[7], count_block_stack[8],
 410                   count_block_stack[9], count_block_stack[10]);
 411         dolog("Distribution of store stack depth");
 412         dolog("     0     1     2     3     4     5     6     7     8     9  >=10");
 413         dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
 414                   count_store_depth[0], count_store_depth[1], count_store_depth[2],
 415                   count_store_depth[3], count_store_depth[4], count_store_depth[5],
 416                   count_store_depth[6], count_store_depth[7], count_store_depth[8],
 417                   count_store_depth[9], count_store_depth[10]);
 418         dolog("Distribution of store creator chains first part");
 419         dolog("     0     1     2     3     4     5     6     7     8     9");
 420         dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
 421                   count_store_length[0], count_store_length[1], count_store_length[2],
 422                   count_store_length[3], count_store_length[4], count_store_length[5],
 423                   count_store_length[6], count_store_length[7], count_store_length[8],
 424                   count_store_length[9]);
 425         dolog("Distribution of store creator chains second part");
 426         dolog("    10    11    12    13    14    15    16    17    18    19  >=20");
 427         dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
 428                   count_store_length[10], count_store_length[11],
 429                   count_store_length[12], count_store_length[13],
 430                   count_store_length[14], count_store_length[15],
 431                   count_store_length[16], count_store_length[17],
 432                   count_store_length[18], count_store_length[19],
 433                   count_store_length[20]);
 434         dolog("Distribution of analysis iterations");
 435         dolog("     1     2     3     4   >=5");
 436         dolog("%6d%6d%6d%6d%6d",
 437                   count_analyse_iterations[0], count_analyse_iterations[1],
 438                   count_analyse_iterations[2], count_analyse_iterations[3],
 439                   count_analyse_iterations[4]);
 440
 441
 442         /* Distribution of basic blocks per method ********************************/
 443
 444         log_println("Distribution of basic blocks per method:");
 445         log_println("   <=5  <=10  <=15  <=20  <=30  <=40  <=50  <=75   >75");
 446
 447         log_start();
 448         for (i = 0; i <= 8; i++)
 449                 log_print("%6d", count_method_bb_distribution[i]);
 450         log_finish();
 451
 452         /* print ratio */
 453
 454         f = (float) count_methods;
 455
 456         log_start();
 457         for (i = 0; i <= 8; i++)
 458                 log_print("%6.2f", (float) count_method_bb_distribution[i] / f);
 459         log_finish();
 460
 461         /* print cumulated ratio */
 462
 463         log_start();
 464         for (i = 0, sum = 0; i <= 8; i++) {
 465                 sum += count_method_bb_distribution[i];
 466                 log_print("%6.2f", (float) sum / f);
 467         }
 468         log_finish();
 469
 470
 471         /* Distribution of basic block sizes **************************************/
 472
 473         log_println("Distribution of basic block sizes:");
 474         log_println("     0     1     2     3     4     5     6     7     8     9   <13   <15   <17   <19   <21   <26   <31   >30");
 475
 476         /* print block sizes */
 477
 478         log_start();
 479         for (i = 0; i <= 17; i++)
 480                 log_print("%6d", count_block_size_distribution[i]);
 481         log_finish();
 482
 483         /* print ratio */
 484
 485         f = (float) count_basic_blocks;
 486
 487         log_start();
 488         for (i = 0; i <= 17; i++)
 489                 log_print("%6.2f", (float) count_block_size_distribution[i] / f);
 490         log_finish();
 491
 492         /* print cumulated ratio */
 493
 494         log_start();
 495         for (i = 0, sum = 0; i <= 17; i++) {
 496                 sum += count_block_size_distribution[i];
 497                 log_print("%6.2f", (float) sum / f);
 498         }
 499         log_finish();
 500
 501         dolog("Size of Code Area:        %10.3f kB", (float) count_code_len / 1024);
 502         dolog("Size of Data Area:        %10.3f kB", (float) count_data_len / 1024);
 503         dolog("Size of Class Infos:      %10.3f kB", (float) count_class_infos / 1024);
 504         dolog("Size of Const Pool:       %10.3f kB", (float) (count_const_pool_len + count_utf_len) / 1024);
 505         dolog("Size of Class refs:       %10.3f kB", (float) count_classref_len / 1024);
 506         dolog("Size of descriptors:      %10.3f kB", (float) count_parsed_desc_len / 1024);
 507         dolog("Size of vftbl:            %10.3f kB", (float) count_vftbl_len / 1024);
 508         dolog("Size of compiler stubs:   %10.3f kB", (float) count_cstub_len / 1024);
 509         dolog("Size of native stubs:     %10.3f kB", (float) count_nstub_len / 1024);
 510         dolog("Size of utf:              %10.3f kB", (float) count_utf_len / 1024);
 511         dolog("Size of VMCode:           %10.3f kB (%d)",
 512                   (float) count_vmcode_len / 1024,
 513                   count_vmcode_len - 18 * count_all_methods);
 514         dolog("Size of exception tables: %10.3f kB\n", (float) count_extable_len / 1024);
 515
 516         dolog("Number of class loads:    %6d", count_class_loads);
 517         dolog("Number of class inits:    %6d", count_class_inits);
 518         dolog("Number of loaded Methods: %6d\n", count_all_methods);
 519
 520         dolog("Calls of utf_new:                 %6d", count_utf_new);
 521         dolog("Calls of utf_new (element found): %6d\n", count_utf_new_found);
 522
 523
 524         /* LSRA statistics ********************************************************/
 525
 526         dolog("Moves reg -> reg:     %6d", count_mov_reg_reg);
 527         dolog("Moves mem -> reg:     %6d", count_mov_mem_reg);
 528         dolog("Moves reg -> mem:     %6d", count_mov_reg_mem);
 529         dolog("Moves mem -> mem:     %6d", count_mov_mem_mem);
 530
 531         dolog("Methods allocated by LSRA:         %6d",
 532                   count_methods_allocated_by_lsra);
 533         dolog("Conflicts between local Variables: %6d", count_locals_conflicts);
 534         dolog("Local Variables held in Memory:    %6d", count_locals_spilled);
 535         dolog("Local Variables held in Registers: %6d", count_locals_register);
 536         dolog("Stackslots held in Memory:         %6d", count_ss_spilled);
 537         dolog("Stackslots held in Registers:      %6d", count_ss_register);
 538         dolog("Memory moves at BB Boundaries:     %6d", count_mem_move_bb);
 539         dolog("Number of interface slots:         %6d\n", count_interface_size);
 540         dolog("Number of Argument stack slots in register:  %6d",
 541                   count_argument_reg_ss);
 542         dolog("Number of Argument stack slots in memory:    %6d\n",
 543                   count_argument_mem_ss);
 544         dolog("Number of Methods kept in registers:         %6d\n",
 545                   count_method_in_register);
 546
 547
 548         /* instruction scheduler statistics ***************************************/
 549
 550 #if defined(USE_SCHEDULER)
 551         dolog("Instruction scheduler statistics:");
 552         dolog("Number of basic blocks:       %7d", count_schedule_basic_blocks);
 553         dolog("Number of nodes:              %7d", count_schedule_nodes);
 554         dolog("Number of leaders nodes:      %7d", count_schedule_leaders);
 555         dolog("Number of max. leaders nodes: %7d", count_schedule_max_leaders);
 556         dolog("Length of critical path:      %7d\n", count_schedule_critical_path);
 557 #endif
 558
 559
 560         /* call statistics ********************************************************/
 561
 562         dolog("Function call statistics:");
 563         dolog("Number of native function invokations:           %ld",
 564                   count_native_function_calls);
 565         dolog("Number of jni->CallXMethod function invokations: %ld",
 566                   count_jni_callXmethod_calls);
 567         dolog("Overall number of jni invokations:               %ld",
 568                   count_jni_calls);
 569
 570
 571         /* now print other statistics ********************************************/
 572
 573 #if defined(ENABLE_INTRP)
 574         print_dynamic_super_statistics();
 575 #endif
 576 }
 577
 578
 579 /* mem_usagelog ****************************************************************
 580
 581    prints some memory related infos
 582
 583 *******************************************************************************/
 584
 585 void mem_usagelog(bool givewarnings)
 586 {
 587         if ((memoryusage != 0) && givewarnings) {
 588                 dolog("Allocated memory not returned: %9d", (s4) memoryusage);
 589         }
 590
 591         if ((globalallocateddumpsize != 0) && givewarnings) {
 592                 dolog("Dump memory not returned:      %9d",
 593                           (s4) globalallocateddumpsize);
 594         }
 595
 596         dolog("Code - max. memory usage:      %9d kB",
 597                   (s4) ((maxcodememusage + 1023) / 1024));
 598         dolog("Random - max. memory usage:    %9d kB",
 599                   (s4) ((maxmemusage + 1023) / 1024));
 600         dolog("Dump - max. memory usage:      %9d kB",
 601                   (s4) ((maxdumpsize + 1023) / 1024));
 602 }
 603
 604
 605 /*
 606  * These are local overrides for various environment variables in Emacs.
 607  * Please do not remove this and leave it at the end of the file, where
 608  * Emacs will automagically detect them.
 609  * ---------------------------------------------------------------------
 610  * Local variables:
 611  * mode: c
 612  * indent-tabs-mode: t
 613  * c-basic-offset: 4
 614  * tab-width: 4
 615  * End:
 616  */