* src/vm/statistics.c (count_branches_resolved)
[cacao.git] / 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    $Id: statistics.c 6080 2006-11-28 22:28:52Z twisti $
30
31 */
32
33
34 #include "config.h"
35
36 #include <string.h> 
37 #include <sys/time.h>
38 #include <sys/resource.h>
39
40 #include "vm/types.h"
41
42 #include "toolbox/logging.h"
43 #include "vm/global.h"
44 #include "vm/options.h"
45 #include "vm/statistics.h"
46
47
48 /* global variables ***********************************************************/
49
50 static s8 loadingtime = 0;              /* accumulated loading time           */
51 static s8 loadingstarttime = 0;
52 static s8 loadingstoptime = 0;
53 static s4 loadingtime_recursion = 0;
54
55 static s8 compilingtime = 0;            /* accumulated compile time           */
56 static s8 compilingstarttime = 0;
57 static s8 compilingstoptime = 0;
58 static s4 compilingtime_recursion = 0;
59
60 s4 codememusage = 0;
61 s4 maxcodememusage = 0;
62
63 s4 memoryusage = 0;
64 s4 maxmemusage = 0;
65
66 s4 maxdumpsize = 0;
67
68 s4 globalallocateddumpsize = 0;
69 s4 globaluseddumpsize = 0;
70
71
72 /* variables for measurements *************************************************/
73
74 s4 size_classinfo  = 0;
75 s4 size_fieldinfo  = 0;
76 s4 size_methodinfo = 0;
77 s4 size_codeinfo   = 0;
78
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 */
85
86 int count_vmcode_len = 0;
87 int count_extable_len = 0;
88 int count_class_loads = 0;
89 int count_class_inits = 0;
90
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  */
94
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;
110
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;
142 int count_calls = 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;
150
151 s4 count_branches_resolved   = 0;
152 s4 count_branches_unresolved = 0;
153
154 u8 count_native_function_calls=0;
155 u8 count_jni_callXmethod_calls=0;
156 u8 count_jni_calls=0;
157
158
159 static int count_block_stack_init[11] = {
160         0, 0, 0, 0, 0, 
161         0, 0, 0, 0, 0, 
162         0
163 };
164 int *count_block_stack = count_block_stack_init;
165 static int count_analyse_iterations_init[5] = {
166         0, 0, 0, 0, 0
167 };
168 int *count_analyse_iterations = count_analyse_iterations_init;
169 static int count_method_bb_distribution_init[9] = {
170         0, 0, 0, 0, 0,
171         0, 0, 0, 0
172 };
173 int *count_method_bb_distribution = count_method_bb_distribution_init;
174 static int count_block_size_distribution_init[18] = {
175         0, 0, 0, 0, 0,
176         0, 0, 0, 0, 0,
177         0, 0, 0, 0, 0,
178         0, 0, 0
179 };
180 int *count_block_size_distribution = count_block_size_distribution_init;
181 static int count_store_length_init[21] = {
182         0, 0, 0, 0, 0,
183         0, 0, 0, 0, 0,
184         0, 0, 0, 0, 0,
185         0, 0, 0, 0, 0,
186         0
187 };
188 int *count_store_length = count_store_length_init;
189 static int count_store_depth_init[11] = {
190         0, 0, 0, 0, 0,
191         0, 0, 0, 0, 0,
192         0
193 };
194 int *count_store_depth = count_store_depth_init;
195
196
197 /* instruction scheduler statistics *******************************************/
198
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;
204
205
206 /* nativeinvokation ***********************************************************
207
208    increments the native invokation count by one
209         
210 *******************************************************************************/
211
212 void nativeinvokation(void)
213 {
214         /* XXX do locking here */
215         count_native_function_calls++;
216 }
217
218
219 /* jnicallXmethodinvokation ***************************************************
220
221    increments the jni CallXMethod invokation count by one
222         
223 *******************************************************************************/
224
225 void jnicallXmethodnvokation(void)
226 {
227         /* XXX do locking here */
228         count_jni_callXmethod_calls++;
229 }
230
231
232 /* jniinvokation *************************************************************
233
234    increments the jni overall  invokation count by one
235         
236 *******************************************************************************/
237
238 void jniinvokation(void)
239 {
240         /* XXX do locking here */
241         count_jni_calls++;
242 }
243
244
245 /* getcputime *********************************** ******************************
246
247    Returns the used CPU time in microseconds
248         
249 *******************************************************************************/
250
251 s8 getcputime(void)
252 {
253         struct rusage ru;
254         int sec, usec;
255
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;
259
260         return sec * 1000000 + usec;
261 }
262
263
264 /* loadingtime_stop ************************************************************
265
266    XXX
267
268 *******************************************************************************/
269
270 void loadingtime_start(void)
271 {
272         loadingtime_recursion++;
273
274         if (loadingtime_recursion == 1)
275                 loadingstarttime = getcputime();
276 }
277
278
279 /* loadingtime_stop ************************************************************
280
281    XXX
282
283 *******************************************************************************/
284
285 void loadingtime_stop(void)
286 {
287         if (loadingtime_recursion == 1) {
288                 loadingstoptime = getcputime();
289                 loadingtime += (loadingstoptime - loadingstarttime);
290         }
291
292         loadingtime_recursion--;
293 }
294
295
296 /* compilingtime_stop **********************************************************
297
298    XXX
299
300 *******************************************************************************/
301
302 void compilingtime_start(void)
303 {
304         compilingtime_recursion++;
305
306         if (compilingtime_recursion == 1)
307                 compilingstarttime = getcputime();
308 }
309
310
311 /* compilingtime_stop **********************************************************
312
313    XXX
314
315 *******************************************************************************/
316
317 void compilingtime_stop(void)
318 {
319         if (compilingtime_recursion == 1) {
320                 compilingstoptime = getcputime();
321                 compilingtime += (compilingstoptime - compilingstarttime);
322         }
323
324         compilingtime_recursion--;
325 }
326
327
328 /* print_times *****************************************************************
329
330    Prints a summary of CPU time usage.
331
332 *******************************************************************************/
333
334 void print_times(void)
335 {
336         s8 totaltime;
337         s8 runtime;
338
339         totaltime = getcputime();
340         runtime = totaltime - loadingtime - compilingtime;
341
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);
347 #else
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);
352 #endif
353 }
354
355
356 /* print_stats *****************************************************************
357
358    outputs detailed compiler statistics
359
360 *******************************************************************************/
361
362 void print_stats(void)
363 {
364         s4    i;
365         float f;
366         s4    sum;
367
368
369         dolog("Number of JIT compiler calls: %6d", count_jit_calls);
370         dolog("Number of compiled methods:   %6d", count_methods);
371
372         dolog("Number of compiled basic blocks:               %6d",
373                   count_basic_blocks);
374         dolog("Number of max. basic blocks per method:        %6d",
375                   count_max_basic_blocks);
376
377         dolog("Number of compiled JavaVM instructions:        %6d",
378                   count_javainstr);
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);
383
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]);
450
451
452         /* Distribution of basic blocks per method ********************************/
453
454         log_println("Distribution of basic blocks per method:");
455         log_println("   <=5  <=10  <=15  <=20  <=30  <=40  <=50  <=75   >75");
456
457         log_start();
458         for (i = 0; i <= 8; i++)
459                 log_print("%6d", count_method_bb_distribution[i]);
460         log_finish();
461
462         /* print ratio */
463
464         f = (float) count_methods;
465
466         log_start();
467         for (i = 0; i <= 8; i++)
468                 log_print("%6.2f", (float) count_method_bb_distribution[i] / f);
469         log_finish();
470
471         /* print cumulated ratio */
472
473         log_start();
474         for (i = 0, sum = 0; i <= 8; i++) {
475                 sum += count_method_bb_distribution[i];
476                 log_print("%6.2f", (float) sum / f);
477         }
478         log_finish();
479
480
481         /* Distribution of basic block sizes **************************************/
482
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");
485
486         /* print block sizes */
487
488         log_start();
489         for (i = 0; i <= 17; i++)
490                 log_print("%6d", count_block_size_distribution[i]);
491         log_finish();
492
493         /* print ratio */
494
495         f = (float) count_basic_blocks;
496
497         log_start();
498         for (i = 0; i <= 17; i++)
499                 log_print("%6.2f", (float) count_block_size_distribution[i] / f);
500         log_finish();
501
502         /* print cumulated ratio */
503
504         log_start();
505         for (i = 0, sum = 0; i <= 17; i++) {
506                 sum += count_block_size_distribution[i];
507                 log_print("%6.2f", (float) sum / f);
508         }
509         log_finish();
510
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);
513
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);
518
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);
528
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);
532
533         dolog("Calls of utf_new:                 %6d", count_utf_new);
534         dolog("Calls of utf_new (element found): %6d\n", count_utf_new_found);
535
536
537         /* LSRA statistics ********************************************************/
538
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);
543
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);
559
560
561         /* instruction scheduler statistics ***************************************/
562
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);
570 #endif
571
572
573         /* call statistics ********************************************************/
574
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",
581                   count_jni_calls);
582
583
584         /* now print other statistics ********************************************/
585
586 #if defined(ENABLE_INTRP)
587         print_dynamic_super_statistics();
588 #endif
589 }
590
591
592 /* mem_usagelog ****************************************************************
593
594    prints some memory related infos
595
596 *******************************************************************************/
597
598 void mem_usagelog(bool givewarnings)
599 {
600         if ((memoryusage != 0) && givewarnings) {
601                 dolog("Allocated memory not returned: %9d", (s4) memoryusage);
602         }
603
604         if ((globalallocateddumpsize != 0) && givewarnings) {
605                 dolog("Dump memory not returned:      %9d",
606                           (s4) globalallocateddumpsize);
607         }
608
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));
615 }
616
617
618 /*
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  * ---------------------------------------------------------------------
623  * Local variables:
624  * mode: c
625  * indent-tabs-mode: t
626  * c-basic-offset: 4
627  * tab-width: 4
628  * End:
629  */