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