Message delay/lag when sending a large number of lines #768

Closed
Shawn-Smith opened this Issue Feb 7, 2014 · 14 comments

Projects

None yet

6 participants

@Shawn-Smith

The issue seems to happen when InspIRCd is sending a large number of lines to a user. Part way through the sending InspIRCd will stop all sending and wait for the user to send another command of any kind before continuing sending the previous commands lines.

The logs below are from the channel #InspIRCd on irc.chatspike.net

> 16:56:04 chatspike +| NAMES #inspircd
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :@ChanServ!ChanServ@services.chatspike.net %slush!djslash@ChatSpikepti.kgv.188.89.IP psychon!psychon@ChatSpike19k7o9.out.znc.in jenkins!irc@ChatSpikeb26jnb.compute.amazonaws.com alprox!kimmo@ChatSpikes6eef7.pp.htv.fi ruok!ruok@ChatSpikee6orhv.fyvm.org macgyver-dgi!wa7dgi@ChatSpikeistutj.wa.comcast.net &@Attila!attila@ChatSpikeb49i86.love.livesex.hu berndj!berndj@ChatSpiketq86k6.isadsl.co.za alyx!alyx@ChatSpikeh11h28.vmkit.net
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :SmallR2002!Robert@ChatSpikerfu7ua.il.comcast.net mac-mini!mac-mini@ChatSpikel9osmf.mac-mini.org KindOne!KindOne@ChatSpikeidhqj5.ip.windstream.net &@danieldg!me@i.know.regexes +grawity!grawity@virgule.cluenet.org &@Majic!sexeh.pants@staff.chatspike.net @spb!stephen@ChatSpikelffj09.depleted.org %fraggeln!fragg@ChatSpiketd4.2v0.63.144.IP %Shutter!Shutter@ChatSpikej7s8g0.org cereal!cereal@ChatSpikep8kn9u.com kylef!kylef@ChatSpike2571aq.drk.sc
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :mlatin!mlatin@ChatSpikeaqeq82.il.comcast.net &@aquanight!aquanight@ChatSpikevmq.0kl.118.159.IP MillenniumFalc0n!falc0n@corellia.snoonet.org +Adam!Adam@ChatSpike942tam.compute-1.amazonaws.com jerith!jerith@ChatSpike7e06h5.slipgate.za.net +Colgate!rabbit@ChatSpikemrt4fo.wa.comcast.net Murarth!Murarth@ChatSpikeuuo16n.phnx.qwest.net deathspawn!deathspawn@ChatSpike0hdkit.crushandrun.net Googolplexed!Googol@ChatSpiker4a94p.tpgi.com.au
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :md_5!md_5@ChatSpikekqr0qm.prod1.spigotmc.org LinDaa!MzBabii@ChatSpikeo3l.6nb.199.99.IP +special!jbrooks@ChatSpike7bvo91.dereferenced.net Meistarin!coolguy@ChatSpikes44eg5.rev.poneytelecom.eu Kazuma!Kazuma@ChatSpikeo308ll.net Nazca__!Nazca@ChatSpikesma.i0t.75.77.IP Stmeter!Stmeter@ChatSpike528.v1a.71.64.IP Rylee!rylai@ChatSpikehaq7to.me AleX!agent@ChatSpike0kh.6nb.163.46.IP +beorn!bjorn@ChatSpikelp5qdj.90-149-32.nextgentel.com Duck!Duck@friendship.is.magic
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :Colin!Colin__@ChatSpikenptrv6.cfsgaming.com %SaberUK!saberuk@ChatSpikekeipj8.testificate.com cooper!jake@ChatSpikevslona.rlygd.net danneh_!d@ChatSpikeesv.9ej.165.101.IP Ikaros!bd@ChatSpikeqh089k.fios.verizon.net edem!edem@i.love.livesex.hu tty0!tty0@ChatSpike64nvtn.netnerdz.se Ch4c!Blink@ChatSpike3rj.4bk.47.78.IP ~@FrostyCoolWork!craig@frostycoolslug.com Techman!sid11863@uxbridge.irccloud.com %ChrisTX!Chris@ChatSpikego4e8q.ovh.net
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :Domin_!Domin@ChatSpike4p5k5q.org therock247uk!therock247u@ChatSpike6621k1.cable.virginm.net Ben!Ben@50.31.2.116 DanielNM!amen@ChatSpikectdnh7.lionsden.yi.org HeavyMetal!user@ChatSpikempc.3bj.248.206.IP alamar!alamar@ChatSpikenlce8a.syserv-solutions.de Svetlana!noone@ChatSpikeab6adj.xen.prgmr.com Syloq!Syloq@ChatSpikeq4i.v8d.254.173.IP macmaN!chezburger@ChatSpikebdhcm5.dyn.estpak.ee Kross!Azhrarn@BOFH.chatspike.net
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :@satmd!satmd@ChatSpikenfl65m.dedicated.hosteurope.de cooldude!cooldude132@ChatSpike2p7hdg.blackhole.mycooldude.info Xaquseg!xaquseg@ChatSpikeetogcq.pixelhunger.com shayne!shayne@ChatSpiked1epl5.members.linode.com LeaChim!LeaChim@ChatSpike8gg4qc.net O_O!ae@ChatSpikefrpbh8.darchoods.net xyzzy!.@ChatSpikepd0.5uv.45.92.IP &@peavey!ambient@devils.own Cronus!Cronus@ChatSpike70fh1m.cronus89.com Sagar!ICP@ChatSpikegas.nn1.63.74.IP
< 16:56:04 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :roe_!roe@ChatSpikermfm2s.cc.lehigh.edu JanE!jeri@ChatSpike7c77of.179.getinternet.no nimrod!cdxx@ChatSpikea30.ajs.241.199.IP ~@w00t!burchr@rburchell.com k1ng!k1ng@ChatSpike3er.9mc.73.76.IP Simos!simos@ChatSpike3bsqbp.simosnap.com Phantomal!muh@ChatSpike60eij2.clients.your-server.de Vincent!Vincent@ChatSpikedm6r73.al.comcast.net JD!JD@ChatSpike9n2i4v.static.sonic.net +Robby!robby@ChatSpikem8k1u2.access.telenet.be m4z!m4z@ChatSpikeuur353.i7c.org

