the code showing timing injection.


            delta_time = time() - self.start_time
	    log("delta_time(pre pyro init)  %s"% delta_time)

            arrival = common_services.arrival_DBM()

            delta_time = time() - self.start_time
	    log("delta_time(mid pyro init)  %s"% delta_time)

            arrival.initialize()

            delta_time = time() - self.start_time
	    log("delta_time(pyro init)  %s"% delta_time)

-----------
for common_services.arrival

    def __init__(self):
        """ """
        # really should make a separate initiator to replicate init call
        Pyro.core.initClient(banner=0)
        self.remote_object = Pyro.core.getProxyForURI("PYRONAME://arrival_DBM")

timing from my code showing a three second delay.  Note: these times are cumulative from the beginning of the method.

Oct 11 13:45:57 harvee2pb python: 32312:: postfix_prefilter.py process_rcpttos 164: 1:1: proc_rcpttos ['esj@harvee.org']
Oct 11 13:45:57 harvee2pb python: 32312:: postfix_prefilter.py process_rcpttos 173: 1:1: delta_time(pre pyro init)  0.00242710113525
Oct 11 13:46:00 harvee2pb python: 32312:: postfix_prefilter.py process_rcpttos 178: 1:1: delta_time(mid pyro init)  3.07307600975
Oct 11 13:46:00 harvee2pb python: 32312:: postfix_prefilter.py process_rcpttos 183: 1:1: delta_time(pyro init)  3.08925390244

the output of TCP dump.  Around the time of the delay (13:45:57) and there are a series of broadcasts.  I have two name servers running both supplying the same services.  when I eliminate the second name server, I see the exact same pattern in TCP dump.

13:45:56.856141 arp who-has 192.168.0.31 tell green.harvee.org
13:45:56.857395 IP tpblue.33177 > xeno.harvee.org.domain:  46035+ PTR? 31.0.168.192.in-addr.arpa. (43)
13:45:56.858275 IP xeno.harvee.org.domain > tpblue.33177:  46035 NXDomain* 0/0/0 (43)
13:45:57.144017 IP 192.168.0.31.42184 > tpblue.smtp: S 1850267861:1850267861(0) win 5840 <mss 1460,sackOK,timestamp 43170097 0,nop,wscale 2>
13:45:57.144275 IP tpblue.smtp > 192.168.0.31.42184: S 1645640663:1645640663(0) ack 1850267862 win 5792 <mss 1460,sackOK,timestamp 42365171 43170097,nop,wscale 2>
13:45:57.147902 IP 192.168.0.31.42184 > tpblue.smtp: . ack 1 win 1460 <nop,nop,timestamp 43170098 42365171>
13:45:57.239238 IP tpblue.33177 > xeno.harvee.org.domain:  33944+ PTR? 31.0.168.192.in-addr.arpa. (43)
13:45:57.240219 IP xeno.harvee.org.domain > tpblue.33177:  33944 NXDomain* 0/0/0 (43)
13:45:57.245343 IP tpblue.smtp > 192.168.0.31.42184: P 1:50(49) ack 1 win 1448 <nop,nop,timestamp 42365196 43170098>
13:45:57.246961 IP 192.168.0.31.42184 > tpblue.smtp: . ack 50 win 1460 <nop,nop,timestamp 43170119 42365196>
13:45:57.247835 IP 192.168.0.31.42184 > tpblue.smtp: P 1:19(18) ack 50 win 1460 <nop,nop,timestamp 43170120 42365196>
13:45:57.249146 IP tpblue.smtp > 192.168.0.31.42184: . ack 19 win 1448 <nop,nop,timestamp 42365197 43170120>
13:45:57.251195 IP tpblue.smtp > 192.168.0.31.42184: P 50:159(109) ack 19 win 1448 <nop,nop,timestamp 42365197 43170120>
13:45:57.253779 IP 192.168.0.31.42184 > tpblue.smtp: P 19:65(46) ack 159 win 1460 <nop,nop,timestamp 43170123 42365197>
13:45:57.291197 IP tpblue.smtp > 192.168.0.31.42184: . ack 65 win 1448 <nop,nop,timestamp 42365208 43170123>
13:45:57.294817 IP tpblue.smtp > 192.168.0.31.42184: P 159:167(8) ack 65 win 1448 <nop,nop,timestamp 42365208 43170123>
13:45:57.296723 IP 192.168.0.31.42184 > tpblue.smtp: P 65:91(26) ack 167 win 1460 <nop,nop,timestamp 43170144 42365208>
13:45:57.296842 IP tpblue.smtp > 192.168.0.31.42184: . ack 91 win 1448 <nop,nop,timestamp 42365209 43170144>
13:45:57.396905 IP tpblue.33177 > 255.255.255.255.9090: UDP, length 8
13:45:57.398397 IP tpblue.33177 > 255.255.255.255.9091: UDP, length 8
13:45:58.152129 IP tpblue.33177 > 255.255.255.255.9090: UDP, length 8
13:45:58.152515 IP tpblue.33177 > 255.255.255.255.9091: UDP, length 8
13:45:58.184533 802.1d config 8000.00:12:25:55:f3:ec.8001 root 8000.00:12:25:55:f3:ec pathcost 0 age 0 max 20 hello 2 fdelay 0
13:45:58.908481 IP tpblue.33177 > 255.255.255.255.9090: UDP, length 8
13:45:58.911615 IP tpblue.33177 > 255.255.255.255.9091: UDP, length 8
13:45:59.663736 IP tpblue.33177 > 255.255.255.255.9090: UDP, length 8
13:45:59.664142 IP tpblue.33177 > 255.255.255.255.9091: UDP, length 8
13:46:00.179822 802.1d config 8000.00:12:25:55:f3:ec.8001 root 8000.00:12:25:55:f3:ec pathcost 0 age 0 max 20 hello 2 fdelay 0
13:46:00.468770 IP tpblue.58818 > xeno.harvee.org.smtp: S 1649267519:1649267519(0) win 5840 <mss 1460,sackOK,timestamp 42366002 0,nop,wscale 2>
13:46:00.469558 IP xeno.harvee.org.smtp > tpblue.58818: S 58445807:58445807(0) ack 1649267520 win 5792 <mss 1460,sackOK,timestamp 376476773 42366002,nop,wscale 2>


