[prev in list] [next in list] [prev in thread] [next in thread]
List: intermezzo-devel
Subject: Re: tomorrow
From: Rob Simmonds <simmonds () cpsc ! ucalgary ! ca>
Date: 2000-03-09 17:11:54
[Download RAW message or body]
Peter,
OK, I have now run the POE tests on my laptop, after increasing the
event count to the same as used in the tests I am performing on our
extensions to the Event package.
Below are two sets of results for POE, one with the version we use
with InterMezzo and one with the latest version. Then come the tests
I sent you before. After that, a few tests done after modifying the
test script so that the function references are to non-anon functions
making it easier to see what is going on.
One thing to note is that Event::post is not really part of the Event
package. I just put it in the Event.xs code for testing since this
saved me some time. Also the Event::_loop function is the XS looping
function called by the Event::loop function at startup.
Re next steps. Before doing the things you have suggested (I think
"delay" needs to be added to that list) I would like to spend a little
time seeing if I can make the calls from C to Perl a little cheaper.
This should not take too long and the information may be important for
interface design decisions.
Rob
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
First the test version of the program using the version of POE
currently used with InterMezzo.
[root@lynx NPOE]# dprofpp
Total Elapsed Time = 42.48707 Seconds
User+System Time = 40.57707 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
25.5 10.36 10.070 100003 0.0001 0.0001 POE::Kernel::_enqueue_state
20.0 8.145 30.780 100000 0.0001 0.0003 POE::Kernel::_dispatch_state
18.8 7.660 45.330 1 7.6599 45.329 POE::Kernel::run
17.5 7.108 6.810 99999 0.0001 0.0001 POE::Kernel::_collect_garbage
15.1 6.138 5.840 100001 0.0001 0.0001 POE::Kernel::alias_resolve
10.1 4.125 19.130 100001 0.0000 0.0002 POE::Kernel::post
8.08 3.278 23.230 99998 0.0000 0.0002 POE::Session::_invoke_state
4.98 2.019 20.550 99997 0.0000 0.0002 main::__ANON__
1.95 0.790 0.370 140005 0.0000 0.0000 Time::HiRes::time
0.22 0.090 0.478 5 0.0180 0.0956 main::BEGIN
0.15 0.060 0.149 8 0.0075 0.0186 POE::Kernel::BEGIN
0.10 0.040 0.040 27 0.0015 0.0015 Exporter::export
0.05 0.020 0.030 4 0.0050 0.0075 IO::Seekable::BEGIN
0.02 0.010 0.010 5 0.0020 0.0020 DynaLoader::dl_install_xsub
0.02 0.010 0.010 5 0.0020 0.0020 DynaLoader::dl_load_file
[root@lynx NPOE]#
Now a test using the latest version of POE just downloaded from CPAN.
[root@lynx NPOE]# dprofpp
Total Elapsed Time = 41.87867 Seconds
User+System Time = 40.19867 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
24.4 9.828 9.630 100003 0.0001 0.0001 POE::Kernel::_enqueue_state
19.0 7.670 43.330 1 7.6699 43.329 POE::Kernel::run
16.9 6.819 6.620 99999 0.0001 0.0001 POE::Kernel::_collect_garbage
16.0 6.467 28.830 100002 0.0001 0.0003 POE::Kernel::_dispatch_state
12.0 4.856 18.110 100001 0.0000 0.0002 POE::Kernel::post
10.1 4.069 3.870 100001 0.0000 0.0000 POE::Kernel::alias_resolve
7.58 3.049 22.760 99998 0.0000 0.0002 POE::Session::_invoke_state
5.97 2.399 20.110 99997 0.0000 0.0002 main::__ANON__
2.59 1.040 0.760 140006 0.0000 0.0000 Time::HiRes::time
0.25 0.100 0.379 5 0.0200 0.0759 main::BEGIN
0.10 0.040 0.080 6 0.0067 0.0133 POE::Kernel::BEGIN
0.02 0.010 0.010 1 0.0100 0.0100 POSIX::bootstrap
0.02 0.010 0.010 14 0.0007 0.0007 Exporter::export
0.02 0.010 0.190 4 0.0025 0.0474 POE::BEGIN
0.02 0.010 0.010 1 0.0100 0.0100 AutoLoader::import
[root@lynx NPOE]#
All the other tests use the Event perl package, not POE ...
Event package with Peter's initial Perl based session extensions.
[lynx:NPOE] dprofpp
Total Elapsed Time = 11.28729 Seconds
User+System Time = 11.24729 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
37.8 4.259 3.960 100007 0.0000 0.0000 Kernel::post
31.4 3.540 14.729 1 3.5399 14.729 Event::_loop
31.4 3.538 6.900 100004 0.0000 0.0001 main::__ANON__
20.0 2.249 8.550 100004 0.0000 0.0001 Context::dispatch
16.9 1.909 9.860 100002 0.0000 0.0001 Kernel::dispatch
15.4 1.739 11.000 100002 0.0000 0.0001 Kernel::__ANON__
4.36 0.490 0.190 100001 0.0000 0.0000 Event::Event::DESTROY
0.36 0.040 0.079 4 0.0100 0.0198 Kernel::BEGIN
0.09 0.010 0.010 7 0.0014 0.0014 Exporter::export
0.09 0.010 0.010 3 0.0033 0.0033 Context::BEGIN
0.09 0.010 0.020 17 0.0006 0.0012 Event::BEGIN
0.09 0.010 0.079 4 0.0025 0.0198 main::BEGIN
0.09 0.010 0.010 5 0.0020 0.0019 Event::_load_watcher
0.00 0.000 -0.000 3 0.0000 - DynaLoader::dl_find_symbol
0.00 0.000 -0.000 3 0.0000 - DynaLoader::dl_install_xsub
[lynx:NPOE]
First try at adding session management using Event's C API to handle
the sessions.
[root@lynx R1]# dprofpp
Total Elapsed Time = 5.667817 Seconds
User+System Time = 5.647817 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
56.8 3.208 3.130 100004 0.0000 0.0000 main::__ANON__
46.7 2.639 5.270 100004 0.0000 0.0001 Context::dispatch
30.8 1.740 7.010 1 1.7400 7.0098 Event::_loop
11.8 0.670 0.420 100007 0.0000 0.0000 Event::post
0.53 0.030 0.099 7 0.0043 0.0142 main::BEGIN
0.35 0.020 0.020 17 0.0012 0.0012 Event::BEGIN
0.35 0.020 0.020 2 0.0100 0.0100 lib::BEGIN
0.18 0.010 0.010 1 0.0100 0.0100 Event::bootstrap
0.18 0.010 0.030 1 0.0100 0.0300 ExtUtils::testlib::BEGIN
0.18 0.010 0.010 5 0.0020 0.0019 Event::_load_watcher
0.00 0.000 -0.000 9 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::FETCH
0.00 0.000 -0.000 1 0.0000 - lib::import
0.00 0.000 -0.000 10 0.0000 - strict::import
0.00 0.000 -0.000 13 0.0000 - strict::bits
[root@lynx R1]#
Second attempt. This time references to subroutines are sent to the
kernel rather than sending the name of the subroutine. This removes
the need to have a symbolic lookup in the dispatcher.
[lynx:R1] dprofpp
Total Elapsed Time = 3.598317 Seconds
User+System Time = 3.588317 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
91.6 3.289 3.350 100004 0.0000 0.0000 main::__ANON__
25.3 0.910 4.260 1 0.9100 4.2599 Event::_loop
18.3 0.660 0.460 100007 0.0000 0.0000 Event::post
0.84 0.030 0.089 7 0.0043 0.0128 main::BEGIN
0.56 0.020 0.030 17 0.0012 0.0018 Event::BEGIN
0.56 0.020 0.020 2 0.0100 0.0100 lib::BEGIN
0.28 0.010 0.010 1 0.0100 0.0100 Event::var::allocate
0.28 0.010 0.010 6 0.0017 0.0017 base::import
0.00 0.000 -0.000 9 0.0000 - Exporter::import
0.00 0.000 -0.000 9 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::FETCH
0.00 0.000 -0.000 1 0.0000 - lib::import
0.00 0.000 -0.000 10 0.0000 - strict::import
0.00 0.000 -0.000 13 0.0000 - strict::bits
0.00 0.000 -0.000 3 0.0000 - attrs::BEGIN
[lynx:R1]
Now with a version modified to use non-anon function calls to make
profiling easier. This means that the receive handler ping
(main::rh_ping) and the send handler rep (main::sh_rep) now show up
rather than being grouped as main::__ANON__ .
[root@lynx R1]# dprofpp
Total Elapsed Time = 3.908317 Seconds
User+System Time = 3.888317 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
41.6 1.620 4.560 1 1.6200 4.5599 Event::_loop
40.0 1.559 1.550 50002 0.0000 0.0000 main::rh_ping
36.2 1.409 1.390 50000 0.0000 0.0000 main::sh_rep
14.6 0.570 0.370 100007 0.0000 0.0000 Event::post
0.77 0.030 0.099 7 0.0043 0.0142 main::BEGIN
0.51 0.020 0.020 17 0.0012 0.0012 Event::BEGIN
0.51 0.020 0.020 2 0.0100 0.0100 lib::BEGIN
0.51 0.020 0.020 5 0.0040 0.0040 Event::_load_watcher
0.00 0.000 -0.000 9 0.0000 - Exporter::import
0.00 0.000 -0.000 9 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::FETCH
0.00 0.000 -0.000 1 0.0000 - lib::import
0.00 0.000 -0.000 10 0.0000 - strict::import
0.00 0.000 -0.000 13 0.0000 - strict::bits
0.00 0.000 -0.000 3 0.0000 - attrs::BEGIN
[root@lynx R1]#
Now a version that dispatches 50 events from a fast FIFO C level queue
(all executed at Perl level) before going back to the Event inner
loop. In a real system executing events in this way would be used to
amortize the cost of calling select and gettimeofday in the inner
loop across a number of events. 50 is too large a number since on new
I/O will be seen during this execution period, it is used here assess
where the costs are occurring.
[root@lynx R1]# dprofpp
Total Elapsed Time = 3.678317 Seconds
User+System Time = 3.668317 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
47.6 1.749 1.680 50002 0.0000 0.0000 main::rh_ping
45.2 1.659 1.710 50000 0.0000 0.0000 main::sh_rep
25.9 0.950 4.340 1 0.9500 4.3399 Event::_loop
15.8 0.580 0.380 100007 0.0000 0.0000 Event::post
1.09 0.040 0.099 7 0.0057 0.0142 main::BEGIN
0.55 0.020 0.020 2 0.0100 0.0100 lib::BEGIN
0.55 0.020 0.020 5 0.0040 0.0040 Event::_load_watcher
0.27 0.010 0.010 17 0.0006 0.0006 Event::BEGIN
0.00 0.000 -0.000 9 0.0000 - Exporter::import
0.00 0.000 -0.000 9 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::FETCH
0.00 0.000 -0.000 1 0.0000 - lib::import
0.00 0.000 -0.000 10 0.0000 - strict::import
0.00 0.000 -0.000 13 0.0000 - strict::bits
0.00 0.000 -0.000 3 0.0000 - attrs::BEGIN
[root@lynx R1]#
This time I increased the number of events executed without going back
to Event's main queue was increased to 500 (just for profiling
information).
[root@lynx R1]# dprofpp
Total Elapsed Time = 3.768317 Seconds
User+System Time = 3.678317 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
46.1 1.699 1.660 50002 0.0000 0.0000 main::rh_ping
41.3 1.519 1.570 50000 0.0000 0.0000 main::sh_rep
30.4 1.120 4.350 1 1.1200 4.3499 Event::_loop
16.5 0.610 0.410 100007 0.0000 0.0000 Event::post
0.54 0.020 0.020 17 0.0012 0.0012 Event::BEGIN
0.54 0.020 0.020 2 0.0100 0.0100 lib::BEGIN
0.54 0.020 0.020 5 0.0040 0.0040 Event::_load_watcher
0.54 0.020 0.099 7 0.0028 0.0142 main::BEGIN
0.27 0.010 0.010 3 0.0033 0.0033 DynaLoader::bootstrap
0.00 0.000 -0.000 9 0.0000 - Exporter::import
0.00 0.000 -0.000 9 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::FETCH
0.00 0.000 -0.000 1 0.0000 - lib::import
0.00 0.000 -0.000 10 0.0000 - strict::import
0.00 0.000 -0.000 13 0.0000 - strict::bits
[root@lynx R1]#
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic