On Sun, Jul 01, 2001 at 10:14:26PM -0400, Mark-Jason Dominus wrote:
>
> The program at
>
> http://www.plover.com/~mjd/misc/err.pl
>
> demonstrates this. It is a P::C::I application which logs into #mjd
> and does two things: it echoes back all convesation on the channel,
> and it emits a HOUSEKEEPING message every second.
>
> The console output gets very far ahead of the IRC output; the program
> has executed the 'housekeeping' function for the 40th time before the
> 20th 'HOUSEKEEPING; message appears on the IRC channel. The program
> gets similarly behind in processing public conversation. The
> irc_public function is called in timely fashion, as soon as anyone
> says anything, but delay before the appearanace of the message from
> the server echoing what was said gets longer and longer.
tcpdump on a modified version of err.pl seems to indicate that the
slowdown is in ircd. Packets are being sest timely, but ircd's
response time increases forever and the bot finally floods off.
IRC session dump. Responses are observed becoming more and more
delayed as time passes.
(R12348:#mjd) HOUSEKEEPING Mon Jul 2 13:15:00 2001
## Join #mjd: R12348 ([EMAIL PROTECTED])
<R12348> HOUSEKEEPING Mon Jul 2 13:15:01 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:02 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:03 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:04 2001
<dngnot> one lag check
<R12348> HOUSEKEEPING Mon Jul 2 13:15:05 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:06 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:07 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:08 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:09 2001
<R12348> dngnot says "one lag check"
<R12348> HOUSEKEEPING Mon Jul 2 13:15:10 2001
<dngnot> two lag check
<R12348> HOUSEKEEPING Mon Jul 2 13:15:11 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:12 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:13 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:14 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:15 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:16 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:17 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:18 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:19 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:20 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:21 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:22 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:23 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:24 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:25 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:26 2001
<R12348> dngnot says "two lag check"
<R12348> HOUSEKEEPING Mon Jul 2 13:15:28 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:29 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:30 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:31 2001
<R12348> HOUSEKEEPING Mon Jul 2 13:15:32 2001
## Signoff #mjd: R12348 (Read error: 0 (Success))
This is a packet dump of the same IRC session.
The bot sends a housekeeping ping. The timestamp in the message
matches the TCP header's timestamp (first field on first line):
13:15:00.712004 206.251.198.172.2627 > 199.245.105.172.6667: [...]
[...]
0x0070 0d0a 5052 4956 4d53 4720 236d 6a64 203a ..PRIVMSG.#mjd.:
0x0080 484f 5553 454b 4545 5049 4e47 204d 6f6e HOUSEKEEPING.Mon
0x0090 204a 756c 2020 3220 3133 3a31 353a 3030 .Jul..2.13:15:00
0x00a0 2032 3030 310d 0a0d 0a .2001....
My client receives the housekeeping ping after maybe 7/10 seconds
delay, which isn't that bad considering I'm on a modem:
13:15:01.302017 195.82.114.160.6667 > 206.251.198.172.elan: [...]
[...]
0x0060 7275 732e 6e65 7420 5052 4956 4d53 4720 rus.net.PRIVMSG.
0x0070 236d 6a64 203a 484f 5553 454b 4545 5049 #mjd.:HOUSEKEEPI
0x0080 4e47 204d 6f6e 204a 756c 2020 3220 3133 NG.Mon.Jul..2.13
0x0090 3a31 353a 3030 2032 3030 310d 0a :15:00.2001..
Time passes, and I send a lag check message:
13:15:08.960569 206.251.198.172.elan > 195.82.114.160.6667: [...]
[...]
0x0030 219e 2053 5052 4956 4d53 4720 236d 6a64 !..SPRIVMSG.#mjd
0x0040 203a 6f6e 6520 6c61 6720 6368 6563 6b0d .:one.lag.check.
The bot receives it after about a second:
13:15:09.842492 199.245.105.172.6667 > 206.251.198.172.2627: [...]
[...]
0x0060 7573 2e6e 6574 2050 5249 564d 5347 2023 us.net.PRIVMSG.#
0x0070 6d6a 6420 3a6f 6e65 206c 6167 2063 6865 mjd.:one.lag.che
0x0080 636b 0a ck.
The bot echoes me in about 1/10 of a second. That's time spent inside
POE itself.
13:15:09.942227 206.251.198.172.2627 > 199.245.105.172.6667: [...]
[...]
0x0030 45e0 10b4 5052 4956 4d53 4720 236d 6a64 E...PRIVMSG.#mjd
0x0040 203a 646e 676e 6f74 2073 6179 7320 226f .:dngnot.says."o
0x0050 6e65 206c 6167 2063 6865 636b 220d 0a0d ne.lag.check"...
0x0060 0a
My client receives it ten seconds later!
13:15:19.442703 195.82.114.160.6667 > 206.251.198.172.elan: [...]
[...]
0x0060 7275 732e 6e65 7420 5052 4956 4d53 4720 rus.net.PRIVMSG.
0x0070 236d 6a64 203a 646e 676e 6f74 2073 6179 #mjd.:dngnot.say
0x0080 7320 226f 6e65 206c 6167 2063 6865 636b s."one.lag.check
0x0090 220d 0a "..
Here's a housekeeping ping later on in the bot's session. The
timestamp inside the packet matches the time it was transmitted.
13:15:26.989748 206.251.198.172.2627 > 199.245.105.172.6667: [...]
[...]
0x0030 45e0 171c 5052 4956 4d53 4720 236d 6a64 E...PRIVMSG.#mjd
0x0040 203a 484f 5553 454b 4545 5049 4e47 204d .:HOUSEKEEPING.M
0x0050 6f6e 204a 756c 2020 3220 3133 3a31 353a on.Jul..2.13:15:
0x0060 3236 2032 3030 310d 0a0d 0a 26.2001....
But it takes almost half a minute to return!
13:15:53.384472 195.82.114.160.6667 > 206.251.198.172.elan: [...]
[...]
0x0050 616d 692d 464c 2d32 2d31 3732 2e6e 6574 ami-FL-2-172.net
0x0060 7275 732e 6e65 7420 5052 4956 4d53 4720 rus.net.PRIVMSG.
0x0070 236d 6a64 203a 484f 5553 454b 4545 5049 #mjd.:HOUSEKEEPI
0x0080 4e47 204d 6f6e 204a 756c 2020 3220 3133 NG.Mon.Jul..2.13
0x0090 3a31 353a 3236 2032 3030 310d 0a :15:26.2001..
So it looks like POE's ok. Yay!
-- Rocco Caputo / [EMAIL PROTECTED] / poe.perl.org / poe.sourceforge.net