--------- 
looking on local host, I discovered a bunch of traffic between name server and one of the processes as well as a pyro calls.  The timestamps are different because it's a different call.  Equivalent log file entries are:

Oct 11 14:17:17 harvee2pb python: 32380:: postfix_prefilter.py process_rcpttos 164: 1:1: proc_rcpttos ['esj@harvee.org']
Oct 11 14:17:17 harvee2pb python: 32380:: postfix_prefilter.py process_rcpttos 173: 1:1: delta_time(pre pyro init)  0.00231599807739
Oct 11 14:17:20 harvee2pb python: 32380:: postfix_prefilter.py process_rcpttos 178: 1:1: delta_time(mid pyro init)  3.11243796349
Oct 11 14:17:20 harvee2pb python: 32380:: postfix_prefilter.py process_rcpttos 183: 1:1: delta_time(pyro init)  3.13132810593

---------------

14:17:17.461291 IP harvee2pb.harvee.org.59010 > harvee2pb.harvee.org.7766: P 832042620:832042716(96) ack 835752835 win 8192 <nop,nop,timestamp 42835221 42832717>
14:17:17.462713 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.59010: P 1:34(33) ack 96 win 8192 <nop,nop,timestamp 42835221 42835221>
14:17:17.463915 IP harvee2pb.harvee.org.59010 > harvee2pb.harvee.org.7766: . ack 34 win 8192 <nop,nop,timestamp 42835221 42835221>
14:17:17.694808 IP localhost.56191 > localhost.30025: S 3650606861:3650606861(0) win 32767 <mss 16396,sackOK,timestamp 42835279 0,nop,wscale 2>
14:17:17.694919 IP localhost.30025 > localhost.56191: S 3649520057:3649520057(0) ack 3650606862 win 32767 <mss 16396,sackOK,timestamp 42835279 42835279,nop,wscale 2>
14:17:17.696762 IP localhost.56191 > localhost.30025: . ack 1 win 8192 <nop,nop,timestamp 42835280 42835279>
14:17:17.713903 IP localhost.30025 > localhost.56191: P 1:57(56) ack 1 win 8192 <nop,nop,timestamp 42835284 42835280>
14:17:17.713982 IP localhost.56191 > localhost.30025: . ack 57 win 8192 <nop,nop,timestamp 42835284 42835284>
14:17:17.717460 IP localhost.56191 > localhost.30025: P 1:28(27) ack 57 win 8192 <nop,nop,timestamp 42835285 42835284>
14:17:17.717525 IP localhost.30025 > localhost.56191: . ack 28 win 8192 <nop,nop,timestamp 42835285 42835285>
14:17:17.721198 IP localhost.30025 > localhost.56191: P 57:92(35) ack 28 win 8192 <nop,nop,timestamp 42835286 42835285>
14:17:17.761217 IP localhost.56191 > localhost.30025: . ack 92 win 8192 <nop,nop,timestamp 42835296 42835286>
14:17:17.761427 IP localhost.30025 > localhost.56191: P 92:141(49) ack 28 win 8192 <nop,nop,timestamp 42835296 42835296>
14:17:17.761468 IP localhost.56191 > localhost.30025: . ack 141 win 8192 <nop,nop,timestamp 42835296 42835296>
14:17:17.762087 IP localhost.56191 > localhost.30025: P 28:104(76) ack 141 win 8192 <nop,nop,timestamp 42835296 42835296>
14:17:17.764989 IP localhost.30025 > localhost.56191: P 141:149(8) ack 104 win 8192 <nop,nop,timestamp 42835297 42835296>
14:17:17.765790 IP localhost.56191 > localhost.30025: P 104:150(46) ack 149 win 8192 <nop,nop,timestamp 42835297 42835297>
14:17:17.768879 IP localhost.30025 > localhost.56191: P 149:157(8) ack 150 win 8192 <nop,nop,timestamp 42835297 42835297>
14:17:17.769850 IP localhost.56191 > localhost.30025: P 150:176(26) ack 157 win 8192 <nop,nop,timestamp 42835298 42835297>
14:17:20.822608 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: S 3646323567:3646323567(0) win 32767 <mss 16396,sackOK,timestamp 42836061 0,nop,wscale 2>
14:17:20.822696 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: S 3655249496:3655249496(0) ack 3646323568 win 32767 <mss 16396,sackOK,timestamp 42836061 42836061,nop,wscale 2>
14:17:20.824869 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: . ack 1 win 8192 <nop,nop,timestamp 42836061 42836061>
14:17:20.837828 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: P 1:35(34) ack 1 win 8192 <nop,nop,timestamp 42836065 42836061>
14:17:20.838008 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: . ack 35 win 8192 <nop,nop,timestamp 42836065 42836065>
14:17:20.842187 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: P 1:42(41) ack 35 win 8192 <nop,nop,timestamp 42836066 42836065>
14:17:20.846044 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: . ack 42 win 8192 <nop,nop,timestamp 42836067 42836066>
14:17:20.850779 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: P 35:42(7) ack 42 win 8192 <nop,nop,timestamp 42836068 42836066>
14:17:20.854272 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: P 42:144(102) ack 42 win 8192 <nop,nop,timestamp 42836069 42836068>
14:17:20.858948 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: P 42:99(57) ack 144 win 8192 <nop,nop,timestamp 42836070 42836069>
14:17:20.859712 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: P 144:220(76) ack 99 win 8192 <nop,nop,timestamp 42836070 42836070>
14:17:20.862020 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: P 99:121(22) ack 220 win 8192 <nop,nop,timestamp 42836071 42836070>
14:17:20.862633 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: F 220:220(0) ack 121 win 8192 <nop,nop,timestamp 42836071 42836071>
14:17:20.863728 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: S 3656289702:3656289702(0) win 32767 <mss 16396,sackOK,timestamp 42836071 0,nop,wscale 2>
14:17:20.863789 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: S 3643215663:3643215663(0) ack 3656289703 win 32767 <mss 16396,sackOK,timestamp 42836071 42836071,nop,wscale 2>
14:17:20.863861 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: . ack 1 win 8192 <nop,nop,timestamp 42836071 42836071>
14:17:20.867554 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53890: F 121:121(0) ack 221 win 8192 <nop,nop,timestamp 42836072 42836071>
14:17:20.867663 IP harvee2pb.harvee.org.53890 > harvee2pb.harvee.org.9090: . ack 122 win 8192 <nop,nop,timestamp 42836072 42836072>
14:17:20.872892 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: P 1:35(34) ack 1 win 8192 <nop,nop,timestamp 42836073 42836071>
14:17:20.873181 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: . ack 35 win 8192 <nop,nop,timestamp 42836074 42836073>
14:17:20.874069 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: P 1:42(41) ack 35 win 8192 <nop,nop,timestamp 42836074 42836073>
14:17:20.875460 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: . ack 42 win 8192 <nop,nop,timestamp 42836074 42836074>
14:17:20.877579 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: P 35:42(7) ack 42 win 8192 <nop,nop,timestamp 42836075 42836074>
14:17:20.878130 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: P 42:144(102) ack 42 win 8192 <nop,nop,timestamp 42836075 42836075>
14:17:20.880719 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: P 42:99(57) ack 144 win 8192 <nop,nop,timestamp 42836075 42836075>
14:17:20.881838 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: P 144:243(99) ack 99 win 8192 <nop,nop,timestamp 42836076 42836075>
14:17:20.884175 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: P 99:254(155) ack 243 win 8192 <nop,nop,timestamp 42836076 42836076>
14:17:20.885057 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: F 243:243(0) ack 254 win 8192 <nop,nop,timestamp 42836076 42836076>
14:17:20.888431 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: S 3645329191:3645329191(0) win 32767 <mss 16396,sackOK,timestamp 42836077 0,nop,wscale 2>
14:17:20.888526 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: S 3655121275:3655121275(0) ack 3645329192 win 32767 <mss 16396,sackOK,timestamp 42836077 42836077,nop,wscale 2>
14:17:20.888708 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: . ack 1 win 8192 <nop,nop,timestamp 42836077 42836077>
14:17:20.894771 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: P 1:35(34) ack 1 win 8192 <nop,nop,timestamp 42836079 42836077>
14:17:20.894933 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: . ack 35 win 8192 <nop,nop,timestamp 42836079 42836079>
14:17:20.895690 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: P 1:42(41) ack 35 win 8192 <nop,nop,timestamp 42836079 42836079>
14:17:20.897115 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: . ack 42 win 8192 <nop,nop,timestamp 42836080 42836079>
14:17:20.898663 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: P 35:42(7) ack 42 win 8192 <nop,nop,timestamp 42836080 42836079>
14:17:20.899483 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: P 42:167(125) ack 42 win 8192 <nop,nop,timestamp 42836080 42836080>
14:17:20.903979 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: P 42:64(22) ack 167 win 8192 <nop,nop,timestamp 42836081 42836080>
14:17:20.921225 IP harvee2pb.harvee.org.9090 > harvee2pb.harvee.org.53891: F 254:254(0) ack 244 win 8192 <nop,nop,timestamp 42836085 42836076>
14:17:20.921429 IP harvee2pb.harvee.org.53891 > harvee2pb.harvee.org.9090: . ack 255 win 8192 <nop,nop,timestamp 42836086 42836085>
14:17:20.927329 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: P 167:271(104) ack 64 win 8192 <nop,nop,timestamp 42836087 42836081>
14:17:20.937634 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: P 64:86(22) ack 271 win 8192 <nop,nop,timestamp 42836090 42836087>
14:17:20.938646 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: P 271:379(108) ack 86 win 8192 <nop,nop,timestamp 42836090 42836090>
14:17:20.941071 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: P 86:108(22) ack 379 win 8192 <nop,nop,timestamp 42836090 42836090>
14:17:20.942555 IP harvee2pb.harvee.org.41533 > harvee2pb.harvee.org.7766: F 379:379(0) ack 108 win 8192 <nop,nop,timestamp 42836091 42836090>
14:17:20.943036 IP localhost.30025 > localhost.56191: P 157:165(8) ack 176 win 8192 <nop,nop,timestamp 42836091 42835298>
14:17:20.947369 IP harvee2pb.harvee.org.7766 > harvee2pb.harvee.org.41533: F 1