1 /* src/vm/statistics.c - global varables for statistics
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
8 This file is part of CACAO.
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.
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.
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
25 Contact: cacao@cacaojvm.org
27 Authors: Christian Thalinger
29 $Id: statistics.c 6080 2006-11-28 22:28:52Z twisti $
38 #include <sys/resource.h>
42 #include "toolbox/logging.h"
43 #include "vm/global.h"
44 #include "vm/options.h"
45 #include "vm/statistics.h"
48 /* global variables ***********************************************************/
50 static s8 loadingtime = 0; /* accumulated loading time */
51 static s8 loadingstarttime = 0;
52 static s8 loadingstoptime = 0;
53 static s4 loadingtime_recursion = 0;
55 static s8 compilingtime = 0; /* accumulated compile time */
56 static s8 compilingstarttime = 0;
57 static s8 compilingstoptime = 0;
58 static s4 compilingtime_recursion = 0;
61 s4 maxcodememusage = 0;
68 s4 globalallocateddumpsize = 0;
69 s4 globaluseddumpsize = 0;
72 /* variables for measurements *************************************************/
74 s4 size_classinfo = 0;
75 s4 size_fieldinfo = 0;
76 s4 size_methodinfo = 0;
79 int count_const_pool_len = 0;
80 int count_classref_len = 0;
81 int count_parsed_desc_len = 0;
82 int count_vftbl_len = 0;
83 int count_all_methods = 0;
84 int count_methods_marked_used = 0; /* RTA */
86 int count_vmcode_len = 0;
87 int count_extable_len = 0;
88 int count_class_loads = 0;
89 int count_class_inits = 0;
91 int count_utf_len = 0; /* size of utf hash */
92 int count_utf_new = 0; /* calls of utf_new */
93 int count_utf_new_found = 0; /* calls of utf_new with fast return */
95 int count_locals_conflicts = 0; /* register allocator statistics */
96 int count_locals_spilled = 0;
97 int count_locals_register = 0;
98 int count_ss_spilled = 0;
99 int count_ss_register = 0;
100 int count_methods_allocated_by_lsra = 0;
101 int count_mem_move_bb = 0;
102 int count_interface_size = 0;
103 int count_argument_mem_ss = 0;
104 int count_argument_reg_ss = 0;
105 int count_method_in_register = 0;
106 int count_mov_reg_reg = 0;
107 int count_mov_mem_reg = 0;
108 int count_mov_reg_mem = 0;
109 int count_mov_mem_mem = 0;
111 int count_jit_calls = 0;
112 int count_methods = 0;
113 int count_spills = 0;
114 int count_spills_read = 0;
115 int count_pcmd_activ = 0;
116 int count_pcmd_drop = 0;
117 int count_pcmd_zero = 0;
118 int count_pcmd_const_store = 0;
119 int count_pcmd_const_alu = 0;
120 int count_pcmd_const_bra = 0;
121 int count_pcmd_load = 0;
122 int count_pcmd_move = 0;
123 int count_load_instruction = 0;
124 int count_pcmd_store = 0;
125 int count_pcmd_store_comb = 0;
126 int count_dup_instruction = 0;
127 int count_pcmd_op = 0;
128 int count_pcmd_mem = 0;
129 int count_pcmd_met = 0;
130 int count_pcmd_bra = 0;
131 int count_pcmd_table = 0;
132 int count_pcmd_return = 0;
133 int count_pcmd_returnx = 0;
134 int count_check_null = 0;
135 int count_check_bound = 0;
136 int count_max_basic_blocks = 0;
137 int count_basic_blocks = 0;
138 int count_javainstr = 0;
139 int count_max_javainstr = 0;
140 int count_javacodesize = 0;
141 int count_javaexcsize = 0;
143 int count_tryblocks = 0;
144 int count_code_len = 0;
145 int count_data_len = 0;
146 int count_cstub_len = 0;
147 int count_nstub_len = 0;
148 int count_max_new_stack = 0;
149 int count_upper_bound_new_stack = 0;
151 s4 count_branches_resolved = 0;
152 s4 count_branches_unresolved = 0;
154 u8 count_native_function_calls=0;
155 u8 count_jni_callXmethod_calls=0;
156 u8 count_jni_calls=0;
159 static int count_block_stack_init[11] = {
164 int *count_block_stack = count_block_stack_init;
165 static int count_analyse_iterations_init[5] = {
168 int *count_analyse_iterations = count_analyse_iterations_init;
169 static int count_method_bb_distribution_init[9] = {
173 int *count_method_bb_distribution = count_method_bb_distribution_init;
174 static int count_block_size_distribution_init[18] = {
180 int *count_block_size_distribution = count_block_size_distribution_init;
181 static int count_store_length_init[21] = {
188 int *count_store_length = count_store_length_init;
189 static int count_store_depth_init[11] = {
194 int *count_store_depth = count_store_depth_init;
197 /* instruction scheduler statistics *******************************************/
199 s4 count_schedule_basic_blocks = 0;
200 s4 count_schedule_nodes = 0;
201 s4 count_schedule_leaders = 0;
202 s4 count_schedule_max_leaders = 0;
203 s4 count_schedule_critical_path = 0;
206 /* nativeinvokation ***********************************************************
208 increments the native invokation count by one
210 *******************************************************************************/
212 void nativeinvokation(void)
214 /* XXX do locking here */
215 count_native_function_calls++;
219 /* jnicallXmethodinvokation ***************************************************
221 increments the jni CallXMethod invokation count by one
223 *******************************************************************************/
225 void jnicallXmethodnvokation(void)
227 /* XXX do locking here */
228 count_jni_callXmethod_calls++;
232 /* jniinvokation *************************************************************
234 increments the jni overall invokation count by one
236 *******************************************************************************/
238 void jniinvokation(void)
240 /* XXX do locking here */
245 /* getcputime *********************************** ******************************
247 Returns the used CPU time in microseconds
249 *******************************************************************************/
256 getrusage(RUSAGE_SELF, &ru);
257 sec = ru.ru_utime.tv_sec + ru.ru_stime.tv_sec;
258 usec = ru.ru_utime.tv_usec + ru.ru_stime.tv_usec;
260 return sec * 1000000 + usec;
264 /* loadingtime_stop ************************************************************
268 *******************************************************************************/
270 void loadingtime_start(void)
272 loadingtime_recursion++;
274 if (loadingtime_recursion == 1)
275 loadingstarttime = getcputime();
279 /* loadingtime_stop ************************************************************
283 *******************************************************************************/
285 void loadingtime_stop(void)
287 if (loadingtime_recursion == 1) {
288 loadingstoptime = getcputime();
289 loadingtime += (loadingstoptime - loadingstarttime);
292 loadingtime_recursion--;
296 /* compilingtime_stop **********************************************************
300 *******************************************************************************/
302 void compilingtime_start(void)
304 compilingtime_recursion++;
306 if (compilingtime_recursion == 1)
307 compilingstarttime = getcputime();
311 /* compilingtime_stop **********************************************************
315 *******************************************************************************/
317 void compilingtime_stop(void)
319 if (compilingtime_recursion == 1) {
320 compilingstoptime = getcputime();
321 compilingtime += (compilingstoptime - compilingstarttime);
324 compilingtime_recursion--;
328 /* print_times *****************************************************************
330 Prints a summary of CPU time usage.
332 *******************************************************************************/
334 void print_times(void)
339 totaltime = getcputime();
340 runtime = totaltime - loadingtime - compilingtime;
342 #if SIZEOF_VOID_P == 8
343 dolog("Time for loading classes: %6ld ms", loadingtime / 1000);
344 dolog("Time for compiling code: %6ld ms", compilingtime / 1000);
345 dolog("Time for running program: %6ld ms", runtime / 1000);
346 dolog("Total time: %6ld ms", totaltime / 1000);
348 dolog("Time for loading classes: %6lld ms", loadingtime / 1000);
349 dolog("Time for compiling code: %6lld ms", compilingtime / 1000);
350 dolog("Time for running program: %6lld ms", runtime / 1000);
351 dolog("Total time: %6lld ms", totaltime / 1000);
356 /* print_stats *****************************************************************
358 outputs detailed compiler statistics
360 *******************************************************************************/
362 void print_stats(void)
369 dolog("Number of JIT compiler calls: %6d", count_jit_calls);
370 dolog("Number of compiled methods: %6d", count_methods);
372 dolog("Number of compiled basic blocks: %6d",
374 dolog("Number of max. basic blocks per method: %6d",
375 count_max_basic_blocks);
377 dolog("Number of compiled JavaVM instructions: %6d",
379 dolog("Number of max. JavaVM instructions per method: %6d",
380 count_max_javainstr);
381 dolog("Size of compiled JavaVM instructions: %6d(%d)",
382 count_javacodesize, count_javacodesize - count_methods * 18);
384 dolog("Size of compiled Exception Tables: %d", count_javaexcsize);
385 dolog("Number of Machine-Instructions: %d", count_code_len >> 2);
386 dolog("Number of Spills (write to memory): %d", count_spills);
387 dolog("Number of Spills (read from memory): %d", count_spills_read);
388 dolog("Number of Activ Pseudocommands: %6d", count_pcmd_activ);
389 dolog("Number of Drop Pseudocommands: %6d", count_pcmd_drop);
390 dolog("Number of Const Pseudocommands: %6d (zero:%5d)",
391 count_pcmd_load, count_pcmd_zero);
392 dolog("Number of ConstAlu Pseudocommands: %6d (cmp: %5d, store:%5d)",
393 count_pcmd_const_alu, count_pcmd_const_bra, count_pcmd_const_store);
394 dolog("Number of Move Pseudocommands: %6d", count_pcmd_move);
395 dolog("Number of Load Pseudocommands: %6d", count_load_instruction);
396 dolog("Number of Store Pseudocommands: %6d (combined: %5d)",
397 count_pcmd_store, count_pcmd_store - count_pcmd_store_comb);
398 dolog("Number of OP Pseudocommands: %6d", count_pcmd_op);
399 dolog("Number of DUP Pseudocommands: %6d", count_dup_instruction);
400 dolog("Number of Mem Pseudocommands: %6d", count_pcmd_mem);
401 dolog("Number of Method Pseudocommands: %6d", count_pcmd_met);
402 dolog("Number of Branch Pseudocommands: %6d (rets:%5d, Xrets: %5d)",
403 count_pcmd_bra, count_pcmd_return, count_pcmd_returnx);
404 log_println(" resolved branches: %6d", count_branches_resolved);
405 log_println(" unresolved branches: %6d", count_branches_unresolved);
406 dolog("Number of Table Pseudocommands: %6d", count_pcmd_table);
407 dolog("Number of Useful Pseudocommands: %6d", count_pcmd_table +
408 count_pcmd_bra + count_pcmd_load + count_pcmd_mem + count_pcmd_op);
409 dolog("Number of Null Pointer Checks: %6d", count_check_null);
410 dolog("Number of Array Bound Checks: %6d", count_check_bound);
411 dolog("Number of Try-Blocks: %d", count_tryblocks);
412 dolog("Maximal count of stack elements: %d", count_max_new_stack);
413 dolog("Upper bound of max stack elements: %d", count_upper_bound_new_stack);
414 dolog("Distribution of stack sizes at block boundary");
415 dolog(" 0 1 2 3 4 5 6 7 8 9 >=10");
416 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
417 count_block_stack[0], count_block_stack[1], count_block_stack[2],
418 count_block_stack[3], count_block_stack[4], count_block_stack[5],
419 count_block_stack[6], count_block_stack[7], count_block_stack[8],
420 count_block_stack[9], count_block_stack[10]);
421 dolog("Distribution of store stack depth");
422 dolog(" 0 1 2 3 4 5 6 7 8 9 >=10");
423 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
424 count_store_depth[0], count_store_depth[1], count_store_depth[2],
425 count_store_depth[3], count_store_depth[4], count_store_depth[5],
426 count_store_depth[6], count_store_depth[7], count_store_depth[8],
427 count_store_depth[9], count_store_depth[10]);
428 dolog("Distribution of store creator chains first part");
429 dolog(" 0 1 2 3 4 5 6 7 8 9");
430 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
431 count_store_length[0], count_store_length[1], count_store_length[2],
432 count_store_length[3], count_store_length[4], count_store_length[5],
433 count_store_length[6], count_store_length[7], count_store_length[8],
434 count_store_length[9]);
435 dolog("Distribution of store creator chains second part");
436 dolog(" 10 11 12 13 14 15 16 17 18 19 >=20");
437 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
438 count_store_length[10], count_store_length[11],
439 count_store_length[12], count_store_length[13],
440 count_store_length[14], count_store_length[15],
441 count_store_length[16], count_store_length[17],
442 count_store_length[18], count_store_length[19],
443 count_store_length[20]);
444 dolog("Distribution of analysis iterations");
445 dolog(" 1 2 3 4 >=5");
446 dolog("%6d%6d%6d%6d%6d",
447 count_analyse_iterations[0], count_analyse_iterations[1],
448 count_analyse_iterations[2], count_analyse_iterations[3],
449 count_analyse_iterations[4]);
452 /* Distribution of basic blocks per method ********************************/
454 log_println("Distribution of basic blocks per method:");
455 log_println(" <=5 <=10 <=15 <=20 <=30 <=40 <=50 <=75 >75");
458 for (i = 0; i <= 8; i++)
459 log_print("%6d", count_method_bb_distribution[i]);
464 f = (float) count_methods;
467 for (i = 0; i <= 8; i++)
468 log_print("%6.2f", (float) count_method_bb_distribution[i] / f);
471 /* print cumulated ratio */
474 for (i = 0, sum = 0; i <= 8; i++) {
475 sum += count_method_bb_distribution[i];
476 log_print("%6.2f", (float) sum / f);
481 /* Distribution of basic block sizes **************************************/
483 log_println("Distribution of basic block sizes:");
484 log_println(" 0 1 2 3 4 5 6 7 8 9 <13 <15 <17 <19 <21 <26 <31 >30");
486 /* print block sizes */
489 for (i = 0; i <= 17; i++)
490 log_print("%6d", count_block_size_distribution[i]);
495 f = (float) count_basic_blocks;
498 for (i = 0; i <= 17; i++)
499 log_print("%6.2f", (float) count_block_size_distribution[i] / f);
502 /* print cumulated ratio */
505 for (i = 0, sum = 0; i <= 17; i++) {
506 sum += count_block_size_distribution[i];
507 log_print("%6.2f", (float) sum / f);
511 log_println("Size of Code Area: %10.3f kB", (float) count_code_len / 1024);
512 log_println("Size of Data Area: %10.3f kB", (float) count_data_len / 1024);
514 log_println("Size of classinfo (%3d B): %10.3f kB", sizeof(classinfo), (float) size_classinfo / 1024);
515 log_println("Size of fieldinfo (%3d B): %10.3f kB", sizeof(fieldinfo), (float) size_fieldinfo / 1024);
516 log_println("Size of methodinfo (%3d B): %10.3f kB", sizeof(methodinfo), (float) size_methodinfo / 1024);
517 log_println("Size of codeinfo (%3d B): %10.3f kB", sizeof(codeinfo), (float) size_codeinfo / 1024);
519 log_println("Size of Const Pool: %10.3f kB", (float) (count_const_pool_len + count_utf_len) / 1024);
520 log_println("Size of Class refs: %10.3f kB", (float) count_classref_len / 1024);
521 log_println("Size of descriptors: %10.3f kB", (float) count_parsed_desc_len / 1024);
522 log_println("Size of vftbl: %10.3f kB", (float) count_vftbl_len / 1024);
523 log_println("Size of compiler stubs: %10.3f kB", (float) count_cstub_len / 1024);
524 log_println("Size of native stubs: %10.3f kB", (float) count_nstub_len / 1024);
525 log_println("Size of utf: %10.3f kB", (float) count_utf_len / 1024);
526 log_println("Size of VMCode: %10.3f kB", (float) count_vmcode_len / 1024);
527 log_println("Size of exception tables: %10.3f kB\n", (float) count_extable_len / 1024);
529 dolog("Number of class loads: %6d", count_class_loads);
530 dolog("Number of class inits: %6d", count_class_inits);
531 dolog("Number of loaded Methods: %6d\n", count_all_methods);
533 dolog("Calls of utf_new: %6d", count_utf_new);
534 dolog("Calls of utf_new (element found): %6d\n", count_utf_new_found);
537 /* LSRA statistics ********************************************************/
539 dolog("Moves reg -> reg: %6d", count_mov_reg_reg);
540 dolog("Moves mem -> reg: %6d", count_mov_mem_reg);
541 dolog("Moves reg -> mem: %6d", count_mov_reg_mem);
542 dolog("Moves mem -> mem: %6d", count_mov_mem_mem);
544 dolog("Methods allocated by LSRA: %6d",
545 count_methods_allocated_by_lsra);
546 dolog("Conflicts between local Variables: %6d", count_locals_conflicts);
547 dolog("Local Variables held in Memory: %6d", count_locals_spilled);
548 dolog("Local Variables held in Registers: %6d", count_locals_register);
549 dolog("Stackslots held in Memory: %6d", count_ss_spilled);
550 dolog("Stackslots held in Registers: %6d", count_ss_register);
551 dolog("Memory moves at BB Boundaries: %6d", count_mem_move_bb);
552 dolog("Number of interface slots: %6d\n", count_interface_size);
553 dolog("Number of Argument stack slots in register: %6d",
554 count_argument_reg_ss);
555 dolog("Number of Argument stack slots in memory: %6d\n",
556 count_argument_mem_ss);
557 dolog("Number of Methods kept in registers: %6d\n",
558 count_method_in_register);
561 /* instruction scheduler statistics ***************************************/
563 #if defined(USE_SCHEDULER)
564 dolog("Instruction scheduler statistics:");
565 dolog("Number of basic blocks: %7d", count_schedule_basic_blocks);
566 dolog("Number of nodes: %7d", count_schedule_nodes);
567 dolog("Number of leaders nodes: %7d", count_schedule_leaders);
568 dolog("Number of max. leaders nodes: %7d", count_schedule_max_leaders);
569 dolog("Length of critical path: %7d\n", count_schedule_critical_path);
573 /* call statistics ********************************************************/
575 dolog("Function call statistics:");
576 dolog("Number of native function invokations: %ld",
577 count_native_function_calls);
578 dolog("Number of jni->CallXMethod function invokations: %ld",
579 count_jni_callXmethod_calls);
580 dolog("Overall number of jni invokations: %ld",
584 /* now print other statistics ********************************************/
586 #if defined(ENABLE_INTRP)
587 print_dynamic_super_statistics();
592 /* mem_usagelog ****************************************************************
594 prints some memory related infos
596 *******************************************************************************/
598 void mem_usagelog(bool givewarnings)
600 if ((memoryusage != 0) && givewarnings) {
601 dolog("Allocated memory not returned: %9d", (s4) memoryusage);
604 if ((globalallocateddumpsize != 0) && givewarnings) {
605 dolog("Dump memory not returned: %9d",
606 (s4) globalallocateddumpsize);
609 dolog("Code - max. memory usage: %9d kB",
610 (s4) ((maxcodememusage + 1023) / 1024));
611 dolog("Random - max. memory usage: %9d kB",
612 (s4) ((maxmemusage + 1023) / 1024));
613 dolog("Dump - max. memory usage: %9d kB",
614 (s4) ((maxdumpsize + 1023) / 1024));
619 * These are local overrides for various environment variables in Emacs.
620 * Please do not remove this and leave it at the end of the file, where
621 * Emacs will automagically detect them.
622 * ---------------------------------------------------------------------
625 * indent-tabs-mode: t