Long time reported for ref($x->{key})
Martin
has comments on the following extract of a Devel::NYTProf run. The
code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
the local 1Gb network (and it takes over 400s). We are NOT using
LWP::UserAgent::POE - in fact it is not even installed on this
machine. I fail to see how line 158 below can take 320s. This is a
POST request to an apache server with a small amount of Perl to read
the file and check it belongs to the person who is retrieving it. Run
outside of the POE Server the same POST takes around 5s with this
code:
use LWP::UserAgent;
use HTTP::Request;
my $ua = LWP::UserAgent->new();
$get = HTTP::Request->new('POST', 'http://xxx.yyy.zzz/cgi/x.cgi?
job_id=697171&session_id=892416290D9E04EFE040007F01006F5B');
my $r = $ua->request($get);
and this is the same code being run inside the POE Server.
Devel::NYTProf reports the top time in HTTP::Message::add_content like
this:
149 sub add_content
150
# spent 320s (320+149ms) within HTTP::Message::add_content which was
called 7585 times, avg 42.3ms/call: # 7585 times (320s+149ms) by
LWP::Protocol::__ANON__[/usr/local/share/perl/5.10.0/LWP/Protocol.pm:
139] at line 137 of LWP/Protocol.pm, avg 42.3ms/call
{
151 7585 12.0ms my $self = shift;
152 7585 22.4ms $self->_content unless exists $self->{_content};
153 7585 14.5ms my $chunkref = \$_[0];
154 7585 14.7ms $chunkref = $$chunkref if ref($$chunkref); # legacy
155
156 7585 66.2ms 7585 149ms _utf8_downgrade($$chunkref);
# spent 149ms making 7585 calls to HTTP::Message::__ANON__[HTTP/
Message.pm:18], avg 20µs/call
157
158 7585 320s my $ref = ref($self->{_content});
159 7585 53.9ms if (!$ref) {
160 7585 365ms $self->{_content} .= $$chunkref;
161 }
162 elsif ($ref eq "SCALAR") {
163 ${$self->{_content}} .= $$chunkref;
164 }
165 else {
166 Carp::croak("Can't append to $ref content");
167 }
168 7585 242ms delete $self->{_parts};
169 }
POE::Kernel::CORE:sselect is next with an exclusive time of 103s which
I can imagine is the waiting for data to be sent from Apache.
Unfortunately this is a huge bit of code and I've been unsuccessful in
reducing it to a small example which exhibits the same problem so far.
I'd appreciate any comments or suggestions before I go any further in
case someone sees something obvious I've missed.
Thanks.
Tim Bunce
> Before I get further lost in this I wonder if anyone else believes or
> has comments on the following extract of a Devel::NYTProf run. The
> code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
> the local 1Gb network (and it takes over 400s). We are NOT using
> LWP::UserAgent::POE - in fact it is not even installed on this
> machine. I fail to see how line 158 below can take 320s.
Can you send me the profile data file?
Tim.
Martin
tomorrow when back at work as my colleague has it.
It may be very large in which case I may provide FTP access to it.
Martin
Tim Bunce
On Thu, Jun 17, 2010 at 11:04:11AM -0700, Martin wrote:
> Before I get further lost in this I wonder if anyone else believes or
> has comments on the following extract of a Devel::NYTProf run. The
> code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
> the local 1Gb network (and it takes over 400s).
The overall numbers make sense though. The application run really does
take the amount of time nytprof says, and the subroutine times and
statement times are consistent. So I suspect perl not nytprof.
> I fail to see how line 158 below can take 320s.
> Run outside of the POE Server the same POST takes around 5s with this
> code: [...]
> and this is the same code being run inside the POE Server.
> Devel::NYTProf reports the top time in HTTP::Message::add_content like
> this:
>
> 149 sub add_content
> ...
> 151 7585 12.0ms my $self = shift;
> 152 7585 22.4ms $self->_content unless exists $self->{_content};
> 153 7585 14.5ms my $chunkref = \$_[0];
> 154 7585 14.7ms $chunkref = $$chunkref if ref($$chunkref); # legacy
> 155
> 156 7585 66.2ms 7585 149ms _utf8_downgrade($$chunkref);
> 157
> 158 7585 320s my $ref = ref($self->{_content});
> 159 7585 53.9ms if (!$ref) {
> 160 7585 365ms $self->{_content} .= $$chunkref;
> 161 }
Something very strange is going on.
Looking at the stream of statement timings I can see that that that line
in that file (fid 68) starts out only taking a small amount of time
Read 68:156 11 ticks
Read 68:158 35 ticks
Read 68:159 18 ticks
Read 68:160 67 ticks
but the time taken grows steadily, so later it's:
Read 68:156 11 ticks
Read 68:158 22197 ticks
Read 68:159 33 ticks
Read 68:160 284 ticks
and so it grows and grows until the final execution is:
Read 68:156 12 ticks
Read 68:158 888959 ticks
Read 68:159 64 ticks
Read 68:160 244 ticks
Nick, does this ring any bells with you?
Martin, please try with perl 5.10.1 as your 5.10.0 may be buggy.
Tim.
Martin
> Thanks for sending me the profile Martin.
>
> On Thu, Jun 17, 2010 at 11:04:11AM -0700, Martin wrote:
> > Before I get further lost in this I wonder if anyone else believes or
> > has comments on the following extract of a Devel::NYTProf run. The
> > code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
> > the local 1Gb network (and it takes over 400s).
>
> The overall numbers make sense though. The application run really does
> take the amount of time nytprof says, and the subroutine times and
> statement times are consistent. So I suspect perl not nytprof.
have stated that to avoid confusion - sorry.
>
>
> > I fail to see how line 158 below can take 320s.
> > Run outside of the POE Server the same POST takes around 5s with this
> > code: [...]
> > and this is the same code being run inside the POE Server.
> > Devel::NYTProf reports the top time in HTTP::Message::add_content like
> > this:
>
> > 149 sub add_content
> > ...
> > 151 7585 12.0ms my $self = shift;
> > 152 7585 22.4ms $self->_content unless exists $self->{_content};
> > 153 7585 14.5ms my $chunkref = \$_[0];
> > 154 7585 14.7ms $chunkref = $$chunkref if ref($$chunkref); # legacy
> > 155
> > 156 7585 66.2ms 7585 149ms _utf8_downgrade($$chunkref);
> > 157
> > 158 7585 320s my $ref = ref($self->{_content});
> > 159 7585 53.9ms if (!$ref) {
> > 160 7585 365ms $self->{_content} .= $$chunkref;
> > 161 }
>
> Something very strange is going on.
> Looking at the stream of statement timings I can see that that that line
> in that file (fid 68) starts out only taking a small amount of time
>
> Read 68:156 11 ticks
> Read 68:158 35 ticks
> Read 68:159 18 ticks
> Read 68:160 67 ticks
>
> but the time taken grows steadily, so later it's:
>
> Read 68:156 11 ticks
> Read 68:158 22197 ticks
> Read 68:159 33 ticks
> Read 68:160 284 ticks
>
> and so it grows and grows until the final execution is:
>
> Read 68:156 12 ticks
> Read 68:158 888959 ticks
> Read 68:159 64 ticks
> Read 68:160 244 ticks
The code in question is:
my $ref = ref($self->{_content});
$self->{_content} .= $$chunkref;
}
and I could see the concatenation perhaps taking longer and longer as
it is concatenating 4K chunks each time until it reaches 30Mb. I
didn't understand why the 320s was reported on the ref() though and
that is what confused me.
> Nick, does this ring any bells with you?
>
> Martin, please try with perl 5.10.1 as your 5.10.0 may be buggy.
>
> Tim.
modules in use but I'll have a go.
I'm now also getting negative times for some statements time in subs:
49 1 19µs 1 -90.1s $out = $q->sendRequest(\%r);
# spent - 90.1s making 1 call to XXX::Queue::sendRequest
so very strange things are happening.
Thanks for looking at it.
I'm still looking at it so I'll come back with what I find.
Martin
Martin
It is going to be a PITA to do this permanently but I seem to have
little choice.
I've no idea what problem was fixed between 5.10.0 and 5.10.1 which
caused this,
I had a quick look in perldelta but nothing struck me.
Thanks Tim for suggesting that.
Martin
Tim Bunce
>
> I upgraded to Perl 5.10.1 and problem has gone away.
> It is going to be a PITA to do this permanently but I seem to have
> little choice. I've no idea what problem was fixed between 5.10.0 and
> 5.10.1 which caused this, I had a quick look in perldelta but nothing
> struck me.
There were weird things with bless, overload and pathalogical hases
around the time of 5.10.0 but I didn't need to pay attention (since
we're using 5.8 .8 now and 5.12.1 soon) so I didn't.
Maybe Nicholas can shed some pumpkin light on it.
Please also give us your perl -V output, for the record.
> Thanks Tim for suggesting that.
You're welcome.
I'm glad NYTProf did "exactly what it said on the tin" :)
Tim.
Tim Bunce
> On Jun 18, 10:17 am, Tim Bunce <Tim.Bu...@pobox.com> wrote:
> > Thanks for sending me the profile Martin.
> >
> > On Thu, Jun 17, 2010 at 11:04:11AM -0700, Martin wrote:
> > > Before I get further lost in this I wonder if anyone else believes or
> > > has comments on the following extract of a Devel::NYTProf run. The
> > > code uses LWP::UserAgent in a POE server to retrieve ~ 30Mb file on
> > > the local 1Gb network (and it takes over 400s).
> >
> > The overall numbers make sense though. The application run really does
> > take the amount of time nytprof says, and the subroutine times and
> > statement times are consistent. So I suspect perl not nytprof.
>
> The application run really does take that time, I agree and I should
> have stated that to avoid confusion - sorry.
No problem. I was just stating it for the record. I often do "stream
of thought" emails when I'm working on diagnosing a problem.
> I'm now also getting negative times for some statements time in subs:
(actually that's a subroutine profiler time for time spent in the sub)
> 49 1 19µs 1 -90.1s $out = $q->sendRequest(\%r);
> # spent - 90.1s making 1 call to XXX::Queue::sendRequest
I don't see sendRequest in the profile you sent me, but I do see some
negative times for subroutines. Looking at the table of all subs and
sorting by inclusive time gives me:
Subroutines
Calls P F Exclusive Inclusive
8 1 1 -429s -105s LWP::Protocol::collect
8 1 1 6.28ms -91.3s LWP::Protocol::http::request
8 1 1 2.00ms -91.2s LWP::UserAgent::send_request
8 5 1 1.08ms -91.2s LWP::UserAgent::request
8 1 1 525µs -91.2s LWP::UserAgent::simple_request
4 1 1 10.5ms -80.8s BET::Service::User::get_job_result
5 1 1 72.2ms -80.7s BET::Service::User::call_action
5 1 1 77.4ms -80.5s main::new_request
18 4 3 1.21ms -77.2s POE::Kernel::call
5 1 1 895µs -77.2s main::__ANON__[/home/jason/bet/server/service.pl:269]
5 1 1 534µs -77.2s POE::Wheel::ReadWrite::__ANON__[/usr/local/share/perl/5.10.0/POE/Wheel/ReadWrite.pm:293]
5 1 1 123µs -77.2s POE::Component::Server::TCP::__ANON__[/usr/local/share/perl/5.10.0/POE/Component/Server/TCP.pm:323]
208 2 1 25.5ms -76.8s POE::Kernel::_data_handle_enqueue_ready
250 3 1 12.1ms -74.9s POE::Session::_invoke_state
243 7 4 20.9ms -74.8s POE::Kernel::_dispatch_event
Recursion tends to cause odd timings but I'm not sure if that's the case here.
I've committed a change to add recursion details to the subroutine table.
The way timings are handled for subs that recurse is quite possibly broken.
Tim.
Martin
Summary of my perl5 (revision 5 version 10 subversion 0)
configuration:
Platform:
osname=linux, osvers=2.6.24-23-server, archname=i486-linux-gnu-
thread-multi
uname='linux vernadsky 2.6.24-23-server #1 smp wed apr 1 22:22:14
utc 2009 i686 gnulinux '
config_args='-Dusethreads -Duselargefiles -Dccflags=-DDEBIAN -
Dcccdlflags=-fPIC -Darchname=i486-linux-gnu -Dprefix=/usr -Dprivlib=/
usr/share/perl/5.10 -Darchlib=/usr/lib/perl/5.10 -Dvendorprefix=/usr -
Dvendorlib=/usr/share/perl5 -Dvendorarch=/usr/lib/perl5 -Dsiteprefix=/
usr/local -Dsitelib=/usr/local/share/perl/5.10.0 -Dsitearch=/usr/local/
lib/perl/5.10.0 -Dman1dir=/usr/share/man/man1 -Dman3dir=/usr/share/man/
man3 -Dsiteman1dir=/usr/local/man/man1 -Dsiteman3dir=/usr/local/man/
man3 -Dman1ext=1 -Dman3ext=3perl -Dpager=/usr/bin/sensible-pager -Uafs
-Ud_csh -Ud_ualarm -Uusesfio -Uusenm -DDEBUGGING=-g -Doptimize=-O2 -
Duseshrplib -Dlibperl=libperl.so.5.10.0 -Dd_dosuid -des'
hint=recommended, useposix=true, d_sigaction=define
useithreads=define, usemultiplicity=define
useperlio=define, d_sfio=undef, uselargefiles=define,
usesocks=undef
use64bitint=undef, use64bitall=undef, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
cc='cc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-
aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -
D_FILE_OFFSET_BITS=64',
optimize='-O2 -g',
cppflags='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing
-pipe -I/usr/local/include'
ccversion='', gccversion='4.4.1', gccosandvers=''
intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
d_longlong=define, longlongsize=8, d_longdbl=define,
longdblsize=12
ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t',
lseeksize=8
alignbytes=4, prototype=define
Linker and Libraries:
ld='cc', ldflags =' -L/usr/local/lib'
libpth=/usr/local/lib /lib /usr/lib /usr/lib64
libs=-lgdbm -lgdbm_compat -ldb -ldl -lm -lpthread -lc -lcrypt
perllibs=-ldl -lm -lpthread -lc -lcrypt
libc=/lib/libc-2.10.1.so, so=so, useshrplib=true,
libperl=libperl.so.5.10.0
gnulibc_version='2.10.1'
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E'
cccdlflags='-fPIC', lddlflags='-shared -O2 -g -L/usr/local/lib'
Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV
PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP
USE_ITHREADS
USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API
Built under linux
Compiled at Oct 1 2009 22:19:26
%ENV:
PERL5LIB="/home/martin/bet/tools/modules/BET/lib:/home/martin/bet/
cgi"
@INC:
/home/martin/bet/tools/modules/BET/lib
/home/martin/bet/cgi
/etc/perl
/usr/local/lib/perl/5.10.0
/usr/local/share/perl/5.10.0
/usr/lib/perl5
/usr/share/perl5
/usr/lib/perl/5.10
/usr/share/perl/5.10
/usr/local/lib/site_perl
.
Nicholas Clark
>
> my $ref = ref($self->{_content});
> if (!$ref) {
> $self->{_content} .= $$chunkref;
> }
>
> and I could see the concatenation perhaps taking longer and longer as
> it is concatenating 4K chunks each time until it reaches 30Mb. I
> didn't understand why the 320s was reported on the ref() though and
> that is what confused me.
That's what I would have thought.
Assuming that the line number attribution is accurate, and it's something
in the hash lookup and reference taking, that's most strange. I don't think
that there's any copying involved.
On Fri, Jun 18, 2010 at 02:26:53PM +0100, Tim Bunce wrote:
> On Fri, Jun 18, 2010 at 05:47:50AM -0700, Martin wrote:
> >
> > I upgraded to Perl 5.10.1 and problem has gone away.
> > It is going to be a PITA to do this permanently but I seem to have
> > little choice. I've no idea what problem was fixed between 5.10.0 and
> > 5.10.1 which caused this, I had a quick look in perldelta but nothing
> > struck me.
>
> There were weird things with bless, overload and pathalogical hases
> around the time of 5.10.0 but I didn't need to pay attention (since
> we're using 5.8 .8 now and 5.12.1 soon) so I didn't.
>
> Maybe Nicholas can shed some pumpkin light on it.
>
> Please also give us your perl -V output, for the record.
-V for both would be interesting.
5.10.0 and 5.10.1 generate an identical optree for
my $ref = ref($self->{_content});
if (!$ref) {
$self->{_content} .= $$chunkref;
}
and the blame annotation: http://perl5.git.perl.org/perl.git/tree/maint-5.10
shows no changes to the code since 5.10.0 was shipped, so I can't see why it
would differ.
Nicholas Clark
Nicholas Clark
> It may take a bit longer to try 5.10.1 as we have a huge number of
> modules in use but I'll have a go.
5.10.1 is binary compatible with 5.10.0 (if you build it with the same options)
So you don't (shouldn't) need to rebuild any modules.
Nicholas Clark
Tim Bunce
> perl -V for broken case:
>
That's a curious configuration. On the plus side it does mean the binary
will have symbols. So you could use a sampling profiler[1]to probe where
perl is spending its time.
Tim.
[1] Like http://oprofile.sourceforge.net/about/
> --
> You've received this message because you are subscribed to
> the Devel::NYTProf Development User group.
>
> Group hosted at: http://groups.google.com/group/develnytprof-dev
> Project hosted at: http://perl-devel-nytprof.googlecode.com
> CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf
>
> To post, email: develnyt...@googlegroups.com
> To unsubscribe, email: develnytprof-d...@googlegroups.com
>
Martin
Summary of my perl5 (revision 5 version 10 subversion 1)
configuration:
Platform:
osname=linux, osvers=2.6.31-15-generic, archname=i686-linux
uname='linux betdevel 2.6.31-15-generic #50-ubuntu smp tue nov 10
14:54:29 utc 2009 i686 gnulinux '
config_args='-de -Dprefix=/home/martin/perl5101'
hint=recommended, useposix=true, d_sigaction=define
useithreads=undef, usemultiplicity=undef
usesocks=undef
use64bitint=undef, use64bitall=undef, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
optimize='-O2',
cppflags='-fno-strict-aliasing -pipe -fstack-protector -I/usr/
local/include'
intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
d_longlong=define, longlongsize=8, d_longdbl=define,
longdblsize=12
ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t',
lseeksize=8
alignbytes=4, prototype=define
Linker and Libraries:
libpth=/usr/local/lib /lib /usr/lib /usr/lib64
libs=-lnsl -ldb -ldl -lm -lcrypt -lutil -lc
perllibs=-lnsl -ldl -lm -lcrypt -lutil -lc
libc=/lib/libc-2.10.1.so, so=so, useshrplib=false,
libperl=libperl.a
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E'
fstack-protector'
Characteristics of this binary (from libperl):
USE_LARGE_FILES USE_PERLIO
Built under linux
Compiled at Dec 3 2009 16:41:19
PERL5LIB="/home/martin/bet/tools/modules/BET/lib:/home/martin/bet/
cgi"
@INC:
/home/martin/bet/tools/modules/BET/lib
/home/martin/bet/cgi
/home/martin/perl5101/lib/5.10.1
/home/martin/perl5101/lib/site_perl/5.10.1/i686-linux
/home/martin/perl5101/lib/site_perl/5.10.1
.
Martin
On Jun 19, 7:37 pm, Tim Bunce <Tim.Bu...@pobox.com> wrote:
> On Fri, Jun 18, 2010 at 08:39:47AM -0700, Martin wrote:
> > perl -V for broken case:
>
> > -DDEBUGGING=-g -Doptimize=-O2
>
> That's a curious configuration.
by Ubuntu. The newer 5.10.1 was built by me using all defaults.
> On the plus side it does mean the binary
> will have symbols. So you could use a sampling profiler[1]to probe where
> perl is spending its time.
>
> Tim.
>
> [1] Likehttp://oprofile.sourceforge.net/about/
>
So far I have been unable to reproduce this is a smaller test case but
I am continuing to try.
Martin
Martin
taint checking. The one that was taking ages was running with -t from
init and I forgot that and I was running it manually without -t.
Now I am even more suspicious of the concatentation line rather than
the ref(x) line taking the time. Since Tim found a line was taking
more and more ticks and the concatenation adds 4K each time to 32Mb it
almost sounds like taint checking is expensive and doing something
every time a chunk is added to the string.
I'm very sorry I forgot about taint checking. This is the second issue
we've found like this. I'm really going off taint mode quickly.
I can now reproduce with this:
create a file.dat file in your apache htdocs and make it around 32Mb
in size then run this:
use LWP::UserAgent;
use HTTP::Request;
my $ua = LWP::UserAgent->new();
with and without taint checking. I should also add our Apache
returns .dat files as UTF-8 encoded.
Is this something I should report elsewhere?
Martin
Martin
which was just recently (in March this year) fixed in 5.12.
Martin
reporting a long time spent on the wrong line. I know this is not a
Devel::NYTProf issue and it is simply that I used Devel::NYTProf to
highlight the troublesome line. Here is a smaller, self contained
example which proves the line originally highlighted by Devel::NYTProf
is the problem:
use strict;
use warnings;
use Scalar::Util qw(tainted);
my $fd;
open($fd, ">", "file.dat");
print $fd 'x' x 4096;
close $fd;
my $data;
{
local $/;
open ($fd, "<", "file.dat");
$data = <$fd>;
close $fd;
}
print "data is tainted: ", tainted($data) ? 'yes' : 'no', "\n";
my %hash;
$hash{content} = '';
foreach (1..10000) {
# comment following line out to make this fly
my $ref = ref($hash{content});
#if (!$ref) {
$hash{content} .= $data;
#}
}
print length($hash{content}), "\n";
Problem exists at least until up to 5.12.1.
I will pursue this elsewhere now (although I'm not sure where right
now) and thanks for your help.
Martin
Joshua ben Jore
If you run `perlbug` then you can file this is as a bug against core
perl and all the core perl 5 developers will hear about it in an
email. Most of what you've already posted would be great to copy/paste
into the bug report. It'll generate a formatted email to an address
something like per...@perl.org. You can then let it either send the
message directly if your system routes for external email or do what I
do which is then save the bug report as a text file and use my gmail
to send the exact "same" message. Please use the text formatting as
generated by perlbug.
Josh
Martin
On Jun 22, 3:34 pm, Joshua ben Jore <twi...@gmail.com> wrote:
> do which is then save the bug report as a text file and use my gmail
> to send the exact "same" message. Please use the text formatting as
> generated by perlbug.
>
> Josh
Martin