Devel-NYTProf

 view release on metacpan or  search on metacpan

NYTProf.xs  view on Meta::CPAN

4631
4632
4633
4634
4635
4636
4637
4638
4639
4640
4641
4642
4643
4644
4645
4646
4647
4648
4649
4650
4651
        }
    }
    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,

NYTProf.xs  view on Meta::CPAN

4653
4654
4655
4656
4657
4658
4659
4660
4661
4662
4663
4664
4665
4666
4667
4668
4669
4670
4671
4672
4673
    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,

NYTProf.xs  view on Meta::CPAN

4689
4690
4691
4692
4693
4694
4695
4696
4697
4698
4699
4700
4701
4702
4703
4704
4705
4706
4707
4708
*   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);

NYTProf.xs  view on Meta::CPAN

4714
4715
4716
4717
4718
4719
4720
4721
4722
4723
4724
4725
4726
4727
4728
4729
4730
4731
4732
4733
4734
4735
        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)",

NYTProf.xs  view on Meta::CPAN

4738
4739
4740
4741
4742
4743
4744
4745
4746
4747
4748
4749
4750
4751
4752
4753
4754
4755
4756
4757
4758
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;

NYTProf.xs  view on Meta::CPAN

4760
4761
4762
4763
4764
4765
4766
4767
4768
4769
4770
4771
4772
4773
4774
4775
4776
4777
4778
4779
4780
4781
4782
4783
4784
4785
4786
4787
4788
4789
4790
4791
4792
4793
4794
4795
4796
4797
4798
4799
4800
4801
4802
4803
4804
4805
4806
4807
4808
4809
4810
4811
4812
4813
4814
4815
4816
4817
4818
4819
4820
4821
4822
4823
4824
4825
4826
4827
4828
4829
4830
4831
4832
4833
4834
4835
4836
4837
4838
4839
4840
4841
4842
4843
4844
4845
4846
4847
4848
4849
4850
4851
4852
4853
4854
4855
4856
4857
4858
4859
4860
4861
4862
4863
4864
4865
4866
4867
4868
4869
4870
4871
4872
4873
4874
4875
4876
4877
4878
4879
4880
4881
4882
4883
4884
4885
4886
4887
4888
4889
4890
4891
4892
4893
4894
4895
4896
4897
4898
4899
4900
4901
4902
4903
    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)",

NYTProf.xs  view on Meta::CPAN

4914
4915
4916
4917
4918
4919
4920
4921
4922
4923
4924
4925
4926
4927
4928
4929
4930
4931
4932
4933
4934
4935
4936
4937
4938
4939
4940
4941
4942
4943
4944
4945
4946
4947
4948
4949
4950
4951
4952
4953
4954
4955
4956
4957
4958
4959
4960
4961
                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)",

NYTProf.xs  view on Meta::CPAN

4990
4991
4992
4993
4994
4995
4996
4997
4998
4999
5000
5001
5002
5003
5004
5005
5006
5007
5008
5009
5010
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);
}

NYTProf.xs  view on Meta::CPAN

5144
5145
5146
5147
5148
5149
5150
5151
5152
5153
5154
5155
5156
5157
5158
5159
5160
5161
5162
5163
5164
                          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

61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
#
# 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

708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
subroutines that exit via C<goto &sub;> - 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:
 
=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

886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
Using C<open('-|')> in code running under L<FCGI::Engine> causes a panic in nytprofcalls.
 
=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

4711
4712
4713
4714
4715
4716
4717
4718
4719
4720
4721
4722
4723
4724
4725
4726
4727
4728
4729
4730
4731
/*
   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.271 second using v1.01-cache-2.11-cpan-ec4f86ec37b )