1 /* src/vm/statistics.c - global variables for statistics
3 Copyright (C) 1996-2005, 2006, 2007, 2008
4 CACAOVM - Verein zur Foerderung der freien virtuellen Maschine CACAO
6 This file is part of CACAO.
8 This program is free software; you can redistribute it and/or
9 modify it under the terms of the GNU General Public License as
10 published by the Free Software Foundation; either version 2, or (at
11 your option) any later version.
13 This program is distributed in the hope that it will be useful, but
14 WITHOUT ANY WARRANTY; without even the implied warranty of
15 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
16 General Public License for more details.
18 You should have received a copy of the GNU General Public License
19 along with this program; if not, write to the Free Software
20 Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
31 #if defined(HAVE_TIME_H)
35 #if defined(HAVE_SYS_TIME_H)
36 # include <sys/time.h>
39 #if defined(HAVE_SYS_RESOURCE_H)
40 # include <sys/resource.h>
47 #include "toolbox/logging.h"
51 #include "vm/global.h"
52 #include "vm/method.h"
53 #include "vm/options.h"
54 #include "vm/statistics.h"
56 #include "vm/jit/code.h"
59 /* global variables ***********************************************************/
61 static s8 loadingtime = 0; /* accumulated loading time */
62 static s8 loadingstarttime = 0;
63 static s8 loadingstoptime = 0;
64 static s4 loadingtime_recursion = 0;
66 static s8 compilingtime = 0; /* accumulated compile time */
67 static s8 compilingstarttime = 0;
68 static s8 compilingstoptime = 0;
69 static s4 compilingtime_recursion = 0;
72 s4 maxcodememusage = 0;
79 s4 globalallocateddumpsize = 0;
80 s4 globaluseddumpsize = 0;
83 /* variables for measurements *************************************************/
85 s4 size_classinfo = 0;
86 s4 size_fieldinfo = 0;
87 s4 size_methodinfo = 0;
91 s4 size_stub_native = 0;
93 s4 size_stack_map = 0;
96 s4 size_threadobject = 0;
97 int32_t size_thread_index_t = 0;
98 int32_t size_stacksize = 0;
100 s4 size_lock_record = 0;
101 s4 size_lock_hashtable = 0;
102 s4 size_lock_waiter = 0;
104 int32_t count_linenumbertable = 0;
105 int32_t size_linenumbertable = 0;
107 s4 size_patchref = 0;
109 s4 size_cachedref = 0;
111 u8 count_calls_java_to_native = 0;
112 u8 count_calls_native_to_java = 0;
114 int count_const_pool_len = 0;
115 int count_classref_len = 0;
116 int count_parsed_desc_len = 0;
117 int count_vftbl_len = 0;
118 int count_all_methods = 0;
119 int count_methods_marked_used = 0; /* RTA */
121 int count_vmcode_len = 0;
122 int count_extable_len = 0;
123 int count_class_loads = 0;
124 int count_class_inits = 0;
126 int count_utf_len = 0; /* size of utf hash */
127 int count_utf_new = 0; /* calls of utf_new */
128 int count_utf_new_found = 0; /* calls of utf_new with fast return */
130 int count_locals_conflicts = 0; /* register allocator statistics */
131 int count_locals_spilled = 0;
132 int count_locals_register = 0;
133 int count_ss_spilled = 0;
134 int count_ss_register = 0;
135 int count_methods_allocated_by_lsra = 0;
136 int count_mem_move_bb = 0;
137 int count_interface_size = 0;
138 int count_argument_mem_ss = 0;
139 int count_argument_reg_ss = 0;
140 int count_method_in_register = 0;
141 int count_mov_reg_reg = 0;
142 int count_mov_mem_reg = 0;
143 int count_mov_reg_mem = 0;
144 int count_mov_mem_mem = 0;
146 int count_jit_calls = 0;
147 int count_methods = 0;
148 int count_spills_read_ila = 0;
149 int count_spills_read_flt = 0;
150 int count_spills_read_dbl = 0;
151 int count_spills_write_ila = 0;
152 int count_spills_write_flt = 0;
153 int count_spills_write_dbl = 0;
154 int count_pcmd_activ = 0;
155 int count_pcmd_drop = 0;
156 int count_pcmd_zero = 0;
157 int count_pcmd_const_store = 0;
158 int count_pcmd_const_alu = 0;
159 int count_pcmd_const_bra = 0;
160 int count_pcmd_load = 0;
161 int count_pcmd_move = 0;
162 int count_load_instruction = 0;
163 int count_pcmd_store = 0;
164 int count_pcmd_store_comb = 0;
165 int count_dup_instruction = 0;
166 int count_pcmd_op = 0;
167 int count_pcmd_mem = 0;
168 int count_pcmd_met = 0;
169 int count_pcmd_bra = 0;
170 int count_pcmd_table = 0;
171 int count_pcmd_return = 0;
172 int count_pcmd_returnx = 0;
173 int count_check_null = 0;
174 int count_check_bound = 0;
175 int count_max_basic_blocks = 0;
176 int count_basic_blocks = 0;
177 int count_javainstr = 0;
178 int count_max_javainstr = 0;
179 int count_javacodesize = 0;
180 int count_javaexcsize = 0;
182 int count_tryblocks = 0;
183 int count_code_len = 0;
184 int count_data_len = 0;
185 int count_cstub_len = 0;
186 int count_max_new_stack = 0;
187 int count_upper_bound_new_stack = 0;
189 int count_emit_branch = 0;
190 int count_emit_branch_8bit = 0;
191 int count_emit_branch_16bit = 0;
192 int count_emit_branch_32bit = 0;
193 int count_emit_branch_64bit = 0;
195 s4 count_branches_resolved = 0;
196 s4 count_branches_unresolved = 0;
198 u8 count_jni_callXmethod_calls=0;
199 u8 count_jni_calls=0;
202 static int count_block_stack_init[11] = {
207 int *count_block_stack = count_block_stack_init;
208 static int count_analyse_iterations_init[5] = {
211 int *count_analyse_iterations = count_analyse_iterations_init;
212 static int count_method_bb_distribution_init[9] = {
216 int *count_method_bb_distribution = count_method_bb_distribution_init;
217 static int count_block_size_distribution_init[18] = {
223 int *count_block_size_distribution = count_block_size_distribution_init;
224 static int count_store_length_init[21] = {
231 int *count_store_length = count_store_length_init;
232 static int count_store_depth_init[11] = {
237 int *count_store_depth = count_store_depth_init;
240 /* instruction scheduler statistics *******************************************/
242 s4 count_schedule_basic_blocks = 0;
243 s4 count_schedule_nodes = 0;
244 s4 count_schedule_leaders = 0;
245 s4 count_schedule_max_leaders = 0;
246 s4 count_schedule_critical_path = 0;
249 /* jnicallXmethodinvokation ***************************************************
251 increments the jni CallXMethod invokation count by one
253 *******************************************************************************/
255 void jnicallXmethodnvokation(void)
257 /* XXX do locking here */
258 count_jni_callXmethod_calls++;
262 /* jniinvokation *************************************************************
264 increments the jni overall invokation count by one
266 *******************************************************************************/
268 void jniinvokation(void)
270 /* XXX do locking here */
275 /* getcputime *********************************** ******************************
277 Returns the used CPU time in microseconds
279 *******************************************************************************/
283 #if defined(HAVE_GETRUSAGE)
287 getrusage(RUSAGE_SELF, &ru);
289 sec = ru.ru_utime.tv_sec + ru.ru_stime.tv_sec;
290 usec = ru.ru_utime.tv_usec + ru.ru_stime.tv_usec;
292 return sec * 1000000 + usec;
294 /* If we don't have getrusage, simply return 0. */
301 /* loadingtime_stop ************************************************************
305 *******************************************************************************/
307 void loadingtime_start(void)
309 loadingtime_recursion++;
311 if (loadingtime_recursion == 1)
312 loadingstarttime = getcputime();
316 /* loadingtime_stop ************************************************************
320 *******************************************************************************/
322 void loadingtime_stop(void)
324 if (loadingtime_recursion == 1) {
325 loadingstoptime = getcputime();
326 loadingtime += (loadingstoptime - loadingstarttime);
329 loadingtime_recursion--;
333 /* compilingtime_stop **********************************************************
337 *******************************************************************************/
339 void compilingtime_start(void)
341 compilingtime_recursion++;
343 if (compilingtime_recursion == 1)
344 compilingstarttime = getcputime();
348 /* compilingtime_stop **********************************************************
352 *******************************************************************************/
354 void compilingtime_stop(void)
356 if (compilingtime_recursion == 1) {
357 compilingstoptime = getcputime();
358 compilingtime += (compilingstoptime - compilingstarttime);
361 compilingtime_recursion--;
365 /* print_times *****************************************************************
367 Prints a summary of CPU time usage.
369 *******************************************************************************/
371 void print_times(void)
376 totaltime = getcputime();
377 runtime = totaltime - loadingtime - compilingtime;
379 #if SIZEOF_VOID_P == 8
380 dolog("Time for loading classes: %6ld ms", loadingtime / 1000);
381 dolog("Time for compiling code: %6ld ms", compilingtime / 1000);
382 dolog("Time for running program: %6ld ms", runtime / 1000);
383 dolog("Total time: %6ld ms", totaltime / 1000);
385 dolog("Time for loading classes: %6lld ms", loadingtime / 1000);
386 dolog("Time for compiling code: %6lld ms", compilingtime / 1000);
387 dolog("Time for running program: %6lld ms", runtime / 1000);
388 dolog("Total time: %6lld ms", totaltime / 1000);
393 /* print_stats *****************************************************************
395 outputs detailed compiler statistics
397 *******************************************************************************/
399 void print_stats(void)
406 dolog("Number of JIT compiler calls: %6d", count_jit_calls);
407 dolog("Number of compiled methods: %6d", count_methods);
409 dolog("Number of compiled basic blocks: %6d",
411 dolog("Number of max. basic blocks per method: %6d",
412 count_max_basic_blocks);
414 dolog("Number of compiled JavaVM instructions: %6d",
416 dolog("Number of max. JavaVM instructions per method: %6d",
417 count_max_javainstr);
418 dolog("Size of compiled JavaVM instructions: %6d(%d)",
419 count_javacodesize, count_javacodesize - count_methods * 18);
421 dolog("Size of compiled Exception Tables: %d", count_javaexcsize);
422 dolog("Number of Machine-Instructions: %d", count_code_len >> 2);
423 dolog("Number of Spills (write to memory) <all [i/l/a|flt|dbl]>: %d [%d|%d|%d]",
424 count_spills_write_ila + count_spills_write_flt + count_spills_write_dbl,
425 count_spills_write_ila, count_spills_write_flt, count_spills_write_dbl);
426 dolog("Number of Spills (read from memory) <all [i/l/a|flt|dbl]>: %d [%d|%d|%d]",
427 count_spills_read_ila + count_spills_read_flt + count_spills_read_dbl,
428 count_spills_read_ila, count_spills_read_flt, count_spills_read_dbl);
429 dolog("Number of Activ Pseudocommands: %6d", count_pcmd_activ);
430 dolog("Number of Drop Pseudocommands: %6d", count_pcmd_drop);
431 dolog("Number of Const Pseudocommands: %6d (zero:%5d)",
432 count_pcmd_load, count_pcmd_zero);
433 dolog("Number of ConstAlu Pseudocommands: %6d (cmp: %5d, store:%5d)",
434 count_pcmd_const_alu, count_pcmd_const_bra, count_pcmd_const_store);
435 dolog("Number of Move Pseudocommands: %6d", count_pcmd_move);
436 dolog("Number of Load Pseudocommands: %6d", count_load_instruction);
437 dolog("Number of Store Pseudocommands: %6d (combined: %5d)",
438 count_pcmd_store, count_pcmd_store - count_pcmd_store_comb);
439 dolog("Number of OP Pseudocommands: %6d", count_pcmd_op);
440 dolog("Number of DUP Pseudocommands: %6d", count_dup_instruction);
441 dolog("Number of Mem Pseudocommands: %6d", count_pcmd_mem);
442 dolog("Number of Method Pseudocommands: %6d", count_pcmd_met);
443 dolog("Number of Branch Pseudocommands: %6d (rets:%5d, Xrets: %5d)",
444 count_pcmd_bra, count_pcmd_return, count_pcmd_returnx);
445 log_println(" resolved branches: %6d", count_branches_resolved);
446 log_println(" unresolved branches: %6d", count_branches_unresolved);
447 dolog("Number of Table Pseudocommands: %6d", count_pcmd_table);
448 dolog("Number of Useful Pseudocommands: %6d", count_pcmd_table +
449 count_pcmd_bra + count_pcmd_load + count_pcmd_mem + count_pcmd_op);
450 dolog("Number of Null Pointer Checks: %6d", count_check_null);
451 dolog("Number of Array Bound Checks: %6d", count_check_bound);
452 dolog("Number of Try-Blocks: %d", count_tryblocks);
454 dolog("Number of branch_emit (total, 8bit/16bit/32bit/64bit offset): %d, %d/%d/%d/%d",
455 count_emit_branch, count_emit_branch_8bit, count_emit_branch_16bit,
456 count_emit_branch_32bit, count_emit_branch_64bit);
458 dolog("Maximal count of stack elements: %d", count_max_new_stack);
459 dolog("Upper bound of max stack elements: %d", count_upper_bound_new_stack);
460 dolog("Distribution of stack sizes at block boundary");
461 dolog(" 0 1 2 3 4 5 6 7 8 9 >=10");
462 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
463 count_block_stack[0], count_block_stack[1], count_block_stack[2],
464 count_block_stack[3], count_block_stack[4], count_block_stack[5],
465 count_block_stack[6], count_block_stack[7], count_block_stack[8],
466 count_block_stack[9], count_block_stack[10]);
467 dolog("Distribution of store stack depth");
468 dolog(" 0 1 2 3 4 5 6 7 8 9 >=10");
469 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
470 count_store_depth[0], count_store_depth[1], count_store_depth[2],
471 count_store_depth[3], count_store_depth[4], count_store_depth[5],
472 count_store_depth[6], count_store_depth[7], count_store_depth[8],
473 count_store_depth[9], count_store_depth[10]);
474 dolog("Distribution of store creator chains first part");
475 dolog(" 0 1 2 3 4 5 6 7 8 9");
476 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
477 count_store_length[0], count_store_length[1], count_store_length[2],
478 count_store_length[3], count_store_length[4], count_store_length[5],
479 count_store_length[6], count_store_length[7], count_store_length[8],
480 count_store_length[9]);
481 dolog("Distribution of store creator chains second part");
482 dolog(" 10 11 12 13 14 15 16 17 18 19 >=20");
483 dolog("%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d%6d",
484 count_store_length[10], count_store_length[11],
485 count_store_length[12], count_store_length[13],
486 count_store_length[14], count_store_length[15],
487 count_store_length[16], count_store_length[17],
488 count_store_length[18], count_store_length[19],
489 count_store_length[20]);
490 dolog("Distribution of analysis iterations");
491 dolog(" 1 2 3 4 >=5");
492 dolog("%6d%6d%6d%6d%6d",
493 count_analyse_iterations[0], count_analyse_iterations[1],
494 count_analyse_iterations[2], count_analyse_iterations[3],
495 count_analyse_iterations[4]);
498 /* Distribution of basic blocks per method ********************************/
500 log_println("Distribution of basic blocks per method:");
501 log_println(" <=5 <=10 <=15 <=20 <=30 <=40 <=50 <=75 >75");
504 for (i = 0; i <= 8; i++)
505 log_print("%6d", count_method_bb_distribution[i]);
510 f = (float) count_methods;
513 for (i = 0; i <= 8; i++)
514 log_print("%6.2f", (float) count_method_bb_distribution[i] / f);
517 /* print cumulated ratio */
520 for (i = 0, sum = 0; i <= 8; i++) {
521 sum += count_method_bb_distribution[i];
522 log_print("%6.2f", (float) sum / f);
527 /* Distribution of basic block sizes **************************************/
529 log_println("Distribution of basic block sizes:");
530 log_println(" 0 1 2 3 4 5 6 7 8 9 <13 <15 <17 <19 <21 <26 <31 >30");
532 /* print block sizes */
535 for (i = 0; i <= 17; i++)
536 log_print("%6d", count_block_size_distribution[i]);
541 f = (float) count_basic_blocks;
544 for (i = 0; i <= 17; i++)
545 log_print("%6.2f", (float) count_block_size_distribution[i] / f);
548 /* print cumulated ratio */
551 for (i = 0, sum = 0; i <= 17; i++) {
552 sum += count_block_size_distribution[i];
553 log_print("%6.2f", (float) sum / f);
557 statistics_print_memory_usage();
559 dolog("Number of class loads: %6d", count_class_loads);
560 dolog("Number of class inits: %6d", count_class_inits);
561 dolog("Number of loaded Methods: %6d\n", count_all_methods);
563 dolog("Calls of utf_new: %6d", count_utf_new);
564 dolog("Calls of utf_new (element found): %6d\n", count_utf_new_found);
567 /* LSRA statistics ********************************************************/
569 dolog("Moves reg -> reg: %6d", count_mov_reg_reg);
570 dolog("Moves mem -> reg: %6d", count_mov_mem_reg);
571 dolog("Moves reg -> mem: %6d", count_mov_reg_mem);
572 dolog("Moves mem -> mem: %6d", count_mov_mem_mem);
574 dolog("Methods allocated by LSRA: %6d",
575 count_methods_allocated_by_lsra);
576 dolog("Conflicts between local Variables: %6d", count_locals_conflicts);
577 dolog("Local Variables held in Memory: %6d", count_locals_spilled);
578 dolog("Local Variables held in Registers: %6d", count_locals_register);
579 dolog("Stackslots held in Memory: %6d", count_ss_spilled);
580 dolog("Stackslots held in Registers: %6d", count_ss_register);
581 dolog("Memory moves at BB Boundaries: %6d", count_mem_move_bb);
582 dolog("Number of interface slots: %6d\n", count_interface_size);
583 dolog("Number of Argument stack slots in register: %6d",
584 count_argument_reg_ss);
585 dolog("Number of Argument stack slots in memory: %6d\n",
586 count_argument_mem_ss);
587 dolog("Number of Methods kept in registers: %6d\n",
588 count_method_in_register);
591 /* instruction scheduler statistics ***************************************/
593 #if defined(USE_SCHEDULER)
594 dolog("Instruction scheduler statistics:");
595 dolog("Number of basic blocks: %7d", count_schedule_basic_blocks);
596 dolog("Number of nodes: %7d", count_schedule_nodes);
597 dolog("Number of leaders nodes: %7d", count_schedule_leaders);
598 dolog("Number of max. leaders nodes: %7d", count_schedule_max_leaders);
599 dolog("Length of critical path: %7d\n", count_schedule_critical_path);
603 /* call statistics ********************************************************/
605 dolog("Function call statistics:");
606 dolog("Number of jni->CallXMethod function invokations: %ld",
607 count_jni_callXmethod_calls);
608 dolog("Overall number of jni invokations: %ld",
611 log_println("java-to-native calls: %10ld", count_calls_java_to_native);
612 log_println("native-to-java calls: %10ld", count_calls_native_to_java);
615 /* now print other statistics ********************************************/
617 #if defined(ENABLE_INTRP)
618 print_dynamic_super_statistics();
623 /* statistics_print_date *******************************************************
625 Print current date and time.
627 *******************************************************************************/
629 void statistics_print_date(void)
634 #if defined(HAVE_TIME)
640 #if defined(HAVE_LOCALTIME_R)
641 localtime_r(&t, &tm);
643 # error !HAVE_LOCALTIME_R
646 log_println("%d-%02d-%02d %02d:%02d:%02d",
647 1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday,
648 tm.tm_hour, tm.tm_min, tm.tm_sec);
652 /* statistics_print_memory_usage ***********************************************
654 Print current memory usage.
656 *******************************************************************************/
658 void statistics_print_memory_usage(void)
662 log_println("memory usage ----------------------");
664 log_println("code: %10d", count_code_len);
665 log_println("data: %10d", count_data_len);
666 log_println(" ----------");
672 log_println(" %10d", sum);
676 log_println("classinfo (%3d B): %10d", (int) sizeof(classinfo), size_classinfo);
677 log_println("fieldinfo (%3d B): %10d", (int) sizeof(fieldinfo), size_fieldinfo);
678 log_println("methodinfo (%3d B): %10d", (int) sizeof(methodinfo), size_methodinfo);
679 log_println("lineinfo (%3d B): %10d", (int) sizeof(lineinfo), size_lineinfo);
680 log_println("codeinfo (%3d B): %10d", (int) sizeof(codeinfo), size_codeinfo);
681 log_println(" ----------");
690 log_println(" %10d", sum);
694 log_println("linenumber tables (%5d): %10d", count_linenumbertable, size_linenumbertable);
695 log_println("exception tables: %10d", count_extable_len);
696 log_println("patcher references: %10d", size_patchref);
697 log_println("cached references: %10d", size_cachedref);
698 log_println(" ----------");
701 size_linenumbertable +
706 log_println(" %10d", sum);
710 log_println("constant pool: %10d", count_const_pool_len);
711 log_println("classref: %10d", count_classref_len);
712 log_println("parsed descriptors: %10d", count_parsed_desc_len);
713 log_println("vftbl: %10d", count_vftbl_len);
714 log_println("compiler stubs: %10d", count_cstub_len);
715 log_println("native stubs: %10d", size_stub_native);
716 log_println("utf: %10d", count_utf_len);
717 log_println("vmcode: %10d", count_vmcode_len);
718 log_println("stack map: %10d", size_stack_map);
719 log_println("string: %10d", size_string);
720 log_println("threadobject: %10d", size_threadobject);
721 log_println("thread index: %10d", size_thread_index_t);
722 log_println("stack size: %10d", size_stacksize);
723 log_println("lock record: %10d", size_lock_record);
724 log_println("lock hashtable: %10d", size_lock_hashtable);
725 log_println("lock waiter: %10d", size_lock_waiter);
726 log_println(" ----------");
729 count_const_pool_len +
731 count_parsed_desc_len +
740 size_thread_index_t +
743 size_lock_hashtable +
746 log_println(" %10d", sum);
750 log_println("max. code memory: %10d", maxcodememusage);
751 log_println("max. heap memory: %10d", maxmemusage);
752 log_println("max. dump memory: %10d", maxdumpsize);
754 log_println("heap memory not freed: %10d", (int32_t) memoryusage);
755 log_println("dump memory not freed: %10d", (int32_t) globalallocateddumpsize);
761 /* statistics_print_gc_memory_usage ********************************************
763 Print current GC memory usage.
765 *******************************************************************************/
767 void statistics_print_gc_memory_usage(void)
769 static int64_t count = 0;
778 max = gc_get_max_heap_size();
779 size = gc_get_heap_size();
780 free = gc_get_free_bytes();
782 total = gc_get_total_bytes();
784 if (opt_ProfileMemoryUsageGNUPlot) {
786 fprintf(opt_ProfileMemoryUsageGNUPlot, "plot \"profile.dat\" using 1:2 with lines title \"max. Java heap size\", \"profile.dat\" using 1:3 with lines title \"Java heap size\", \"profile.dat\" using 1:4 with lines title \"used\", \"profile.dat\" using 1:5 with lines title \"free\"\n");
788 #if SIZEOF_VOID_P == 8
789 fprintf(opt_ProfileMemoryUsageGNUPlot, "%ld %ld %ld %ld %ld\n", count, max, size, used, free);
791 fprintf(opt_ProfileMemoryUsageGNUPlot, "%lld %lld %lld %lld %lld\n", count, max, size, used, free);
794 fflush(opt_ProfileMemoryUsageGNUPlot);
797 log_println("GC memory usage -------------------");
799 log_println("max. Java heap size: %10lld", max);
801 log_println("Java heap size: %10lld", size);
802 log_println("used: %10lld", used);
803 log_println("free: %10lld", free);
804 log_println("totally used: %10lld", total);
811 * These are local overrides for various environment variables in Emacs.
812 * Please do not remove this and leave it at the end of the file, where
813 * Emacs will automagically detect them.
814 * ---------------------------------------------------------------------
817 * indent-tabs-mode: t
821 * vim:noexpandtab:sw=4:ts=4: