Devel-NYTProf
view release on metacpan or search on metacpan
}
}
va_end(args);
assert(i <= C_ARRAY_LENGTH(state->cb_args));
PUTBACK;
call_sv((SV *)state->cb[tag], G_DISCARD);
}
static loader_callback perl_callbacks[nytp_tag_max] =
{
0,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback,
load_perl_callback
};
static loader_callback processing_callbacks[nytp_tag_max] =
{
0,
0, /* version */
load_attribute_callback,
load_option_callback,
0, /* comment */
load_time_callback,
load_time_callback,
load_discount_callback,
load_new_fid_callback,
* fid_line_time => [ [...],[...],.. ] # index by [fid][line]
* }
* The value of each [fid][line] is an array ref containing:
* [ number of calls, total time spent ]
* lines containing string evals also get an extra element
* [ number of calls, total time spent, [...] ]
* which is an reference to an array containing the [calls,time]
* data for each line of the string eval.
*/
static void
load_profile_data_from_stream(pTHX_ loader_callback *callbacks,
Loader_state_base *state, NYTP_file in)
{
int file_major, file_minor;
SV *tmp_str1_sv = newSVpvn("",0);
SV *tmp_str2_sv = newSVpvn("",0);
size_t buffer_len = MAXPATHLEN * 2;
char *buffer = (char *)safemalloc(buffer_len);
croak("NYTProf data format error while parsing header");
if (file_major != NYTP_FILE_MAJOR_VERSION)
croak("NYTProf data format version %d.%d is not supported by NYTProf %s (which expects version %d.%d)",
file_major, file_minor, XS_VERSION, NYTP_FILE_MAJOR_VERSION, NYTP_FILE_MINOR_VERSION);
if (file_minor > NYTP_FILE_MINOR_VERSION)
warn("NYTProf data format version %d.%d is newer than that understood by this NYTProf %s, so errors are likely",
file_major, file_minor, XS_VERSION);
}
if (callbacks[nytp_version])
callbacks[nytp_version](state, nytp_version, file_major, file_minor);
while (1) {
/* Loop "forever" until EOF. We can only check the EOF flag *after* we
attempt a read. */
char c;
if (NYTP_read_unchecked(in, &c, sizeof(c)) != sizeof(c)) {
if (NYTP_eof(in))
break;
croak("Profile format error '%s' whilst reading tag at %ld (see TROUBLESHOOTING in NYTProf docs)",
state->input_chunk_seqn++;
if (trace_level >= 9)
logwarn("Chunk %lu token is %d ('%c') at %ld%s\n",
state->input_chunk_seqn, c, c, NYTP_tell(in)-1,
NYTP_type_of_offset(in));
switch (c) {
case NYTP_TAG_DISCOUNT:
{
callbacks[nytp_discount](state, nytp_discount);
break;
}
case NYTP_TAG_TIME_LINE: /*FALLTHRU*/
case NYTP_TAG_TIME_BLOCK:
{
I32 ticks = read_i32(in);
unsigned int file_num = read_u32(in);
unsigned int line_num = read_u32(in);
unsigned int block_line_num = 0;
nytp_tax_index tag = nytp_time_line;
if (c == NYTP_TAG_TIME_BLOCK) {
block_line_num = read_u32(in);
sub_line_num = read_u32(in);
tag = nytp_time_block;
}
/* Because it happens that the two "optional" arguments are
last, a single call will work. */
callbacks[tag](state, tag, ticks, file_num, line_num,
block_line_num, sub_line_num);
break;
}
case NYTP_TAG_NEW_FID: /* file */
{
SV *filename_sv;
unsigned int file_num = read_u32(in);
unsigned int eval_file_num = read_u32(in);
unsigned int eval_line_num = read_u32(in);
unsigned int fid_flags = read_u32(in);
unsigned int file_size = read_u32(in);
unsigned int file_mtime = read_u32(in);
filename_sv = read_str(aTHX_ in, NULL);
callbacks[nytp_new_fid](state, nytp_new_fid, file_num,
eval_file_num, eval_line_num,
fid_flags, file_size, file_mtime,
filename_sv);
break;
}
case NYTP_TAG_SRC_LINE:
{
unsigned int file_num = read_u32(in);
unsigned int line_num = read_u32(in);
SV *src = read_str(aTHX_ in, NULL);
callbacks[nytp_src_line](state, nytp_src_line, file_num,
line_num, src);
break;
}
case NYTP_TAG_SUB_ENTRY:
{
unsigned int file_num = read_u32(in);
unsigned int line_num = read_u32(in);
if (callbacks[nytp_sub_entry])
callbacks[nytp_sub_entry](state, nytp_sub_entry, file_num, line_num);
break;
}
case NYTP_TAG_SUB_RETURN:
{
unsigned int depth = read_u32(in);
NV incl_time = read_nv(in);
NV excl_time = read_nv(in);
SV *subname = read_str(aTHX_ in, tmp_str1_sv);
if (callbacks[nytp_sub_return])
callbacks[nytp_sub_return](state, nytp_sub_return, depth, incl_time, excl_time, subname);
break;
}
case NYTP_TAG_SUB_INFO:
{
unsigned int fid = read_u32(in);
SV *subname_sv = read_str(aTHX_ in, tmp_str1_sv);
unsigned int first_line = read_u32(in);
unsigned int last_line = read_u32(in);
callbacks[nytp_sub_info](state, nytp_sub_info, fid,
first_line, last_line, subname_sv);
break;
}
case NYTP_TAG_SUB_CALLERS:
{
unsigned int fid = read_u32(in);
unsigned int line = read_u32(in);
SV *caller_subname_sv = read_str(aTHX_ in, tmp_str2_sv);
unsigned int count = read_u32(in);
NV incl_time = read_nv(in);
NV excl_time = read_nv(in);
NV reci_time = read_nv(in);
unsigned int rec_depth = read_u32(in);
SV *called_subname_sv = read_str(aTHX_ in, tmp_str1_sv);
callbacks[nytp_sub_callers](state, nytp_sub_callers, fid,
line, count, incl_time, excl_time,
reci_time, rec_depth,
called_subname_sv,
caller_subname_sv);
break;
}
case NYTP_TAG_PID_START:
{
unsigned int pid = read_u32(in);
unsigned int ppid = read_u32(in);
NV start_time = read_nv(in);
callbacks[nytp_pid_start](state, nytp_pid_start, pid, ppid,
start_time);
break;
}
case NYTP_TAG_PID_END:
{
unsigned int pid = read_u32(in);
NV end_time = read_nv(in);
callbacks[nytp_pid_end](state, nytp_pid_end, pid, end_time);
break;
}
case NYTP_TAG_ATTRIBUTE:
{
char *value, *key_end;
char *end = NYTP_gets(in, &buffer, &buffer_len);
if (NULL == end)
/* probably EOF */
croak("Profile format error reading attribute (see TROUBLESHOOTING in NYTProf docs)");
--end; /* End, as returned, points 1 after the \n */
if ((NULL == (value = (char *)memchr(buffer, '=', end - buffer)))) {
logwarn("attribute malformed '%s'\n", buffer);
continue;
}
key_end = value++;
callbacks[nytp_attribute](state, nytp_attribute, buffer,
(unsigned long)(key_end - buffer),
0, value,
(unsigned long)(end - value), 0);
if (memEQs(buffer, key_end - buffer, "ticks_per_sec")) {
ticks_per_sec = (unsigned int)atoi(value);
}
else if (memEQs(buffer, key_end - buffer, "nv_size")) {
if (sizeof(NV) != atoi(value))
croak("Profile data created by incompatible perl config (NV size %d but ours is %d)",
if (NULL == end)
/* probably EOF */
croak("Profile format error reading attribute (see TROUBLESHOOTING in NYTProf docs)");
--end; /* end, as returned, points 1 after the \n */
if ((NULL == (value = (char *)memchr(buffer, '=', end - buffer)))) {
logwarn("option malformed '%s'\n", buffer);
continue;
}
key_end = value++;
callbacks[nytp_option](state, nytp_option, buffer,
(unsigned long)(key_end - buffer),
0, value,
(unsigned long)(end - value), 0);
break;
}
case NYTP_TAG_COMMENT:
{
char *end = NYTP_gets(in, &buffer, &buffer_len);
if (!end)
/* probably EOF */
croak("Profile format error reading comment (see TROUBLESHOOTING in NYTProf docs)");
if (callbacks[nytp_comment])
callbacks[nytp_comment](state, nytp_comment, buffer,
(unsigned long)(end - buffer), 0);
if (trace_level >= 1)
logwarn("# %s", buffer); /* includes \n */
break;
}
case NYTP_TAG_START_DEFLATE:
{
#ifdef HAS_ZLIB
if (callbacks[nytp_start_deflate]) {
callbacks[nytp_start_deflate](state, nytp_start_deflate);
}
NYTP_start_inflate(in);
#else
croak("File uses compression but compression is not supported by this build of NYTProf");
#endif
break;
}
default:
croak("Profile format error: token %d ('%c'), chunk %lu, pos %ld%s (see TROUBLESHOOTING in NYTProf docs)",
state.sub_subinfo_hv = newHV();
state.live_pids_hv = newHV();
state.attr_hv = newHV();
state.option_hv = newHV();
state.file_info_stash = gv_stashpv("Devel::NYTProf::FileInfo", GV_ADDWARN);
av_extend(state.fid_fileinfo_av, 64); /* grow them up front. */
av_extend(state.fid_srclines_av, 64);
av_extend(state.fid_line_time_av, 64);
load_profile_data_from_stream(aTHX_ processing_callbacks,
(Loader_state_base *)&state, in);
if (HvKEYS(state.live_pids_hv)) {
logwarn("Profile data incomplete, no terminator for %" IVdf " pids %s\n",
(IV)HvKEYS(state.live_pids_hv),
"(refer to TROUBLESHOOTING in the NYTProf documentation)");
store_attrib_sv(aTHX_ state.attr_hv, STR_WITH_LEN("complete"),
&PL_sv_no);
}
callback_info[i].description);
state.cb[i] = (CV *)SvRV(*svp);
} else
state.cb[i] = default_cb;
} else
state.cb[i] = default_cb;
}
for (i = 0; i < C_ARRAY_LENGTH(state.cb_args); i++)
state.cb_args[i] = sv_newmortal();
load_profile_data_from_stream(aTHX_ perl_callbacks, (Loader_state_base *)&state,
in);
}
struct int_constants_t {
const char *name;
int value;
};
static struct int_constants_t int_constants[] = {
/* NYTP_FIDf_* */
bin/nytprofcalls view on Meta::CPAN
#
# Building a call tree from return events is a little tricky because they don't
# appear in natural order. The code can return from a call at any depth
# deeper than the last seen depth.
#
my $root = {};
my @stack = ($root);
my $total_in = 0;
my $callbacks = {
OPTION => sub { my (undef, $k, $v) = @_; $option{$k} = $v },
ATTRIBUTE => sub { my (undef, $k, $v) = @_; $attribute{$k} = $v },
};
$callbacks->{SUB_ENTRY} = \&on_sub_entry_log if $opt_verbose;
$callbacks->{SUB_RETURN} = \&on_sub_return_build_call_stack;
$callbacks->{all_loaded} = sub {
output_call_path_hash( extract_call_path_hash($root) );
};
foreach my $input (@ARGV) {
warn "Reading $input...\n" if $opt_verbose;
Devel::NYTProf::Data->new({
filename => $input,
quiet => 1,
callback => $callbacks
});
}
$callbacks->{all_loaded}->();
exit 0;
sub on_sub_entry_log {
my (undef, $fid, $line) = @_;
warn "> at $fid:$line\n";
}
lib/Devel/NYTProf.pm view on Meta::CPAN
subroutines that exit via C<goto ⊂> - most frequently encountered in
AUTOLOAD subs and code using the L<Memoize> module.
In general the overall subroutine timing is accurate and should be trusted more
than the sum of statement or nested sub call timings.
=head2 Perl 5.10.1+ (or else 5.8.9+) is Recommended
These versions of perl yield much more detailed information about calls to
BEGIN, CHECK, INIT, and END blocks, the code handling tied or overloaded
variables, and callbacks from XS code.
Perl 5.12 will hopefully also fix an inaccuracy in the timing of the last
statement and the condition clause of some kinds of loops:
L<http://rt.perl.org/rt3/Ticket/Display.html?id=60954>
=head2 eval $string
Perl treats each execution of a string eval (C<eval $string;> not C<eval { ... }>)
as a distinct file, so NYTProf does as well. The 'files' are given names with
this structure:
lib/Devel/NYTProf.pm view on Meta::CPAN
Using C<open('-|')> in code running under L<FCGI::Engine> causes a panic in nytprofcalls.
See https://github.com/timbunce/devel-nytprof/issues/20 for more information.
=head2 For perl < 5.8.8 it may change what caller() returns
For example, the L<Readonly> module croaks with "Invalid tie" when profiled with
perl versions before 5.8.8. That's because L<Readonly> explicitly checking for
certain values from caller(). The L<NEXT> module is also affected.
=head2 For perl < 5.10.1 it can't see some implicit calls and callbacks
For perl versions prior to 5.8.9 and 5.10.1, some implicit subroutine calls
can't be seen by the I<subroutine> profiler. Technically this affects calls
made via the various perl C<call_*()> internal APIs.
For example, BEGIN/CHECK/INIT/END blocks, the C<TIE>I<whatever> subroutine
called by C<tie()>, all calls made via operator overloading, and callbacks from
XS code, are not seen.
The effect is that time in those subroutines is accumulated by the
subs that triggered the call to them. So time spent in calls invoked by
perl to handle overloading are accumulated by the subroutines that trigger
overloading (so it is measured, but the cost is dispersed across possibly many
calling locations).
Although the calls aren't seen by the subroutine profiler, the individual
I<statements> executed by the code in the called subs are profiled by the
lib/Devel/NYTProf/js/jit/jit.js view on Meta::CPAN
/*
Method: onClick
This method is called when clicking on a tree node. It mainly performs all calculations and the animation of contracting, translating and expanding pertinent nodes.
Parameters:
id - A node id.
options - A group of options and callbacks such as
- _onComplete_ an object callback called when the animation finishes.
- _Move_ an object that has as properties _offsetX_ or _offsetY_ for adding some offset position to the centered node.
Example:
(start code js)
st.onClick('mynodeid', {
Move: {
enable: true,
( run in 0.769 second using v1.01-cache-2.11-cpan-9b1e4054eb1 )