[svn:parrot] r40401 - in branches/pluggable_runcore: config/gen/makefiles src src/runcore tools/dev
cotto at svn.parrot.org
cotto at svn.parrot.org
Wed Aug 5 07:17:31 UTC 2009
Author: cotto
Date: Wed Aug 5 07:17:29 2009
New Revision: 40401
URL: https://trac.parrot.org/parrot/changeset/40401
Log:
[profiling] repurpose the old profiling runcore and remove some now-unused functions
also add a script to turn profiling output into something Callgrind can consume
There are many things that need work in this code. I'm aware of some of them.
Added:
branches/pluggable_runcore/tools/dev/pprof2cg.pl
Modified:
branches/pluggable_runcore/config/gen/makefiles/root.in
branches/pluggable_runcore/src/embed.c
branches/pluggable_runcore/src/runcore/cores.c
Modified: branches/pluggable_runcore/config/gen/makefiles/root.in
==============================================================================
--- branches/pluggable_runcore/config/gen/makefiles/root.in Wed Aug 5 01:27:41 2009 (r40400)
+++ branches/pluggable_runcore/config/gen/makefiles/root.in Wed Aug 5 07:17:29 2009 (r40401)
@@ -101,7 +101,7 @@
AS := @as@
CC := @cc@
CC_INC := @cc_inc@
-C_LIBS := @libs@
+C_LIBS := @libs@ -lrt
CC_SHARED := @cc_shared@
CFLAGS := $(CC_INC) @ccflags@ @cc_debug@ @ccwarn@ @cc_hasjit@ @cg_flag@ @gc_flag@ $(CC_SHARED)
LINK_DYNAMIC := @link_dynamic@
Modified: branches/pluggable_runcore/src/embed.c
==============================================================================
--- branches/pluggable_runcore/src/embed.c Wed Aug 5 01:27:41 2009 (r40400)
+++ branches/pluggable_runcore/src/embed.c Wed Aug 5 07:17:29 2009 (r40401)
@@ -30,9 +30,6 @@
/* HEADERIZER BEGIN: static */
/* Don't modify between HEADERIZER BEGIN / HEADERIZER END. Your changes will be lost. */
-static FLOATVAL calibrate(PARROT_INTERP)
- __attribute__nonnull__(1);
-
PARROT_CANNOT_RETURN_NULL
PARROT_OBSERVER
static const char * op_name(PARROT_INTERP, int k)
@@ -44,9 +41,6 @@
static void print_debug(PARROT_INTERP, SHIM(int status), SHIM(void *p))
__attribute__nonnull__(1);
-static void print_profile(PARROT_INTERP, SHIM(int status), SHIM(void *p))
- __attribute__nonnull__(1);
-
static int prof_sort_f(ARGIN(const void *a), ARGIN(const void *b))
__attribute__nonnull__(1)
__attribute__nonnull__(2);
@@ -60,16 +54,12 @@
__attribute__nonnull__(1)
__attribute__nonnull__(3);
-#define ASSERT_ARGS_calibrate __attribute__unused__ int _ASSERT_ARGS_CHECK = \
- PARROT_ASSERT_ARG(interp)
#define ASSERT_ARGS_op_name __attribute__unused__ int _ASSERT_ARGS_CHECK = \
PARROT_ASSERT_ARG(interp)
#define ASSERT_ARGS_print_constant_table __attribute__unused__ int _ASSERT_ARGS_CHECK = \
PARROT_ASSERT_ARG(interp)
#define ASSERT_ARGS_print_debug __attribute__unused__ int _ASSERT_ARGS_CHECK = \
PARROT_ASSERT_ARG(interp)
-#define ASSERT_ARGS_print_profile __attribute__unused__ int _ASSERT_ARGS_CHECK = \
- PARROT_ASSERT_ARG(interp)
#define ASSERT_ARGS_prof_sort_f __attribute__unused__ int _ASSERT_ARGS_CHECK = \
PARROT_ASSERT_ARG(a) \
|| PARROT_ASSERT_ARG(b)
@@ -723,122 +713,6 @@
/*
-=item C<static FLOATVAL calibrate(PARROT_INTERP)>
-
-With this calibration, reported times of C<parrot -p> almost match those
-measured with time C<parrot -R bounds>.
-
-=cut
-
-*/
-
-static FLOATVAL
-calibrate(PARROT_INTERP)
-{
- ASSERT_ARGS(calibrate)
- opcode_t code[] = { 1 }; /* noop */
- opcode_t *pc = code;
- const size_t count = 1000000;
- size_t n = count;
- const FLOATVAL start = Parrot_floatval_time();
- FLOATVAL now = start;
-
- /* op timing isn't free; it requires at least one time fetch per op */
- for (; n; --n) {
- pc = (interp->op_func_table[*code])(pc, interp);
- now = Parrot_floatval_time();
- }
-
- return (now - start) / (FLOATVAL) count;
-}
-
-
-/*
-
-=item C<static void print_profile(PARROT_INTERP, int status, void *p)>
-
-Prints out a profile listing.
-
-=cut
-
-*/
-
-static void
-print_profile(PARROT_INTERP, SHIM(int status), SHIM(void *p))
-{
- ASSERT_ARGS(print_profile)
- RunProfile * const profile = interp->profile;
-
- if (profile) {
- UINTVAL j;
- int k, jit;
- UINTVAL op_count = 0;
- UINTVAL call_count = 0;
- FLOATVAL sum_time = 0.0;
- const FLOATVAL empty = calibrate(interp);
-
- Parrot_io_printf(interp,
- "Calibration: overhead = %.6f ms/op\n", 1000.0 * empty);
-
- Parrot_io_printf(interp,
- " Code J Name "
- "Calls Total/s Avg/ms\n");
-
- for (j = 0; j < interp->op_count + PARROT_PROF_EXTRA; j++) {
- const UINTVAL n = profile->data[j].numcalls;
- profile->data[j].op = j;
-
- if (j >= PARROT_PROF_EXTRA) {
- profile->data[j].time -= empty * n;
-
- /* faster than noop */
- if (profile->data[j].time < 0.0)
- profile->data[j].time = 0.0;
- }
- }
-
- qsort(profile->data, interp->op_count + PARROT_PROF_EXTRA,
- sizeof (ProfData), prof_sort_f);
-
- for (j = 0; j < interp->op_count + PARROT_PROF_EXTRA; j++) {
- const UINTVAL n = profile->data[j].numcalls;
-
- if (n > 0) {
- const FLOATVAL t = profile->data[j].time;
-
- op_count++;
- call_count += n;
- sum_time += t;
-
- k = profile->data[j].op;
- jit = '-';
-#if JIT_CAPABLE
- if (k >= PARROT_PROF_EXTRA &&
- op_jit[k - PARROT_PROF_EXTRA].extcall != 1)
- jit = 'j';
-#endif
- Parrot_io_printf(interp, " %4d %c %-25s %8vu %10vf %10.6vf\n",
- k - PARROT_PROF_EXTRA,
- jit,
- op_name(interp, k),
- n,
- t,
- (FLOATVAL)(t * 1000.0 / (FLOATVAL)n));
- }
- }
-
- Parrot_io_printf(interp, " %4vu - %-25s %8vu %10vf %10.6vf\n",
- op_count,
- "-",
- call_count,
- sum_time,
- (FLOATVAL)(sum_time * 1000.0 / (FLOATVAL)call_count));
- }
-}
-
-
-/*
-
=item C<static void print_debug(PARROT_INTERP, int status, void *p)>
Prints GC info.
@@ -1005,7 +879,6 @@
* before exiting, then print debug infos if turned on.
*/
Parrot_on_exit(interp, print_debug, NULL);
- Parrot_on_exit(interp, print_profile, NULL);
/* Let's kick the tires and light the fires--call interpreter.c:runops. */
main_sub = CONTEXT(interp)->current_sub;
Modified: branches/pluggable_runcore/src/runcore/cores.c
==============================================================================
--- branches/pluggable_runcore/src/runcore/cores.c Wed Aug 5 01:27:41 2009 (r40400)
+++ branches/pluggable_runcore/src/runcore/cores.c Wed Aug 5 07:17:29 2009 (r40401)
@@ -498,9 +498,6 @@
return pc;
}
-#undef code_start
-#undef code_end
-
/*
@@ -519,38 +516,75 @@
runops_profile_core(PARROT_INTERP, ARGIN(opcode_t *pc))
{
ASSERT_ARGS(runops_profile_core)
- RunProfile * const profile = interp->profile;
- const opcode_t old_op = profile->cur_op;
- /* if reentering the runloop, remember old op and calc time 'til now */
- if (old_op)
- profile->data[old_op].time +=
- Parrot_floatval_time() - profile->starttime;
-
- while (pc) {/* && pc >= code_start && pc < code_end) */
- opcode_t cur_op;
-
- CONTEXT(interp)->current_pc = pc;
- profile->cur_op = cur_op = *pc + PARROT_PROF_EXTRA;
- profile->starttime = Parrot_floatval_time();
- profile->data[cur_op].numcalls++;
+ Parrot_Context_info info;
+ struct timespec preop, postop;
+ long long op_time;
+ char unknown_sub[] = "(unknown sub)";
+ char unknown_file[] = "(unknown file)";
+
+ FILE *prof_fd = fopen("parrot.pprof", "w");
+
+ if (!prof_fd) {
+ fprintf(stderr, "unable to open parrot_prof.out for writing");
+ exit(1);
+ }
+
+ Parrot_Context_get_info(interp, CONTEXT(interp), &info);
+ fprintf(prof_fd, "F:%s\n", info.file->strstart);
+ fprintf(prof_fd, "S:%s\n", info.subname->strstart);
+ while (pc) {
+
+ char *file_preop, *file_postop;
+ char *sub_preop, *sub_postop;
+
+ if (pc < code_start || pc >= code_end) {
+ Parrot_ex_throw_from_c_args(interp, NULL, 1,
+ "attempt to access code outside of current code segment");
+ }
+
+ Parrot_Context_get_info(interp, CONTEXT(interp), &info);
+ file_preop = info.file->strstart;
+ sub_preop = info.subname->strstart;
+
+ CONTEXT(interp)->current_pc = pc;
+ clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &preop);
DO_OP(pc, interp);
+ clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &postop);
- /* profile->cur_op may be different, if exception was thrown */
- profile->data[profile->cur_op].time +=
- Parrot_floatval_time() - profile->starttime;
- }
+ op_time = (postop.tv_sec * 1000000000 + postop.tv_nsec) -
+ (preop.tv_sec * 1000000000 + preop.tv_nsec);
- if (old_op) {
- /* old opcode continues */
- profile->starttime = Parrot_floatval_time();
- profile->cur_op = old_op;
+ Parrot_Context_get_info(interp, CONTEXT(interp), &info);
+ file_postop = info.file->strstart;
+ sub_postop = info.subname->strstart;
+
+ if (!file_preop) file_preop = unknown_file;
+ if (!file_postop) file_postop = unknown_file;
+ if (!sub_preop) file_preop = unknown_sub;
+ if (!sub_preop) file_postop = unknown_sub;
+
+ if (pc) {
+ if (strcmp(file_preop, file_postop))
+ fprintf(prof_fd, "F:%s\n", file_postop);
+ if (strcmp(sub_preop, sub_postop))
+ fprintf(prof_fd, "S:%s\n", sub_postop);
+ fprintf(prof_fd, "%d:%lli:%d:%s\n",
+ info.line, op_time, (int)CONTEXT(interp)->recursion_depth,
+ (interp->op_info_table)[*pc].name);
+ }
}
+ fclose(prof_fd);
return pc;
+
+
}
+#undef code_start
+#undef code_end
+
/*
=item C<opcode_t * runops_debugger_core(PARROT_INTERP, opcode_t *pc)>
Added: branches/pluggable_runcore/tools/dev/pprof2cg.pl
==============================================================================
--- /dev/null 00:00:00 1970 (empty, because file is newly added)
+++ branches/pluggable_runcore/tools/dev/pprof2cg.pl Wed Aug 5 07:17:29 2009 (r40401)
@@ -0,0 +1,178 @@
+#!/usr/bin/perl
+
+no warnings;
+use v5.10.0;
+use warnings;
+use strict;
+
+use Data::Dumper;
+
+#what about throw and rethrow?
+my @call_ops = (qw{invoke invokecc});
+my @return_ops = (qw{yield returncc tailcall});
+my @prof_stack = ();
+my %stats;
+
+my ($file, $func, $line, $op_seq, $op) = ('', '', 0, 0, 0);
+my ($call, $return) = (0,0);
+my $prev_func = '';
+my $total_time = 0;
+my ($prev_line, $new_line, $op_num) = (0,0,0);
+
+while (<>) {
+ if (/^F:(.*)$/) {
+ $file = $1;
+ #say "found file $file";
+ $stats{$file} = {} unless exists $stats{$file};
+ }
+ elsif (/S:(.*)$/) {
+ $prev_func = $func;
+ $func = $1;
+ #say "found func $func";
+
+ $stats{$file}{$func} = {} unless exists $stats{$file}{$func};
+
+ if ($return) {
+ #pop the current func and op number off the stack
+ #the func is there mainly for debugging
+ ($file, $func, $line, $op_num) = @{pop @prof_stack};
+ #say "popped func $func, op $op_num off the stack";
+ $stats{$file}{$func}{$line}{$op_num}{func_name} = $prev_func;
+ }
+ }
+ elsif (/^(\d+):(\d+):(\d+):(\w+)$/) {
+ my ($line, $op_time, $rec_depth, $op) = ($1, $2, $3, $4);
+
+ $new_line = ($line != $prev_line);
+ $call = ($op ~~ @call_ops);
+ $total_time += $op_time;
+
+ $prev_line = $line;
+
+ if ($new_line && !$return) {
+ $op_num = 0;
+ }
+ else {
+ $op_num++;
+ }
+
+ #say "$func line #$line, op #$op_num is $op";
+
+ if ($new_line) {
+ $stats{$file}{$func}{$line} = {line_calls_func => 0}
+ unless exists $stats{$file}{$func}{$line};
+ }
+
+ if (!exists $stats{$file}{$func}{$line}{$op_num}) {
+ $stats{$file}{$func}{$line}{$op_num} = {
+ time => $op_time,
+ hits => 1,
+ op => $op,
+ };
+ }
+ else {
+ $stats{$file}{$func}{$line}{$op_num}{time} += $op_time;
+ $stats{$file}{$func}{$line}{$op_num}{hits}++;
+ }
+
+ #say "calling a func" if $call;
+ #say "returning from a func" if $return;
+
+ if ($call) {
+
+ #inject a fake op representing the function call
+ $op_num++;
+ if (!exists $stats{$file}{$func}{$line}{$op_num}) {
+ $stats{$file}{$func}{$line}{$op_num} = {
+ time => 0,
+ hits => 1,
+ op => "FUNCTION_CALL",
+ };
+ }
+ else {
+ $stats{$file}{$func}{$line}{$op_num}{hits}++;
+ }
+
+ #say "pushed func $func, op $op_num onto the stack";
+ push @prof_stack, [$file, $func, $line, $op_num];
+ $stats{$file}{$func}{$line}{line_calls_func} = 1;
+ }
+ else {
+ for my $fun (@prof_stack) {
+ my ($file, $func, $line, $op_seq, $op) = @$fun;
+ $stats{$file}{$func}{$line}{$op_seq}{time} += $op_time;
+ }
+ }
+ $return = ($op ~~ @return_ops);
+ }
+}
+
+#print Dumper(%stats);
+
+open(OUT_FH, ">parrot.out") or die "couldn't open parrot.out for writing";
+
+say OUT_FH <<"HEADER";
+version: 1
+creator: 3.4.1-Debian
+pid: 5751
+cmd: ./callgrind_test
+
+part: 1
+desc: I1 cache:
+desc: D1 cache:
+desc: L2 cache:
+desc: Timerange: Basic block 0 - $total_time
+desc: Trigger: Program termination
+positions: line
+events: Ir
+summary: $total_time
+
+HEADER
+
+for $file (keys %stats) {
+
+ say OUT_FH "fl=$file";
+
+ for $func (keys %{ $stats{$file} }) {
+ say OUT_FH "\nfn=$func";
+
+ for $line (sort keys %{ $stats{$file}{$func} }) {
+
+ if ($stats{$file}{$func}{$line}{line_calls_func}) {
+
+ my $line_time = 0;
+ my $func_op_num = 0;
+
+ for $op_num (sort grep {$_ ne 'line_calls_func'} keys %{ $stats{$file}{$func}{$line} }) {
+
+ if ($stats{$file}{$func}{$line}{$op_num}{op} eq "FUNCTION_CALL") {
+ $func_op_num = $op_num;
+ }
+ else {
+ $line_time += $stats{$file}{$func}{$line}{$op_num}{time}
+ unless $stats{$file}{$func}{$line}{$op_num}{op} ~~ @call_ops;
+ }
+ }
+ say OUT_FH "$line $line_time";
+
+ my $func_name = $stats{$file}{$func}{$line}{$func_op_num}{func_name};
+ my $hits = $stats{$file}{$func}{$line}{$func_op_num}{hits};
+ $line_time = $stats{$file}{$func}{$line}{$func_op_num-1}{time};
+ say OUT_FH "cfn=$func_name";
+ say OUT_FH "calls=$hits $line_time";
+
+ my $func_time = $stats{$file}{$func}{$line}{$func_op_num}{time};
+
+ say OUT_FH "$line $func_time";
+ }
+ else {
+ #aggregate all lines
+ my $line_time = 0;
+ for $op_num (sort grep {$_ ne 'line_calls_func'} keys %{ $stats{$file}{$func}{$line} }) {
+ $line_time += $stats{$file}{$func}{$line}{$op_num}{time};
+ }
+ say OUT_FH "$line $line_time";
+ }
+ }
+ }
+}
More information about the parrot-commits
mailing list