< Nothing happens from here until I issue another command, 20 seconds later. >

> 16:56:24 chatspike +| MAP
< 16:56:24 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :Alpha!Alpha@ChatSpike83of94.wi.charter.com Dragon!Dragon@ChatSpike0e5r02.dragon.co.ck Whiskey!Whiskey@ChatSpikeneg.us2.44.31.IP kraft!kraft@ChatSpike17d.a67.246.46.IP Sporks!spoon@sporks.is.smarter.than.you.chatspike.net Simwar!Simwar@ChatSpike2qsukm.kimsufi.com blaster!blaster@ChatSpikeolqjri.wa.comcast.net +Brick!brik@staff.chatspike.net tomaw!chatspike@ChatSpike6u4oqj.tomaw.net DukePyrolator!DukePyrolat@ChatSpikeq6lkif.anope.org
< 16:56:24 chatspike +| :stitch.chatspike.net 353 Shawn = #inspircd :Keith!Keith@ChatSpiken9c.kvp.214.67.IP Zyferus!Zyferus@ChatSpike358o6t.mo.comcast.net hayuto!hayuto@ChatSpikehqt.p1v.59.37.IP +TinMan!metal@ChatSpikecnl.a6h.162.178.IP MzLinDaa!Mzbabii@ChatSpikeo3l.6nb.199.99.IP Milliways!aircpp@ChatSpike0e0a5t.tn.glocalnet.net ctcp!khdfdg@ChatSpikesoojdd.dynamic.ziggo.nl wloo299!wloo299999@ChatSpike4mjhq1.ma.comcast.net pcpl2!pcpl2@ChatSpike6j0f0f.gorzow.mm.pl %Shawn!Shawn@ChatSpikeieh5kr.res.rr.com
< 16:56:24 chatspike +| :stitch.chatspike.net 366 Shawn #inspircd :End of /NAMES list.
< 16:56:24 chatspike +| :stitch.chatspike.net 006 Shawn :stitch.chatspike.net     255 [49.51%]
< 16:56:24 chatspike +| :stitch.chatspike.net 006 Shawn :kenny.chatspike.net      250 [48.54%]
< 16:56:24 chatspike +| :stitch.chatspike.net 006 Shawn :services.chatspike.net    10 [ 1.94%]
< 16:56:24 chatspike +| :stitch.chatspike.net 270 Shawn :3 servers and 515 users, average 171.67 users per server
< 16:56:24 chatspike +| :stitch.chatspike.net 007 Shawn :End of /MAP

