The attached patch (not for application, yet) hijacks parrot -p to emit dprofpp-compatible output to standard error. This allows us to profile PIR code at the PIR level (not the C level).
The caveats are: * you'll have to edit out anything else that appears on standard error, or dprofpp will complain * you'll have to edit the file manually to add the magic old-style dprofpp header, or dprofpp will complain The header is: #fOrTyTwO $hz=100; $XS_VERSION=’DProf 19970606’; # All values are given in HZ $rrun_utime=2; $rrun_stime=0; $rrun_rtime=7 PART2 Don't worry about that part. Just catenate it to the file, then run dprofpp to your results. Some of the statistics are a little bit wonky (probably because the header is wrong-ish), but they should give you a much better idea of where your time is going in PIR programs. I may make this emit callgrind-compatible output in the future, but this was the easiest proof of concept I could make work now. Enjoy. -- c
=== src/runops_cores.c ================================================================== --- src/runops_cores.c (revision 26556) +++ src/runops_cores.c (local) @@ -23,11 +23,16 @@ #include "parrot/embed.h" #include "trace.h" #include "interp_guts.h" +#include <sys/times.h> +#include <time.h> #ifdef HAVE_COMPUTED_GOTO # include "parrot/oplib/core_ops_cg.h" #endif +#define Parrot_report_entry(i) Parrot_report_profile((i), "+") +#define Parrot_report_exit(i) Parrot_report_profile((i), "-") + /* HEADERIZER HFILE: src/runops_cores.h */ /* HEADERIZER BEGIN: static */ @@ -38,6 +43,10 @@ __attribute__nonnull__(1) __attribute__nonnull__(2); +static void Parrot_report_profile(PARROT_INTERP, const char *s) + __attribute__nonnull__(1) + __attribute__nonnull__(2); + /* HEADERIZER END: static */ /* @@ -274,8 +283,9 @@ opcode_t * runops_profile_core(PARROT_INTERP, ARGIN(opcode_t *pc)) { - RunProfile * const profile = interp->profile; - const opcode_t old_op = profile->cur_op; + RunProfile * const profile = interp->profile; + const opcode_t old_op = profile->cur_op; + int report_entry = 1; /* if reentering the runloop, remember old op and calc time 'til now */ if (old_op) @@ -283,13 +293,24 @@ Parrot_floatval_time() - profile->starttime; while (pc) {/* && pc >= code_start && pc < code_end) */ - opcode_t cur_op; + opcode_t cur_op; + op_info_t op_info = interp->op_info_table[*pc]; CONTEXT(interp)->current_pc = pc; profile->cur_op = cur_op = *pc + PARROT_PROF_EXTRA; profile->starttime = Parrot_floatval_time(); profile->data[cur_op].numcalls++; + if (report_entry) { + Parrot_report_entry(interp); + report_entry = 0; + } + + if (op_info.jump & PARROT_JUMP_ENEXT) { + Parrot_report_exit(interp); + report_entry = 1; + } + DO_OP(pc, interp); /* profile->cur_op may be different, if exception was thrown */ @@ -306,6 +327,22 @@ return pc; } +void +Parrot_report_profile(PARROT_INTERP, NOTNULL(const char *s)) +{ + Parrot_Context *ctx = CONTEXT(interp); + struct tms buf; + Parrot_Context_info info; + + Parrot_Context_get_info(interp, ctx, &info); + times(&buf); + + fprintf( stderr, "%s %02d %02d %d %s::%s\n", + s, (int)buf.tms_utime, (int)buf.tms_stime, (int)time(NULL), + string_to_cstring(interp, info.nsname), + string_to_cstring(interp, info.subname) ); +} + /* =back