Re: Help with slow startup
On 1/18/2010 4:52 PM, Jan Dubois wrote: > On Mon, 18 Jan 2010, Michael Ellery wrote: >> >> I have a slow startup problem with a library I have written. The >> observed behavior is that perl scripts that use my library >> *intermittently* take 30 seconds to startup. If I run them again >> immediately thereafter, they drop back down to about 10 seconds to >> startup. If I wait for some time (several hours, perhaps, although I'm >> not sure what the trigger is), then the script will exhibit slow startup >> again for the first execution and behave normally thereafter. Rebooting >> also causes the problem to reappear. > > Please try this patch to Win32::OLE::Const: > > http://code.google.com/p/libwin32/source/diff?spec=svn465&r=465&format=side&path=/trunk/Win32-OLE/lib/Win32/OLE/Const.pm > > It specifically deals with some slowness in Win32::OLE::Const that > _may_ be the problem you are seeing. > > I guess I should make a Win32::OLE CPAN release to get this change > out to the rest of the world. So please confirm if this solves > your problem! > > Cheers, > -Jan > > Jan, Thanks for that patch. I've patched the file on my system and rebooted - now I see times shown below. Now my first startup time is only double my "steady state" time, which seems to be an improvement (previous run was more than 3 times the subsequent time). However, since the patch appears in a .pm file, shouldn't this change have an impact *every time* the script is executed, or is this code only loaded under certain conditions? Thanks, Mike C:\s2>dprofpp tmon_FIRST.out Total Elapsed Time = 20.19217 Seconds User+System Time = 2.898179 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 75.2 2.181 2.173 1730 0.0013 0.0013 Win32::OLE::Dispatch 8.11 0.235 0.326 2 0.1174 0.1628 Win32::OLE::Const::_Typelibs 3.14 0.091 0.091744 0.0001 0.0001 Win32::OLE::Const::_Typelib 2.69 0.078 0.450 23 0.0034 0.0196 STRIDE::BEGIN 1.55 0.045 0.041796 0.0001 0.0001 Win32::OLE::DESTROY 1.38 0.040 1.133 1729 0. 0.0007 Win32::OLE::AUTOLOAD 1.10 0.032 0.032 2 0.0160 0.0160 Win32::OLE::new 1.07 0.031 0.031 5 0.0062 0.0062 Devel::Symdump::_symdump 1.07 0.031 0.541 39 0.0008 0.0139 STRIDE::Test::BEGIN 0.55 0.016 0.016 1 0.0160 0.0160 Win32::OLE::bootstrap 0.55 0.016 0.031 2 0.0080 0.0153 Pod::POM::parse_file 0.55 0.016 0.016 8 0.0020 0.0020 DynaLoader::dl_load_file 0.55 0.016 0.016 4 0.0040 0.0040 Config::BEGIN 0.55 0.016 0.016 15 0.0011 0.0011 STRIDE::Test::MethodInfo::new 0.55 0.016 0.016 5 0.0032 0.0032 Pod::POM::View::HTML::BEGIN C:\s2>dprofpp tmon_SECOND.out Total Elapsed Time = 10.09317 Seconds User+System Time = 2.742174 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 74.9 2.056 2.064 1730 0.0012 0.0012 Win32::OLE::Dispatch 9.63 0.264 0.342 2 0.1319 0.1708 Win32::OLE::Const::_Typelibs 2.84 0.078 0.078744 0.0001 0.0001 Win32::OLE::Const::_Typelib 1.71 0.047 0.047 5 0.0094 0.0094 Devel::Symdump::_symdump 1.68 0.046 0.419 23 0.0020 0.0182 STRIDE::BEGIN 1.42 0.039 1.039 1729 0. 0.0006 Win32::OLE::AUTOLOAD 1.17 0.032 0.527 39 0.0008 0.0135 STRIDE::Test::BEGIN 1.13 0.031 0.031269 0.0001 0.0001 Win32::OLE::Tie::Store 0.58 0.016 0.016 2 0.0080 0.0080 Win32::OLE::new 0.58 0.016 0.016 1 0.0160 0.0159 ActivePerl::Config::override 0.58 0.016 0.031 5 0.0032 0.0061 Storable::BEGIN 0.58 0.016 0.032 5 0.0032 0.0064 Win32::OLE::BEGIN 0.58 0.016 0.557 4 0.0040 0.1394 main::BEGIN 0.58 0.016 0.016 14 0.0011 0.0011 STRIDE::Function::_perlFromPayload 0.58 0.016 0.016 20 0.0008 0.0008 STRIDE::TestPoint::BEGIN C:\s2>dprofpp tmon_THIRD.out Total Elapsed Time = 10.09317 Seconds User+System Time = 2.775174 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 77.0 2.137 2.129 1730 0.0012 0.0012 Win32::OLE::Dispatch 8.94 0.248 0.326 2 0.1239 0.1628 Win32::OLE::Const::_Typelibs 2.81 0.078 0.078744 0.0001 0.0001 Win32::OLE::Const::_Typelib 1.73 0.048 0.403 23 0.0021 0.0175 STRIDE::BEGIN 1.69 0.047 0.047 5 0.0094 0.0094 Devel::Symdump::_symdump 1.69 0.047 0.511 39 0.0012 0.0131 STRIDE::Test::BEGIN 1.12 0.031 0.031 2 0.0155 0.0155 Win32::OLE::new 1.01 0.028 0.963 3 0.0094 0.3209 STRIDE::TestPoint::Wait 0.58 0.016 0.016 3 0.0053 0.0053 B::BEGIN 0.58 0.016 0.016 5 0.0032 0.0032 base::BEGIN 0.58 0.016 0.016 4 0.0040 0.0040 Pod::POM::Nodes::BEGIN 0.58 0.016 0.031 5 0.0032 0.0061 Storable::BEGIN 0.58 0.016 0.016 48 0.0003 0.0003 Pod::POM::Node::Sequence::new 0.58 0.016 0.031 1
RE: Help with slow startup
On Mon, 18 Jan 2010, Michael Ellery wrote: > > I have a slow startup problem with a library I have written. The > observed behavior is that perl scripts that use my library > *intermittently* take 30 seconds to startup. If I run them again > immediately thereafter, they drop back down to about 10 seconds to > startup. If I wait for some time (several hours, perhaps, although I'm > not sure what the trigger is), then the script will exhibit slow startup > again for the first execution and behave normally thereafter. Rebooting > also causes the problem to reappear. Please try this patch to Win32::OLE::Const: http://code.google.com/p/libwin32/source/diff?spec=svn465&r=465&format=side&path=/trunk/Win32-OLE/lib/Win32/OLE/Const.pm It specifically deals with some slowness in Win32::OLE::Const that _may_ be the problem you are seeing. I guess I should make a Win32::OLE CPAN release to get this change out to the rest of the world. So please confirm if this solves your problem! Cheers, -Jan ___ Perl-Win32-Users mailing list Perl-Win32-Users@listserv.ActiveState.com To unsubscribe: http://listserv.ActiveState.com/mailman/mysubs
Help with slow startup
I have a slow startup problem with a library I have written. The observed behavior is that perl scripts that use my library *intermittently* take 30 seconds to startup. If I run them again immediately thereafter, they drop back down to about 10 seconds to startup. If I wait for some time (several hours, perhaps, although I'm not sure what the trigger is), then the script will exhibit slow startup again for the first execution and behave normally thereafter. Rebooting also causes the problem to reappear. I'm using Win32::OLE quite extensively to interact with several of our COM objects - and I even have some COM calls in one of by BEGIN blocks. All of this works fine, with the exception of this intermittent startup lag. I have trouble reproducing the problem, so I even have trouble diagnosing it further (using process explorer, etc). Does anyone have any suggestion or advice for what might be going on and how to track it down? I'm wondering if there is some caching of COM objects going on perhaps that could be going on? I'm running on Windows XP 32 bit (perhaps that matters, I don't know). I've tried running with -dprof and here's what it shows for the first and second runs: FIRST RUN: Total Elapsed Time = 37.44117 Seconds User+System Time = 2.947177 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 70.8 2.087 2.079 1730 0.0012 0.0012 Win32::OLE::Dispatch 9.03 0.266 0.421 2 0.1329 0.2103 Win32::OLE::Const::_Typelibs 5.26 0.155 0.155744 0.0002 0.0002 Win32::OLE::Const::_Typelib 3.19 0.094 0.714 39 0.0024 0.0183 STRIDE::Test::BEGIN 1.56 0.046 0.759 4 0.0115 0.1899 main::BEGIN 1.53 0.045 0.041796 0.0001 0.0001 Win32::OLE::DESTROY 1.36 0.040 1.053 1729 0. 0.0006 Win32::OLE::AUTOLOAD 1.09 0.032 0.032 2 0.0160 0.0160 Win32::OLE::new 1.05 0.031 0.031 5 0.0062 0.0062 Devel::Symdump::_symdump 1.05 0.031 0.031 4 0.0077 0.0077 Config::BEGIN 1.05 0.031 0.045 8 0.0039 0.0057 Pod::POM::BEGIN 0.54 0.016 0.016 1 0.0160 0.0160 Win32::OLE::Uninitialize 0.54 0.016 0.016 1 0.0160 0.0160 Devel::Symdump::_partdump 0.54 0.016 0.016 5 0.0032 0.0032 File::Basename::BEGIN 0.54 0.016 0.016 6 0.0027 0.0027 Text::Wrap::BEGIN SECOND RUN: Total Elapsed Time = 10.91888 Seconds User+System Time = 2.918880 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 75.3 2.200 2.238 1730 0.0013 0.0013 Win32::OLE::Dispatch 10.1 0.295 0.419 2 0.1474 0.2094 Win32::OLE::Const::_Typelibs 4.25 0.124 0.124744 0.0002 0.0002 Win32::OLE::Const::_Typelib 2.19 0.064 0.590 39 0.0016 0.0151 STRIDE::Test::BEGIN 1.61 0.047 0.047 5 0.0094 0.0094 Devel::Symdump::_symdump 1.30 0.038 0.035 2536 0. 0. Win32::OLE::Tie::FETCH 0.55 0.016 0.016 1 0.0160 0.0159 ActivePerl::Config::override 0.55 0.016 0.016 3 0.0053 0.0053 DynaLoader::BEGIN 0.55 0.016 0.016 5 0.0032 0.0032 Pod::POM::View::HTML::BEGIN 0.55 0.016 0.016 7 0.0023 0.0023 IO::Handle::BEGIN 0.55 0.016 0.636 4 0.0040 0.1589 main::BEGIN 0.55 0.016 0.015 8 0.0020 0.0019 Pod::POM::BEGIN 0.55 0.016 0.027 30 0.0005 0.0009 STRIDE::Test::AddAnnotation 0.55 0.016 0.016 42 0.0004 0.0004 Pod::POM::Node::new 0.51 0.015 0.015414 0. 0. Pod::POM::Node::AUTOLOAD So, clearly it's showing the discrepancy in total time, but nothing stands out as far as the code that is profiled by dprof. Any advice about other things I should try? Thanks, Mike Ellery ___ Perl-Win32-Users mailing list Perl-Win32-Users@listserv.ActiveState.com To unsubscribe: http://listserv.ActiveState.com/mailman/mysubs