As you can see, part way through sending me the NAMES reply it stops for at least 20 seconds before I send the MAP command. It then finishes sending me the NAMES reply and then sends me the output of MAP.

@Shawn-Smith

I can also reproduce this by issuing LIST. The list wont finish until I send another command. Similar to the above logs with NAMES.

@ElementalAlchemist

This sounds like something I remember having been fixed already. What client are you using, and are you connected using SSL?

@Shawn-Smith

@ElementalAlchemist Weechat 0.4.2, and yes I'm using SSL.

Colgate on IRC thought it sounded like something that was mentioned before too but couldn't find a commit or other issue to reference.

@Adam-
Member
Adam- commented Feb 8, 2014
@Shawn-Smith

@Adam- Thanks! Is there anything clients should be doing to fix this on their end?

@Adam-
Member
Adam- commented Feb 8, 2014

I don't know what the problem is or why this fixes it. Attila might know.

@Shawn-Smith

I'll leave this issue open until @attilamolnar sees it and can provide more insight to what client authors should be doing to fix this then.

@Robby-
Robby- commented Feb 8, 2014

I'll be damned, I first hit this problem a LONG time ago, when creating an opered bot, connected via SSL. I've not experienced this bug much lately, though, but a CHECK * also causes this issue on a network with a few hundred users. I always blamed the bot for this as I could never reproduce it on my own client for some reason. I didn't think this was an InspIRCd issue as making the bot send another command (or anything) simply triggered the pending data to be processed by the bot, I just figured it was the bot being stalled and didn't investigate further.

@ElementalAlchemist

It's primarily a client issue, specifically in how they handle the message queue in SSL packets. There was a change in 1.2 to send as many messages as possible in a single packet, which chokes some clients that have no idea how to SSL.

The issue can be mitigated with server changes, but at the core, it's a client issue.

@SaberUK
SaberUK commented Feb 8, 2014

Is the server you are testing on running the latest version of InspIRCd? This should have been fixed in 7dd381f. Adam already said this.

@Shawn-Smith

@ElementalAlchemist How would client authors fix this?

@ElementalAlchemist

Don't just stop processing the message queue after the first line in an SSL packet is processed? I'd imagine that's the problem anyway. Most clients didn't seem to have an issue with it, of course.

Of course, all these clients that just delay processing are still doing better than Pidgin did when this was first implemented, and Pidgin would just drop all the lines that weren't the first.

@Shawn-Smith

Going to close this now since it's not an InspIRCd issue and information has been given for client authors to fix this on their end.

@Shawn-Smith Shawn-Smith closed this Mar 5, 2014
@bgeraghty

Just an FYI for those dealing with this:
I encountered this issue, and was able to remedy it by doubling the size of the read buffers in my client app. Seemed otherwise lines were getting dropped / missed by my client.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment